Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

updates to logging to automatically include file name, function name … #9

Open
wants to merge 4 commits into
base: main
Choose a base branch
from

Conversation

jefhai
Copy link
Contributor

@jefhai jefhai commented Oct 20, 2020

…and execution line. this will be useful for debugging. formating improvements will allow us to use GUI tools for log viewing

…and execution line. this will be useful for debugging. formating improvements will allow us to use GUI tools for log viewing
@jefhai
Copy link
Contributor Author

jefhai commented Oct 20, 2020

@travisdesell the idea was to improve logging by determining where a log function was invoked.

Still need to compile and test this on Ubuntu and cluster. Working on my Mac without modifying CMake or environment variables.

Some more work to be done to get log messages to be well formatted in output.

Delimiting log message sections with ':' so we can use some GUI log viewers for search and filtering.

@jefhai
Copy link
Contributor Author

jefhai commented Oct 20, 2020

[DEBUG genome_2_worker_2]: rnn.cxx:57 validate_parameters:	 		'Supp_Fuel_Flow'
[DEBUG genome_2_worker_2]: rnn.cxx:57 validate_parameters:	 		'Main_Flm_Int'
[DEBUG genome_2_worker_2]: rnn.cxx:60 validate_parameters:	 	output_parameter_names:[DEBUG genome_2_worker_2]: rnn.cxx:62 validate_parameters:	 		'Main_Flm_Int'
[DEBUG genome_2_worker_2]: rnn.cxx:65 validate_parameters:	 	output_node names:[DEBUG genome_2_worker_2]: rnn.cxx:67 validate_parameters:	 		'Main_Flm_Int'
[INFO genome_6_worker_1]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    8, mse: 0.0524268928, lr: 0.001000, norm: 0.034571, UNDER THRESHOLD, multiplier: 1.446289
[DEBUG genome_4_worker_3]: rnn_genome.cxx:1533 get_mae:	 series[    0] MAE: 0.7541628284
[DEBUG genome_2_worker_2]: rnn_genome.cxx:1533 get_mae:	 series[    0] MAE: 0.8612302304
[INFO genome_6_worker_1]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    5, mse: 0.1227850094, lr: 0.001000, norm: 0.129877
[DEBUG genome_4_worker_3]: rnn_genome.cxx:1533 get_mae:	 series[    1] MAE: 0.6852711509
[DEBUG genome_2_worker_2]: rnn_genome.cxx:1533 get_mae:	 series[    1] MAE: 0.7374285911
[DEBUG genome_4_worker_3]: rnn_genome.cxx:1539 get_mae:	 average MAE: 0.7197169896
[INFO genome_4_worker_3]: rnn_genome.cxx:1457 backpropagate_stochastic:	 iteration    0, mse: 0.4974654971, v_mse: 0.5239680642, bv_mse: 0.5239680642, avg_norm: 29.0842058955
[DEBUG genome_2_worker_2]: rnn_genome.cxx:1539 get_mae:	 average MAE: 0.7993294107
[INFO genome_2_worker_2]: rnn_genome.cxx:1457 backpropagate_stochastic:	 iteration    0, mse: 0.6430581360, v_mse: 0.6469023493, bv_mse: 0.6469023493, avg_norm: 42.3972666043
[INFO genome_6_worker_1]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    0, mse: 0.0430370653, lr: 0.001000, norm: 0.018817, UNDER THRESHOLD, multiplier: 2.657138
[INFO genome_4_worker_3]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    0, mse: 0.4355571105, lr: 0.001000, norm: 1.075731, OVER THRESHOLD, multiplier: 0.929600
[INFO genome_2_worker_2]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    5, mse: 0.8590945838, lr: 0.001000, norm: 3.457191, OVER THRESHOLD, multiplier: 0.289252
[INFO genome_6_worker_1]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    1, mse: 0.1071059473, lr: 0.001000, norm: 0.103777
[INFO genome_4_worker_3]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    3, mse: 0.4551648877, lr: 0.001000, norm: 1.258589, OVER THRESHOLD, multiplier: 0.794541
[INFO genome_2_worker_2]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    2, mse: 0.3562536123, lr: 0.001000, norm: 0.908502
[INFO genome_6_worker_1]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    3, mse: 0.0677791294, lr: 0.001000, norm: 0.050018
[INFO genome_4_worker_3]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    1, mse: 0.5236968510, lr: 0.001000, norm: 1.540606, OVER THRESHOLD, multiplier: 0.649095
[INFO genome_2_worker_2]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    4, mse: 0.6050522448, lr: 0.001000, norm: 1.957607, OVER THRESHOLD, multiplier: 0.510828
[INFO genome_6_worker_1]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    7, mse: 0.0413847813, lr: 0.001000, norm: 0.022542, UNDER THRESHOLD, multiplier: 2.218119
[INFO genome_4_worker_3]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    2, mse: 0.1946385160, lr: 0.001000, norm: 0.332505
[INFO genome_2_worker_2]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    7, mse: 0.3769916790, lr: 0.001000, norm: 0.961879
[INFO genome_6_worker_1]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    2, mse: 0.0058644367, lr: 0.001000, norm: 0.000977, UNDER THRESHOLD, multiplier: 51.159589
[INFO genome_4_worker_3]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    7, mse: 0.2814866143, lr: 0.001000, norm: 0.577194
[INFO genome_6_worker_1]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    6, mse: 0.0769682816, lr: 0.001000, norm: 0.060136
[INFO genome_2_worker_2]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    0, mse: 0.3120507955, lr: 0.001000, norm: 0.641313
[INFO genome_4_worker_3]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    6, mse: 0.3094780223, lr: 0.001000, norm: 0.653025
[INFO genome_6_worker_1]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    4, mse: 0.0531734757, lr: 0.001000, norm: 0.035907, UNDER THRESHOLD, multiplier: 1.392473
[INFO genome_2_worker_2]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    6, mse: 0.3720796207, lr: 0.001000, norm: 0.918712
[INFO genome_6_worker_1]: rnn_genome.cxx:1375 backpropagate_stochastic:	 iteration       1, series:    9, mse: 0.0098523881, lr: 0.001000, norm: 0.002156, UNDER THRESHOLD, multiplier: 23.195774
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Conditioner_Inlet_Temp used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Conditioner_Outlet_Temp used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Coal_Feeder_Rate used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Primary_Air_Flow used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Primary_Air_Split used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	System_Secondary_Air_Flow_Total used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Secondary_Air_Flow used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Secondary_Air_Split used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Tertiary_Air_Split used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Total_Comb_Air_Flow used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Supp_Fuel_Flow used: 1780558032
[DEBUG main_2]: time_series.cxx:278 TimeSeriesSet:	 	Main_Flm_Int used: 1780558032
[INFO main_1]: time_series.cxx:84 print_statistics:	 	         Coal_Feeder_Rate stats, min: 0.000424, avg: 0.881890, max: 0.994216, min_change: -0.401672, max_change: 0.833334, std_dev: 0.169650, variance: 0.028781
[INFO main_1]: time_series.cxx:84 print_statistics:	 	   Conditioner_Inlet_Temp stats, min: 0.171203, avg: 0.707074, max: 0.882068, min_change: -0.168072, max_change: 0.376294, std_dev: 0.098659, variance: 0.009734
[INFO main_1]: time_series.cxx:84 print_statistics:	 	  Conditioner_Outlet_Temp stats, min: 0.300470, avg: 0.366281, max: 0.606686, min_change: -0.154274, max_change: 0.067703, std_dev: 0.028008, variance: 0.000784
[INFO main_1]: time_series.cxx:84 print_statistics:	 	             Main_Flm_Int stats, min: 0.217048, avg: 0.685396, max: 0.820038, min_change: -0.154755, max_change: 0.385723, std_dev: 0.088470, variance: 0.007827
[INFO main_1]: time_series.cxx:84 print_statistics:	 	         Primary_Air_Flow stats, min: 0.033840, avg: 0.701585, max: 0.828437, min_change: -0.409826, max_change: 0.624807, std_dev: 0.122128, variance: 0.014915
[INFO main_1]: time_series.cxx:84 print_statistics:	 	        Primary_Air_Split stats, min: 0.257819, avg: 0.970504, max: 0.995818, min_change: -0.484128, max_change: 0.681201, std_dev: 0.092947, variance: 0.008639
[INFO main_1]: time_series.cxx:84 print_statistics:	 	       Secondary_Air_Flow stats, min: 0.105488, avg: 0.611412, max: 0.828293, min_change: -0.106363, max_change: 0.147005, std_dev: 0.118752, variance: 0.014102
[INFO main_1]: time_series.cxx:84 print_statistics:	 	      Secondary_Air_Split stats, min: 0.004150, avg: 0.029238, max: 0.720424, min_change: -0.651896, max_change: 0.441015, std_dev: 0.083413, variance: 0.006958
[INFO main_1]: time_series.cxx:84 print_statistics:	 	           Supp_Fuel_Flow stats, min: 0.003257, avg: 0.003391, max: 0.033144, min_change: -0.029815, max_change: 0.029815, std_dev: 0.000337, variance: 0.000000
[INFO main_1]: time_series.cxx:84 print_statistics:	 	System_Secondary_Air_Flow_Total stats, min: 0.000000, avg: 0.718256, max: 1.000000, min_change: -0.147153, max_change: 0.203381, std_dev: 0.156388, variance: 0.024457
[INFO main_1]: time_series.cxx:84 print_statistics:	 	       Tertiary_Air_Split stats, min: 0.004670, avg: 0.036131, max: 1.000000, min_change: -0.809491, max_change: 0.708746, std_dev: 0.145247, variance: 0.021097
[INFO main_1]: time_series.cxx:84 print_statistics:	 	      Total_Comb_Air_Flow stats, min: 0.000997, avg: 0.681136, max: 0.834857, min_change: -0.405953, max_change: 0.628772, std_dev: 0.131825, variance: 0.017378
[INFO main_1]: time_series.cxx:337 TimeSeriesSet:	 read time series './datasets/2018_coal/burner_2.csv' with number rows: 14401
[DEBUG main_1]: time_series.cxx:671 load_time_series:	 	./datasets/2018_coal/burner_3.csv
[DEBUG main_1]: time_series.cxx:252 TimeSeriesSet:	 fields.size(): 12, file_fields.size(): 12
[DEBUG main_1]: time_series.cxx:271 TimeSeriesSet:	  -- Field was found!
[DEBUG main_1]: time_series.cxx:271 TimeSeriesSet:	  -- Field was found!

Copy link
Owner

@travisdesell travisdesell left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm a little worried a bout performance effects of this change. The reason I had the va_list/va_start buried a bit further into the functions was to only use them when needed -- many times (depending on log level) they'll never be needed if the message is ignored.

@jefhai jefhai requested a review from travisdesell October 20, 2020 18:36
@travisdesell
Copy link
Owner

Just a thought -- is it possible to put the guards in the #define statement so the function won't even be called depending on the log level? I think that might be the most efficient.

@travisdesell
Copy link
Owner

My thought is that then the compiler might even be able to optimize out those statements. Which would be ideal especially if a block of code had a number of trace/debug statements that could really slow things down.

@jefhai
Copy link
Contributor Author

jefhai commented Oct 20, 2020

Right that makes sense, i.e. ideally avoid prep work prior to log calls. I removed _no_head though so we can focus on a well structured log messages (one line per log function call). I think this avoids redundant logs by avoiding crafting log messages with the _no_head functions. As I have it, you build a string log_str prior to invoking log... To eliminate the work involved in log_str creation we could build a string builder class that gets #define removed when required.

Logs that used _no_head functions seemed to use known state instead of generating new state for log purposes. I have seen print_head==true logs that did generate additional state. I think think this is potentially unavoidable, except for adherence.

So to get performance, shut logs off by potentially disabling them at compile time. Review existing use of log to make sure additional work to prepare a log message is minimized.

@jefhai
Copy link
Contributor Author

jefhai commented Oct 20, 2020

@travisdesell so won't get optimized away because std_message_level aren't static/const, they're also set at runtime through Log::initialize. So the best we can do with #define guards is avoid work to generate varargs params prior to invoking the log call. Worth doing?

@travisdesell
Copy link
Owner

Yeah I think it's worth doing because branch prediction should be pretty good at catching them and it will save us unneeded function calls. I imagine eventually we could set things up where we also had a compile flag to specify logging levels if we really wanted to squeeze out some more performance.

@jefhai
Copy link
Contributor Author

jefhai commented Oct 27, 2020

@travisdesell So two observations implementing this.

  1. Macros don't like namespace included in their identifier... i.e. #define Log::fatal() log() is not valid... Identifiers can't include ::. So to make this work Log::debug becomes LOG_DEBUG.
  2. This approach creates non obvious behavior... Can trip someone up if for example, a postfix increment is not called because the log is suppressed... i++ in the log args might be essential for some iteration logic.

@@ -239,3 +235,8 @@ void Log::log(const char *file, size_t filelen, const char *func, size_t funclen
bool Log::at_level(log_level_t level) {
return level >= std_message_level || level >= file_message_level;
}

bool Log::should_log(log_level_t level) {
return !(std_message_level < level && file_message_level < level)
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@travisdesell I'll simplify this

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants