Persist metrics for container usage (execution time and waiting time) to Testrun table

app/controllers/concerns/submission_scoring.rb

@@ -19,7 +19,15 @@ module SubmissionScoring
                 end
               end
             end
-            Testrun.new(submission: submission, cause: 'assess', file: file, passed: passed, output: testrun_output).save
+            Testrun.new(
+              submission: submission,
+              cause: 'assess',
+              file: file,
+              passed: passed,
+              output: testrun_output,
+              container_execution_time: output[:container_execution_time],
+              waiting_for_container_time: output[:waiting_for_container_time]
+            ).save
             output.merge!(assessment)
             output.merge!(filename: file.name_with_extension, message: feedback_message(file, output[:score]), weight: file.weight)
           end

app/controllers/submissions_controller.rb

@@ -161,8 +161,10 @@ class SubmissionsController < ApplicationController
       # give the docker_client the tubesock object, so that it can send messages (timeout)
       @docker_client.tubesock = tubesock
 
+      container_request_time = Time.now
       result = @docker_client.execute_run_command(@submission, sanitize_filename)
       tubesock.send_data JSON.dump({'cmd' => 'status', 'status' => result[:status]})
+      @waiting_for_container_time = Time.now - container_request_time
 
       if result[:status] == :container_running
         socket = result[:socket]
@@ -199,6 +201,7 @@ class SubmissionsController < ApplicationController
 
         # Send command after all listeners are attached.
         # Newline required to flush
+        @execution_request_time = Time.now
         socket.send command + "\n"
         Rails.logger.info('Sent command: ' + command.to_s)
       else
@@ -208,6 +211,7 @@ class SubmissionsController < ApplicationController
   end
 
   def kill_socket(tubesock)
+    @container_execution_time = Time.now - @execution_request_time unless @execution_request_time.blank?
     # search for errors and save them as StructuredError (for scoring runs see submission_scoring.rb)
     errors = extract_errors
     send_hints(tubesock, errors)
@@ -302,7 +306,14 @@ class SubmissionsController < ApplicationController
   def save_run_output
     unless @run_output.blank?
       @run_output = @run_output[(0..max_run_output_buffer_size-1)] # trim the string to max_message_buffer_size chars
-      Testrun.create(file: @file, cause: 'run', submission: @submission, output: @run_output)
+      Testrun.create(
+        file: @file,
+        cause: 'run',
+        submission: @submission,
+        output: @run_output,
+        container_execution_time: @container_execution_time,
+        waiting_for_container_time: @waiting_for_container_time
+      )
     end
   end
 

db/migrate/20200326115249_add_container_execution_time_to_testruns.rb

@@ -0,0 +1,6 @@
+class AddContainerExecutionTimeToTestruns < ActiveRecord::Migration[5.2]
+  def change
+    add_column :testruns, :container_execution_time, :interval
+    add_column :testruns, :waiting_for_container_time, :interval
+  end
+end

lib/docker_client.rb

@@ -256,13 +256,21 @@ class DockerClient
   #only used by score
   def execute_command(command, before_execution_block, output_consuming_block)
     #tries ||= 0
+    container_request_time = Time.now
     @container = DockerContainerPool.get_container(@execution_environment)
+    waiting_for_container_time = Time.now - container_request_time
     if @container
       @container.status = :executing
       before_execution_block.try(:call)
-      send_command(command, @container, &output_consuming_block)
+      execution_request_time = Time.now
+      command_result = send_command(command, @container, &output_consuming_block)
+      container_execution_time = Time.now - execution_request_time
+
+      command_result.merge!(waiting_for_container_time: waiting_for_container_time)
+      command_result.merge!(container_execution_time: container_execution_time)
+      command_result
     else
-      {status: :container_depleted}
+      {status: :container_depleted, waiting_for_container_time: waiting_for_container_time, container_execution_time: nil}
     end
   rescue Excon::Errors::SocketError => error
     # socket errors seems to be normal when using exec