Wall-clock time in statistics

[tueda]

Printing of statistics is a powerful built-in feature to analyse which part of the program (module) is a bottleneck (e.g., with https://gist.github.com/tueda/3e1b2bec8545c48737c7). But for multithreading, this becomes less useful because FORM prints the CPU time and there are cases that worker threads get busy while the master is idle. One can manually insert a code printing the elapsed time with TIMER_, though, it would be nice to have an option like On MasterWallClockStatistics (or a better name) such that the wall-clock time is printed in statistics for the master thread:

WTime =      5.21 sec    Generated terms =         10
               F         Terms in output =         10
                  reduce Bytes used      =        696

[crmafra]

I'd like to mention something a bit related to the theme "knowing the running time is useful".

On Mon, 26 Sep 2016 at 5:40:51 -0700, Takahiro Ueda wrote:

Printing of statistics is a powerful built-in feature to analyse which part of the program (module) is a bottleneck (e.g., with https://gist.github.com/tueda/3e1b2bec8545c48737c7).

But for multithreading, this becomes less useful because FORM prints the CPU time and there are cases that worker threads get busy while the master is idle.

The commit c9e6f448 ("Error in Allocation EndSort/AssignDollar. Improved MALLOCDEBUG") made printing the running time statistics conditional on not having -q in the command line. So now one doesn't see anymore the useful line

0.03 sec + 0.00 sec: 0.03 sec out of 0.06 sec

unless one also gets all the other stuff that comes without -q.

I agree it is natural to omit statistics information if the "quiet" option is turned on, but I miss the line as it always gives me a (rough) clue about what is going on.

In fact, I have a patch locally that reverts to the old behavior:

diff --git a/sources/startup.c b/sources/startup.c index e04e882..1e33aef 100644 --- a/sources/startup.c +++ b/sources/startup.c @@ -1714,22 +1714,22 @@ VOID PrintRunningTime() mastertime = AM.SumTime + TimeCPU(1); wallclocktime = TimeWallClock(1); totaltime = mastertime+workertime;

• if ( !AM.silent ) { +// if ( !AM.silent ) { MesPrint(" %l.%2i sec + %l.%2i sec: %l.%2i sec out of %l.%2i sec", mastertime/1000,(WORD)((mastertime%1000)/10), workertime/1000,(WORD)((workertime%1000)/10), totaltime/1000,(WORD)((totaltime%1000)/10), wallclocktime/100,(WORD)(wallclocktime%100));
• } +// } }

  else

  LONG mastertime = AM.SumTime + TimeCPU(1); LONG wallclocktime = TimeWallClock(1);

• if ( !AM.silent ) { +// if ( !AM.silent ) { MesPrint(" %l.%2i sec out of %l.%2i sec", mastertime/1000,(WORD)((mastertime%1000)/10), wallclocktime/100,(WORD)(wallclocktime%100));
• } +// }

  endif

  }

How would you assess this situation? Would you accept a patch removing those lines above or a patch adding a new option to the command line to print the running time even when -q is on?

Sorry if this is hijacking the thread too much, but it is related.

[tueda]

On wtimestats was implemented, so I close this issue. formprof.py now also works with log files of multithreaded runs with wtimestats.

@crmafra I don't know whether your patch is relevant to others. If I need only the final timing information, then I would turn off all the statistics/printings, or just use the time command with form -q.