From 9ad421714fd496fd93f3d6e30622dd1d6b551619 Mon Sep 17 00:00:00 2001 From: Laxmikant Kale Date: Tue, 11 Aug 2026 18:12:57 -0500 Subject: [PATCH] trace-summary: record message bytes per entry method per interval A summary detail trace says how much time each entry method spent in an interval and how many times it ran there, which is how many messages it processed, but not how much data those messages carried. The size is already handed to the tracer and thrown away: TraceSummary::beginExecute takes an mlen argument it never reads, and the envelope form drops the length before calling it. Pass the envelope's total size through, remember it for the matching endExecute the way the entry method index is remembered, and accumulate it into a msgBytes array beside numExecutions, in the same bin the run is counted in. The .sumd file gains a MsgBytesPerEPperInterval line in the same run length encoding as the two arrays already written. Only messages delivered to an entry method contribute. Packing and unpacking, which numExecutions also counts because updateSummaryDetail is called for them too, add no bytes. Costs one 8 byte counter per bin per entry method while tracing, next to the 8 byte time and 4 byte count already kept, and one more line per processor in the .sumd file. Readers that do not know the new line are unaffected: Projections' SumDetailReader ignores labels it does not recognise by design, so an older Projections reads a newer .sumd unchanged. Co-Authored-By: Claude Opus 5 (1M context) --- src/ck-perf/trace-summary.C | 46 ++++++++++++++++++++++++++++++++++--- src/ck-perf/trace-summary.h | 17 +++++++++++++- 2 files changed, 59 insertions(+), 4 deletions(-) diff --git a/src/ck-perf/trace-summary.C b/src/ck-perf/trace-summary.C index 2ca7e6325e..eb33f642e3 100644 --- a/src/ck-perf/trace-summary.C +++ b/src/ck-perf/trace-summary.C @@ -218,6 +218,7 @@ SumLogPool::~SumLogPool() delete[] epInfo; delete[] cpuTime; delete[] numExecutions; + delete[] msgBytes; } void SumLogPool::addEventType(int eventType, double time) @@ -272,6 +273,7 @@ void SumLogPool::initMem() cpuTime = NULL; numExecutions = NULL; + msgBytes = NULL; if (sumDetail) { cpuTime = new double[poolSize*epInfoSize]; _MEMCHECK(cpuTime); @@ -279,6 +281,9 @@ void SumLogPool::initMem() numExecutions = new int[poolSize*epInfoSize]; _MEMCHECK(numExecutions); memset(numExecutions, 0, poolSize*epInfoSize*sizeof(int)); + msgBytes = new CmiUInt8[poolSize*epInfoSize]; + _MEMCHECK(msgBytes); + memset(msgBytes, 0, poolSize*epInfoSize*sizeof(CmiUInt8)); // int i, e; // for(i=0; i 1) fprintf(sdfp, "+%d", count); fprintf(sdfp, "\n"); + // Write out msgBytes + // Run length encoding (RLE) along EP axis + fprintf(sdfp, "MsgBytesPerEPperInterval "); + CmiUInt8 lastBytes = getMsgBytes(0,0); + count=0; + fprintf(sdfp, "%llu", (unsigned long long)lastBytes); + for(e=0; e<_numEntries; e++) { + for(i=0; i 1) fprintf(sdfp, "+%d", count); + fprintf(sdfp, " %llu", (unsigned long long)u); + lastBytes = u; + count = 1; + } + } + } + if (count > 1) fprintf(sdfp, "+%d", count); + fprintf(sdfp, "\n"); + // Write out numExecutions // Run length encoding (RLE) along EP axis fprintf(sdfp, "EPCallTimePerInterval "); @@ -525,7 +554,8 @@ void SumLogPool::setEp(int epidx, double time) // Called once from endExecute, endPack, etc. this function updates // the sumDetail intervals. -void SumLogPool::updateSummaryDetail(int epIdx, double startTime, double endTime) +void SumLogPool::updateSummaryDetail(int epIdx, double startTime, double endTime, + CmiUInt8 bytes) { if (epIdx >= epInfoSize) { CmiAbort("Too many entry points!!\n"); @@ -557,7 +587,10 @@ void SumLogPool::updateSummaryDetail(int epIdx, double startTime, double endTime CmiAbort("Error: end time of EP is less than start time\n"); } + // startingBinIdx has been walked forward to the bin the execution ended + // in; count the message, and its size, where the run is counted. incNumExecutions(startingBinIdx, epIdx); + addToMsgBytes(startingBinIdx, epIdx, bytes); } // Shrinks pool[], cpuTime[], and numExecutions[] @@ -576,12 +609,14 @@ void SumLogPool::shrink(void) for (int e=0; e < epInfoSize; e++) { setCPUtime(i, e, getCPUtime(i*2, e) + getCPUtime(i*2+1, e)); setNumExecutions(i, e, getNumExecutions(i*2, e) + getNumExecutions(i*2+1, e)); + setMsgBytes(i, e, getMsgBytes(i*2, e) + getMsgBytes(i*2+1, e)); } } // zero out the remaining intervals if (sumDetail) { memset(&cpuTime[entries*epInfoSize], 0, (numBins-entries)*epInfoSize*sizeof(double)); memset(&numExecutions[entries*epInfoSize], 0, (numBins-entries)*epInfoSize*sizeof(int)); + memset(&msgBytes[entries*epInfoSize], 0, (numBins-entries)*epInfoSize*sizeof(CmiUInt8)); } numBins = entries; CkpvAccess(binSize) *= 2; @@ -647,6 +682,7 @@ TraceSummary::TraceSummary(char **argv):msgNum(0),binStart(0.0),idleStart(0.0), _logPool = new SumLogPool(CkpvAccess(traceRoot)); // assume invalid entry point on start execEp=INVALIDEP; + execMsgBytes = 0; inIdle = 0; inExec = 0; depth = 0; @@ -685,7 +721,9 @@ void TraceSummary::beginExecute(envelope *e, void *obj) beginExecute(-1,-1,_threadEP,-1); } else { - beginExecute(-1,-1,e->getEpIdx(),-1); + // the message length is passed on so that summary detail can record how + // many bytes an entry method received, not only how many messages + beginExecute(-1,-1,e->getEpIdx(),-1,e->getTotalsize()); } } @@ -725,6 +763,7 @@ void TraceSummary::beginExecute(int event,int msgType,int ep,int srcPe, int mlen */ execEp=ep; + execMsgBytes=(mlen > 0) ? (CmiUInt8)mlen : 0; double t = TraceTimer(); //CmiPrintf("start: %f \n", start); @@ -796,9 +835,10 @@ void TraceSummary::endExecute() binTime += t - ts; if (sumDetail && execEp >= 0 ) - _logPool->updateSummaryDetail(execEp, start, t); + _logPool->updateSummaryDetail(execEp, start, t, execMsgBytes); execEp = INVALIDEP; + execMsgBytes = 0; } void TraceSummary::endExecute(char *msg){ diff --git a/src/ck-perf/trace-summary.h b/src/ck-perf/trace-summary.h index 9fdab48dde..04220e5ba1 100644 --- a/src/ck-perf/trace-summary.h +++ b/src/ck-perf/trace-summary.h @@ -184,6 +184,12 @@ class SumLogPool { /// for Summary-Detail double *cpuTime; //[MAX_INTERVALS * MAX_ENTRIES]; int *numExecutions; //[MAX_INTERVALS * MAX_ENTRIES]; + /** Bytes of the messages counted by numExecutions, so that a summary + trace can say how much data an entry method received and not only how + many messages. Only messages delivered to an entry method are counted; + packing and unpacking, which numExecutions also counts, contribute + none. */ + CmiUInt8 *msgBytes; //[MAX_INTERVALS * MAX_ENTRIES]; public: SumLogPool(char *pgm); @@ -232,10 +238,18 @@ class SumLogPool { inline int incNumExecutions(unsigned int interval, unsigned int ep){ ++numExecutions[interval*epInfoSize+ep]; return numExecutions[interval*epInfoSize+ep]; } + inline CmiUInt8 getMsgBytes(unsigned int interval, unsigned int ep){ + return msgBytes[interval*epInfoSize+ep]; } + inline void setMsgBytes(unsigned int interval, unsigned int ep, CmiUInt8 val){ + msgBytes[interval*epInfoSize+ep] = val; } + inline CmiUInt8 addToMsgBytes(unsigned int interval, unsigned int ep, CmiUInt8 val){ + msgBytes[interval*epInfoSize+ep] += val; + return msgBytes[interval*epInfoSize+ep]; } inline int getUtilization(int interval, int ep); - void updateSummaryDetail(int epIdx, double startTime, double endTime); + void updateSummaryDetail(int epIdx, double startTime, double endTime, + CmiUInt8 bytes = 0); }; @@ -250,6 +264,7 @@ class TraceSummary : public Trace { int execEvent; int execEp; int execPe; + CmiUInt8 execMsgBytes; /* size of the message being executed, for summary detail */ int msgNum; /* used to handle multiple endComputation calls?? */ /* per-log metadata maintained to derive cross-event information */