HPCC-12142 Enhancement to Roxie COMPLETE line in log

Signed-off-by: Richard Chapman <rchapman@hpccsystems.com>

common/thorhelper/thorsoapcall.cpp

@@ -1723,8 +1723,8 @@ public:
         while (!master->aborted)
         {
             Owned<ISocket> socket;
-            unsigned startTime, endTime;
-            startTime = msTick();
+            cycle_t startCycles, endCycles;
+            startCycles = get_cycles_now();
             loop 
             {
                 try
@@ -1812,9 +1812,11 @@ public:
                 {
                     throw MakeStringException(-1, "Zero length response in processQuery");
                 }
-                endTime = msTick();
+                endCycles = get_cycles_now();
+                __int64 elapsedNs = cycle_to_nanosec(endCycles-startCycles);
+                master->logctx.noteStatistic(STATS_SOAPCALL_LATENCY, elapsedNs, 1);
                 checkTimeLimitExceeded(&remainingMS);
-                ColumnProvider * meta = (ColumnProvider*)CreateColumnProvider(endTime-startTime, master->flags&SOAPFencoding?true:false);
+                ColumnProvider * meta = (ColumnProvider*)CreateColumnProvider(nanoToMilli(elapsedNs), master->flags&SOAPFencoding?true:false);
                 processResponse(url, response, meta);
                 delete meta;
                 break;

roxie/ccd/ccd.hpp

@@ -696,6 +696,23 @@ public:
         }
     }
 
+    StringBuffer &printStats(StringBuffer &ret) const
+    {
+        SpinBlock b(lock);
+        if (cumulative)
+        {
+            for (unsigned i = 0; i < STATS_SIZE; i++)
+            {
+                if (counts[i])
+                {
+                    StatisticKind kind = mapRoxieStatKind(i);
+                    ret.appendf(" %s=%"I64F"u", queryStatisticName(kind), cumulative[i]);
+                }
+            }
+        }
+        return ret;
+    }
+
     void toXML(StringBuffer &reply) const
     {
         SpinBlock b(lock);
@@ -926,6 +943,11 @@ public:
         stats.dumpStats(*this);
     }
 
+    StringBuffer &printStats(StringBuffer &s) const
+    {
+        return stats.printStats(s);
+    }
+
     virtual void dumpStats(IWorkUnit *wu) const
     {
         stats.dumpStats(wu);

roxie/ccd/ccdlistener.cpp

@@ -1244,7 +1244,11 @@ public:
         if (logctx.queryTraceLevel() > 2)
             logctx.dumpStats();
         if (logctx.queryTraceLevel() && (logctx.queryTraceLevel() > 2 || logFullQueries || logctx.intercept))
-            logctx.CTXLOG("COMPLETE: %s complete in %d msecs memory %d Mb priority %d slavesreply %d", wuid.get(), elapsed, memused, priority, slavesReplyLen);
+        {
+            StringBuffer s;
+            logctx.printStats(s);
+            logctx.CTXLOG("COMPLETE: %s complete in %d msecs memory=%d Mb priority=%d slavesreply=%d%s", wuid.get(), elapsed, memused, priority, slavesReplyLen, s.str());
+        }
         logctx.flush(true, false);
     }
 
@@ -1881,8 +1885,11 @@ readAnother:
             logctx.dumpStats();
         if (logctx.queryTraceLevel() && (logctx.queryTraceLevel() > 2 || logFullQueries || logctx.intercept))
             if (queryName.get())
-                logctx.CTXLOG("COMPLETE: %s %s from %s complete in %d msecs memory %d Mb priority %d slavesreply %d resultsize %d continue %d", queryName.get(), uid, peerStr.str(), elapsed, memused, priority, slavesReplyLen, bytesOut, continuationNeeded);
-
+            {
+                StringBuffer s;
+                logctx.printStats(s);
+                logctx.CTXLOG("COMPLETE: %s %s from %s complete in %d msecs memory=%d Mb priority=%d slavesreply=%d resultsize=%d continue=%d%s", queryName.get(), uid, peerStr.str(), elapsed, memused, priority, slavesReplyLen, bytesOut, continuationNeeded, s.str());
+            }
         if (continuationNeeded)
         {
             rawText.clear();

roxie/ccd/ccdserver.cpp

@@ -25251,9 +25251,9 @@ public:
         if (soaphelper == NULL)
         {
             if (factory->getKind()==TAKhttp_rowdataset)
-                soaphelper.setown(createHttpCallHelper(this, rowAllocator, authToken.str(), SCrow, pClientCert, *ctx, this));
+                soaphelper.setown(createHttpCallHelper(this, rowAllocator, authToken.str(), SCrow, pClientCert, *this, this));
             else
-                soaphelper.setown(createSoapCallHelper(this, rowAllocator, authToken.str(), SCrow, pClientCert, *ctx, this));
+                soaphelper.setown(createSoapCallHelper(this, rowAllocator, authToken.str(), SCrow, pClientCert, *this, this));
             soaphelper->start();
         }
 
@@ -25300,7 +25300,7 @@ public:
     virtual void execute(unsigned parentExtractSize, const byte * parentExtract)
     {
         //MORE: parentExtract not passed to start - although shouldn't be a problem.
-        soaphelper.setown(createSoapCallHelper(this, NULL, ctx->queryAuthToken(), SCrow, pClientCert, *ctx, this));
+        soaphelper.setown(createSoapCallHelper(this, NULL, ctx->queryAuthToken(), SCrow, pClientCert, *this, this));
         soaphelper->start();
         soaphelper->waitUntilDone();
         IException *e = soaphelper->getError();
@@ -25383,7 +25383,7 @@ public:
 
         if (soaphelper == NULL)
         {
-            soaphelper.setown(createSoapCallHelper(this, rowAllocator, authToken.str(), SCdataset, pClientCert, *ctx, this));
+            soaphelper.setown(createSoapCallHelper(this, rowAllocator, authToken.str(), SCdataset, pClientCert, *this, this));
             soaphelper->start();
         }
 
@@ -25445,7 +25445,7 @@ public:
         try
         {
             start(parentExtractSize, parentExtract, false);
-            soaphelper.setown(createSoapCallHelper(this, NULL, ctx->queryAuthToken(), SCdataset, pClientCert, *ctx, this));
+            soaphelper.setown(createSoapCallHelper(this, NULL, ctx->queryAuthToken(), SCdataset, pClientCert, *this, this));
             soaphelper->start();
             soaphelper->waitUntilDone();
             IException *e = soaphelper->getError();

system/jlib/jstats.cpp

@@ -378,6 +378,7 @@ StatisticMeasure queryMeasure(StatisticKind kind)
     case StTimeLocalExecute:
     case StTimeTotalExecute:
     case StTimeRemaining:
+    case StTimeSoapcall:
         return SMeasureTimeNs;
     case StSizeGeneratedCpp:
     case StSizePeakMemory:
@@ -466,6 +467,7 @@ const char * queryStatisticName(StatisticKind kind)
     DEFINE_TIMESTAMPSHORTNAME(Time, LocalExecute);
     DEFINE_TIMESTAMPSHORTNAME(Time, TotalExecute);
     DEFINE_TIMESTAMPSHORTNAME(Time, Remaining);
+    DEFINE_TIMESTAMPSHORTNAME(Time, Soapcall);
 
     DEFINE_DEFAULTSHORTNAME(Size, GeneratedCpp);
     DEFINE_DEFAULTSHORTNAME(Size, PeakMemory);
@@ -557,6 +559,7 @@ const char * queryTreeTag(StatisticKind kind)
     DEFINE_TAGNAME(Time, LocalExecute, "@localTime");
     DEFINE_TAGNAME(Time, TotalExecute, "@totalTime");
     DEFINE_DEFAULTTAGNAME(Time, Remaining);
+    DEFINE_DEFAULTTAGNAME(Time, Soapcall);
 
     DEFINE_DEFAULTTAGNAME(Size, GeneratedCpp);
     DEFINE_DEFAULTTAGNAME(Size, PeakMemory);
@@ -1392,6 +1395,8 @@ extern jlib_decl StatisticKind mapRoxieStatKind(unsigned i)
     case STATS_ATMOST:              return StNumAtmostTriggered;
 
     case STATS_DISK_SEEKS:          return StNumDiskSeeks;
+    case STATS_SOAPCALL_LATENCY:    return StTimeSoapcall;
+
     default:
         throwUnexpected();
     }

system/jlib/jstats.h

@@ -56,6 +56,7 @@ enum OldStatsKind
     STATS_ATMOST,
 
     STATS_DISK_SEEKS,
+    STATS_SOAPCALL_LATENCY,
 
     STATS_SIZE
 };
@@ -146,7 +147,7 @@ enum StatisticKind
     StWhenCompiled,
     StWhenWorkunitModified,             // Not sure this is very useful
 
-    StTimeElapsed,                      // Elapsed wall time between first row and last row.
+    StTimeElapsed,                      // Elapsed wall time between first row and last row
     StTimeLocalExecute,                 // Time spend processing just this activity
     StTimeTotalExecute,                 // Time executing this activity and all inputs
     StTimeRemaining,
@@ -191,6 +192,8 @@ enum StatisticKind
     StNumDiskAccepted,
     StNumDiskRejected,
 
+    StTimeSoapcall,                     // Time spent waiting for soapcalls
+
     StMax,
 
     //For any quantity there is potentially the following variants.