HPCC-27292 Add time taken to load index nodes to the stats

Signed-off-by: Gavin Halliday <gavin.halliday@lexisnexis.com>

roxie/ccd/ccdactivities.cpp

@@ -2424,6 +2424,7 @@ static const StatisticsMapping indexAgentStats({StNumIndexSeeks, StNumIndexScans
                                                 StNumPreFiltered, StNumPostFiltered, StNumIndexAccepted, StNumIndexRejected,
                                                 StNumBlobCacheHits, StNumLeafCacheHits, StNumNodeCacheHits,
                                                 StNumBlobCacheAdds, StNumLeafCacheAdds, StNumNodeCacheAdds,
+                                                StCycleBlobLoadCycles, StCycleLeafLoadCycles, StCycleNodeLoadCycles, // only need to accumulate cycles in the agents - serialized as times
                                                 StNumIndexRowsRead});
 
 class CRoxieIndexActivityFactory : public CRoxieKeyedActivityFactory

roxie/ccd/ccdserver.cpp

@@ -399,12 +399,14 @@ static const StatisticsMapping keyedJoinStatistics({ StNumServerCacheHits, StNum
                                                     StNumIndexRowsRead, StNumDiskRowsRead, StNumDiskSeeks, StNumDiskAccepted,
                                                     StNumBlobCacheHits, StNumLeafCacheHits, StNumNodeCacheHits,
                                                     StNumBlobCacheAdds, StNumLeafCacheAdds, StNumNodeCacheAdds,
+                                                    StTimeBlobLoad, StCycleBlobLoadCycles, StTimeLeafLoad, StCycleLeafLoadCycles, StTimeNodeLoad, StCycleNodeLoadCycles,
                                                     StNumDiskRejected, StSizeAgentReply, StTimeAgentWait}, joinStatistics);
 static const StatisticsMapping indexStatistics({StNumServerCacheHits, StNumIndexSeeks, StNumIndexScans, StNumIndexWildSeeks,
                                                 StNumIndexSkips, StNumIndexNullSkips, StNumIndexMerges, StNumIndexMergeCompares,
                                                 StNumPreFiltered, StNumPostFiltered, StNumIndexAccepted, StNumIndexRejected,
                                                 StNumBlobCacheHits, StNumLeafCacheHits, StNumNodeCacheHits,
                                                 StNumBlobCacheAdds, StNumLeafCacheAdds, StNumNodeCacheAdds,
+                                                StTimeBlobLoad, StCycleBlobLoadCycles, StTimeLeafLoad, StCycleLeafLoadCycles, StTimeNodeLoad, StCycleNodeLoadCycles,
                                                 StNumIndexRowsRead, StSizeAgentReply, StTimeAgentWait}, actStatistics);
 static const StatisticsMapping diskStatistics({StNumServerCacheHits, StNumDiskRowsRead, StNumDiskSeeks, StNumDiskAccepted,
                                                StNumDiskRejected, StSizeAgentReply, StTimeAgentWait }, actStatistics);
@@ -415,7 +417,6 @@ static const StatisticsMapping indexWriteStatistics({ StNumDuplicateKeys }, actS
 
 // These ones get accumulated and reported in COMPLETE: line (and workunit).
 // Excludes ones that are not sensible to sum across activities, other than StTimeTotalExecute which must be explicitly overwritten at global level before we report it
-
 extern const StatisticsMapping accumulatedStatistics({StWhenFirstRow, StTimeLocalExecute, StTimeTotalExecute, StSizeMaxRowSize,
                                                       StNumRowsProcessed, StNumSlaves, StNumStarts, StNumStops, StNumStrands,
                                                       StNumScansPerRow, StNumAllocations, StNumAllocationScans,
@@ -427,6 +428,7 @@ extern const StatisticsMapping accumulatedStatistics({StWhenFirstRow, StTimeLoca
                                                       StNumIndexRowsRead, StNumDiskRowsRead, StNumDiskSeeks, StNumDiskAccepted,
                                                       StNumBlobCacheHits, StNumLeafCacheHits, StNumNodeCacheHits,
                                                       StNumBlobCacheAdds, StNumLeafCacheAdds, StNumNodeCacheAdds,
+                                                      StTimeBlobLoad, StCycleBlobLoadCycles, StTimeLeafLoad, StCycleLeafLoadCycles, StTimeNodeLoad, StCycleNodeLoadCycles,  // If time and cycles are not included they are not serialized from agents
                                                       StNumDiskRejected, StSizeAgentReply, StTimeAgentWait,
                                                       StTimeSoapcall,
                                                       StNumGroups,

system/jhtree/jhtree.cpp

@@ -2417,6 +2417,7 @@ void CNodeCache::getCacheInfo(ICacheInfoRecorder &cacheInfo)
 
 constexpr StatisticKind addStatId[CacheMax] = { StNumNodeCacheAdds, StNumLeafCacheAdds, StNumBlobCacheAdds };
 constexpr StatisticKind hitStatId[CacheMax] = { StNumNodeCacheHits, StNumLeafCacheHits, StNumBlobCacheHits };
+constexpr StatisticKind loadStatId[CacheMax] = { StCycleNodeLoadCycles, StCycleLeafLoadCycles, StCycleBlobLoadCycles };
 constexpr RelaxedAtomic<unsigned> * hitMetric[CacheMax] = { &nodeCacheHits, &leafCacheHits, &blobCacheHits };
 constexpr RelaxedAtomic<unsigned> * addMetric[CacheMax] = { &nodeCacheAdds, &leafCacheAdds, &blobCacheAdds };
 constexpr RelaxedAtomic<unsigned> * dupMetric[CacheMax] = { &nodeCacheDups, &leafCacheDups, &blobCacheDups };
@@ -2537,20 +2538,24 @@ CJHTreeNode *CNodeCache::getNode(INodeLoader *keyIndex, unsigned iD, offset_t po
             unsigned hashcode = hashc(reinterpret_cast<const byte *>(&key), sizeof(key), 0x811C9DC5);
             unsigned whichCs = hashcode % numLoadCritSects;
 
+            cycle_t startCycles = get_cycles_now();
             //Protect loading the node contants with a different critical section - so that the node will only be loaded by one thread.
             //MORE: If this was called by high and low priority threads then there is an outside possibility that it could take a
             //long time for the low priority thread to progress.  That might cause the cache to be temporarily unbounded.  Unlikely in practice.
-            CriticalBlock loadBlock(loadCs[whichCs]);
-            if (!ownedNode->isReady())
             {
-                keyIndex->loadNode(ownedNode, pos);
+                CriticalBlock loadBlock(loadCs[whichCs]);
+                if (!ownedNode->isReady())
+                {
+                    keyIndex->loadNode(ownedNode, pos);
 
-                //Update the associated size of the entry in the hash table before setting isReady (never evicted until isReady is set)
-                cache[cacheType].noteReady(*ownedNode);
-                ownedNode->noteReady();
+                    //Update the associated size of the entry in the hash table before setting isReady (never evicted until isReady is set)
+                    cache[cacheType].noteReady(*ownedNode);
+                    ownedNode->noteReady();
+                }
+                else
+                    (*dupMetric[cacheType])++; // Would have previously loaded the page twice
             }
-            else
-                (*dupMetric[cacheType])++; // Would have previously loaded the page twice
+            if (ctx) ctx->noteStatistic(loadStatId[cacheType], get_cycles_now() - startCycles);
 
             return ownedNode.getClear();
         }

system/jlib/jstatcodes.h

@@ -243,6 +243,12 @@ enum StatisticKind
     StCostFileAccess,
     StNumPods,
     StCostCompile,
+    StTimeNodeLoad,
+    StCycleNodeLoadCycles,
+    StTimeLeafLoad,
+    StCycleLeafLoadCycles,
+    StTimeBlobLoad,
+    StCycleBlobLoadCycles,
     StMax,
 
     //For any quantity there is potentially the following variants.

system/jlib/jstats.cpp

@@ -918,7 +918,13 @@ static const StatisticMeta statsMetaData[StMax] = {
     { CYCLESTAT(AgentWait) },
     { COSTSTAT(FileAccess) },
     { NUMSTAT(Pods) },
-    { COSTSTAT(Compile) }
+    { COSTSTAT(Compile) },
+    { TIMESTAT(NodeLoad) },
+    { CYCLESTAT(NodeLoad) },
+    { TIMESTAT(LeafLoad) },
+    { CYCLESTAT(LeafLoad) },
+    { TIMESTAT(BlobLoad) },
+    { CYCLESTAT(BlobLoad) },
 };
 
 //Is a 0 value likely, and useful to be reported if it does happen to be zero?
@@ -2413,7 +2419,15 @@ void CRuntimeStatisticCollection::mergeStatistic(StatisticKind kind, unsigned __
 {
     CRuntimeStatistic * target = queryOptStatistic(kind);
     if (target)
+    {
         target->merge(value, queryMergeMode(kind));
+    }
+    else
+    {
+        StatisticKind serialKind= querySerializedKind(kind);
+        if (kind != serialKind)
+            mergeStatistic(serialKind, convertMeasure(kind, serialKind, value));
+    }
 }
 
 void CRuntimeStatisticCollection::sumStatistic(StatisticKind kind, unsigned __int64 value)