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 c9e6f44 ("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.