Simplify and capture the decision-making log from the scheduler

modules/Bio/EnsEMBL/Hive/AnalysisStats.pm

@@ -299,20 +299,15 @@ sub job_count_breakout {
 }
 
 
-sub print_stats {
-    my $self = shift @_;
-
-    printf("%-27s(%2d) ",  $self->get_analysis->logic_name, $self->analysis_id );
-    print $self->toString."\n";
-}
-
-
 sub toString {
     my $self = shift @_;
 
     my $analysis = $self->get_analysis;
 
-    my $output = sprintf("%11s jobs(Sem:%d, Rdy:%d, InProg:%d, Done+Pass:%d, Fail:%d)=%d Ave_msec:%d, workers(Running:%d, Reqired:%d) ",
+    my $output .= sprintf("%-27s(%2d) %11s jobs(Sem:%d, Rdy:%d, InProg:%d, Done+Pass:%d, Fail:%d)=%d Ave_msec:%d, workers(Running:%d, Reqired:%d) ",
+        $analysis->logic_name,
+        $self->analysis_id,
+
         $self->status,
 
         $self->semaphored_job_count,
@@ -329,7 +324,7 @@ sub toString {
     );
     $output .=  '  h.cap:'    .( defined($self->hive_capacity) ? $self->hive_capacity : '-' )
                .'  a.cap:'    .( defined($analysis->analysis_capacity) ? $analysis->analysis_capacity : '-')
-               ."  (sync'd "  .$self->seconds_since_last_update." sec ago)",
+               ."  (sync'd "  .$self->seconds_since_last_update." sec ago)";
 
     return $output;
 }

modules/Bio/EnsEMBL/Hive/Queen.pm

@@ -748,7 +748,7 @@ sub print_analysis_status {
 
     my $list_of_analyses = $filter_analysis ? [$filter_analysis] : $self->db->get_AnalysisAdaptor->fetch_all;
     foreach my $analysis (sort {$a->dbID <=> $b->dbID} @$list_of_analyses) {
-        $analysis->stats->print_stats();
+        print $analysis->stats->toString . "\n";
     }
 }
 

modules/Bio/EnsEMBL/Hive/Scheduler.pm

@@ -53,8 +53,9 @@ sub schedule_workers_resync_if_necessary {
         # combined mapping:
     my $analysis_id2rc_name                     = { map { $_ => $rc_id2name->{ $analysis_id2rc_id->{ $_ }} } keys %$analysis_id2rc_id };
 
-    my ($workers_to_submit_by_meadow_type_rc_name, $total_workers_required)
+    my ($workers_to_submit_by_meadow_type_rc_name, $total_workers_required, $log_buffer)
         = schedule_workers($queen, $valley, $filter_analysis, $meadow_capacity_by_type, $analysis_id2rc_name);
+    print $log_buffer;
 
     unless( $total_workers_required ) {
         print "\nScheduler: according to analysis_stats no workers are required... let's see if resync can fix it.\n" ;
@@ -68,8 +69,9 @@ sub schedule_workers_resync_if_necessary {
         print "Scheduler: re-synchronizing the Hive...\n";
         $queen->synchronize_hive($filter_analysis);
 
-        ($workers_to_submit_by_meadow_type_rc_name, $total_workers_required)
+        ($workers_to_submit_by_meadow_type_rc_name, $total_workers_required, $log_buffer)
             = schedule_workers($queen, $valley, $filter_analysis, $meadow_capacity_by_type, $analysis_id2rc_name);
+        print $log_buffer;
     }
 
         # adjustment for pending workers:
@@ -110,19 +112,16 @@ sub schedule_workers {
                                 : @{ $queen->db->get_AnalysisStatsAdaptor->fetch_all_by_suitability_rc_id_meadow_type() };
 
     unless(@suitable_analyses) {
-        print "Scheduler could not find any suitable analyses to start with\n";
-        return ({}, 0);
+        return ({}, 0, "Scheduler could not find any suitable analyses to start with\n");
     }
 
         # the pre-pending-adjusted outcome will be stored here:
     my %workers_to_submit_by_meadow_type_rc_name    = ();
-
     my $total_workers_required                      = 0;
+    my $log_buffer                                  = '';
 
     my $default_meadow_type                         = $valley->get_default_meadow()->type;
 
-    my $available_submit_limit                      = $valley->config_get('SubmitWorkersMax');
-
     my $submit_capacity                             = Bio::EnsEMBL::Hive::Limiter->new( 'Max number of Workers submitted this iteration', $valley->config_get('SubmitWorkersMax') );
     my $queen_capacity                              = Bio::EnsEMBL::Hive::Limiter->new( 'Total reciprocal capacity of the Hive', 1.0 - $queen->get_hive_current_load() );
 
@@ -175,14 +174,14 @@ sub schedule_workers {
 
         my $this_rc_name    = $analysis_id2rc_name->{ $analysis_stats->analysis_id };
         $workers_to_submit_by_meadow_type_rc_name{ $this_meadow_type }{ $this_rc_name } += $extra_workers_this_analysis;
-        $analysis_stats->print_stats();
-        printf("Before checking the Valley for pending jobs, Scheduler allocated $extra_workers_this_analysis x $this_meadow_type:$this_rc_name extra workers for '%s' [%.4f hive_load remaining]\n",
+        $log_buffer .= $analysis_stats->toString . "\n";
+        $log_buffer .= sprintf("Before checking the Valley for pending jobs, Scheduler allocated $extra_workers_this_analysis x $this_meadow_type:$this_rc_name extra workers for '%s' [%.4f hive_load remaining]\n",
             $analysis->logic_name,
             $queen_capacity->available_capacity,
         );
     }
 
-    return (\%workers_to_submit_by_meadow_type_rc_name, $total_workers_required);
+    return (\%workers_to_submit_by_meadow_type_rc_name, $total_workers_required, $log_buffer);
 }
 
 

modules/Bio/EnsEMBL/Hive/Worker.pm

@@ -593,7 +593,7 @@ sub run {
     $self->adaptor->register_worker_death($self, 1);
 
     if($self->debug) {
-        $self->worker_say( 'AnalysisStats :'.$self->analysis->stats->toString ) if($self->analysis_id());
+        $self->worker_say( 'AnalysisStats : '.$self->analysis->stats->toString ) if($self->analysis_id());
         $self->worker_say( 'dbc '.$self->adaptor->db->dbc->disconnect_count. ' disconnect cycles' );
     }
 
@@ -669,7 +669,7 @@ sub run_one_batch {
     $self->adaptor->safe_synchronize_AnalysisStats($self->analysis->stats);
 
     if($self->debug) {
-        $self->worker_say( "Stats : ".$self->analysis->stats->toString );
+        $self->worker_say( 'AnalysisStats : '.$self->analysis->stats->toString );
         $self->worker_say( 'claimed '.scalar(@{$jobs}).' jobs to process' );
     }