From d95ccc6bbbf94e957b939ca9d9aea71cda345944 Mon Sep 17 00:00:00 2001 From: Tom Clegg Date: Thu, 18 May 2017 17:25:20 -0400 Subject: [PATCH] 11590: Dry up log_reuse_info() calls. --- services/api/app/models/container.rb | 29 ++++++++++++++-------------- services/api/app/models/job.rb | 8 ++++---- services/api/lib/log_reuse_info.rb | 12 ++++++++---- 3 files changed, 27 insertions(+), 22 deletions(-) diff --git a/services/api/app/models/container.rb b/services/api/app/models/container.rb index 60911bd55c..f72ca4dcf9 100644 --- a/services/api/app/models/container.rb +++ b/services/api/app/models/container.rb @@ -179,50 +179,51 @@ class Container < ArvadosModel def self.find_reusable(attrs) log_reuse_info { "starting with #{Container.all.count} container records in database" } candidates = Container.where_serialized(:command, attrs[:command]) - log_reuse_info { "have #{candidates.count} candidates after filtering on command #{attrs[:command].inspect}" } + log_reuse_info(candidates) { "after filtering on command #{attrs[:command].inspect}" } candidates = candidates.where('cwd = ?', attrs[:cwd]) - log_reuse_info { "have #{candidates.count} candidates after filtering on cwd #{attrs[:cwd].inspect}" } + log_reuse_info(candidates) { "after filtering on cwd #{attrs[:cwd].inspect}" } candidates = candidates.where_serialized(:environment, attrs[:environment]) - log_reuse_info { "have #{candidates.count} candidates after filtering on environment #{attrs[:environment].inspect}" } + log_reuse_info(candidates) { "after filtering on environment #{attrs[:environment].inspect}" } candidates = candidates.where('output_path = ?', attrs[:output_path]) - log_reuse_info { "have #{candidates.count} candidates after filtering on output_path #{attrs[:output_path].inspect}" } + log_reuse_info(candidates) { "after filtering on output_path #{attrs[:output_path].inspect}" } image = resolve_container_image(attrs[:container_image]) candidates = candidates.where('container_image = ?', image) - log_reuse_info { "have #{candidates.count} candidates after filtering on container_image #{image.inspect} (resolved from #{attrs[:container_image].inspect})" } + log_reuse_info(candidates) { "after filtering on container_image #{image.inspect} (resolved from #{attrs[:container_image].inspect})" } candidates = candidates.where_serialized(:mounts, resolve_mounts(attrs[:mounts])) - log_reuse_info { "have #{candidates.count} candidates after filtering on mounts #{attrs[:mounts].inspect}" } + log_reuse_info(candidates) { "after filtering on mounts #{attrs[:mounts].inspect}" } candidates = candidates.where_serialized(:runtime_constraints, resolve_runtime_constraints(attrs[:runtime_constraints])) - log_reuse_info { "have #{candidates.count} candidates after filtering on runtime_constraints #{attrs[:runtime_constraints].inspect}" } + log_reuse_info(candidates) { "after filtering on runtime_constraints #{attrs[:runtime_constraints].inspect}" } + + log_reuse_info { "checking for state=Complete with readable output and log..." } - # Check for Completed candidates whose output and log are both readable. select_readable_pdh = Collection. readable_by(current_user). select(:portable_data_hash). to_sql usable = candidates.where(state: Complete, exit_code: 0) - log_reuse_info { "have #{usable.count} with state=Complete, exit_code=0" } + log_reuse_info(usable) { "with state=Complete, exit_code=0" } usable = usable.where("log IN (#{select_readable_pdh})") - log_reuse_info { "have #{usable.count} with log readable by current user #{current_user.uuid}" } + log_reuse_info(usable) { "with readable log" } usable = usable.where("output IN (#{select_readable_pdh})") - log_reuse_info { "have #{usable.count} with output readable by current user #{current_user.uuid}" } + log_reuse_info(usable) { "with readable output" } - usable = usable.order('finished_at ASC'). - limit(1).first + usable = usable.order('finished_at ASC').limit(1).first if usable - log_reuse_info { "done, reusing completed container #{usable.uuid}" } + log_reuse_info { "done, reusing container #{usable.uuid} with state=Complete" } return usable end # Check for Running candidates and return the most likely to finish sooner. + log_reuse_info { "checking for state=Running..." } running = candidates.where(state: Running). order('progress desc, started_at asc'). limit(1).first diff --git a/services/api/app/models/job.rb b/services/api/app/models/job.rb index 7536c3b5c3..fa38ece244 100644 --- a/services/api/app/models/job.rb +++ b/services/api/app/models/job.rb @@ -245,20 +245,20 @@ class Job < ArvadosModel candidates = candidates.where( 'state = ? or (owner_uuid = ? and state in (?))', Job::Complete, current_user.uuid, [Job::Queued, Job::Running]) - log_reuse_info { "have #{candidates.count} candidates after filtering on job state ((state=Complete) or (state=Queued/Running and (submitted by current user)))" } + log_reuse_info(candidates) { "after filtering on job state ((state=Complete) or (state=Queued/Running and (submitted by current user)))" } digest = Job.sorted_hash_digest(attrs[:script_parameters]) candidates = candidates.where('script_parameters_digest = ?', digest) - log_reuse_info { "have #{candidates.count} candidates after filtering on script_parameters_digest #{digest}" } + log_reuse_info(candidates) { "after filtering on script_parameters_digest #{digest}" } candidates = candidates.where('nondeterministic is distinct from ?', true) - log_reuse_info { "have #{candidates.count} candidates after filtering on !nondeterministic" } + log_reuse_info(candidates) { "after filtering on !nondeterministic" } # prefer Running jobs over Queued candidates = candidates.order('state desc, created_at') candidates = apply_filters candidates, filters - log_reuse_info { "have #{candidates.count} candidates after filtering on repo, script, and custom filters #{filters.inspect}" } + log_reuse_info(candidates) { "after filtering on repo, script, and custom filters #{filters.inspect}" } chosen = nil incomplete_job = nil diff --git a/services/api/lib/log_reuse_info.rb b/services/api/lib/log_reuse_info.rb index 1bf050a777..b325a65e0a 100644 --- a/services/api/lib/log_reuse_info.rb +++ b/services/api/lib/log_reuse_info.rb @@ -2,11 +2,15 @@ module LogReuseInfo # log_reuse_info logs whatever the given block returns, if # log_reuse_decisions is enabled. It accepts a block instead of a # string because in some cases constructing the strings involves - # doing database queries, and we want to skip those queries when - # logging is disabled. - def log_reuse_info + # doing expensive things like database queries, and we want to skip + # those when logging is disabled. + def log_reuse_info(candidates=nil) if Rails.configuration.log_reuse_decisions - Rails.logger.info("find_reusable: " + yield) + msg = yield + if !candidates.nil? + msg = "have #{candidates.count} candidates " + msg + end + Rails.logger.info("find_reusable: " + msg) end end end -- 2.30.2