Merge pull request #8825 from ghalliday/issue12396

HPCC-12396 Add ability to time specific functions

Reviewed-By: Richard Chapman <rchapman@hpccsystems.com>

common/thorhelper/CMakeLists.txt

@@ -36,6 +36,7 @@ set (    SRCS
          thorpipe.cpp 
          thorrparse.cpp 
          thorsoapcall.cpp 
+         thorstats.cpp
          thorstep.cpp 
          thorstep2.cpp 
          thorstrand.cpp
@@ -57,6 +58,7 @@ set (    SRCS
          thorpipe.hpp 
          thorrparse.hpp 
          thorsoapcall.hpp 
+         thorstats.hpp
          thorstep.hpp 
          thorstrand.hpp
          thorxmlread.hpp 

common/thorhelper/roxiehelper.cpp

@@ -2723,3 +2723,14 @@ void HttpHelper::parseURL()
         return;
     parseHttpParameterString(parameters, ++finger);
 }
+
+//=====================================================================================================================
+
+class NullSectionTimer : public CSimpleInterfaceOf<ISectionTimer>
+{
+    virtual unsigned __int64 getStartCycles() { return 0; }
+    virtual void noteSectionTime(unsigned __int64 startCycles) {}
+};
+
+static NullSectionTimer nullSectionTimer;
+ISectionTimer * queryNullSectionTimer() { return &nullSectionTimer; }

common/thorhelper/roxiehelper.hpp

@@ -487,4 +487,6 @@ THORHELPER_API StringBuffer & mangleHelperFileName(StringBuffer & out, const cha
 THORHELPER_API StringBuffer & mangleLocalTempFilename(StringBuffer & out, char const * in);
 THORHELPER_API StringBuffer & expandLogicalFilename(StringBuffer & logicalName, const char * fname, IConstWorkUnit * wu, bool resolveLocally, bool ignoreForeignPrefix);
 
+THORHELPER_API ISectionTimer * queryNullSectionTimer();
+
 #endif // ROXIEHELPER_HPP

common/thorhelper/thorcommon.hpp

@@ -569,6 +569,10 @@ public:
     {
         return ctx->updateWorkUnit();
     }
+    virtual ISectionTimer * registerTimer(unsigned activityId, const char * name)
+    {
+        return ctx->registerTimer(activityId, name);
+    }
 protected:
     ICodeContext * ctx;
 };

common/thorhelper/thorstats.cpp

@@ -0,0 +1,51 @@
+/*##############################################################################
+
+    HPCC SYSTEMS software Copyright (C) 2016 HPCC Systems®.
+
+    Licensed under the Apache License, Version 2.0 (the "License");
+    you may not use this file except in compliance with the License.
+    You may obtain a copy of the License at
+
+       http://www.apache.org/licenses/LICENSE-2.0
+
+    Unless required by applicable law or agreed to in writing, software
+    distributed under the License is distributed on an "AS IS" BASIS,
+    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+    See the License for the specific language governing permissions and
+    limitations under the License.
+############################################################################## */
+
+#include "platform.h"
+#include "jstats.h"
+#include "thorstats.hpp"
+#include "jdebug.hpp"
+
+
+//Cycles are accumulated locally, time is updated once it is serialized or persisted
+const StatisticsMapping nestedSectionStatistics(StCycleLocalExecuteCycles, StTimeLocalExecute, StNumExecutions, StKindNone);
+
+ThorSectionTimer::ThorSectionTimer(const char * _name, CRuntimeStatistic & _occurences, CRuntimeStatistic & _elapsed)
+: occurences(_occurences), elapsed(_elapsed), name(_name)
+{
+}
+
+ThorSectionTimer * ThorSectionTimer::createTimer(CRuntimeStatisticCollection & stats, const char * name)
+{
+    StatsScopeId scope(SSTfunction, name);
+    CRuntimeStatisticCollection & nested = stats.registerNested(scope, nestedSectionStatistics);
+    CRuntimeStatistic & occurences = nested.queryStatistic(StNumExecutions);
+    CRuntimeStatistic & elapsed = nested.queryStatistic(StCycleLocalExecuteCycles);
+    return new ThorSectionTimer(name, occurences, elapsed);
+}
+
+unsigned __int64 ThorSectionTimer::getStartCycles()
+{
+    return get_cycles_now();
+}
+
+void ThorSectionTimer::noteSectionTime(unsigned __int64 startCycles)
+{
+    cycle_t delay = get_cycles_now() - startCycles;
+    elapsed.addAtomic(delay);
+    occurences.addAtomic(1);
+}

common/thorhelper/thorstats.hpp

@@ -0,0 +1,48 @@
+/*##############################################################################
+
+    HPCC SYSTEMS software Copyright (C) 2016 HPCC Systems®.
+
+    Licensed under the Apache License, Version 2.0 (the "License");
+    you may not use this file except in compliance with the License.
+    You may obtain a copy of the License at
+
+       http://www.apache.org/licenses/LICENSE-2.0
+
+    Unless required by applicable law or agreed to in writing, software
+    distributed under the License is distributed on an "AS IS" BASIS,
+    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+    See the License for the specific language governing permissions and
+    limitations under the License.
+############################################################################## */
+
+
+
+#ifndef THORSTATS_HPP
+#define THORSTATS_HPP
+
+#include "eclhelper.hpp"
+#include "jstats.h"
+
+class ThorSectionTimer : public CSimpleInterfaceOf<ISectionTimer>
+{
+public:
+    static ThorSectionTimer * createTimer(CRuntimeStatisticCollection & _stats, const char * _name);
+
+    bool matches(const char * _name) const
+    {
+        return strsame(name, _name);
+    }
+
+    virtual unsigned __int64 getStartCycles();
+    virtual void noteSectionTime(unsigned __int64 startCycles);
+
+protected:
+    ThorSectionTimer(const char * _name, CRuntimeStatistic & _occurences, CRuntimeStatistic & _elapsed);
+
+private:
+    CRuntimeStatistic & occurences;
+    CRuntimeStatistic & elapsed;
+    StringAttr name;
+};
+
+#endif

common/workunit/workunit.cpp

@@ -285,6 +285,9 @@ protected:
                 tag = "node";
                 id += strlen(SubGraphScopePrefix);
                 break;
+            case SSTfunction:
+                //MORE:Should function scopes be included in the graph scope somehow, and if so how?
+                continue;
             default:
                 throwUnexpected();
             }

ecl/eclagent/eclagent.ipp

@@ -509,6 +509,10 @@ public:
 
     unsigned __int64 queryStopAfter() { return stopAfter; }
 
+    virtual ISectionTimer * registerTimer(unsigned activityId, const char * name)
+    {
+        return queryNullSectionTimer();
+    }
 
 //New workflow interface
     virtual void setWorkflowCondition(bool value) { if(workflow) workflow->setCondition(value); }

ecl/hql/hqlatoms.cpp

@@ -418,6 +418,7 @@ IAtom * terminateAtom;
 IAtom * terminatorAtom;
 IAtom * thorAtom;
 IAtom * thresholdAtom;
+IAtom * timeAtom;
 IAtom * timeoutAtom;
 IAtom * timeLimitAtom;
 IAtom * timestampAtom;
@@ -863,6 +864,7 @@ MODULE_INIT(INIT_PRIORITY_HQLATOM)
     MAKEATOM(escape);
     MAKEATOM(thor);
     MAKEATOM(threshold);
+    MAKEATOM(time);
     MAKEATOM(timeout);
     MAKEATOM(timeLimit);
     MAKEATOM(timestamp);

ecl/hql/hqlatoms.hpp

@@ -423,6 +423,7 @@ extern HQL_API IAtom * terminatorAtom;
 extern HQL_API IAtom * escapeAtom;
 extern HQL_API IAtom * thorAtom;
 extern HQL_API IAtom * thresholdAtom;
+extern HQL_API IAtom * timeAtom;
 extern HQL_API IAtom * timeoutAtom;
 extern HQL_API IAtom * timeLimitAtom;
 extern HQL_API IAtom * timestampAtom;

ecl/hql/hqlgram2.cpp

@@ -3774,7 +3774,7 @@ IHqlExpression* HqlGram::checkServiceDef(IHqlScope* serviceScope,IIdAtom * name,
                 cppApi = true;
                 checkSvcAttrNoValue(attr, errpos);
             }
-            else if (name == pureAtom || name == templateAtom || name == volatileAtom || name == onceAtom || name == actionAtom)
+            else if (name == pureAtom || name == templateAtom || name == volatileAtom || name == onceAtom || name == actionAtom || name == timeAtom)
             {
                 checkSvcAttrNoValue(attr, errpos);
             }

ecl/hqlcpp/hqlcatom.cpp

@@ -379,6 +379,7 @@ IIdAtom * getResultUnicodeId;
 IIdAtom * getResultVarStringId;
 IIdAtom * getResultVarUnicodeId;
 IIdAtom * getRootResultId;
+IIdAtom * getStartCyclesId;
 IIdAtom * getWorkflowIdId;
 IIdAtom * getWuidId;
 IIdAtom * groupedDataset2RowsetXId;
@@ -461,6 +462,7 @@ IIdAtom * newSelectNArgId;
 IIdAtom * newSplitArgId;
 IIdAtom * newWorkUnitReadArgId;
 IIdAtom * newWorkUnitWriteArgId;
+IIdAtom * noteSectionTimeId;
 IIdAtom * offsetProviderId;
 IIdAtom * outputXmlBeginNestedId;
 IIdAtom * outputXmlBeginArrayId;
@@ -531,6 +533,7 @@ IIdAtom * regexNewUStrReplaceXId;
 IIdAtom * regexMatchSetId;
 IIdAtom * regexUStrMatchSetId;
 IIdAtom * regexReplaceXId;
+IIdAtom * registerTimerId;
 IIdAtom * releaseRowId;
 IIdAtom * releaseRowsetId;
 IIdAtom * reportFieldOverflowId;
@@ -1032,6 +1035,7 @@ MODULE_INIT(INIT_PRIORITY_HQLATOM-1)
     MAKEID(getResultVarString);
     MAKEID(getResultVarUnicode);
     MAKEID(getRootResult);
+    MAKEID(getStartCycles);
     MAKEID(getWorkflowId);
     MAKEID(getWuid);
     MAKEID(groupedDataset2RowsetX);
@@ -1113,6 +1117,7 @@ MODULE_INIT(INIT_PRIORITY_HQLATOM-1)
     MAKEID(newSplitArg);
     MAKEID(newWorkUnitReadArg);
     MAKEID(newWorkUnitWriteArg);
+    MAKEID(noteSectionTime);
     MAKEID(offsetProvider);
     MAKEID(outputXmlBeginArray);
     MAKEID(outputXmlBeginNested);
@@ -1197,6 +1202,7 @@ MODULE_INIT(INIT_PRIORITY_HQLATOM-1)
     MAKEID(regexMatchSet);
     MAKEID(regexUStrMatchSet);
     MAKEID(regexReplaceX);
+    MAKEID(registerTimer);
     MAKEID(releaseRow);
     MAKEID(releaseRowset);
     MAKEID(reportFieldOverflow);

ecl/hqlcpp/hqlcatom.hpp

@@ -379,6 +379,7 @@ extern IIdAtom * getResultUnicodeId;
 extern IIdAtom * getResultVarStringId;
 extern IIdAtom * getResultVarUnicodeId;
 extern IIdAtom * getRootResultId;
+extern IIdAtom * getStartCyclesId;
 extern IIdAtom * getWorkflowIdId;
 extern IIdAtom * getWuidId;
 extern IIdAtom * groupedDataset2RowsetXId;
@@ -461,6 +462,7 @@ extern IIdAtom * newSelectNArgId;
 extern IIdAtom * newSplitArgId;
 extern IIdAtom * newWorkUnitReadArgId;
 extern IIdAtom * newWorkUnitWriteArgId;
+extern IIdAtom * noteSectionTimeId;
 extern IIdAtom * offsetProviderId;
 extern IIdAtom * outputXmlBeginArrayId;
 extern IIdAtom * outputXmlBeginNestedId;
@@ -531,6 +533,7 @@ extern IIdAtom * regexNewUStrReplaceXId;
 extern IIdAtom * regexMatchSetId;
 extern IIdAtom * regexUStrMatchSetId;
 extern IIdAtom * regexReplaceXId;
+extern IIdAtom * registerTimerId;
 extern IIdAtom * releaseRowId;
 extern IIdAtom * releaseRowsetId;
 extern IIdAtom * reportFieldOverflowId;

ecl/hqlcpp/hqlcpp.cpp

@@ -6179,6 +6179,10 @@ void HqlCppTranslator::doBuildCall(BuildCtx & ctx, const CHqlBoundTarget * tgt,
 
     OwnedHqlExpr call = bindTranslatedFunctionCall(funcdef, args);
 
+    CHqlBoundExpr boundTimer, boundStart;
+    if (external->hasAttribute(timeAtom))
+        buildStartTimer(ctx, boundTimer, boundStart, str(external->queryId()));
+
     //either copy the integral value across, or a var string to fixed string
     if (returnMustAssign)
     {
@@ -6217,6 +6221,9 @@ void HqlCppTranslator::doBuildCall(BuildCtx & ctx, const CHqlBoundTarget * tgt,
     if (resultRow)
         finalizeTempRow(ctx, resultRow, resultRowBuilder);
 
+    if (external->hasAttribute(timeAtom))
+        buildStopTimer(ctx, boundTimer, boundStart);
+
     if (returnByReference)
         ctx.associateExpr(expr, localBound);
 }

ecl/hqlcpp/hqlcpp.ipp

@@ -1571,6 +1571,9 @@ public:
     IHqlExpression * getFirstCharacter(IHqlExpression * source);
     bool hasAddress(BuildCtx & ctx, IHqlExpression * expr);
 
+    void buildStartTimer(BuildCtx & ctx, CHqlBoundExpr & boundTimer, CHqlBoundExpr & boundStart, const char * name);
+    void buildStopTimer(BuildCtx & ctx, const CHqlBoundExpr & boundTimer, const CHqlBoundExpr & boundStart);
+
     IHqlExpression * convertOrToAnd(IHqlExpression * expr);
     bool childrenRequireTemp(BuildCtx & ctx, IHqlExpression * expr, bool includeChildren);
     bool requiresTemp(BuildCtx & ctx, IHqlExpression * expr, bool includeChildren);

ecl/hqlcpp/hqlcppsys.ecl

@@ -886,6 +886,9 @@ const char * cppSystemText[]  = {
     "   compileEmbeddedScript(const utf8 script) : method,entrypoint='compileEmbeddedScript';",
     "   utf8 substituteEmbeddedScript(const utf8 script, const utf8 fields, const utf8 substitute) : eclrtl,include,pure,entrypoint='rtlSubstituteEmbeddedScript';",
     "   import(const utf8 script) : method,entrypoint='importFunction';",
+    "   varstring registerTimer(unsigned4 id, const varstring name) : ctxmethod;",
+    "   unsigned8 getStartCycles() : method;",
+    "   noteSectionTime(unsigned8 started) : method;",
     "   END;",
     NULL };
 

ecl/hqlcpp/hqlhtcpp.cpp

@@ -17841,6 +17841,44 @@ void HqlCppTranslator::doBuildExprRegexFindSet(BuildCtx & ctx, IHqlExpression *
 }
 
 //---------------------------------------------------------------------------
+
+void HqlCppTranslator::buildStartTimer(BuildCtx & ctx, CHqlBoundExpr & boundTimer, CHqlBoundExpr & boundStart, const char * name)
+{
+    BuildCtx * initCtx = &ctx;
+    BuildCtx * declareCtx = &ctx;
+    getInvariantMemberContext(ctx, &declareCtx, &initCtx, true, false);
+
+    Owned<ITypeInfo> timerType = makePointerType(makeClassType("ISectionTimer"));
+    OwnedHqlExpr timer = declareCtx->getTempDeclare(timerType, NULL);
+    boundTimer.expr.set(timer);
+
+    unsigned activityId = 0;
+    ActivityInstance * activity = queryCurrentActivity(ctx);
+    if (activity)
+        activityId = activity->activityId;
+
+    HqlExprArray registerArgs;
+    registerArgs.append(*getSizetConstant(activityId));
+    registerArgs.append(*createConstant(name));
+    OwnedHqlExpr call = bindFunctionCall(registerTimerId, registerArgs);
+    initCtx->addAssign(timer, call);
+
+    HqlExprArray nowArgs;
+    nowArgs.append(*boundTimer.getTranslatedExpr());
+    OwnedHqlExpr now = bindFunctionCall(getStartCyclesId, nowArgs);
+    buildTempExpr(ctx, now, boundStart);
+}
+
+void HqlCppTranslator::buildStopTimer(BuildCtx & ctx, const CHqlBoundExpr & boundTimer, const CHqlBoundExpr & boundStart)
+{
+    HqlExprArray nowArgs;
+    nowArgs.append(*boundTimer.getTranslatedExpr());
+    nowArgs.append(*boundStart.getTranslatedExpr());
+    OwnedHqlExpr done = bindFunctionCall(noteSectionTimeId, nowArgs);
+    buildStmt(ctx, done);
+}
+
+//---------------------------------------------------------------------------
 //-- no_null [DATASET] --
 
 ABoundActivity * HqlCppTranslator::doBuildActivityNull(BuildCtx & ctx, IHqlExpression * expr, bool isRoot)

roxie/ccd/ccdactivities.cpp

@@ -541,6 +541,11 @@ public:
     virtual unsigned getResultHash(const char * name, unsigned sequence) { throwUnexpected(); }
     virtual unsigned getExternalResultHash(const char * wuid, const char * name, unsigned sequence) { throwUnexpected(); }
 
+    virtual ISectionTimer * registerTimer(unsigned activityId, const char * name)
+    {
+        return queryNullSectionTimer();
+    }
+
     // Not yet thought about these....
 
     virtual char *getWuid() { throwUnexpected(); } // caller frees return string.

roxie/ccd/ccdcontext.cpp

@@ -23,6 +23,7 @@
 #include "rtlread_imp.hpp"
 #include "thorplugin.hpp"
 #include "thorxmlread.hpp"
+#include "thorstats.hpp"
 #include "roxiemem.hpp"
 #include "eventqueue.hpp"
 
@@ -1125,6 +1126,7 @@ public:
 
 //---------------------------------------------------------------------------------------
 
+static const StatisticsMapping graphStatistics(StKindNone);
 class CRoxieContextBase : public CInterface, implements IRoxieSlaveContext, implements ICodeContext, implements roxiemem::ITimeLimiter, implements IRowAllocatorMetaActIdCacheCallback
 {
 protected:
@@ -1207,7 +1209,7 @@ protected:
 public:
     IMPLEMENT_IINTERFACE;
     CRoxieContextBase(const IQueryFactory *_factory, const IRoxieContextLogger &_logctx)
-        : factory(_factory), logctx(_logctx), options(factory->queryOptions())
+        : factory(_factory), logctx(_logctx), options(factory->queryOptions()), globalStats(graphStatistics)
     {
         startTime = lastWuAbortCheck = msTick();
         persists = NULL;
@@ -1469,8 +1471,7 @@ public:
             }
             graph.clear();
             childGraphs.kill();
-            if (graphStats)
-                graphStats.clear();
+            graphStats.clear();
             if (error)
                 throw error;
         }
@@ -1972,6 +1973,10 @@ public:
         useContext(sequence).getProp(name, x);
         return rtlVCodepageToVUnicodeX(x.str(), "utf-8");
     }
+    virtual ISectionTimer * registerTimer(unsigned activityId, const char * name)
+    {
+        return queryNullSectionTimer();
+    }
 
 protected:
     mutable CriticalSection contextCrit;
@@ -1981,6 +1986,8 @@ protected:
     IPropertyTree *rereadResults;
     PTreeReaderOptions xmlStoredDatasetReadFlags;
     CDeserializedResultStore *deserializedResultStore;
+    MapStringToMyClass<ThorSectionTimer> functionTimers;
+    CRuntimeStatisticCollection globalStats;
 
     IPropertyTree &useContext(unsigned sequence)
     {
@@ -2600,6 +2607,14 @@ protected:
 
     void doPostProcess()
     {
+        if (workUnit)
+        {
+            WorkunitUpdate w(&workUnit->lock());
+            Owned<IStatisticGatherer> builder = createGlobalStatisticGatherer(w);
+            globalStats.recordStatistics(*builder);
+        }
+        logctx.mergeStats(globalStats);
+        globalStats.reset();
         if (!protocol)
             return;
 
@@ -3535,6 +3550,26 @@ public:
         return NULL; // TBD - Richard, where do user credentials for a roxie query come from
     }
 
+    virtual ISectionTimer * registerTimer(unsigned activityId, const char * name)
+    {
+        if (activityId)
+        {
+            IRoxieServerActivity *act = graph->queryActivity(activityId);
+            if (act)
+                return act->registerTimer(activityId, name);
+        }
+
+        CriticalBlock b(contextCrit);
+        ISectionTimer *timer = functionTimers.getValue(name);
+        if (!timer)
+        {
+            timer = ThorSectionTimer::createTimer(globalStats, name);
+            functionTimers.setValue(name, timer);
+            timer->Release(); // Value returned is not linked
+        }
+        return timer;
+    }
+
     virtual bool isResult(const char * name, unsigned sequence)
     {
         CriticalBlock b(contextCrit);

roxie/ccd/ccdquery.hpp

@@ -67,6 +67,7 @@ interface IActivityGraph : extends IInterface
     virtual IRoxieServerChildGraph * queryLoopGraph() = 0;
     virtual IRoxieServerChildGraph * createGraphLoopInstance(IRoxieSlaveContext *ctx, unsigned loopCounter, unsigned parentExtractSize, const byte * parentExtract, const IRoxieContextLogger &logctx) = 0;
     virtual const char *queryName() const = 0;
+    virtual IRoxieServerActivity *queryActivity(unsigned _activityId) = 0;
 };
 
 interface IRoxiePackage;

roxie/ccd/ccdserver.cpp

@@ -29,6 +29,7 @@
 #include "thorsoapcall.hpp"
 #include "thorcommon.ipp"
 #include "thorsort.hpp"
+#include "thorstats.hpp"
 #include "jlzw.hpp"
 #include "javahash.hpp"
 #include "javahash.tpp"
@@ -929,6 +930,7 @@ protected:
     CriticalSection statscrit;
 
     mutable CRuntimeStatisticCollection stats;
+    MapStringToMyClass<ThorSectionTimer> functionTimers;
     unsigned processed;
     ActivityTimeAccumulator totalCycles;
     cycle_t localCycles;
@@ -1032,6 +1034,31 @@ public:
     {
         stats.deserializeMerge(buf);
     }
+    virtual ISectionTimer *registerTimer(unsigned activityId, const char * name)
+    {
+        CriticalBlock b(statscrit); // reuse statscrit to protect functionTimers - it will not be held concurrently
+        ISectionTimer *timer = functionTimers.getValue(name);
+        if (!timer)
+        {
+            timer = ThorSectionTimer::createTimer(stats, name);
+            functionTimers.setValue(name, timer);
+            timer->Release(); // Value returned is not linked
+        }
+        return timer;
+    }
+    virtual IRoxieServerActivity * queryChildActivity(unsigned activityId)
+    {
+        ForEachItemIn(i, childGraphs)
+        {
+            IRoxieServerActivity * activity = childGraphs.item(i).queryActivity(activityId);
+            if (activity)
+                return activity;
+        }
+#ifdef _DEBUG
+        throwUnexpectedX("Unable to map child activity id to an activity");
+#endif
+        return nullptr;
+    }
     void mergeStrandStats(unsigned strandProcessed, const ActivityTimeAccumulator & strandCycles, const CRuntimeStatisticCollection & strandStats)
     {
         CriticalBlock cb(statscrit);
@@ -26705,6 +26732,18 @@ public:
         return graphName.get();
     }
 
+    virtual IRoxieServerActivity *queryActivity(unsigned _activityId)
+    {
+        unsigned idx = graphDefinition.recursiveFindActivityIndex(_activityId);
+        if (idx==NotFound)
+            return nullptr;
+        assertex(activities.isItem(idx));
+        IRoxieServerActivity *activity = &activities.item(idx);
+        if (activity->queryId() == _activityId)
+            return activity;
+        return activity->queryChildActivity(_activityId);
+    }
+
     void createGraph(IRoxieSlaveContext *_ctx)
     {
         if (graphDefinition.isMultiInstance())
@@ -27087,6 +27126,7 @@ public:
     virtual IRoxieServerChildGraph * queryLoopGraph() { throwUnexpected(); }
     virtual IRoxieServerChildGraph * createGraphLoopInstance(IRoxieSlaveContext *ctx, unsigned loopCounter, unsigned parentExtractSize, const byte * parentExtract, const IRoxieContextLogger &logctx) { throwUnexpected(); }
     virtual const char *queryName() const { throwUnexpected(); }
+    virtual IRoxieServerActivity *queryActivity(unsigned _activityId) { return nullptr; } // MORE - may need something here!?
 
     virtual IEclGraphResults * evaluate(unsigned parentExtractSize, const byte * parentExtract)
     {
@@ -27309,6 +27349,7 @@ public:
     virtual IThorChildGraph * queryChildGraph() { throwUnexpected(); }
     virtual IEclGraphResults * queryLocalGraph() { throwUnexpected(); }
     virtual IRoxieServerChildGraph * queryLoopGraph() { throwUnexpected(); }
+    virtual IRoxieServerActivity *queryActivity(unsigned _activityId) { return nullptr; } // MORE - may need something here!?
 
     virtual void onCreate(IHThorArg *_colocalParent)
     { 

roxie/ccd/ccdserver.hpp

@@ -181,6 +181,8 @@ interface IRoxieServerActivity : extends IActivityBase
     virtual ThorActivityKind getKind() const = 0;
     virtual const IRoxieContextLogger &queryLogCtx() const = 0;
     virtual void mergeStats(MemoryBuffer &stats) = 0;
+    virtual ISectionTimer * registerTimer(unsigned activityId, const char * name) = 0;
+    virtual IRoxieServerActivity * queryChildActivity(unsigned activityId) = 0;
 };
 
 interface IRoxieServerActivityFactory : extends IActivityFactory

rtl/include/eclhelper.hpp

@@ -536,6 +536,12 @@ interface IThorChildGraph : public IInterface
     virtual IEclGraphResults * evaluate(unsigned parentExtractSize, const byte * parentExtract) = 0;
 };
 
+interface ISectionTimer : public IInterface
+{
+    virtual unsigned __int64 getStartCycles() = 0;
+    virtual void noteSectionTime(unsigned __int64 startCycles) = 0;
+};
+
 //NB: New methods must always be added at the end of this interface to retain backward compatibility
 interface IContextLogger;
 interface IDebuggableContext;
@@ -647,6 +653,7 @@ interface ICodeContext : public IResourceContext
     virtual const void * fromJson(IEngineRowAllocator * _rowAllocator, size32_t len, const char * utf8, IXmlToRowTransformer * xmlTransformer, bool stripWhitespace) = 0;
     virtual void getRowJSON(size32_t & lenResult, char * & result, IOutputMetaData & info, const void * row, unsigned flags) = 0;
     virtual unsigned getExternalResultHash(const char * wuid, const char * name, unsigned sequence) = 0;
+    virtual ISectionTimer * registerTimer(unsigned activityId, const char * name) = 0;
 };
 
 

system/jlib/jstatcodes.h

@@ -23,6 +23,8 @@
 #define EdgeScopePrefix "e"
 #define SubGraphScopePrefix "sg"
 #define GraphScopePrefix "graph"
+#define FunctionScopePrefix "f"
+
 #define CONST_STRLEN(x) (sizeof(x)-1)       // sizeof(const-string) = strlen(const-string) + 1 byte for the \0 terminator
 #define MATCHES_CONST_PREFIX(search, prefix) (strncmp(search, prefix, CONST_STRLEN(prefix)) == 0)
 
@@ -63,6 +65,7 @@ enum StatisticScopeType
     SSTcompilestage,                    // a stage within the compilation process
     SSTdfuworkunit,                     // a reference to an executing dfu workunit
     SSTedge,
+    SSTfunction,                        // a function call
     SSTmax
 };
 
@@ -103,7 +106,6 @@ enum StatisticKind
 {
     StKindNone,
     StKindAll,
-
     StWhenGraphStarted,                 // When a graph starts
     StWhenGraphFinished,                // When a graph stopped
     StWhenFirstRow,                     // When the first row is processed by slave activity
@@ -112,16 +114,13 @@ enum StatisticKind
     StWhenCreated,
     StWhenCompiled,
     StWhenWorkunitModified,             // Not sure this is very useful
-
     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,
-
     StSizeGeneratedCpp,
     StSizePeakMemory,
     StSizeMaxRowSize,
-
     StNumRowsProcessed,                 // on edge
     StNumSlaves,                        // on edge
     StNumStarted,                       // on edge
@@ -175,9 +174,11 @@ enum StatisticKind
     StSizeSpillFile,
     StCycleSpillElapsedCycles,
     StCycleSortElapsedCycles,
-
-    // Stranding stats - on edge
-    StNumStrands,
+    StNumStrands,                       // Stranding stats - on edge
+    StCycleTotalExecuteCycles,
+    StNumExecutions,
+    StTimeTotalNested,
+    StCycleLocalExecuteCycles,
 
     StMax,
 

system/jlib/jstats.cpp

@@ -31,6 +31,7 @@
 static CriticalSection statsNameCs;
 static StringBuffer statisticsComponentName;
 static StatisticCreatorType statisticsComponentType = SCTunknown;
+const static unsigned currentStatisticsVersion = 1;
 
 StatisticCreatorType queryStatisticsComponentType()
 {
@@ -65,7 +66,7 @@ void setStatisticsComponentName(StatisticCreatorType processType, const char * p
 // Textual forms of the different enumerations, first items are for none and all.
 static const char * const measureNames[] = { "", "all", "ns", "ts", "cnt", "sz", "cpu", "skw", "node", "ppm", "ip", "cy", NULL };
 static const char * const creatorTypeNames[]= { "", "all", "unknown", "hthor", "roxie", "roxie:s", "thor", "thor:m", "thor:s", "eclcc", "esp", "summary", NULL };
-static const char * const scopeTypeNames[] = { "", "all", "global", "graph", "subgraph", "activity", "allocator", "section", "compile", "dfu", "edge", NULL };
+static const char * const scopeTypeNames[] = { "", "all", "global", "graph", "subgraph", "activity", "allocator", "section", "compile", "dfu", "edge", "function", NULL };
 
 static unsigned matchString(const char * const * names, const char * search)
 {
@@ -481,14 +482,14 @@ extern jlib_decl StatsMergeAction queryMergeMode(StatisticKind kind)
     BASE_TAGS(x, y) \
     "@TimeDelta" # y
 
-#define CORESTAT(x, y, m)     St##x##y, m, { NAMES(x, y) }, { TAGS(x, y) }
+#define CORESTAT(x, y, m)     St##x##y, m, St##x##y, { NAMES(x, y) }, { TAGS(x, y) }
 #define STAT(x, y, m)         CORESTAT(x, y, m)
 
 //--------------------------------------------------------------------------------------------------------------------
 
 //These are the macros to use to define the different entries in the stats meta table
 #define TIMESTAT(y) STAT(Time, y, SMeasureTimeNs)
-#define WHENSTAT(y) St##When##y, SMeasureTimestampUs, { TIMENAMES(When, y) }, { TIMETAGS(When, y) }
+#define WHENSTAT(y) St##When##y, SMeasureTimestampUs, St##When##y, { TIMENAMES(When, y) }, { TIMETAGS(When, y) }
 #define NUMSTAT(y) STAT(Num, y, SMeasureCount)
 #define SIZESTAT(y) STAT(Size, y, SMeasureSize)
 #define LOADSTAT(y) STAT(Load, y, SMeasureLoad)
@@ -496,7 +497,7 @@ extern jlib_decl StatsMergeAction queryMergeMode(StatisticKind kind)
 #define NODESTAT(y) STAT(Node, y, SMeasureNode)
 #define PERSTAT(y) STAT(Per, y, SMeasurePercent)
 #define IPV4STAT(y) STAT(IPV4, y, SMeasureIPV4)
-#define CYCLESTAT(y) STAT(Cycle, y, SMeasureCycle)
+#define CYCLESTAT(y) St##Cycle##y##Cycles, SMeasureCycle, St##Time##y, { NAMES(Cycle, y##Cycles) }, { TAGS(Cycle, y##Cycles) }
 
 //--------------------------------------------------------------------------------------------------------------------
 
@@ -505,14 +506,15 @@ class StatisticMeta
 public:
     StatisticKind kind;
     StatisticMeasure measure;
+    StatisticKind serializeKind;
     const char * names[StNextModifier/StVariantScale];
     const char * tags[StNextModifier/StVariantScale];
 };
 
 //The order of entries in this table must match the order in the enumeration
 static const StatisticMeta statsMetaData[StMax] = {
-    { StKindNone, SMeasureNone, { "none" }, { "@none" } },
-    { StKindAll, SMeasureAll, { "all" }, { "@all" } },
+    { StKindNone, SMeasureNone, StKindNone, { "none" }, { "@none" } },
+    { StKindAll, SMeasureAll, StKindAll, { "all" }, { "@all" } },
     { WHENSTAT(GraphStarted) },
     { WHENSTAT(GraphFinished) },
     { WHENSTAT(FirstRow) },
@@ -569,8 +571,8 @@ static const StatisticMeta statsMetaData[StMax] = {
     { TIMESTAT(DiskWriteIO) },
     { SIZESTAT(DiskRead) },
     { SIZESTAT(DiskWrite) },
-    { CYCLESTAT(DiskReadIOCycles) },
-    { CYCLESTAT(DiskWriteIOCycles) },
+    { CYCLESTAT(DiskReadIO) },
+    { CYCLESTAT(DiskWriteIO) },
     { NUMSTAT(DiskReads) },
     { NUMSTAT(DiskWrites) },
     { NUMSTAT(Spills) },
@@ -579,9 +581,13 @@ static const StatisticMeta statsMetaData[StMax] = {
     { NUMSTAT(Groups) },
     { NUMSTAT(GroupMax) },
     { SIZESTAT(SpillFile) },
-    { CYCLESTAT(SpillElapsedCycles) },
-    { CYCLESTAT(SortElapsedCycles) },
+    { CYCLESTAT(SpillElapsed) },
+    { CYCLESTAT(SortElapsed) },
     { NUMSTAT(Strands) },
+    { CYCLESTAT(TotalExecute) },
+    { NUMSTAT(Executions) },
+    { TIMESTAT(TotalNested) },
+    { CYCLESTAT(LocalExecute) },
 };
 
 
@@ -647,6 +653,15 @@ unsigned __int64 convertMeasure(StatisticKind from, StatisticKind to, unsigned _
 }
 
 
+StatisticKind querySerializedKind(StatisticKind kind)
+{
+    StatisticKind rawkind = (StatisticKind)(kind & StKindMask);
+    if (rawkind >= StMax)
+        return kind;
+    StatisticKind serialKind = statsMetaData[rawkind].serializeKind;
+    return (StatisticKind)(serialKind | (kind & ~StKindMask));
+}
+
 //--------------------------------------------------------------------------------------------------------------------
 
 void queryLongStatisticName(StringBuffer & out, StatisticKind kind)
@@ -790,17 +805,20 @@ static int compareUnsigned(unsigned const * left, unsigned const * right)
 
 StatisticsMapping::StatisticsMapping(StatisticKind kind, ...)
 {
-    indexToKind.append(kind);
-    va_list args;
-    va_start(args, kind);
-    for (;;)
+    if (kind != StKindNone)
     {
-        unsigned next  = va_arg(args, unsigned);
-        if (!next)
-            break;
-        indexToKind.appendUniq(next);
+        indexToKind.append(kind);
+        va_list args;
+        va_start(args, kind);
+        for (;;)
+        {
+            unsigned next  = va_arg(args, unsigned);
+            if (!next)
+                break;
+            indexToKind.appendUniq(next);
+        }
+        va_end(args);
     }
-    va_end(args);
     createMappings();
 }
 
@@ -885,7 +903,10 @@ public:
         out.append((unsigned)kind);
         out.append(value);
     }
-
+    StringBuffer & toXML(StringBuffer &out) const
+    {
+        return out.append("  <Stat name=\"").append(queryStatisticName(kind)).append("\" value=\"").append(value).append("\"/>\n");
+    }
 public:
     StatisticKind kind;
     unsigned __int64 value;
@@ -905,19 +926,28 @@ StringBuffer & StatsScopeId::getScopeText(StringBuffer & out) const
         return out.append(ActivityScopePrefix).append(id);
     case SSTedge:
         return out.append(EdgeScopePrefix).append(id).append("_").append(extra);
+    case SSTfunction:
+        return out.append(FunctionScopePrefix).append(name);
     default:
         throwUnexpected();
+        break;
     }
 }
 
 unsigned StatsScopeId::getHash() const
 {
-    return hashc((const byte *)&id, sizeof(id), (unsigned)scopeType);
+    switch (scopeType)
+    {
+    case SSTfunction:
+        return hashc((const byte *)name.get(), strlen(name), (unsigned)scopeType);
+    default:
+        return hashc((const byte *)&id, sizeof(id), (unsigned)scopeType);
+    }
 }
 
 bool StatsScopeId::matches(const StatsScopeId & other) const
 {
-    return (scopeType == other.scopeType) && (id == other.id) && (extra == other.extra);
+    return (scopeType == other.scopeType) && (id == other.id) && (extra == other.extra) && strsame(name, other.name);
 }
 
 unsigned StatsScopeId::queryActivity() const
@@ -948,8 +978,12 @@ void StatsScopeId::deserialize(MemoryBuffer & in, unsigned version)
         in.read(id);
         in.read(extra);
         break;
+    case SSTfunction:
+        in.read(name);
+        break;
     default:
         throwUnexpected();
+        break;
     }
 }
 
@@ -967,8 +1001,12 @@ void StatsScopeId::serialize(MemoryBuffer & out) const
         out.append(id);
         out.append(extra);
         break;
+    case SSTfunction:
+        out.append(name);
+        break;
     default:
         throwUnexpected();
+        break;
     }
 }
 
@@ -994,6 +1032,8 @@ bool StatsScopeId::setScopeText(const char * text)
             return false;
         setEdgeId(atoi(text + CONST_STRLEN(EdgeScopePrefix)), atoi(underscore+1));
     }
+    else if (MATCHES_CONST_PREFIX(text, FunctionScopePrefix))
+        setFunctionId(text+CONST_STRLEN(FunctionScopePrefix));
     else
         return false;
 
@@ -1012,6 +1052,11 @@ void StatsScopeId::setSubgraphId(unsigned _id)
 {
     setId(SSTsubgraph, _id);
 }
+void StatsScopeId::setFunctionId(const char * _name)
+{
+    scopeType = SSTfunction;
+    name.set(_name);
+}
 
 //--------------------------------------------------------------------------------------------------------------------
 
@@ -1074,6 +1119,8 @@ public:
 
     virtual byte getCollectionType() const { return SCintermediate; }
 
+    StringBuffer &toXML(StringBuffer &out) const;
+
 //interface IStatisticCollection:
     virtual StatisticScopeType queryScopeType() const
     {
@@ -1230,6 +1277,25 @@ private:
     StatsArray stats;
 };
 
+StringBuffer &CStatisticCollection::toXML(StringBuffer &out) const
+{
+    out.append("<Scope id=\"");
+    id.getScopeText(out).append("\">\n");
+    if (stats.ordinality())
+    {
+        out.append(" <Stats>");
+        ForEachItemIn(i, stats)
+            stats.item(i).toXML(out);
+        out.append(" </Stats>\n");
+    }
+
+    SuperHashIteratorOf<CStatisticCollection> iter(children, false);
+    for (iter.first(); iter.isValid(); iter.next())
+        iter.query().toXML(out);
+    out.append("</Scope>\n");
+    return out;
+}
+
 //---------------------------------------------------------------------------------------------------------------------
 
 void CollectionHashTable::onAdd(void *et)
@@ -1310,7 +1376,6 @@ public:
 
 void serializeStatisticCollection(MemoryBuffer & out, IStatisticCollection * collection)
 {
-    unsigned currentStatisticsVersion = 1;
     out.append(currentStatisticsVersion);
     collection->serialize(out);
 }
@@ -1410,6 +1475,20 @@ void CRuntimeStatistic::merge(unsigned __int64 otherValue, StatsMergeAction merg
     value = mergeStatisticValue(value, otherValue, mergeAction);
 }
 
+//--------------------------------------------------------------------------------------------------------------------
+
+CRuntimeStatisticCollection::~CRuntimeStatisticCollection()
+{
+    delete [] values;
+    delete nested;
+}
+
+void CRuntimeStatisticCollection::ensureNested()
+{
+    if (!nested)
+        nested = new CNestedRuntimeStatisticMap;
+}
+
 void CRuntimeStatisticCollection::merge(const CRuntimeStatisticCollection & other)
 {
     ForEachItemIn(i, other)
@@ -1419,6 +1498,11 @@ void CRuntimeStatisticCollection::merge(const CRuntimeStatisticCollection & othe
         if (value)
             mergeStatistic(kind, other.getStatisticValue(kind));
     }
+    if (other.nested)
+    {
+        ensureNested();
+        nested->merge(*other.nested);
+    }
 }
 
 void CRuntimeStatisticCollection::mergeStatistic(StatisticKind kind, unsigned __int64 value)
@@ -1426,6 +1510,12 @@ void CRuntimeStatisticCollection::mergeStatistic(StatisticKind kind, unsigned __
     queryStatistic(kind).merge(value, queryMergeMode(kind));
 }
 
+CRuntimeStatisticCollection & CRuntimeStatisticCollection::registerNested(const StatsScopeId & scope, const StatisticsMapping & mapping)
+{
+    ensureNested();
+    return nested->addNested(scope, mapping);
+}
+
 void CRuntimeStatisticCollection::rollupStatistics(unsigned numTargets, IContextLogger * const * targets) const
 {
     ForEachItem(iStat)
@@ -1449,11 +1539,17 @@ void CRuntimeStatisticCollection::recordStatistics(IStatisticGatherer & target)
         if (value)
         {
             StatisticKind kind = getKind(i);
-            StatsMergeAction mergeAction = queryMergeMode(kind);
-            target.updateStatistic(kind, values[i].get(), mergeAction);
+            StatisticKind serialKind= querySerializedKind(kind);
+            if (kind != serialKind)
+                value = convertMeasure(kind, serialKind, value);
+
+            StatsMergeAction mergeAction = queryMergeMode(serialKind);
+            target.updateStatistic(serialKind, value, mergeAction);
         }
     }
     reportIgnoredStats();
+    if (nested)
+        nested->recordStatistics(target);
 }
 
 void CRuntimeStatisticCollection::reportIgnoredStats() const
@@ -1474,6 +1570,8 @@ StringBuffer & CRuntimeStatisticCollection::toXML(StringBuffer &str) const
             str.appendf("<%s>%" I64F "d</%s>", name, value, name);
         }
     }
+    if (nested)
+        nested->toXML(str);
     return str;
 }
 
@@ -1490,6 +1588,8 @@ StringBuffer & CRuntimeStatisticCollection::toStr(StringBuffer &str) const
             formatStatistic(str, value, kind);
         }
     }
+    if (nested)
+        nested->toStr(str);
     return str;
 }
 
@@ -1505,6 +1605,13 @@ void CRuntimeStatisticCollection::deserialize(MemoryBuffer& in)
         StatisticKind kind = (StatisticKind)kindVal;
         setStatistic(kind, value);
     }
+    bool hasNested;
+    in.read(hasNested);
+    if (hasNested)
+    {
+        ensureNested();
+        nested->deserializeMerge(in);
+    }
 }
 
 void CRuntimeStatisticCollection::deserializeMerge(MemoryBuffer& in)
@@ -1520,6 +1627,13 @@ void CRuntimeStatisticCollection::deserializeMerge(MemoryBuffer& in)
         StatsMergeAction mergeAction = queryMergeMode(kind);
         mergeStatistic(kind, value, mergeAction);
     }
+    bool hasNested;
+    in.read(hasNested);
+    if (hasNested)
+    {
+        ensureNested();
+        nested->deserializeMerge(in);
+    }
 }
 
 bool CRuntimeStatisticCollection::serialize(MemoryBuffer& out) const
@@ -1537,16 +1651,155 @@ bool CRuntimeStatisticCollection::serialize(MemoryBuffer& out) const
         unsigned __int64 value = values[i2].get();
         if (value)
         {
-            out.appendPacked((unsigned)mapping.getKind(i2));
+            StatisticKind kind = mapping.getKind(i2);
+            StatisticKind serialKind= querySerializedKind(kind);
+            if (kind != serialKind)
+                value = convertMeasure(kind, serialKind, value);
+
+            out.appendPacked((unsigned)serialKind);
             out.appendPacked(value);
         }
     }
-    return numValid != 0;
+
+    bool nonEmpty = (numValid != 0);
+    out.append(nested != nullptr);
+    if (nested)
+    {
+        if (nested->serialize(out))
+            nonEmpty = true;
+    }
+    return nonEmpty;
 }
 
 
 //---------------------------------------------------
 
+bool CNestedRuntimeStatisticCollection::matches(const StatsScopeId & otherScope) const
+{
+    return scope.matches(otherScope);
+}
+
+//NOTE: When deserializing, the scope is deserialized by the caller, and the correct target selected
+//which is why there is no corresponding deserialize() method
+bool CNestedRuntimeStatisticCollection::serialize(MemoryBuffer& out) const
+{
+    scope.serialize(out);
+    return CRuntimeStatisticCollection::serialize(out);
+}
+
+void CNestedRuntimeStatisticCollection::recordStatistics(IStatisticGatherer & target) const
+{
+    target.beginScope(scope);
+    CRuntimeStatisticCollection::recordStatistics(target);
+    target.endScope();
+}
+
+StringBuffer & CNestedRuntimeStatisticCollection::toStr(StringBuffer &str) const
+{
+    str.append("{Scope ");
+    scope.getScopeText(str).newline();
+    CRuntimeStatisticCollection::toStr(str);
+    return str.append("}").newline();
+}
+
+StringBuffer & CNestedRuntimeStatisticCollection::toXML(StringBuffer &str) const
+{
+    str.append("<Scope id=\"");
+    scope.getScopeText(str).append("\">");
+    CRuntimeStatisticCollection::toXML(str);
+    return str.append("</Scope>");
+}
+
+//---------------------------------------------------
+
+CRuntimeStatisticCollection & CNestedRuntimeStatisticMap::addNested(const StatsScopeId & scope, const StatisticsMapping & mapping)
+{
+    ForEachItemIn(i, map)
+    {
+        CNestedRuntimeStatisticCollection & cur = map.item(i);
+        if (cur.matches(scope))
+            return cur;
+    }
+    CNestedRuntimeStatisticCollection * stats = new CNestedRuntimeStatisticCollection(scope, mapping);
+    map.append(*stats);
+    return *stats;
+}
+
+
+void CNestedRuntimeStatisticMap::deserialize(MemoryBuffer& in)
+{
+    unsigned numItems;
+    in.readPacked(numItems);
+    for (unsigned i=0; i < numItems; i++)
+    {
+        StatsScopeId scope;
+        scope.deserialize(in, currentStatisticsVersion);
+
+        //Use allStatistics as the default mapping if it hasn't already been added.
+        CRuntimeStatisticCollection & child = addNested(scope, allStatistics);
+        child.deserialize(in);
+    }
+}
+
+void CNestedRuntimeStatisticMap::deserializeMerge(MemoryBuffer& in)
+{
+    unsigned numItems;
+    in.readPacked(numItems);
+    for (unsigned i=0; i < numItems; i++)
+    {
+        StatsScopeId scope;
+        scope.deserialize(in, currentStatisticsVersion);
+
+        //Use allStatistics as the default mapping if it hasn't already been added.
+        CRuntimeStatisticCollection & child = addNested(scope, allStatistics);
+        child.deserializeMerge(in);
+    }
+}
+
+void CNestedRuntimeStatisticMap::merge(const CNestedRuntimeStatisticMap & other)
+{
+    ForEachItemIn(i, other.map)
+    {
+        CNestedRuntimeStatisticCollection & cur = other.map.item(i);
+        CRuntimeStatisticCollection & target = addNested(cur.scope, cur.queryMapping());
+        target.merge(cur);
+    }
+}
+
+bool CNestedRuntimeStatisticMap::serialize(MemoryBuffer& out) const
+{
+    out.appendPacked(map.ordinality());
+    bool nonEmpty = false;
+    ForEachItemIn(i, map)
+    {
+        if (map.item(i).serialize(out))
+            nonEmpty = true;
+    }
+    return nonEmpty;
+}
+
+void CNestedRuntimeStatisticMap::recordStatistics(IStatisticGatherer & target) const
+{
+    ForEachItemIn(i, map)
+        map.item(i).recordStatistics(target);
+}
+
+StringBuffer & CNestedRuntimeStatisticMap::toStr(StringBuffer &str) const
+{
+    ForEachItemIn(i, map)
+        map.item(i).toStr(str);
+    return str;
+}
+
+StringBuffer & CNestedRuntimeStatisticMap::toXML(StringBuffer &str) const
+{
+    ForEachItemIn(i, map)
+        map.item(i).toXML(str);
+    return str;
+}
+
+//---------------------------------------------------
+
 bool ScopedItemFilter::matchDepth(unsigned low, unsigned high) const
 {
     if (maxDepth && low && maxDepth < low)

system/jlib/jstats.h

@@ -31,11 +31,15 @@ inline StatisticKind queryStatsVariant(StatisticKind kind) { return (StatisticKi
 class jlib_decl StatsScopeId
 {
 public:
-    StatsScopeId() : id(0), extra(0), scopeType(SSTnone) {}
+    StatsScopeId() {}
     StatsScopeId(StatisticScopeType _scopeType, unsigned _id, unsigned _extra = 0)
         : id(_id), extra(_extra), scopeType(_scopeType)
     {
     }
+    StatsScopeId(StatisticScopeType _scopeType, const char * _name)
+        : name(_name), scopeType(_scopeType)
+    {
+    }
 
     StatisticScopeType queryScopeType() const { return scopeType; }
     StringBuffer & getScopeText(StringBuffer & out) const;
@@ -51,15 +55,17 @@ public:
     void setId(StatisticScopeType _scopeType, unsigned _id, unsigned _extra = 0);
     void setActivityId(unsigned _id);
     void setEdgeId(unsigned _id, unsigned _output);
+    void setFunctionId(const char * _name);
     void setSubgraphId(unsigned _id);
 
     bool operator == (const StatsScopeId & other) const { return matches(other); }
 
 protected:
     //If any more items are added then this could become a union...
-    unsigned id;
-    unsigned extra;
-    StatisticScopeType scopeType;
+    unsigned id = 0;
+    unsigned extra = 0;
+    StringAttr name;
+    StatisticScopeType scopeType = SSTnone;
 };
 
 interface IStatisticCollectionIterator;
@@ -160,6 +166,16 @@ public:
     }
 };
 
+class StatsScope : public StatsScopeBlock
+{
+public:
+    inline StatsScope(IStatisticGatherer & _gatherer, const StatsScopeId & id) : StatsScopeBlock(_gatherer)
+    {
+        gatherer.beginScope(id);
+    }
+};
+
+
 //---------------------------------------------------------------------------------------------------------------------
 
 class ScopedItemFilter
@@ -261,36 +277,44 @@ extern const jlib_decl StatisticsMapping diskWriteRemoteStatistics;
 
 //---------------------------------------------------------------------------------------------------------------------
 
-//MORE: We probably want to have functions that perform the atomic equivalents
 class jlib_decl CRuntimeStatistic
 {
 public:
     CRuntimeStatistic() : value(0) {}
-    inline void add(unsigned __int64 delta) { value += delta; }
-    inline void addAtomic(unsigned __int64 delta) { value += delta; }
+    inline void add(unsigned __int64 delta)
+    {
+        //load and store default to relaxed - so this has no atomic synchronization
+        value.store(value.load() + delta);
+    }
+    inline void addAtomic(unsigned __int64 delta)
+    {
+        value.fetch_add(delta);
+    }
     inline unsigned __int64 get() const { return value; }
     inline unsigned __int64 getClear()
     {
         unsigned __int64 ret = value;
-        value -= ret;
+        value.store(0);
         return ret;
     }
     inline unsigned __int64 getClearAtomic()
     {
         unsigned __int64 ret = value;
-        value -= ret; // should be atomic dec...
+        value.fetch_sub(ret);
         return ret;
     }
     inline void clear() { set(0); }
     void merge(unsigned __int64 otherValue, StatsMergeAction mergeAction);
-    inline void set(unsigned __int64 delta) { value = delta; }
+    inline void set(unsigned __int64 _value) { value = _value; }
 
 protected:
-    unsigned __int64 value;
+    RelaxedAtomic<unsigned __int64> value;
 };
 
 //This class is used to gather statistics for an activity - it has no notion of scope.
 interface IContextLogger;
+class CNestedRuntimeStatisticMap;
+
 class jlib_decl CRuntimeStatisticCollection
 {
 public:
@@ -306,10 +330,7 @@ public:
         for (unsigned i=0; i <= num; i++)
             values[i].set(_other.values[i].get());
     }
-    ~CRuntimeStatisticCollection()
-    {
-        delete [] values;
-    }
+    ~CRuntimeStatisticCollection();
 
     inline CRuntimeStatistic & queryStatistic(StatisticKind kind)
     {
@@ -352,6 +373,8 @@ public:
             values[i].clear();
     }
 
+    CRuntimeStatisticCollection & registerNested(const StatsScopeId & scope, const StatisticsMapping & mapping);
+
     inline const StatisticsMapping & queryMapping() const { return mapping; };
     inline unsigned ordinality() const { return mapping.numStatistics(); }
     inline StatisticKind getKind(unsigned i) const { return mapping.getKind(i); }
@@ -371,12 +394,56 @@ public:
     bool serialize(MemoryBuffer & out) const;  // Returns true if any non-zero
     void deserialize(MemoryBuffer & in);
     void deserializeMerge(MemoryBuffer& in);
+
 protected:
+    void ensureNested();
     void reportIgnoredStats() const;
     const CRuntimeStatistic & queryUnknownStatistic() const { return values[mapping.numStatistics()]; }
+
 private:
     const StatisticsMapping & mapping;
     CRuntimeStatistic * values;
+    CNestedRuntimeStatisticMap * nested = nullptr;
+};
+
+class CNestedRuntimeStatisticCollection : public CRuntimeStatisticCollection, public CInterface
+{
+public:
+    CNestedRuntimeStatisticCollection(const StatsScopeId & _scope, const StatisticsMapping & _mapping)
+    : CRuntimeStatisticCollection(_mapping), scope(_scope)
+    {
+    }
+    CNestedRuntimeStatisticCollection(const CNestedRuntimeStatisticCollection & _other)
+    : CRuntimeStatisticCollection(_other), scope(_other.scope)
+    {
+    }
+    bool matches(const StatsScopeId & otherScope) const;
+    bool serialize(MemoryBuffer & out) const;  // Returns true if any non-zero
+    void deserialize(MemoryBuffer & in);
+    void recordStatistics(IStatisticGatherer & target) const;
+    StringBuffer & toStr(StringBuffer &str) const;
+    StringBuffer & toXML(StringBuffer &str) const;
+
+public:
+    StatsScopeId scope;
+};
+
+class CNestedRuntimeStatisticMap
+{
+public:
+    CRuntimeStatisticCollection & addNested(const StatsScopeId & scope, const StatisticsMapping & mapping);
+
+    bool serialize(MemoryBuffer & out) const;  // Returns true if any non-zero
+    void deserialize(MemoryBuffer & in);
+    void deserializeMerge(MemoryBuffer& in);
+    void merge(const CNestedRuntimeStatisticMap & other);
+    void recordStatistics(IStatisticGatherer & target) const;
+    StringBuffer & toStr(StringBuffer &str) const;
+    StringBuffer & toXML(StringBuffer &str) const;
+
+protected:
+    CIArrayOf<CNestedRuntimeStatisticCollection> map;
+
 };
 
 //---------------------------------------------------------------------------------------------------------------------

testing/regress/ecl/key/sets3.xml

@@ -8,3 +8,12 @@
  <Row><id>1</id></Row>
  <Row><id>2</id></Row>
 </Dataset>
+<Dataset name='Result 4'>
+ <Row><Result_4><Item>1</Item><Item>4</Item></Result_4></Row>
+</Dataset>
+<Dataset name='Result 5'>
+ <Row><id>1</id><children><Row><id>2</id><zips><Item>1</Item><Item>3</Item></zips></Row><Row><id>3</id><zips><Item>1</Item><Item>4</Item></zips></Row></children></Row>
+ <Row><id>2</id><children><Row><id>3</id><zips><Item>1</Item><Item>4</Item></zips></Row><Row><id>4</id><zips><Item>1</Item><Item>5</Item></zips></Row></children></Row>
+ <Row><id>3</id><children><Row><id>4</id><zips><Item>1</Item><Item>5</Item></zips></Row><Row><id>5</id><zips><Item>1</Item><Item>6</Item></zips></Row></children></Row>
+ <Row><id>4</id><children><Row><id>5</id><zips><Item>1</Item><Item>6</Item></zips></Row><Row><id>6</id><zips><Item>1</Item><Item>7</Item></zips></Row></children></Row>
+</Dataset>

testing/regress/ecl/sets3.ecl

@@ -17,7 +17,7 @@
 
 gavLib := service
     set of integer4 getPrimes() : eclrtl,pure,library='eclrtl',entrypoint='rtlTestGetPrimes',oldSetFormat;
-    set of integer4 getFibList(const set of integer4 inlist) : eclrtl,pure,library='eclrtl',entrypoint='rtlTestFibList',newset;
+    set of integer4 getFibList(const set of integer4 inlist) : eclrtl,pure,library='eclrtl',entrypoint='rtlTestFibList',newset,time;
 end;
 
 r1 := record
@@ -65,3 +65,18 @@ f3 := p3(id*2 in zips);
 
 output(f3, {id});
 
+nothor(output(gavLib.getFibList([1,3])));
+
+
+r3 := record
+    unsigned id;
+    dataset(r2) children;
+end;
+
+r3 t4(unsigned id) := transform
+    ds2 := NOFOLD(DATASET(2, transform(r1, SELF.id := id + COUNTER)));
+    SELF.id := id;
+    SELF.children := SORT(NOFOLD(PROJECT(ds2, t(LEFT))), id);
+END;
+
+output(NOFOLD(PROJECT(d, t4(LEFT.id))));

thorlcr/graph/thgraph.hpp

@@ -535,6 +535,10 @@ class graph_decl CGraphBase : public CInterface, implements IEclGraphResults, im
             return ctx->getDaliServers();
         }
         virtual IWorkUnit *updateWorkUnit() const { return ctx->updateWorkUnit(); }
+        virtual ISectionTimer * registerTimer(unsigned activityId, const char * name)
+        {
+            return ctx->registerTimer(activityId, name);
+        }
    } graphCodeContext;
 
 protected:

thorlcr/thorcodectx/thcodectx.cpp

@@ -29,6 +29,7 @@
 #include "thorxmlread.hpp"
 #include "thgraph.hpp"
 #include "thorxmlwrite.hpp"
+#include "roxiehelper.hpp"
 
 CThorCodeContextBase::CThorCodeContextBase(CJobChannel &_jobChannel, ILoadedDllEntry &_querySo, IUserDescriptor &_userDesc) : jobChannel(_jobChannel), querySo(_querySo), userDesc(&_userDesc)
 {
@@ -154,3 +155,8 @@ const void * CThorCodeContextBase::fromJson(IEngineRowAllocator * rowAllocator,
 {
     return createRowFromJson(rowAllocator, len, utf8, xmlTransformer, stripWhitespace);
 }
+
+ISectionTimer * CThorCodeContextBase::registerTimer(unsigned activityId, const char * name)
+{
+    return queryNullSectionTimer();
+}

thorlcr/thorcodectx/thcodectx.hpp

@@ -119,6 +119,7 @@ public:
     virtual IEngineContext *queryEngineContext() { return NULL; }
     virtual char *getDaliServers();
     virtual IWorkUnit *updateWorkUnit() const { throwUnexpected(); }
+    virtual ISectionTimer * registerTimer(unsigned activityId, const char * name);
 };
 
 #endif

tools/wutool/wutool.cpp

@@ -1778,7 +1778,7 @@ protected:
             virtual IEngineContext *queryEngineContext() { return NULL; }
             virtual char *getDaliServers() { throwUnexpected(); }
             virtual IWorkUnit* updateWorkUnit() const { throwUnexpected(); }
-
+            virtual ISectionTimer * registerTimer(unsigned activityId, const char * name) { throwUnexpected(); }
         } ctx;
 
         size32_t lenResult;