Log elapsed time in default_data, input_processor, and init jobs in file

init_log.csv

.gitignore

@@ -26,3 +26,4 @@ aclocal.m4
 autom4te.cache
 trick_test
 gmon.out
+*init_log.csv*

include/trick/Executive.hh

@@ -832,21 +832,27 @@ namespace Trick {
 
             /**
              * Calls the default_data jobs.
+             * @param open file stream for a log to record the elapsed 
+             * time of each job.
              * @return 0 for no errors or throws exception otherwise.
              */
-            virtual int call_default_data() ;
+            virtual int call_default_data(std::ofstream& init_log_stream) ;
 
             /**
              * Calls the input_processor jobs.
+             * @param open file stream for a log to record the elapsed 
+             * time of each job.
              * @return 0 for no errors or throws exception otherwise.
              */
-            virtual int call_input_processor() ;
+            virtual int call_input_processor(std::ofstream& init_log_stream) ;
 
             /**
              * Calls the initialization jobs.
+             * @param open file stream for a log to record the elapsed 
+             * time of each job.
              * @return 0 for no errors or throws exception otherwise.
              */
-            virtual int call_initialization() ;
+            virtual int call_initialization(std::ofstream& init_log_stream) ;
 
             /**
              * This job copies the job information from the executive to a checkpointable form.

trick_sims/.gitignore

@@ -5,6 +5,7 @@ S_run_summary
 send_hs
 varserver_log
 log_*
+*init_log.csv*
 chkpnt_*
 MONTE_RUN_*
 .S_library*

trick_source/sim_services/Clock/clock_c_intf.cpp

@@ -34,4 +34,4 @@ extern "C" int clock_set_rt_clock_ratio(double in_clock_ratio) {
 
 extern "C" unsigned long long clock_tics_per_sec(void) {
 	return the_clock->clock_tics_per_sec;
-}
+}

trick_source/sim_services/CommandLineArguments/CommandLineArguments.cpp

@@ -31,6 +31,9 @@ Trick::CommandLineArguments::CommandLineArguments() {
 
     output_dir = std::string(".") ;
     default_dir = std::string(".") ;
+
+    argc = 0;
+    argv = NULL;
 }
 
 int Trick::CommandLineArguments::get_argc() {

trick_source/sim_services/Executive/Executive_call_default_data.cpp

@@ -1,9 +1,11 @@
 
 #include <iostream>
 #include <sys/resource.h>
+#include<fstream>
 
 #include "trick/Executive.hh"
 #include "trick/ExecutiveException.hh"
+#include "trick/clock_proto.h"
 
 /**
 @details
@@ -15,7 +17,7 @@
       returned from Trick::Executive::init().
 -# If no execption is thrown return 0
 */
-int Trick::Executive::call_default_data() {
+int Trick::Executive::call_default_data(std::ofstream& init_log_stream) {
 
     int ret = 0 ;
 
@@ -24,7 +26,12 @@ int Trick::Executive::call_default_data() {
     /* Call the default data jobs. */
     default_data_queue.reset_curr_index() ;
     while ( (curr_job = default_data_queue.get_next_job()) != NULL ) {
+        long long start = clock_wall_time();
         ret = curr_job->call() ;
+        long long end = clock_wall_time();
+        if(init_log_stream) {
+          init_log_stream << "default_data," << curr_job->name << ',' << (double)(end-start)/clock_tics_per_sec() << '\n';
+        }
         if ( ret != 0 ) {
             throw Trick::ExecutiveException(ret , curr_job->name.c_str() , 0 , "default_data job did not return 0") ;
         }

trick_source/sim_services/Executive/Executive_call_initialization.cpp

@@ -1,9 +1,10 @@
 
 #include <iostream>
+#include<fstream>
 #include <sys/resource.h>
-
 #include "trick/Executive.hh"
 #include "trick/ExecutiveException.hh"
+#include "trick/clock_proto.h"
 
 /**
 @details
@@ -13,7 +14,7 @@
       returned from Trick::Executive::init().
 -# If no execption is thrown return 0
 */
-int Trick::Executive::call_initialization() {
+int Trick::Executive::call_initialization(std::ofstream& init_log_stream) {
 
     int ret = 0 ;
 
@@ -22,7 +23,12 @@ int Trick::Executive::call_initialization() {
     /* Call the initialization jobs. */
     initialization_queue.reset_curr_index() ;
     while ( (curr_job = initialization_queue.get_next_job()) != NULL ) {
+        long long start = clock_wall_time();
         ret = curr_job->call() ;
+        long long end = clock_wall_time();
+        if(init_log_stream) {
+            init_log_stream << "init," << curr_job->name << ',' << (double)(end-start)/clock_tics_per_sec() << '\n';
+        }
         if ( ret != 0 ) {
             throw Trick::ExecutiveException(ret , curr_job->name.c_str() , 0 , "initialization job did not return 0") ;
         }

trick_source/sim_services/Executive/Executive_call_input_processor.cpp

@@ -1,9 +1,11 @@
 
 #include <iostream>
 #include <sys/resource.h>
+#include<fstream>
 
 #include "trick/Executive.hh"
 #include "trick/ExecutiveException.hh"
+#include "trick/clock_proto.h"
 
 /**
 @details
@@ -13,7 +15,7 @@
       returned from Trick::Executive::init().
 -# If no execption is thrown return 0
 */
-int Trick::Executive::call_input_processor() {
+int Trick::Executive::call_input_processor(std::ofstream& init_log_stream) {
 
     int ret = 0 ;
 
@@ -25,7 +27,12 @@ int Trick::Executive::call_input_processor() {
        So we test for the restart_called flag and break out of the loop if we restart_called is set. */
     input_processor_queue.reset_curr_index() ;
     while ( !restart_called and (curr_job = input_processor_queue.get_next_job()) != NULL ) {
+        long long start = clock_wall_time();
         ret = curr_job->call() ;
+        long long end = clock_wall_time();
+        if(init_log_stream) {
+          init_log_stream << "input_processor," << curr_job->name << ',' << (double)(end-start)/clock_tics_per_sec() << '\n';
+        }
         if ( ret != 0 ) {
             throw Trick::ExecutiveException(ret , curr_job->name.c_str() , 0 , "input_processor job did not return 0") ;
         }

trick_source/sim_services/Executive/Executive_init.cpp

@@ -2,10 +2,14 @@
 #include <iostream>
 #include <stdlib.h>
 #include <sys/resource.h>
+#include <fstream>
+#include <cstring>
+#include <cerrno>
 
 #include "trick/Executive.hh"
 #include "trick/ExecutiveException.hh"
 #include "trick/exec_proto.h"
+#include "trick/command_line_protos.h"
 
 /**
 @details
@@ -25,6 +29,7 @@ int Trick::Executive::init() {
 
     double cpu_time ;
 
+
     try {
 
         mode = Initialization ;
@@ -33,16 +38,30 @@ int Trick::Executive::init() {
         struct rusage cpu_usage_buf ;
         getrusage(RUSAGE_SELF, &cpu_usage_buf);
         cpu_start =   ((double) cpu_usage_buf.ru_utime.tv_sec) + ((double) cpu_usage_buf.ru_utime.tv_usec / 1000000.0);
+        std::ofstream init_log_stream;
 
-        call_default_data() ;
+        /* First parse command line to see if trick is in Sie generation mode. 
+           If not, create the init_log file and record the elapsed time of
+           default_data, input_processor, and init jobs */ 
+        int argc ;
+        char ** argv ;
+        argc = command_line_args_get_argc() ;
+        argv = command_line_args_get_argv() ;
+        if (argc < 2 || strcmp(argv[1], "sie")) {
+            init_log_stream.open((std::string(command_line_args_get_output_dir()) + std::string("/init_log.csv")).c_str(), std::ofstream::out);
+            init_log_stream << "class,job,duration (s)\n";
+        }
 
-        call_input_processor() ;
+        call_default_data(init_log_stream) ;
+        call_input_processor(init_log_stream) ;
 
         // If we are starting from a checkpoint, restart_called will be true.  Skip init routines in this case.
         if ( ! restart_called ) {
-            call_initialization() ;
+            call_initialization(init_log_stream) ;
         }
 
+        init_log_stream.close();
+
         /* Set the initial values for the scheduler times. */
         next_frame_check_tics = software_frame_tics + time_tics ;
         job_call_time_tics = next_frame_check_tics ;

trick_source/sim_services/Executive/Executive_process_sim_args.cpp

@@ -69,4 +69,3 @@ int Trick::Executive::process_sim_args() {
 
     return(0) ;
 }
-

trick_source/sim_services/Executive/test/Executive_test.cpp

@@ -14,6 +14,8 @@
 #include "trick/SimObject.hh"
 #include "trick/MemoryManager.hh"
 #include "trick/memorymanager_c_intf.h"
+#include "trick/CommandLineArguments.hh"
+#include "trick/GetTimeOfDayClock.hh"
 
 void sig_hand(int sig) ;
 void ctrl_c_hand(int sig) ;
@@ -225,10 +227,12 @@ class ExecutiveTest : public ::testing::Test {
         Trick::MessagePublisher mpublisher ;
         Trick::MessageCout mcout ;
         Trick::MemoryManager mm ;
+        Trick::CommandLineArguments cla ;
+        Trick::GetTimeOfDayClock gtodc ;
         //Trick::RequirementScribe req;
 
 
-        ExecutiveTest() {}
+        ExecutiveTest() {gtodc.set_global_clock();}
         ~ExecutiveTest() {}
         virtual void SetUp() ;
         virtual void TearDown() {}

trick_source/trick_utils/unicode/.gitignore

@@ -0,0 +1 @@
+*unicode_utils_test*