From fadda55abfc5bd5913267ccbb91a1f202424235e Mon Sep 17 00:00:00 2001 From: Scott Fennell Date: Fri, 14 Jun 2019 09:04:20 -0500 Subject: [PATCH] Log elapsed time in default_data, input_processor, and init jobs in file init_log.csv --- .gitignore | 1 + include/trick/Executive.hh | 12 ++++++--- trick_sims/.gitignore | 1 + .../sim_services/Clock/clock_c_intf.cpp | 2 +- .../CommandLineArguments.cpp | 3 +++ .../Executive/Executive_call_default_data.cpp | 9 ++++++- .../Executive_call_initialization.cpp | 10 ++++++-- .../Executive_call_input_processor.cpp | 9 ++++++- .../sim_services/Executive/Executive_init.cpp | 25 ++++++++++++++++--- .../Executive/Executive_process_sim_args.cpp | 1 - .../Executive/test/Executive_test.cpp | 6 ++++- trick_source/trick_utils/unicode/.gitignore | 1 + 12 files changed, 67 insertions(+), 13 deletions(-) create mode 100644 trick_source/trick_utils/unicode/.gitignore diff --git a/.gitignore b/.gitignore index 8f45bde9..e4782dd4 100644 --- a/.gitignore +++ b/.gitignore @@ -26,3 +26,4 @@ aclocal.m4 autom4te.cache trick_test gmon.out +*init_log.csv* diff --git a/include/trick/Executive.hh b/include/trick/Executive.hh index ee6f8e19..7126b6da 100644 --- a/include/trick/Executive.hh +++ b/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. diff --git a/trick_sims/.gitignore b/trick_sims/.gitignore index 50833d24..f3f5b2a5 100644 --- a/trick_sims/.gitignore +++ b/trick_sims/.gitignore @@ -5,6 +5,7 @@ S_run_summary send_hs varserver_log log_* +*init_log.csv* chkpnt_* MONTE_RUN_* .S_library* diff --git a/trick_source/sim_services/Clock/clock_c_intf.cpp b/trick_source/sim_services/Clock/clock_c_intf.cpp index 8b588573..f51ceae1 100644 --- a/trick_source/sim_services/Clock/clock_c_intf.cpp +++ b/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; -} \ No newline at end of file +} diff --git a/trick_source/sim_services/CommandLineArguments/CommandLineArguments.cpp b/trick_source/sim_services/CommandLineArguments/CommandLineArguments.cpp index ac94142d..b46c747a 100644 --- a/trick_source/sim_services/CommandLineArguments/CommandLineArguments.cpp +++ b/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() { diff --git a/trick_source/sim_services/Executive/Executive_call_default_data.cpp b/trick_source/sim_services/Executive/Executive_call_default_data.cpp index ea669054..f79511b6 100644 --- a/trick_source/sim_services/Executive/Executive_call_default_data.cpp +++ b/trick_source/sim_services/Executive/Executive_call_default_data.cpp @@ -1,9 +1,11 @@ #include #include +#include #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") ; } diff --git a/trick_source/sim_services/Executive/Executive_call_initialization.cpp b/trick_source/sim_services/Executive/Executive_call_initialization.cpp index bedd53c9..edb38dc6 100644 --- a/trick_source/sim_services/Executive/Executive_call_initialization.cpp +++ b/trick_source/sim_services/Executive/Executive_call_initialization.cpp @@ -1,9 +1,10 @@ #include +#include #include - #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") ; } diff --git a/trick_source/sim_services/Executive/Executive_call_input_processor.cpp b/trick_source/sim_services/Executive/Executive_call_input_processor.cpp index f7f77551..c7acfc73 100644 --- a/trick_source/sim_services/Executive/Executive_call_input_processor.cpp +++ b/trick_source/sim_services/Executive/Executive_call_input_processor.cpp @@ -1,9 +1,11 @@ #include #include +#include #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") ; } diff --git a/trick_source/sim_services/Executive/Executive_init.cpp b/trick_source/sim_services/Executive/Executive_init.cpp index 935878ed..6e1174a0 100644 --- a/trick_source/sim_services/Executive/Executive_init.cpp +++ b/trick_source/sim_services/Executive/Executive_init.cpp @@ -2,10 +2,14 @@ #include #include #include +#include +#include +#include #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 ; diff --git a/trick_source/sim_services/Executive/Executive_process_sim_args.cpp b/trick_source/sim_services/Executive/Executive_process_sim_args.cpp index e84d614f..2af7ed80 100644 --- a/trick_source/sim_services/Executive/Executive_process_sim_args.cpp +++ b/trick_source/sim_services/Executive/Executive_process_sim_args.cpp @@ -69,4 +69,3 @@ int Trick::Executive::process_sim_args() { return(0) ; } - diff --git a/trick_source/sim_services/Executive/test/Executive_test.cpp b/trick_source/sim_services/Executive/test/Executive_test.cpp index 1a5b203f..78e0726b 100644 --- a/trick_source/sim_services/Executive/test/Executive_test.cpp +++ b/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() {} diff --git a/trick_source/trick_utils/unicode/.gitignore b/trick_source/trick_utils/unicode/.gitignore new file mode 100644 index 00000000..7ef31105 --- /dev/null +++ b/trick_source/trick_utils/unicode/.gitignore @@ -0,0 +1 @@ +*unicode_utils_test*