Merge pull request #6517 from ghalliday/issue12370

HPCC-12370 Improve timing display and support merging statistics

Reviewed-By: Gordon Smith <gordon.smith@lexisnexis.com>
Reviewed-By: Richard Chapman <rchapman@hpccsystems.com>

common/workunit/workunit.cpp

@@ -1188,7 +1188,7 @@ public:
     void setStateEx(const char * text);
     void setAgentSession(__int64 sessionId);
     void setSecurityToken(const char *value);
-    void setStatistic(StatisticCreatorType creatorType, const char * creator, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * optDescription, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, bool merge);
+    void setStatistic(StatisticCreatorType creatorType, const char * creator, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * optDescription, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, StatsMergeAction mergeAction);
     void setTracingValue(const char * propname, const char * value);
     void setTracingValueInt(const char * propname, int value);
     void setUser(const char * value);
@@ -1610,8 +1610,8 @@ public:
             { c->setStateEx(text); }
     virtual void setAgentSession(__int64 sessionId)
             { c->setAgentSession(sessionId); }
-    virtual void setStatistic(StatisticCreatorType creatorType, const char * creator, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * optDescription, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, bool merge)
-            { c->setStatistic(creatorType, creator, scopeType, scope, kind, optDescription, value, count, maxValue, merge); }
+    virtual void setStatistic(StatisticCreatorType creatorType, const char * creator, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * optDescription, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, StatsMergeAction mergeAction)
+            { c->setStatistic(creatorType, creator, scopeType, scope, kind, optDescription, value, count, maxValue, mergeAction); }
     virtual void setTracingValue(const char * propname, const char * value)
             { c->setTracingValue(propname, value); }
     virtual void setTracingValueInt(const char * propname, int value)
@@ -3998,7 +3998,7 @@ void CLocalWorkUnit::unlockRemote(bool commit)
         {
             assertex(connectAtRoot);
             //MORE: I'm not convinced this is useful...
-            setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTglobal, NULL, StWhenWorkunitModified, NULL, getTimeStampNowValue(), 1, 0, false);
+            setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTglobal, NULL, StWhenWorkunitModified, NULL, getTimeStampNowValue(), 1, 0, StatsMergeReplace);
             try { connection->commit(); }
             catch (IException *e)
             { 
@@ -5912,7 +5912,7 @@ protected:
     Linked<const IStatisticsFilter> filter;
 };
 
-void CLocalWorkUnit::setStatistic(StatisticCreatorType creatorType, const char * creator, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * optDescription, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, bool merge)
+void CLocalWorkUnit::setStatistic(StatisticCreatorType creatorType, const char * creator, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * optDescription, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, StatsMergeAction mergeAction)
 {
     if (!scope) scope = GLOBAL_SCOPE;
 
@@ -5928,8 +5928,7 @@ void CLocalWorkUnit::setStatistic(StatisticCreatorType creatorType, const char *
         stats = p->addPropTree("Statistics", createPTree("Statistics"));
 
     IPropertyTree * statTree = NULL;
-    bool append = false;
-    if (!append)
+    if (mergeAction != StatsMergeAppend)
     {
         StringBuffer xpath;
         xpath.append("Statistic[@creator='").append(creator).append("'][@scope='").append(scope).append("'][@kind='").append(kindName).append("']");
@@ -5954,10 +5953,10 @@ void CLocalWorkUnit::setStatistic(StatisticCreatorType creatorType, const char *
         if (statistics.cached)
             statistics.append(LINK(statTree));
 
-        merge = false;
+        mergeAction = StatsMergeAppend;
     }
 
-    if (merge)
+    if (mergeAction != StatsMergeAppend)
     {
         unsigned __int64 oldValue = statTree->getPropInt64("@value", 0);
         unsigned __int64 oldCount = statTree->getPropInt64("@count", 0);
@@ -5965,7 +5964,7 @@ void CLocalWorkUnit::setStatistic(StatisticCreatorType creatorType, const char *
         if (oldMax < oldValue)
             oldMax = oldValue;
 
-        statTree->setPropInt64("@value", mergeStatistic(measure, value, oldValue));
+        statTree->setPropInt64("@value", mergeStatisticValue(oldValue, value, mergeAction));
         statTree->setPropInt64("@count", count + oldCount);
         if (maxValue > oldMax)
             statTree->setPropInt64("@max", maxValue);
@@ -10569,7 +10568,7 @@ extern WORKUNIT_API void descheduleWorkunit(char const * wuid)
 
 extern WORKUNIT_API void updateWorkunitTimeStat(IWorkUnit * wu, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * description, unsigned __int64 value)
 {
-    wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, description, value, 1, 0, false);
+    wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, description, value, 1, 0, StatsMergeReplace);
 }
 
 extern WORKUNIT_API void updateWorkunitTimings(IWorkUnit * wu, ITimeReporter *timer)
@@ -10580,13 +10579,13 @@ extern WORKUNIT_API void updateWorkunitTimings(IWorkUnit * wu, ITimeReporter *ti
         StatisticScopeType scopeType= timer->getScopeType(i);
         timer->getScope(i, scope.clear());
         StatisticKind kind = timer->getTimerType(i);
-        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, NULL, timer->getTime(i), timer->getCount(i), timer->getMaxTime(i), false);
+        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, NULL, timer->getTime(i), timer->getCount(i), timer->getMaxTime(i), StatsMergeReplace);
     }
 }
 
 extern WORKUNIT_API void addTimeStamp(IWorkUnit * wu, StatisticScopeType scopeType, const char * scope, StatisticKind kind)
 {
-    wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, NULL, getTimeStampNowValue(), 1, 0, false);
+    wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, NULL, getTimeStampNowValue(), 1, 0, StatsMergeAppend);
 }
 
 

common/workunit/workunit.hpp

@@ -1095,7 +1095,7 @@ interface IWorkUnit : extends IConstWorkUnit
     virtual void setState(WUState state) = 0;
     virtual void setStateEx(const char * text) = 0;
     virtual void setAgentSession(__int64 sessionId) = 0;
-    virtual void setStatistic(StatisticCreatorType creatorType, const char * creator, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * optDescription, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, bool merge) = 0;
+    virtual void setStatistic(StatisticCreatorType creatorType, const char * creator, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * optDescription, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, StatsMergeAction mergeAction) = 0;
     virtual void setTracingValue(const char * propname, const char * value) = 0;
     virtual void setTracingValueInt(const char * propname, int value) = 0;
     virtual void setUser(const char * value) = 0;
@@ -1304,9 +1304,9 @@ class WuStatisticTarget : implements IStatisticTarget
 public:
     WuStatisticTarget(IWorkUnit * _wu, const char * _defaultWho) : wu(_wu), defaultWho(_defaultWho) {}
 
-    virtual void addStatistic(StatisticScopeType scopeType, const char * scope, StatisticKind kind, char * description, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, bool merge)
+    virtual void addStatistic(StatisticScopeType scopeType, const char * scope, StatisticKind kind, char * description, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, StatsMergeAction mergeAction)
     {
-        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, description, value, count, maxValue, merge);
+        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, description, value, count, maxValue, mergeAction);
     }
 
 protected:

ecl/eclccserver/eclccserver.cpp

@@ -211,7 +211,7 @@ class EclccCompileThread : public CInterface, implements IPooledThread, implemen
                     const char * scope = section.str();
                     StatisticScopeType scopeType = SSTcompilestage;
                     StatisticKind kind = StTimeElapsed;
-                    workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, NULL, nval, cnt, nmax, false);
+                    workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, NULL, nval, cnt, nmax, StatsMergeReplace);
                 }
             }
             else

ecl/hqlcpp/hqlhtcpp.cpp

@@ -5914,7 +5914,7 @@ public:
     {
         StatisticScopeType scopeType = SSTsection; // MORE?
         StatisticKind kind = StTimeElapsed;
-        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, description, totaltime, count, maxtime, false);
+        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, description, totaltime, count, maxtime, StatsMergeReplace);
     }
 
 protected:

esp/src/eclwatch/ESPWorkunit.js

@@ -126,15 +126,27 @@ define([
             }
             this.set("sourceFiles", sourceFiles);
         },
+        ExtractTime: function (Timer) {
+            var nsIndex = Timer.indexOf("ns");
+            if (nsIndex !== -1) {
+                return Timer.substr(0, nsIndex) / 1000000000;
+            }
+            var msIndex = Timer.indexOf("ms");
+            if (msIndex !== -1) {
+                return Timer.substr(0, msIndex) / 1000;
+            }
+            //MORE: This code doesn't cope with separate days
+            var secs = 0;
+            var timeParts = Timer.split(":");
+            for (var j = 0; j < timeParts.length; ++j) {
+                secs = secs * 60 + timeParts[j];
+            }
+            return secs;
+        },
         _TimersSetter: function (Timers) {
             var timers = [];
             for (var i = 0; i < Timers.ECLTimer.length; ++i) {
-                var timeParts = Timers.ECLTimer[i].Value.split(":");
-                var secs = 0;
-                for (var j = 0; j < timeParts.length; ++j) {
-                    secs = secs * 60 + timeParts[j] * 1;
-                }
-
+                var secs = this.ExtractTime(Timers.ECLTimer[i].Value);
                 timers.push(lang.mixin(Timers.ECLTimer[i], {
                     __hpcc_id: i + 1,
                     Seconds: Math.round(secs * 1000) / 1000,

roxie/ccd/ccd.hpp

@@ -691,7 +691,7 @@ public:
             for (unsigned i = 0; i < STATS_SIZE; i++)
             {
                 if (counts[i])
-                    wu->setStatistic(SCTroxie, whoami, SSTglobal, NULL, mapRoxieStatKind(i), NULL, cumulative[i], counts[i], 0, false);
+                    wu->setStatistic(SCTroxie, whoami, SSTglobal, NULL, mapRoxieStatKind(i), NULL, cumulative[i], counts[i], 0, StatsMergeReplace);
             }
         }
     }

roxie/roxiemem/roxiemem.cpp

@@ -1727,11 +1727,11 @@ public:
             else
                 activityText.append("ac").append(allocatorId & MAX_ACTIVITY_ID);
 
-            target.addStatistic(SSTallocator, activityText.str(), StSizePeakMemory, NULL, results[j]->usage, results[j]->allocations, 0, false);
+            target.addStatistic(SSTallocator, activityText.str(), StSizePeakMemory, NULL, results[j]->usage, results[j]->allocations, 0, StatsMergeMax);
         }
         delete [] results;
 
-        target.addStatistic(SSTglobal, NULL, StSizePeakMemory, NULL, totalUsed, 1, 0, false);
+        target.addStatistic(SSTglobal, NULL, StSizePeakMemory, NULL, totalUsed, 1, 0, StatsMergeMax);
     }
 };
 
@@ -3267,7 +3267,7 @@ public:
         }
         if (map)
             map->reportStatistics(target, detail, allocatorCache);
-        target.addStatistic(SSTglobal, NULL, StSizePeakMemory, NULL, peakPages * HEAP_ALIGNMENT_SIZE, 1, 0, false);
+        target.addStatistic(SSTglobal, NULL, StSizePeakMemory, NULL, peakPages * HEAP_ALIGNMENT_SIZE, 1, 0, StatsMergeMax);
     }
 
     void restoreLimit(unsigned numRequested)

system/jlib/jstats.cpp

@@ -150,6 +150,7 @@ unsigned __int64 getIPV4StatsValue(const IpAddress & ip)
 
 //--------------------------------------------------------------------------------------------------------------------
 
+const static unsigned __int64 oneMilliSecond = I64C(1000000);
 const static unsigned __int64 oneSecond = I64C(1000000000);
 const static unsigned __int64 oneMinute = I64C(60000000000);
 const static unsigned __int64 oneHour = I64C(3600000000000);
@@ -157,27 +158,36 @@ const static unsigned __int64 oneDay = 24 * I64C(3600000000000);
 
 static void formatTime(StringBuffer & out, unsigned __int64 value)
 {
-    unsigned days = (unsigned)(value / oneDay);
-    value = value % oneDay;
-    unsigned hours = (unsigned)(value / oneHour);
-    value = value % oneHour;
-    unsigned mins = (unsigned)(value / oneMinute);
-    value = value % oneMinute;
-    unsigned secs = (unsigned)(value / oneSecond);
-    unsigned ns = (unsigned)(value % oneSecond);
-
-    if (days > 0)
-        out.appendf("%u days ", days);
-    if (hours > 0 || days)
-        out.appendf("%u:%02u:%02u", hours, mins, secs);
-    else if (mins >= 5)
-        out.appendf("%u:%02u", mins, secs);
-    else if (mins >= 1)
-        out.appendf("%u:%02u.%03u", mins, secs, ns / 1000000);
-    else if (secs >= 10)
-        out.appendf("%u.%03u", secs, ns / 1000000);
+    //Aim to display at least 3 significant digits in the result string
+    if (value < oneMilliSecond)
+        out.appendf("%uns", (unsigned)value);
+    else if (value < oneSecond)
+    {
+        unsigned uvalue = (unsigned)value;
+        out.appendf("%u.%03ums", uvalue / 1000000, (uvalue / 1000) % 1000);
+    }
     else
-        out.appendf("%u.%06u", secs, ns / 1000);
+    {
+        unsigned days = (unsigned)(value / oneDay);
+        value = value % oneDay;
+        unsigned hours = (unsigned)(value / oneHour);
+        value = value % oneHour;
+        unsigned mins = (unsigned)(value / oneMinute);
+        value = value % oneMinute;
+        unsigned secs = (unsigned)(value / oneSecond);
+        unsigned ns = (unsigned)(value % oneSecond);
+
+        if (days > 0)
+            out.appendf("%u days ", days);
+        if (hours > 0 || days)
+            out.appendf("%u:%02u:%02u", hours, mins, secs);
+        else if (mins >= 10)
+            out.appendf("%u:%02u", mins, secs);
+        else if (mins >= 1)
+            out.appendf("%u:%02u.%03u", mins, secs, ns / 1000000);
+        else
+            out.appendf("%u.%03us", secs, ns / 1000000);
+    }
 }
 
 static void formatTimeStamp(StringBuffer & out, unsigned __int64 value)
@@ -331,6 +341,23 @@ StatisticMeasure queryMeasure(const char *  measure)
     return (StatisticMeasure)matchString(measureNames, measure);
 }
 
+StatsMergeAction queryMergeMode(StatisticMeasure measure)
+{
+    switch (measure)
+    {
+    case SMeasureTimeNs:        return StatsMergeSum;
+    case SMeasureTimestampUs:   return StatsMergeKeep;
+    case SMeasureCount:         return StatsMergeSum;
+    case SMeasureSize:          return StatsMergeSum;
+    case SMeasureLoad:          return StatsMergeMax;
+    case SMeasureSkew:          return StatsMergeMax;
+    case SMeasureNode:          return StatsMergeKeep;
+    case SMeasurePercent:       return StatsMergeReplace;
+    case SMeasureIPV4:          return StatsMergeKeep;
+    default:
+        throwUnexpected();
+    }
+}
 //--------------------------------------------------------------------------------------------------------------------
 
 StatisticMeasure queryMeasure(StatisticKind kind)
@@ -679,6 +706,31 @@ unsigned __int64 mergeStatistic(StatisticMeasure measure, unsigned __int64 value
     return value;
 }
 
+unsigned __int64 mergeStatisticValue(unsigned __int64 prevValue, unsigned __int64 newValue, StatsMergeAction mergeAction)
+{
+    switch (mergeAction)
+    {
+    case StatsMergeKeep:
+        return prevValue;
+    case StatsMergeAppend:
+    case StatsMergeReplace:
+        return newValue;
+    case StatsMergeSum:
+        return prevValue + newValue;
+    case StatsMergeMin:
+        if (prevValue > newValue)
+            return newValue;
+        else
+            return prevValue;
+    case StatsMergeMax:
+        if (prevValue < newValue)
+            return newValue;
+        else
+            return prevValue;
+    default:
+        throwUnexpected();
+    }
+}
 
 //--------------------------------------------------------------------------------------------------------------------
 
@@ -1092,6 +1144,23 @@ public:
         stats.append(*new Statistic(kind, value));
     }
 
+    void updateStatistic(StatisticKind kind, unsigned __int64 value, StatsMergeAction mergeAction)
+    {
+        if (mergeAction != StatsMergeAppend)
+        {
+            ForEachItemIn(i, stats)
+            {
+                Statistic & cur = stats.element(i);
+                if (cur.kind == kind)
+                {
+                    cur.value = mergeStatisticValue(cur.value, value, mergeAction);
+                    return;
+                }
+            }
+        }
+        stats.append(*new Statistic(kind, value));
+    }
+
     CStatisticCollection * ensureSubScope(const StatsScopeId & search, bool hasChildren)
     {
         //MORE: Implement hasChildren
@@ -1287,6 +1356,11 @@ public:
         CStatisticCollection & tos = scopes.tos();
         tos.addStatistic(kind, value);
     }
+    virtual void updateStatistic(StatisticKind kind, unsigned __int64 value, StatsMergeAction mergeAction)
+    {
+        CStatisticCollection & tos = scopes.tos();
+        tos.updateStatistic(kind, value, mergeAction);
+    }
     virtual IStatisticCollection * getResult()
     {
         return LINK(rootScope);

system/jlib/jstats.h

@@ -281,6 +281,16 @@ interface IStatisticCollectionIterator : public IIteratorOf<IStatisticCollection
 {
 };
 
+enum StatsMergeAction
+{
+    StatsMergeKeep,
+    StatsMergeReplace,
+    StatsMergeSum,
+    StatsMergeMin,
+    StatsMergeMax,
+    StatsMergeAppend,
+};
+
 interface IStatisticGatherer : public IInterface
 {
 public:
@@ -290,6 +300,7 @@ public:
     virtual void beginEdgeScope(unsigned id, unsigned oid) = 0;
     virtual void endScope() = 0;
     virtual void addStatistic(StatisticKind kind, unsigned __int64 value) = 0;
+    virtual void updateStatistic(StatisticKind kind, unsigned __int64 value, StatsMergeAction mergeAction) = 0;
     virtual IStatisticCollection * getResult() = 0;
 };
 
@@ -430,6 +441,7 @@ extern jlib_decl unsigned __int64 getIPV4StatsValue(const IpAddress & ip);
 extern jlib_decl void formatStatistic(StringBuffer & out, unsigned __int64 value, StatisticMeasure measure);
 extern jlib_decl void formatStatistic(StringBuffer & out, unsigned __int64 value, StatisticKind kind);
 extern jlib_decl unsigned __int64 mergeStatistic(StatisticMeasure measure, unsigned __int64 value, unsigned __int64 otherValue);
+extern jlib_decl unsigned __int64 mergeStatisticValue(unsigned __int64 prevValue, unsigned __int64 newValue, StatsMergeAction mergeAction);
 
 extern jlib_decl StatisticMeasure queryMeasure(StatisticKind kind);
 extern jlib_decl const char * queryStatisticName(StatisticKind kind);
@@ -438,6 +450,7 @@ extern jlib_decl const char * queryTreeTag(StatisticKind kind);
 extern jlib_decl const char * queryCreatorTypeName(StatisticCreatorType sct);
 extern jlib_decl const char * queryScopeTypeName(StatisticScopeType sst);
 extern jlib_decl const char * queryMeasureName(StatisticMeasure measure);
+extern jlib_decl StatsMergeAction queryMergeMode(StatisticMeasure measure);
 
 extern jlib_decl StatisticMeasure queryMeasure(const char *  measure);
 extern jlib_decl StatisticKind queryStatisticKind(const char *  kind);
@@ -463,7 +476,7 @@ extern jlib_decl void verifyStatisticFunctions();
 //This interface is primarily here to reduce the dependency between the different components.
 interface IStatisticTarget
 {
-    virtual void addStatistic(StatisticScopeType scopeType, const char * scope, StatisticKind kind, char * description, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, bool merge) = 0;
+    virtual void addStatistic(StatisticScopeType scopeType, const char * scope, StatisticKind kind, char * description, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue, StatsMergeAction mergeAction) = 0;
 };
 
 #endif

thorlcr/graph/thgraphmaster.cpp

@@ -2641,7 +2641,7 @@ void CMasterGraph::done()
                         //GH-.JCS is this correct queryGraphId() is a subgraph?
                         formatGraphTimerScope(scope, graph.queryJob().queryGraphName(), graph.queryGraphId(), 0);
                         scope.append(":").append(timerScope);
-                        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTsection, scope, StTimeElapsed, timerStr.str(), totaltime, count, maxtime, false);
+                        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTsection, scope, StTimeElapsed, timerStr.str(), totaltime, count, maxtime, StatsMergeReplace);
 
                     }
                 } wureport(*this);

thorlcr/master/thgraphmanager.cpp

@@ -752,7 +752,7 @@ bool CJobManager::executeGraph(IConstWorkUnit &workunit, const char *graphName,
 
         updateWorkunitTimeStat(wu, SSTgraph, graphName, StTimeElapsed, graphTimeStr, graphTimeNs);
         updateWorkunitTimeStat(wu, SSTglobal, GLOBAL_SCOPE, StTimeElapsed, NULL, totalThisTimeNs+graphTimeNs);
-        wu->setStatistic(SCTsummary, "thor", SSTglobal, GLOBAL_SCOPE, StTimeElapsed, totalTimeStr, totalTimeNs+graphTimeNs, 1, 0, false);
+        wu->setStatistic(SCTsummary, "thor", SSTglobal, GLOBAL_SCOPE, StTimeElapsed, totalTimeStr, totalTimeNs+graphTimeNs, 1, 0, StatsMergeReplace);
 
         addTimeStamp(wu, SSTgraph, graphName, StWhenGraphFinished);