From 617b19c78efd709770df199f71d11555d0a05ea5 Mon Sep 17 00:00:00 2001 From: Takahiro Ueda Date: Wed, 2 Nov 2016 22:05:11 +0100 Subject: [PATCH] Add wtimestats option (#127) This option is for printing the wall-clock time in statistics on the master. This is not applied to statistics on workers. Command line option: -W Syntax: #:wtimestats on On wtimestats; Off wtimestats; --- sources/checkpoint.c | 5 +++++ sources/compcomm.c | 1 + sources/execute.c | 2 ++ sources/setfile.c | 4 ++++ sources/sort.c | 48 ++++++++++++++++++++++++++++++++++++++------ sources/startup.c | 4 ++++ sources/structs.h | 13 +++++++----- sources/tools.c | 15 ++++++++++++++ 8 files changed, 81 insertions(+), 11 deletions(-) diff --git a/sources/checkpoint.c b/sources/checkpoint.c index ce184a9c..a186009f 100644 --- a/sources/checkpoint.c +++ b/sources/checkpoint.c @@ -772,6 +772,8 @@ static void print_M() MesPrint("%d", AM.ggProcessStats); MesPrint("%d", AM.gOldParallelStats); MesPrint("%d", AM.ggOldParallelStats); + MesPrint("%d", AM.gWTimeStatsFlag); + MesPrint("%d", AM.ggWTimeStatsFlag); MesPrint("%d", AM.maxFlevels); MesPrint("--MARK 6"); MesPrint("%d", AM.resetTimeOnClear); @@ -1065,6 +1067,7 @@ static void print_C() MesPrint("%d", AC.ThreadSortFileSynch); MesPrint("%d", AC.ProcessStats); MesPrint("%d", AC.OldParallelStats); + MesPrint("%d", AC.WTimeStatsFlag); MesPrint("%d", AC.BracketNormalize); MesPrint("%d", AC.maxtermlevel); MesPrint("%d", AC.dumnumflag); @@ -1491,6 +1494,7 @@ int DoRecovery(int *moduletype) R_SET(AM.SizeForSpectatorFiles,int); R_SET(AM.gOldGCDflag,int); R_SET(AM.ggOldGCDflag,int); + R_SET(AM.gWTimeStatsFlag, int); #ifdef PRINTDEBUG print_M(); @@ -2556,6 +2560,7 @@ static int DoSnapshot(int moduletype) S_WRITE_B(&AM.SizeForSpectatorFiles,sizeof(int)); S_WRITE_B(&AM.gOldGCDflag,sizeof(int)); S_WRITE_B(&AM.ggOldGCDflag,sizeof(int)); + S_WRITE_B(&AM.gWTimeStatsFlag, sizeof(int)); /*#] AM :*/ /*#[ AC :*/ diff --git a/sources/compcomm.c b/sources/compcomm.c index 16b073b1..6fbf774b 100644 --- a/sources/compcomm.c +++ b/sources/compcomm.c @@ -127,6 +127,7 @@ static KEYWORD onoffoptions[] = { ,{"memdebugflag", (TFUN)&(AC.MemDebugFlag), 1, 0} ,{"oldgcd", (TFUN)&(AC.OldGCDflag), 1, 0} ,{"innertest", (TFUN)&(AC.InnerTest), 1, 0} + ,{"wtimestats", (TFUN)&(AC.WTimeStatsFlag), 1, 0} }; static WORD one = 1; diff --git a/sources/execute.c b/sources/execute.c index 6ed591de..932aea6a 100644 --- a/sources/execute.c +++ b/sources/execute.c @@ -283,6 +283,7 @@ WORD PopVariables() AC.ThreadStats = AM.gThreadStats; AC.FinalStats = AM.gFinalStats; AC.OldGCDflag = AM.gOldGCDflag; + AC.WTimeStatsFlag = AM.gWTimeStatsFlag; AC.ThreadsFlag = AM.gThreadsFlag; AC.ThreadBalancing = AM.gThreadBalancing; AC.ThreadSortFileSynch = AM.gThreadSortFileSynch; @@ -415,6 +416,7 @@ VOID MakeGlobal() AM.gThreadStats = AC.ThreadStats; AM.gFinalStats = AC.FinalStats; AM.gOldGCDflag = AC.OldGCDflag; + AM.gWTimeStatsFlag = AC.WTimeStatsFlag; AM.gThreadsFlag = AC.ThreadsFlag; AM.gThreadBalancing = AC.ThreadBalancing; AM.gThreadSortFileSynch = AC.ThreadSortFileSynch; diff --git a/sources/setfile.c b/sources/setfile.c index 85f95e50..2afeaa6c 100644 --- a/sources/setfile.c +++ b/sources/setfile.c @@ -112,6 +112,7 @@ SETUPPARAMETERS setupparameters[] = ,{(UBYTE *)"threadsortfilesynch", ONOFFVALUE, 0, (LONG)0} ,{(UBYTE *)"totalsize", ONOFFVALUE, 0, (LONG)2} ,{(UBYTE *)"workspace", NUMERICALVALUE, 0, (LONG)WORKBUFFER} + ,{(UBYTE *)"wtimestats", ONOFFVALUE, 0, (LONG)2} }; /* @@ -676,6 +677,9 @@ int AllocSetups() AC.OldFactArgFlag = AM.gOldFactArgFlag = AM.ggOldFactArgFlag = sp->value; sp = GetSetupPar((UBYTE *)"oldgcd"); AC.OldGCDflag = AM.gOldGCDflag = AM.ggOldGCDflag = sp->value; + sp = GetSetupPar((UBYTE *)"wtimestats"); + if ( sp->value == 2 ) sp->value = AM.ggWTimeStatsFlag; + AC.WTimeStatsFlag = AM.gWTimeStatsFlag = AM.ggWTimeStatsFlag = sp->value; sp = GetSetupPar((UBYTE *)"sorttype"); if ( StrICmp((UBYTE *)"lowfirst",(UBYTE *)sp->value) == 0 ) { AC.lSortType = SORTLOWFIRST; diff --git a/sources/sort.c b/sources/sort.c index e62d6570..8cc15a2c 100644 --- a/sources/sort.c +++ b/sources/sort.c @@ -95,6 +95,7 @@ VOID WriteStats(POSITION *plspace, WORD par) WORD timepart; SORTING *S; POSITION pp; + int use_wtime; if ( AT.SS == AT.S0 && AC.StatsFlag ) { #ifdef WITHPTHREADS if ( AC.ThreadStats == 0 && identity > 0 ) return; @@ -132,7 +133,19 @@ VOID WriteStats(POSITION *plspace, WORD par) MesPrint(""); #endif } - millitime = TimeCPU(1); + /* + * We define WTimeStatsFlag as a flag to print the wall-clock time on + * the *master*, not in workers. This can be confusing in thread + * statistics when short statistics is used. Technically, + * TimeWallClock() is not thread-safe in TFORM. + */ + use_wtime = AC.WTimeStatsFlag; +#if defined(WITHPTHREADS) + if ( use_wtime && identity > 0 ) use_wtime = 0; +#elif defined(WITHMPI) + if ( use_wtime && PF.me != MASTER ) use_wtime = 0; +#endif + millitime = use_wtime ? TimeWallClock(1) * 10 : TimeCPU(1); timepart = (WORD)(millitime%1000); millitime /= 1000; timepart /= 10; @@ -391,21 +404,44 @@ VOID WriteStats(POSITION *plspace, WORD par) } } else { if ( par == 1 ) { - MesPrint("Time = %7l.%2i sec",millitime,timepart); + if ( use_wtime ) { + MesPrint("WTime = %7l.%2i sec",millitime,timepart); + } + else { + MesPrint("Time = %7l.%2i sec",millitime,timepart); + } } else { #if ( BITSINLONG > 32 ) if ( S->GenTerms >= 10000000000L ) { - MesPrint("Time = %7l.%2i sec Generated terms = %16l", + if ( use_wtime ) { + MesPrint("WTime = %7l.%2i sec Generated terms = %16l", + millitime,timepart,S->GenTerms); + } + else { + MesPrint("Time = %7l.%2i sec Generated terms = %16l", + millitime,timepart,S->GenTerms); + } + } + else { + if ( use_wtime ) { + MesPrint("WTime = %7l.%2i sec Generated terms = %10l", + millitime,timepart,S->GenTerms); + } + else { + MesPrint("Time = %7l.%2i sec Generated terms = %10l", + millitime,timepart,S->GenTerms); + } + } +#else + if ( use_wtime ) { + MesPrint("WTime = %7l.%2i sec Generated terms = %10l", millitime,timepart,S->GenTerms); } else { MesPrint("Time = %7l.%2i sec Generated terms = %10l", millitime,timepart,S->GenTerms); } -#else - MesPrint("Time = %7l.%2i sec Generated terms = %10l", - millitime,timepart,S->GenTerms); #endif } #if ( BITSINLONG > 32 ) diff --git a/sources/startup.c b/sources/startup.c index af2aa6aa..25a5ed10 100644 --- a/sources/startup.c +++ b/sources/startup.c @@ -279,6 +279,9 @@ int DoTail(int argc, UBYTE **argv) /* if ( threadnum == 1 ) threadnum = 0; */ threadnum++; break; + case 'W': /* Print the wall-clock time on the master. */ + AM.ggWTimeStatsFlag = 1; + break; /* case 'n': Reserved for number of slaves without MPI @@ -1141,6 +1144,7 @@ VOID StartVariables() AC.OldParallelStats = AM.gOldParallelStats = AM.ggOldParallelStats = 0; AC.OldFactArgFlag = AM.gOldFactArgFlag = AM.ggOldFactArgFlag = NEWFACTARG; AC.OldGCDflag = AM.gOldGCDflag = AM.ggOldGCDflag = 1; + AC.WTimeStatsFlag = AM.gWTimeStatsFlag = AM.ggWTimeStatsFlag = 0; AM.gcNumDollars = AP.DollarList.num; AC.SizeCommuteInSet = AM.gSizeCommuteInSet = 0; AC.CommuteInSet = 0; diff --git a/sources/structs.h b/sources/structs.h index a4ff2595..375640cb 100644 --- a/sources/structs.h +++ b/sources/structs.h @@ -1393,6 +1393,8 @@ struct M_const { int SizeForSpectatorFiles; /* Size in AM.spectatorfiles; */ int gOldGCDflag; int ggOldGCDflag; + int gWTimeStatsFlag; + int ggWTimeStatsFlag; WORD MaxTal; /* (M) Maximum number of words in a number */ WORD IndDum; /* (M) Basis value for dummy indices */ WORD DumInd; /* (M) */ @@ -1451,9 +1453,9 @@ struct M_const { WORD havesortdir; WORD BracketFactors[8]; #ifdef WITHPTHREADS - PADPOSITION(17,25,59,81,sizeof(pthread_rwlock_t)+sizeof(pthread_mutex_t)*2); + PADPOSITION(17,25,61,81,sizeof(pthread_rwlock_t)+sizeof(pthread_mutex_t)*2); #else - PADPOSITION(17,23,59,81,0); + PADPOSITION(17,23,61,81,0); #endif }; /* @@ -1695,6 +1697,7 @@ struct C_const { int OldFactArgFlag; int MemDebugFlag; /* Only used when MALLOCDEBUG in tools.c */ int OldGCDflag; + int WTimeStatsFlag; int doloopstacksize; int dolooplevel; int CheckpointFlag; /**< Tells preprocessor whether checkpoint code must executed. @@ -1760,11 +1763,11 @@ struct C_const { UBYTE Commercial[COMMERCIALSIZE+2]; /* (C) Message to be printed in statistics */ UBYTE debugFlags[MAXFLAGS+2]; /* On/Off Flag number(s) */ #if defined(WITHPTHREADS) - PADPOSITION(47,8+3*MAXNEST,71,45+3*MAXNEST+MAXREPEAT,COMMERCIALSIZE+MAXFLAGS+4+sizeof(LIST)*17+sizeof(pthread_mutex_t)); + PADPOSITION(47,8+3*MAXNEST,72,45+3*MAXNEST+MAXREPEAT,COMMERCIALSIZE+MAXFLAGS+4+sizeof(LIST)*17+sizeof(pthread_mutex_t)); #elif defined(WITHMPI) - PADPOSITION(47,8+3*MAXNEST,71,46+3*MAXNEST+MAXREPEAT,COMMERCIALSIZE+MAXFLAGS+4+sizeof(LIST)*17); + PADPOSITION(47,8+3*MAXNEST,72,46+3*MAXNEST+MAXREPEAT,COMMERCIALSIZE+MAXFLAGS+4+sizeof(LIST)*17); #else - PADPOSITION(45,8+3*MAXNEST,69,45+3*MAXNEST+MAXREPEAT,COMMERCIALSIZE+MAXFLAGS+4+sizeof(LIST)*17); + PADPOSITION(45,8+3*MAXNEST,70,45+3*MAXNEST+MAXREPEAT,COMMERCIALSIZE+MAXFLAGS+4+sizeof(LIST)*17); #endif }; /* diff --git a/sources/tools.c b/sources/tools.c index f44d9aa4..af5ce414 100644 --- a/sources/tools.c +++ b/sources/tools.c @@ -3213,8 +3213,17 @@ int CompArg(WORD *s1, WORD *s2) #include +/** + * Returns the wall-clock time. + * + * @param par If zero, the wall-clock time will be reset to 0. + * @return The wall-clock time in centiseconds. + */ LONG TimeWallClock(WORD par) { + /* + * NOTE: this function is not thread-safe. Operations on tp are not atomic. + */ struct timeb tp; ftime(&tp); if ( par ) { @@ -3245,6 +3254,12 @@ LONG TimeChildren(WORD par) #[ TimeCPU : */ +/** + * Returns the CPU time. + * + * @param par If zero, the CPU time will be reset to 0. + * @return The CPU time in milliseconds. + */ LONG TimeCPU(WORD par) { GETIDENTITY