Updated to log applicable time in seconds instead of tics for frame logging (#1623)

* Updated to log applicable time in seconds instead of tics, remove scale attribute in dp product XMLs, and reset clock before realtime clock sync to avoid logging epoch time for frame logging.

* Removed "_seconds" from applicable time variable names.
This commit is contained in:
Hong Chen 2024-01-18 10:17:54 -06:00 committed by GitHub
parent f80e600162
commit 6d86a0fd97
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
7 changed files with 43 additions and 25 deletions

View File

@ -65,9 +65,12 @@ namespace Trick {
/** Thread start time */
long long start_time ;
/** Thread total frame scheduled time */
/** Thread total frame scheduled time in tics*/
long long frame_sched_time ;
/** Thread total frame scheduled time in seconds*/
double frame_time ;
} ;
} ;

View File

@ -88,9 +88,12 @@ namespace Trick {
/** Clock time when job stopped in frame */
long long rt_stop_time ; /**< trick_io(**) */
/** Cumulative time used for job in frame (stop - start) */
/** Cumulative time in tics used for job in frame (stop - start) */
long long frame_time ; /**< trick_io(**) */
/** Cumulative time in seconds used for job in frame (rt_stop_time - rt_start_time) / time_tic_value */
double frame_time_seconds; /**< trick_io(s) */
/** Sim_object_id.id (for job identification in timeline logging) */
double frame_id; /**< trick_io(**) */

View File

@ -67,9 +67,15 @@ namespace Trick {
/** How much time did the current frame take in tics.\n */
long long frame_sched_time ; /**< trick_units(--) */
/** How much time did the current frame take in seconds for frame logging.\n */
double frame_time ; /**< trick_units(s) */
/** The magnitude of the current overrun in tics.\n */
long long frame_overrun_time ; /**< trick_units(--) */
/** The magnitude of the current overrun in seconds for frame logging.\n */
double frame_overrun ; /**< trick_units(s) */
/** This is the start of the frame in wall clock time.\n */
long long last_clock_time ; /**< trick_units(--) */

View File

@ -35,6 +35,7 @@ int Trick::FrameDataRecordGroup::frame_log_clear() {
std::vector< Trick::JobData *>::iterator it ;
for ( it = rec_jobs.begin() ; it != rec_jobs.end() ; it++ ) {
(*it)->frame_time = 0 ;
(*it)->frame_time_seconds = 0.0;
}
return 0 ;
@ -93,6 +94,7 @@ void Trick::FrameDataRecordGroup::start_timer() {
*/
void Trick::FrameDataRecordGroup::stop_timer() {
frame_sched_time = clock_time() - start_time ;
frame_time = frame_sched_time * (1.0/exec_get_time_tic_value());
}
void Trick::FrameDataRecordGroup::adjust_time() {

View File

@ -36,8 +36,8 @@ Trick::FrameLog::FrameLog(Trick::Clock & in_clock) :
fp_time_other(NULL),
clock(in_clock) {
time_value_attr.type = TRICK_LONG_LONG ;
time_value_attr.size = sizeof(long long) ;
time_value_attr.type = TRICK_DOUBLE;
time_value_attr.size = sizeof(double);
time_value_attr.units = strdup("s") ;
the_fl = this ;
@ -144,7 +144,7 @@ void Trick::FrameLog::add_recording_vars_for_jobs() {
}
new_ref->reference = job_name;
new_ref->address = &(all_jobs_vector[ii]->frame_time) ;
new_ref->address = &(all_jobs_vector[ii]->frame_time_seconds) ;
new_ref->attr = &time_value_attr ;
/** @li use TRK tag in S_define to identify trick jobs */
// trick jobs
@ -184,7 +184,7 @@ void Trick::FrameLog::add_recording_vars_for_jobs() {
if ( ii > 0 ) {
std::ostringstream group_name ;
group_name << "trick_frame_userjobs_C" << ii ;
(*fdrg_it)->add_variable( group_name.str() + ".frame_sched_time") ;
(*fdrg_it)->add_variable( group_name.str() + ".frame_time") ;
}
}
drg_trick->set_job_class("end_of_frame") ;
@ -205,8 +205,8 @@ void Trick::FrameLog::add_recording_vars_for_frame() {
char * job_name = NULL ;
int ii ;
drg_frame->add_variable(rt_sim_object_name + std::string(".rt_sync.frame_sched_time")) ;
drg_frame->add_variable(rt_sim_object_name + std::string(".rt_sync.frame_overrun_time")) ;
drg_frame->add_variable(rt_sim_object_name + std::string(".rt_sync.frame_time")) ;
drg_frame->add_variable(rt_sim_object_name + std::string(".rt_sync.frame_overrun")) ;
/* add the log_userjob frame time we created above to the log_frame group */
for ( ii = 0 ; ii < num_threads ; ii++ ) {
@ -220,7 +220,7 @@ void Trick::FrameLog::add_recording_vars_for_frame() {
}
trick_jobs.push_back(std::string(job_name));
new_ref->reference = job_name;
new_ref->address = &(drg_users[ii]->write_job->frame_time);
new_ref->address = &(drg_users[ii]->write_job->frame_time_seconds);
new_ref->attr = &time_value_attr ;
drg_frame->add_variable(new_ref) ;
drg_frame->add_rec_job(drg_users[ii]->write_job) ;
@ -231,7 +231,7 @@ void Trick::FrameLog::add_recording_vars_for_frame() {
asprintf(&job_name, "JOB_data_record_group.trickjobs.%2.2f(end_of_frame)",drg_trick->jobs[0]->frame_id);
trick_jobs.push_back(std::string(job_name));
new_ref->reference = job_name;
new_ref->address = &(drg_trick->write_job->frame_time);
new_ref->address = &(drg_trick->write_job->frame_time_seconds);
new_ref->attr = &time_value_attr ;
drg_frame->add_variable(new_ref) ;
drg_frame->add_rec_job(drg_trick->write_job) ;
@ -360,13 +360,16 @@ int Trick::FrameLog::frame_clock_stop(Trick::JobData * curr_job) {
Trick::JobData * target_job = (Trick::JobData *)curr_job->sup_class_data ;
int thread, mode;
double time_scale;
/** @par Detailed Design: */
if ( target_job != NULL ) {
if ( target_job->rt_start_time >= 0 ) {
/** @li Set current job's stop time and frame time. */
target_job->rt_stop_time = clock.clock_time() ;
time_scale = 1.0 / target_job->time_tic_value;
target_job->frame_time += (target_job->rt_stop_time - target_job->rt_start_time);
target_job->frame_time_seconds = target_job->frame_time * time_scale;
thread = target_job->thread;
mode = exec_get_mode();
@ -405,6 +408,7 @@ int Trick::FrameLog::frame_clock_stop(Trick::JobData * curr_job) {
target_job->rt_stop_time = 0;
} else {
target_job->frame_time = 0 ;
target_job->frame_time_seconds = 0.0;
}
}
@ -496,6 +500,8 @@ void Trick::FrameLog::default_data() {
allocate_recording_groups() ;
add_recording_vars_for_jobs() ;
add_recording_vars_for_frame() ;
// reset clock before frame logging
clock.clock_reset(0);
}
/**
@ -739,14 +745,12 @@ int Trick::FrameLog::create_DP_job_files() {
FILE *fpx;
unsigned int pages, plots, total_plots, vcells, dot;
char *bg_color;
double time_scale;
std::string DP_buff;
const char *headerx = "<?xml version=\"1.0\" encoding=\"ISO-8859-1\"?>\n" \
"<!DOCTYPE product PUBLIC \"-//Tricklab//DTD Product V1.0//EN\" \"Product.dtd\">\n\n" \
"<!-- Description: Plot of Y(t) vs. t, with attributes, titles, labels, units -->\n\n" \
"<product version=\"1.0\">\n";
time_scale = 1.0 / exec_get_time_tic_value();
DP_buff = DP_dir + "/DP_rt_frame.xml";
if ((fpx = fopen(DP_buff.c_str(), "w")) == NULL) {
message_publish(MSG_WARNING, "Could not open DP_rt_frame.xml file for Frame Logging\n") ;
@ -758,16 +762,14 @@ int Trick::FrameLog::create_DP_job_files() {
fprintf(fpx, " <xaxis> <label>Time</label> <units>s</units> </xaxis>\n");
fprintf(fpx, " <yaxis> <label>Frame Overrun/Underrun</label> </yaxis>\n");
fprintf(fpx, " <curve>\n <var>sys.exec.out.time</var>\n");
fprintf(fpx, " <var scale=\"%g\" line_color=\"darkgreen\" label=\"Overrun/Underrun\">%s.rt_sync.frame_overrun_time</var>\n",
time_scale,rt_sim_object_name.c_str());
fprintf(fpx, " <var line_color=\"darkgreen\" label=\"Overrun/Underrun\">%s.rt_sync.frame_overrun</var>\n", rt_sim_object_name.c_str());
fprintf(fpx, " </curve>\n");
fprintf(fpx, " </plot>\n");
fprintf(fpx, " <plot grid=\"yes\">\n <title>Frame Scheduled Jobs Time</title>\n");
fprintf(fpx, " <xaxis> <label>Time</label> <units>s</units> </xaxis>\n");
fprintf(fpx, " <yaxis> <label>Frame Scheduled Jobs Time</label> </yaxis>\n");
fprintf(fpx, " <curve>\n <var>sys.exec.out.time</var>\n");
fprintf(fpx, " <var scale=\"%g\" line_color=\"red\" label=\"Frame Sched Time\">%s.rt_sync.frame_sched_time</var>\n",
time_scale,rt_sim_object_name.c_str());
fprintf(fpx, " <var line_color=\"red\" label=\"Frame Sched Time\">%s.rt_sync.frame_time</var>\n", rt_sim_object_name.c_str());
fprintf(fpx, " </curve>\n");
fprintf(fpx, " </plot>\n");
fprintf(fpx, " </page>\n");
@ -796,8 +798,7 @@ int Trick::FrameLog::create_DP_job_files() {
fprintf(fpx, " <var>sys.exec.out.time</var>\n");
std::ostringstream group_name ;
group_name << "trick_frame_userjobs_C" << (page_count * plots_per_page + ii + 1) ;
fprintf(fpx, " <var scale=\"%g\" line_color=\"red\" label=\"Frame Sched Time\">%s.frame_sched_time</var>\n",
time_scale,group_name.str().c_str());
fprintf(fpx, " <var line_color=\"red\" label=\"Frame Sched Time\">%s.frame_time</var>\n", group_name.str().c_str());
fprintf(fpx, " </curve>\n");
fprintf(fpx, " </plot>\n");
}
@ -809,12 +810,10 @@ int Trick::FrameLog::create_DP_job_files() {
fprintf(fpx, " <label>Sim Time</label>\n <var>sys.exec.out.time</var>\n");
fprintf(fpx, " </column>\n");
fprintf(fpx, " <column format=\"%%13.6f\">\n");
fprintf(fpx, " <label>Overrun/Underrun</label>\n <var scale=\"%g\">%s.rt_sync.frame_overrun_time</var>\n",
time_scale,rt_sim_object_name.c_str());
fprintf(fpx, " <label>Overrun/Underrun</label>\n <var>%s.rt_sync.frame_overrun</var>\n", rt_sim_object_name.c_str());
fprintf(fpx, " </column>\n");
fprintf(fpx, " <column format=\"%%13.6f\">\n");
fprintf(fpx, " <label>Frame Sched Time</label>\n <var scale=\"%g\">%s.rt_sync.frame_sched_time</var>\n",
time_scale,rt_sim_object_name.c_str());
fprintf(fpx, " <label>Frame Sched Time</label>\n <var>%s.rt_sync.frame_time</var>\n", rt_sim_object_name.c_str());
fprintf(fpx, " </column>\n");
fprintf(fpx, " </table>\n</product>");
fclose(fpx);
@ -861,7 +860,7 @@ int Trick::FrameLog::create_DP_job_files() {
fprintf(fpx, " <xaxis> <label>Time</label> <units>s</units> </xaxis>\n");
fprintf(fpx, " <yaxis> <label>Execution Time</label> </yaxis>\n");
fprintf(fpx, " <curve>\n <var>sys.exec.out.time</var>\n");
fprintf(fpx, " <var line_color=\"red\" scale=\"%g\">%s</var>\n", time_scale, (*drb_it)->name.c_str());
fprintf(fpx, " <var line_color=\"red\">%s</var>\n", (*drb_it)->name.c_str());
fprintf(fpx, " </curve>\n");
fprintf(fpx, " </plot>\n");
plots++;
@ -919,7 +918,7 @@ int Trick::FrameLog::create_DP_job_files() {
fprintf(fpx, " <xaxis> <label>Time</label> <units>s</units> </xaxis>\n");
fprintf(fpx, " <yaxis> <label>Execution Time</label> </yaxis>\n");
fprintf(fpx, " <curve>\n <var>sys.exec.out.time</var>\n");
fprintf(fpx, " <var line_color=\"darkgreen\" scale=\"%g\">%s</var>\n", time_scale, (*job_iterator).c_str());
fprintf(fpx, " <var line_color=\"darkgreen\">%s</var>\n", (*job_iterator).c_str());
fprintf(fpx, " </curve>\n");
fprintf(fpx, " </plot>\n");
job_iterator++;

View File

@ -286,6 +286,8 @@ int Trick::RealtimeSync::rt_monitor(long long sim_time_tics) {
/* calculate the current underrun/overrun */
curr_clock_time = rt_clock->clock_time() ;
frame_sched_time = curr_clock_time - last_clock_time ;
frame_time = frame_sched_time * (1.0/tics_per_sec);
/* Set the next frame overrun/underrun reference time to the current time */
last_clock_time = curr_clock_time ;
@ -311,6 +313,8 @@ int Trick::RealtimeSync::rt_monitor(long long sim_time_tics) {
frame_overrun_time = curr_clock_time - sim_time_tics ;
frame_overrun = frame_overrun_time * (1.0/tics_per_sec);
/* If the wall clock time is greater than the sim time an overrun occurred. */
if (curr_clock_time > sim_time_tics) {

View File

@ -32,6 +32,7 @@ Trick::JobData::JobData() {
next_tics = 0 ;
frame_time = 0 ;
frame_time_seconds = 0.0;
}
Trick::JobData::JobData(int in_thread, int in_id, std::string in_job_class_name , void* in_sup_class_data,