Code timing and verbosity

To help with the scaling tests, I have introduced two levels of verbosity.

• './swift -v 1' makes the MPI rank 1 write timing information to stdout.
• './swift -v 2' makes all MPI ranks write timing information to stdout.
• './swift' suppresses all timing information to stdout.

The 'error()' and 'message()' macros now also print the date and time.

Hmm, the output with the date and time included looks quite long and doesn't carry that much useful information:

[0000] [2016-03-07 11:50:00] main: set entry thread's affinity
[0000] [2016-03-07 11:50:00] main: maximum h set to 1.000000e-02.
[0000] [2016-03-07 11:50:00] main: sub size set to 5000.
[0000] [2016-03-07 11:50:00] main: time_end set to 1.000e+00.
[0000] [2016-03-07 11:50:00] main: dt_min set to 1.000000e-07.

so I'd be tempted to truncate that to just show HH:MM:SS or even HH:MM:SS.S:

[0000] [11:51:42.3] main: set entry thread's affinity
[0000] [11:51:42.3] main: maximum h set to 1.000000e-02.
[0000] [11:51:42.3] main: sub size set to 5000.
[0000] [11:51:42.3] main: time_end set to 1.000e+00.
[0000] [11:51:42.3] main: dt_min set to 1.000000e-07.

or even just a number of seconds since the program started:

[0000] [000000.0] main: set entry thread's affinity
[0000] [000000.0] main: maximum h set to 1.000000e-02.
[0000] [000000.0] main: sub size set to 5000.
[0000] [000000.0] main: time_end set to 1.000e+00.
[0000] [000000.0] main: dt_min set to 1.000000e-07.
...
[0001] [000189.4] engine_print: nr_parts = 631733

Ideally this would also be under control of the verbosity level. The point being that the time stamp is a poor man's profiler.

I've forked a branch verbosity-less with some of these ideas implemented. To get the tick stamps output just don't define HAVE_CLOCK_GETTIME or just hack that for now...

Agreed, showing the date is probably overkill. HH:MM:SS is probably the best here. I was not after high-precision timing.

The main reason behind this change was to not get confused any more by the timings reported by the code. More specifically, I did not notice before last week that a lot of time was spend in the i/o routines because they did not report any run time. But if the messages printed to the screen had shown a time stamp then I would have suspected the i/o and not the domain decomposition.

What do you think ? Is HH:MM:SS still too much ?

If it really is just a quick sanity check, then I'd go for HH:MM:SS.S or SSSS.S, may as well be useful. The SSSS.S looks less intrusive, so I'd vote for that.

Ok. I'll use your changes to make it of the form SSSS.S. Thanks for the feedback.

Added 2 commits:

• 7ed1d30a - Don't include date in message time stamps, increase accuracy to 1/10th second, i…
• 1a2e49aa - Change the timestamp to [ssssss.s] to reduce the length of the stdout lines.

Added 1 commit:

• 912f28d4 - Better name for the time-stamp function

Ok, so I have adopted your format for the time-stamp and renamed the function to be more descriptive.

Added 1 commit:

• 0af6a6e4 - Document requirement to call clocks_set_cpufreq()

One final tweak and I'm happy, so accepting.

Status changed to merged

mentioned in commit 2203631a