HPCC-12046 Reimplement the graph and other statistics

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

common/thorhelper/roxiedebug.cpp

@@ -1080,21 +1080,21 @@ BreakpointActionMode CBaseDebugContext::checkBreakpoint(DebugState state, IActiv
         return BreakpointActionContinue;
     class ActivityTimer
     {
-        unsigned __int64 startCycles;
-        unsigned __int64 &accumulator;
+        cycle_t startCycles;
+        cycle_t &accumulator;
     public:
-        inline ActivityTimer(unsigned __int64 &_accumulator) : accumulator(_accumulator)
+        inline ActivityTimer(cycle_t &_accumulator) : accumulator(_accumulator)
         {
             startCycles = get_cycles_now();
         }
         inline ~ActivityTimer()
         {
-            unsigned __int64 elapsed = get_cycles_now() - startCycles;
+            cycle_t elapsed = get_cycles_now() - startCycles;
             accumulator += elapsed;
         }
     } timer(debugCyclesAdjust);
+
     CriticalBlock b(breakCrit); // Note - this may block for a while if program is suspended!
-    
 
     assertex(running);
 

common/thorhelper/roxiedebug.hpp

@@ -253,7 +253,7 @@ protected:
     DebugState currentState; // What program was doing when it was interrupted
     unsigned debuggerActive;
     Semaphore debuggerSem;
-    unsigned __int64 debugCyclesAdjust;
+    cycle_t debugCyclesAdjust;
 
     static const char * queryStateString(DebugState state);
     bool _checkPendingBreakpoints(DebugState state, const char *graphName);

common/workunit/workunit.hpp

@@ -39,6 +39,8 @@
 #include "jstats.h"
 #include "jprop.hpp"
 
+#define GLOBAL_SCOPE "workunit"
+
 #define CHEAP_UCHAR_DEF
 #ifdef _WIN32
 typedef wchar_t UChar;
@@ -710,8 +712,6 @@ enum WUSubscribeOptions
 
 
 
-interface IWUGraphProgress;
-interface IPropertyTree;
 enum WUGraphState
 {
     WUGraphUnknown = 0,
@@ -735,20 +735,28 @@ enum WUFileKind
 
 typedef unsigned __int64 WUGraphIDType;
 typedef unsigned __int64 WUNodeIDType;
+
+interface IWUGraphProgress;
+interface IWUGraphStats;
+interface IPropertyTree;
 interface IConstWUGraphProgress : extends IInterface
 {
-    virtual IPropertyTree * queryProgressTree() = 0;
+    virtual IPropertyTree * getProgressTree() = 0;
     virtual WUGraphState queryGraphState() = 0;
     virtual WUGraphState queryNodeState(WUGraphIDType nodeId) = 0;
     virtual IWUGraphProgress * update() = 0;
+    virtual IWUGraphStats * update(StatisticCreatorType creatorType, const char * creator, unsigned subgraph) = 0;
     virtual unsigned queryFormatVersion() = 0;
 };
 
 
+interface IWUGraphStats : public IInterface
+{
+    virtual IStatisticGatherer & queryStatsBuilder() = 0;
+};
+
 interface IWUGraphProgress : extends IConstWUGraphProgress
 {
-    virtual IPropertyTree & updateEdge(WUGraphIDType nodeId, const char * edgeId) = 0;
-    virtual IPropertyTree & updateNode(WUGraphIDType nodeId, WUNodeIDType id) = 0;
     virtual void setGraphState(WUGraphState state) = 0;
     virtual void setNodeState(WUGraphIDType nodeId, WUGraphState state) = 0;
 };
@@ -781,17 +789,168 @@ interface IConstWUAppValueIterator : extends IScmIterator
     virtual IConstWUAppValue & query() = 0;
 };
 
+//More: Counts on files? optional target?
+/*
+ * Statistics are used to store timestamps, time periods, counts memory usage and any other interesting statistic
+ * which is collected as the query is built or executed.
+ *
+ * Each statistic has the following details:
+ *
+ * Creator      - Which component created the statistic.  This should be the name of the component instance i.e., "mythor_x_y" rather than the type ("thor").
+ *              - It can also be used to represent a subcomponent e.g., mythor:0 the master, mythor:10 means the 10th slave.
+ *              ?? Is the sub component always numeric ??
+ *
+ * Kind         - The specific kind of the statistic - uses a global enumeration.  (Engines can locally use different ranges of numbers and map them to the global enumeration).
+ *
+ * Measure      - What kind of statistic is it?  It can always be derived from the kind.  The following values are supported:
+ *                      time - elapsed time in nanoseconds
+ *                      timestamp/when - a point in time (?to the nanosecond?)
+ *                      count - a count of the number of occurrences
+ *                      memory/size - a quantity of memory (or disk) measured in kb
+ *                      load - measure of cpu activity (stored as 1/1000000 core)
+ *                      skew - a measure of skew. 10000 = perfectly balanced, range [0..infinity]
+ *
+ *Optional:
+ *
+ * Description  - Purely for display, calculated if not explicitly supplied.
+ * Scope        - Where in the execution of the task is statistic gathered?  It can have multiple levels (separated by colons), and statistics for
+ *                a given level can be retrieved independently.  The following scopes are supported:
+ *                "global" - the default if not specified.  Globally/within a workunit.
+ *                "wfid<n>" - within workflow item <n> (is this at all useful?)
+ *                "graphn[:sg<n>[:ac<n>"]"
+ *                Possibly additional levels to allow multiple instances of an activity when used in a graph etc.
+ *
+ * Target       - The target of the thing being monitored.  E.g., a filename.  ?? Is this needed?  Should this be combined with scope??
+ *
+ * Examples:
+ * creator(mythor),scope(),kind(TimeWall)            total time spend processing in thor            search ct(thor),scope(),kind(TimeWall)
+ * creator(mythor),scope(graph1),kind(TimeWall)    - total time spent processing a graph
+ * creator(mythor),scope(graph1:sg<subid>),kind(TimeElapsed)    - total time spent processing a subgraph
+ * creator(mythor),scope(graph1:sg<n>:ac<id>),kind(TimeElapsed) - time for activity from start to stop
+ * creator(mythor),scope(graph1:sg<n>:ac<id>),kind(TimeLocal)   - time spent locally processing
+ * creator(mythor),scope(graph1:sg<n>:ac<id>),kind(TimeWallRowRange) - time from first row to last row
+ * creator(mythor),scope(graph1:sg<n>:ac<id>),kind(WhenFirstRow) - timestamp for first row
+ * creator(myeclccserver@myip),scope(compile),kind(TimeWall)
+ * creator(myeclccserver@myip),scope(compile:transform),kind(TimeWall)
+ * creator(myeclccserver@myip),scope(compile:transform:fold),kind(TimeWall)
+ *
+ * Other possibilities
+ * creator(myesp),scope(filefile::abc::def),kind(NumAccesses)
+ *
+ * Configuring statistic collection:
+ * - Each engine allows the statistics being collected to be specified.  You need to configure the area (time/memory/disk/), the level of detail by component and location.
+ *
+ * Some background notes:
+ * - Start time and end time (time processing first and last record) is useful for detecting time skew/serial activities.
+ * - Information is lost if you only show final skew, rather than skew over time, but storing time series data is
+ *   prohibitive so we may need to create some derived metrics.
+ * - The engines need options to control what information is gathered.
+ * - Need to ensure clocks are synchronized for the timestamps to be useful.
+ *
+ * Some typical analysis we want to perform:
+ * - Activities that show significant skew between first (or last) record times between nodes.
+ * - Activities where the majority of the time is being spent.
+ *
+ * Filtering statistics - with control over who is creating it, what is being recorded, and
+ * [in order of importance]
+ * - which level of creator you are interested in [summary or individual nodes, or both]    (*;*:*)?
+ * - which level of scope (interested in activities, or just by graph, or both)
+ * - a particular kind of statistic
+ * - A particular creator (including fixed/wildcarded sub-component)
+ *
+ * => Provide a class for representing a filter, which can be used to filter when recording and retrieving.  Start simple and then extend.
+ * Text representation creator(*,*:*),creatordepth(n),creatorkind(x),scopedepth(n),scopekind(xxx,yyy),scope(*:23),kind(x).
+ *
+ * Examples
+ * kind(TimeElapsed),scopetype(subgraph)   - subgraph timings
+ * kind(Time*),scopedepth(1)&kind(TimeElapsed),scopedepth(2),scopetype(subgraph) - all legacy global timings.
+ * creatortype(thor),kind(TimeElapsed),scope("")   - how much time has been spent on thor? (Need to sum?)
+ * creator(mythor),kind(TimeElapsed),scope("")     - how much time has been spent on *this* thor.
+ * kind(TimeElapsed),scope("compiled")     - how much time has been spent on *this* thor.
+ *
+ * Need to efficiently
+ * - Get all (simple) stats for a graph/activities (creator(*),kind(*),scope(x:*)) - display in graph, finding hotspots
+ * - Get all stats for an activity (creator(*:*),measure(*:*),scope(x:y)) - providing details in a graph
+ * - Merge stats from multiple components
+ * - Merge stats from multiple runs?
+ *
+ * Bulk updates will tend to be for a given component and should only need minor processing (e.g. patch ids) or no processing to update/combine.
+ * - You need to be able to filter only a certain level of statistic - e.g., times for transforms, but not details of those transforms.
+ *
+ * => suggest store as
+ * stats[creatorDepth,scopeDepth][creator] { kind, scope, value, target }.  sorted by (scope, target, kind)
+ * - allows high level filtering by level
+ * - allows combining with minor updates.
+ * - possibly extra structure within each creator - maybe depending on the level of the scope
+ * - need to be sub-sorted to allow efficient merging between creators (e.g. for calculating skew)
+ * - possibly different structure when collecting [e.g., indexed by stat, or using a local stat mapping ] and storing.
+ *
+ * Use (local) tables to map scope->uid.  Possibly implicitly defined on first occurrence, or zip the entire structure.
+ *
+ * The progress information should be stored compressed, with min,max child ids to avoid decompressing
+ */
+
+// Should the statistics classes be able to be stored globally e.g., for esp and other non workunit contexts?
+
+/*
+ * Work out how to represent all of the existing statistics
+ *
+ * Counts of number of skips on an index:  kind(CountIndexSkips),measure(count),scope(workunit | filename | graph:activity#)
+ * Activity start time                     kind(WhenStart),measure(timestamp),scope(graph:activity#),creator(mythor)
+ *                                         kind(WhenFirstRow),measure(timestamp),scope(graph:activity#),creator(mythor:slave#)
+ * Number of times files accessed by esp:  kind(CountFileAccess),measure(count),scope(),target(filename);
+ * Elapsed/remaining time for sprays:
+ */
+
+/*
+ * Statistics and their kinds - prefixed indicates their type.  Note generally the same type won't be reused for two different things.
+ *
+ * TimeStamps:
+ *      StWhenGraphStart           - When a graph starts
+ *      StWhenFirstRow             - When the first row is processed by slave activity
+ *
+ * Time
+ *      StTimeParseQuery
+ *      StTimeTransformQuery
+ *      StTimeTransformQuery_Fold         - transformquery:fold?  effectively an extra level of detail on the kind.
+ *      StTimeTransformQuery_Normalize
+ *      StTimeElapsedExecuting      - Elapsed wall time between first row and last row.
+ *      StTimeExecuting             - Cpu time spent executing
+ *
+ *
+ * Memory
+ *      StSizeGeneratedCpp
+ *      StSizePeakMemory
+ *
+ * Count
+ *      StCountIndexSeeks
+ *      StCountIndexScans
+ *
+ * Load
+ *      StLoadWhileSorting          - Average load while processing a sort?
+ *
+ * Skew
+ *      StSkewRecordDistribution    - Skew on the records across the different nodes
+ *      StSkewExecutionTime         - Skew in the execution time between activities.
+ *
+ */
+
+
 interface IConstWUStatistic : extends IInterface
 {
-    virtual IStringVal & getFullName(IStringVal & str) const = 0;   // A unique name
-    virtual IStringVal & getCreator(IStringVal & str) const = 0;    // what component gathered the statistic e.g., roxie/eclcc/thorslave[ip]
-    virtual IStringVal & getDescription(IStringVal & str) const = 0;// Description suitable for displaying to the user
-    virtual IStringVal & getName(IStringVal & str) const = 0;       // what is the name of the statistic e.g., wall time
-    virtual IStringVal & getScope(IStringVal & str) const = 0;      // what scope is the statistic gathered over? e.g., workunit, wfid:n, graphn, graphn:m
-    virtual StatisticMeasure getKind() const = 0;
+    virtual IStringVal & getDescription(IStringVal & str, bool createDefault) const = 0;    // Description of the statistic suitable for displaying to the user
+    virtual IStringVal & getCreator(IStringVal & str) const = 0;        // what component gathered the statistic e.g., myroxie/eclserver_12/mythor:100
+    virtual IStringVal & getScope(IStringVal & str) const = 0;          // what scope is the statistic gathered over? e.g., workunit, wfid:n, graphn, graphn:m
+    virtual IStringVal & getFormattedValue(IStringVal & str) const = 0; // The formatted value for display
+    virtual StatisticMeasure getMeasure() const = 0;
+    virtual StatisticKind getKind() const = 0;
+    virtual StatisticCreatorType getCreatorType() const = 0;
+    virtual StatisticScopeType getScopeType() const = 0;
     virtual unsigned __int64 getValue() const = 0;
     virtual unsigned __int64 getCount() const = 0;
     virtual unsigned __int64 getMax() const = 0;
+    virtual unsigned __int64 getTimestamp() const = 0;  // time the statistic was created
+    virtual bool matches(const IStatisticsFilter * filter) const = 0;
 };
 
 interface IConstWUStatisticIterator : extends IScmIterator
@@ -862,17 +1021,10 @@ interface IConstWorkUnit : extends IInterface
     virtual IConstWUResult * getTemporaryByName(const char * name) const = 0;
     virtual IConstWUResultIterator & getTemporaries() const = 0;
     virtual bool getRunningGraph(IStringVal & graphName, WUGraphIDType & subId) const = 0;
-    virtual unsigned getTimerCount(const char * timerName) const = 0;
-    virtual unsigned getTimerDuration(const char * timerName) const = 0;
-    virtual IStringVal & getTimerDescription(const char * timerName, IStringVal & str) const = 0;
-    virtual IStringVal & getTimeStamp(const char * name, const char * instance, IStringVal & str) const = 0;
     virtual IConstWUWebServicesInfo * getWebServicesInfo() const = 0;
     virtual IConstWURoxieQueryInfo * getRoxieQueryInfo() const = 0;
-    virtual IStringIterator & getTimers() const = 0;
-    virtual IConstWUTimerIterator & getTimerIterator() const = 0;
-    virtual IConstWUTimeStampIterator & getTimeStamps() const = 0;
-    virtual IConstWUStatisticIterator & getStatistics() const = 0;
-    virtual IConstWUStatistic * getStatistic(const char * name) const = 0;
+    virtual IConstWUStatisticIterator & getStatistics(const IStatisticsFilter * filter) const = 0; // filter must currently stay alive while the iterator does.
+    virtual IConstWUStatistic * getStatistic(const char * creator, const char * scope, StatisticKind kind) const = 0;
     virtual IStringVal & getUser(IStringVal & str) const = 0;
     virtual IStringVal & getWuScope(IStringVal & str) const = 0;
     virtual IConstWUResult * getVariableByName(const char * name) const = 0;
@@ -906,7 +1058,6 @@ interface IConstWorkUnit : extends IInterface
     virtual unsigned getSourceFileCount() const = 0;
     virtual unsigned getResultCount() const = 0;
     virtual unsigned getVariableCount() const = 0;
-    virtual unsigned getTimerCount() const = 0;
     virtual unsigned getApplicationValueCount() const = 0;
     virtual unsigned getDebugAgentListenerPort() const = 0;
     virtual IStringVal & getDebugAgentListenerIP(IStringVal & ip) const = 0;
@@ -926,8 +1077,6 @@ interface IWorkUnit : extends IConstWorkUnit
     virtual void clearExceptions() = 0;
     virtual void commit() = 0;
     virtual IWUException * createException() = 0;
-    virtual void setTimeStamp(const char * name, const char * instance, const char * event) = 0;
-    virtual void addTimeStamp(const char * name, const char * instance, const char * event) = 0;
     virtual void addProcess(const char *type, const char *instance, unsigned pid, const char *log=NULL) = 0;
     virtual void setAction(WUAction action) = 0;
     virtual void setApplicationValue(const char * application, const char * propname, const char * value, bool overwrite) = 0;
@@ -946,8 +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 setTimerInfo(const char * name, unsigned ms, unsigned count, unsigned __int64 max) = 0;
-    virtual void setStatistic(const char * creator_who, const char * wuScope_where, const char * stat_what, const char * description, StatisticMeasure kind, 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, bool merge) = 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;
@@ -1156,10 +1304,9 @@ class WuStatisticTarget : implements IStatisticTarget
 public:
     WuStatisticTarget(IWorkUnit * _wu, const char * _defaultWho) : wu(_wu), defaultWho(_defaultWho) {}
 
-    virtual void addStatistic(const char * creator_who, const char * wuScope_where, const char * stat_what, const char * description, StatisticMeasure kind, 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, bool merge)
     {
-        if (!creator_who) creator_who = defaultWho;
-        wu->setStatistic(creator_who, wuScope_where, stat_what, description, kind, value, count, maxValue, merge);
+        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, description, value, count, maxValue, merge);
     }
 
 protected:
@@ -1198,6 +1345,7 @@ extern WORKUNIT_API unsigned getEnvironmentHThorClusterNames(StringArray &eclAge
 extern WORKUNIT_API StringBuffer &formatGraphTimerLabel(StringBuffer &str, const char *graphName, unsigned subGraphNum=0, unsigned __int64 subId=0);
 extern WORKUNIT_API StringBuffer &formatGraphTimerScope(StringBuffer &str, const char *graphName, unsigned subGraphNum, unsigned __int64 subId);
 extern WORKUNIT_API bool parseGraphTimerLabel(const char *label, StringAttr &graphName, unsigned & graphNum, unsigned &subGraphNum, unsigned &subId);
+extern WORKUNIT_API bool parseGraphScope(const char *scope, StringAttr &graphName, unsigned & graphNum, unsigned &subGraphNum);
 extern WORKUNIT_API void addExceptionToWorkunit(IWorkUnit * wu, WUExceptionSeverity severity, const char * source, unsigned code, const char * text, const char * filename, unsigned lineno, unsigned column);
 extern WORKUNIT_API IWorkUnitFactory * getWorkUnitFactory();
 extern WORKUNIT_API IWorkUnitFactory * getSecWorkUnitFactory(ISecManager &secmgr, ISecUser &secuser);
@@ -1288,11 +1436,9 @@ extern WORKUNIT_API void gatherLibraryNames(StringArray &names, StringArray &unr
 extern WORKUNIT_API void associateLocalFile(IWUQuery * query, WUFileType type, const char * name, const char * description, unsigned crc);
 
 interface ITimeReporter;
-extern WORKUNIT_API void updateWorkunitTimeStat(IWorkUnit * wu, const char * component, const char * wuScope, const char * stat, const char * description, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue);
-extern WORKUNIT_API void updateWorkunitTiming(IWorkUnit * wu, const char * component, const char * mangledScope, const char * description, unsigned __int64 value, unsigned __int64 count, unsigned __int64 maxValue);
-extern WORKUNIT_API void updateWorkunitTimings(IWorkUnit * wu, ITimeReporter *timer, const char * component);
-
-
+extern WORKUNIT_API void updateWorkunitTimeStat(IWorkUnit * wu, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * description, unsigned __int64 value);
+extern WORKUNIT_API void updateWorkunitTimings(IWorkUnit * wu, ITimeReporter *timer);
+extern WORKUNIT_API IConstWUStatistic * getStatistic(IConstWorkUnit * wu, const IStatisticsFilter & filter);
 
 extern WORKUNIT_API const char *getTargetClusterComponentName(const char *clustname, const char *processType, StringBuffer &name);
 extern WORKUNIT_API void descheduleWorkunit(char const * wuid);
@@ -1302,4 +1448,6 @@ void WORKUNIT_API testWorkflow();
 
 extern WORKUNIT_API const char * getWorkunitStateStr(WUState state);
 
+extern WORKUNIT_API void addTimeStamp(IWorkUnit * wu, StatisticScopeType scopeType, const char * scope, StatisticKind kind);
+
 #endif

dali/daliadmin/daliadmin.cpp

@@ -119,6 +119,8 @@ void usage(const char *exe)
   printf("  validatestore [fix=<true|false>]\n"
          "                [verbose=<true|false>]\n"
          "                [deletefiles=<true|false>]-- perform some checks on dali meta data an optionally fix or remove redundant info \n");
+  printf("  stats <workunit> [<creator-type> <creator> <scope-type> <scope> <kind>]\n"
+         "                                  -- dump the statistics for a workunit\n");
   printf("  workunit <workunit> [true]      -- dump workunit xml, if 2nd parameter equals true, will also include progress data\n");
   printf("  wuidcompress <wildcard> <type>  --  scan workunits that match <wildcard> and compress resources of <type>\n");
   printf("  wuiddecompress <wildcard> <type> --  scan workunits that match <wildcard> and decompress resources of <type>\n");
@@ -2411,6 +2413,89 @@ static void dumpWorkunit(const char *wuid, bool includeProgress)
     exportWorkUnitToXMLFile(workunit, "stdout:", 0, true, includeProgress);
 }
 
+static void dumpProgress(const char *wuid, const char * graph)
+{
+    Owned<IWorkUnitFactory> factory = getWorkUnitFactory();
+    Owned<IConstWorkUnit> workunit = factory->openWorkUnit(wuid, false);
+    if (!workunit)
+        return;
+    Owned<IConstWUGraphProgress> progress = workunit->getGraphProgress(graph);
+    if (!progress)
+        return;
+    Owned<IPropertyTree> tree = progress->getProgressTree();
+    saveXML("stdout:", tree);
+}
+
+static const char * checkDash(const char * s)
+{
+    //Supplying * on the command line is a pain because it needs quoting. Allow - instead.
+    if (streq(s, ".") || streq(s, "-"))
+        return "*";
+    return s;
+}
+static void dumpStats(const char *wuid, const char * creatorTypeText, const char * creator, const char * scopeTypeText, const char * scope, const char * kindText)
+{
+    Owned<IWorkUnitFactory> factory = getWorkUnitFactory();
+    Owned<IConstWorkUnit> workunit = factory->openWorkUnit(wuid, false);
+    if (!workunit)
+        return;
+
+    StatisticsFilter filter(checkDash(creatorTypeText), checkDash(creator), checkDash(scopeTypeText), checkDash(scope), NULL, checkDash(kindText));
+    Owned<IConstWUStatisticIterator> stats = &workunit->getStatistics(&filter);
+    printf("<Statistics>\n");
+    ForEach(*stats)
+    {
+        IConstWUStatistic & cur = stats->query();
+        StringBuffer xml;
+        SCMStringBuffer curCreator;
+        SCMStringBuffer curScope;
+        SCMStringBuffer curDescription;
+        SCMStringBuffer curFormattedValue;
+
+        StatisticCreatorType curCreatorType = cur.getCreatorType();
+        StatisticScopeType curScopeType = cur.getScopeType();
+        StatisticMeasure curMeasure = cur.getMeasure();
+        StatisticKind curKind = cur.getKind();
+        unsigned __int64 value = cur.getValue();
+        unsigned __int64 count = cur.getCount();
+        unsigned __int64 max = cur.getMax();
+        unsigned __int64 ts = cur.getTimestamp();
+        cur.getCreator(curCreator);
+        cur.getScope(curScope);
+        cur.getDescription(curDescription, false);
+        cur.getFormattedValue(curFormattedValue);
+
+        if (curCreatorType != SCTnone)
+            xml.append("<ctype>").append(queryCreatorTypeName(curCreatorType)).append("</ctype>");
+        if (curCreator.length())
+            xml.append("<creator>").append(curCreator.str()).append("</creator>");
+        if (curScopeType != SSTnone)
+            xml.append("<stype>").append(queryScopeTypeName(curScopeType)).append("</stype>");
+        if (curScope.length())
+            xml.append("<scope>").append(curScope.str()).append("</scope>");
+        if (curMeasure != SMeasureNone)
+            xml.append("<unit>").append(queryMeasureName(curMeasure)).append("</unit>");
+        if (curKind != StKindNone)
+            xml.append("<kind>").append(queryStatisticName(curKind)).append("</kind>");
+        xml.append("<rawvalue>").append(value).append("</rawvalue>");
+        xml.append("<value>").append(curFormattedValue).append("</value>");
+        if (count != 1)
+            xml.append("<count>").append(count).append("</count>");
+        if (max)
+            xml.append("<max>").append(value).append("</max>");
+        if (ts)
+        {
+            xml.append("<ts>");
+            formatStatistic(xml, ts, SMeasureTimestampUs);
+            xml.append("</ts>");
+        }
+        if (curDescription.length())
+            xml.append("<desc>").append(curDescription.str()).append("</desc>");
+        printf("<stat>%s</stat>\n", xml.str());
+    }
+    printf("</Statistics>\n");
+}
+
 static void wuidCompress(const char *match, const char *type, bool compress)
 {
     if (0 != stricmp("graph", type))
@@ -2936,6 +3021,16 @@ int main(int argc, char* argv[])
                         CHECKPARAMS(2,2);
                         holdlock(params.item(1), params.item(2), userDesc);
                     }
+                    else if (stricmp(cmd, "progress") == 0) {
+                        CHECKPARAMS(2,2);
+                        dumpProgress(params.item(1), params.item(2));
+                    }
+                    else if (stricmp(cmd, "stats") == 0) {
+                        CHECKPARAMS(1,6);
+                        while (params.ordinality() < 7)
+                            params.append("*");
+                        dumpStats(params.item(1), params.item(2), params.item(3), params.item(4), params.item(5), params.item(6));
+                    }
                     else
                         ERRLOG("Unknown command %s",cmd);
                 }

ecl/agentexec/agentexec.cpp

@@ -84,6 +84,7 @@ void CEclAgentExecutionServer::start(StringBuffer & codeDir)
         ERRLOG("'name' not specified in properties file\n");
         throwUnexpected();
     }
+    setStatisticsComponentName(SCThthor, agentName, true);
 
     //get dali server(s)
     properties->getProp("@daliServers", daliServers);

ecl/eclagent/eclagent.cpp

@@ -1829,7 +1829,7 @@ void EclAgent::doProcess()
             if(noRetry && (w->getState() == WUStateFailed))
                 throw MakeStringException(0, "Ecl agent started in 'no retry' mode for failed workunit, so failing");
             w->setState(WUStateRunning);
-            w->addTimeStamp("EclAgent", GetCachedHostName(), "Started");
+            addTimeStamp(w, SSTglobal, NULL, StWhenQueryStarted);
             if (isRemoteWorkunit)
             {
                 w->setAgentSession(myProcessSession());
@@ -1896,7 +1896,7 @@ void EclAgent::doProcess()
     {
         WorkunitUpdate w = updateWorkUnit();
 
-        w->addTimeStamp("EclAgent", GetCachedHostName(), "Finished");
+        addTimeStamp(w, SSTglobal, NULL, StWhenQueryFinished);
         addTimings();
 
         switch (w->getState())
@@ -3005,7 +3005,7 @@ char * EclAgent::getDaliServers()
 void EclAgent::addTimings()
 {
     WorkunitUpdate w = updateWorkUnit();
-    updateWorkunitTimings(w, queryActiveTimer(), "eclagent");
+    updateWorkunitTimings(w, queryActiveTimer());
 }
 
 // eclagent abort monitoring
@@ -3181,6 +3181,8 @@ extern int HTHOR_API eclagent_main(int argc, const char *argv[], StringBuffer *
     ILogMsgHandler * logMsgHandler = NULL;
     if (!standAloneExe)
     {
+        setStatisticsComponentName(SCThthor, agentTopology->queryProp("@name"), true);
+
         Owned<IComponentLogFileCreator> lf = createComponentLogFileCreator(agentTopology, "eclagent");
         lf->setCreateAliasFile(false);
         logMsgHandler = lf->beginLogging();
@@ -4098,7 +4100,7 @@ public:
         bp.removeEdge(*this);
     }
 
-    virtual void updateProgress(IWUGraphProgress &progress) const 
+    virtual void updateProgress(IStatisticGatherer &progress) const
     {   
         if (in)
             in->updateProgress(progress);

ecl/eclagent/eclagent.ipp

@@ -695,7 +695,7 @@ public:
     bool prepare(IAgentContext & agent, const byte * parentExtract, bool checkDependencies);
     IHThorInput * queryOutput(unsigned idx);
     void updateProgress(IAgentContext & agent);
-    void updateProgress(IWUGraphProgress &progress);
+    void updateProgress(IStatisticGatherer &progress);
 
     void ready() { if (!alreadyUpdated) activity->ready(); }
     void execute() { if (!alreadyUpdated) activity->execute(); }
@@ -850,6 +850,8 @@ private:
         IHThorInput  *in;
         EclSubGraph  *owner;
         size32_t    maxRowSize;
+        unsigned sourceId;
+        unsigned outputIndex;
 
         StringBuffer edgeId;
 
@@ -857,7 +859,7 @@ private:
         IMPLEMENT_IINTERFACE;
 
         LegacyInputProbe(IHThorInput *_in, EclSubGraph *_owner, unsigned _sourceId, int outputidx)
-            : in(_in), owner(_owner)
+            : in(_in), owner(_owner), sourceId(_sourceId), outputIndex(outputidx)
         {
             edgeId.append(_sourceId).append("_").append(outputidx);
             maxRowSize = 0;
@@ -899,10 +901,12 @@ private:
             return ret;
         }
 
-        virtual void updateProgress(IWUGraphProgress &progress) const
+        virtual void updateProgress(IStatisticGatherer &progress) const
         {
-            IPropertyTree &edge = progress.updateEdge(owner->id, edgeId);
-            edge.setPropInt64("@maxrowsize", maxRowSize);
+            {
+                StatsEdgeScope scope(progress, sourceId, outputIndex);
+                progress.addStatistic(StSizeMaxRowSize, maxRowSize);
+            }
             if (in)
                 in->updateProgress(progress);
         }   
@@ -941,7 +945,7 @@ public:
     void executeSubgraphs(const byte * parentExtract);
     EclGraphElement * idToActivity(unsigned id);
     void reset();
-    void updateProgress(IWUGraphProgress & progress);
+    void updateProgress(IStatisticGatherer & progress);
     void updateProgress();
     void doExecuteChild(const byte * parentExtract);
     IEclLoopGraph * resolveLoopGraph(unsigned id);
@@ -993,6 +997,8 @@ public:
     bool isSink;
     bool executed;
     bool created;
+    unsigned __int64 startGraphTime;
+    cycle_t elapsedGraphCycles;
     EclGraph &parent;
     EclSubGraph * owner;
     unsigned parentActivityId;

ecl/eclagent/eclgraph.cpp

@@ -704,7 +704,7 @@ IHThorInput * EclGraphElement::queryOutput(unsigned idx)
     return activity ? activity->queryOutput(idx) : NULL;
 }
 
-void EclGraphElement::updateProgress(IWUGraphProgress &progress)
+void EclGraphElement::updateProgress(IStatisticGatherer &progress)
 {
     if(conditionalLink)
     {
@@ -766,6 +766,8 @@ EclSubGraph::EclSubGraph(IAgentContext & _agent, EclGraph & _parent, EclSubGraph
     executed = false;
     created = false;
     numResults = 0;
+    startGraphTime = 0;
+    elapsedGraphCycles = 0;
 
     subgraphCodeContext.set(_agent.queryCodeContext());
     subgraphCodeContext.setContainer(this);
@@ -878,23 +880,26 @@ void EclSubGraph::updateProgress()
     if (!isChildGraph && agent->queryRemoteWorkunit())
     {
         Owned<IConstWUGraphProgress> graphProgress = parent.getGraphProgress();
-        Owned<IWUGraphProgress> progress = graphProgress->update();
-        updateProgress(*progress);
+        Owned<IWUGraphStats> progress = graphProgress->update(queryStatisticsComponentType(), queryStatisticsComponentName(), id);
+        IStatisticGatherer & stats = progress->queryStatsBuilder();
+        updateProgress(stats);
     }
 }
 
-void EclSubGraph::updateProgress(IWUGraphProgress &progress)
+void EclSubGraph::updateProgress(IStatisticGatherer &progress)
 {
-    if (!isChildGraph)
+    StatsSubgraphScope subgraph(progress, id);
+    if (startGraphTime)
+        progress.addStatistic(StWhenGraphStarted, startGraphTime);
+    if (elapsedGraphCycles)
+        progress.addStatistic(StTimeElapsed, cycle_to_nanosec(elapsedGraphCycles));
+    ForEachItemIn(idx, elements)
     {
-        ForEachItemIn(idx, elements)
-        {
-            EclGraphElement & cur = elements.item(idx);
-            cur.updateProgress(progress);
-        }
-        ForEachItemIn(i2, subgraphs)
-            subgraphs.item(i2).updateProgress(progress);
+        EclGraphElement & cur = elements.item(idx);
+        cur.updateProgress(progress);
     }
+    ForEachItemIn(i2, subgraphs)
+        subgraphs.item(i2).updateProgress(progress);
 }
 
 bool EclSubGraph::prepare(const byte * parentExtract, bool checkDependencies)
@@ -920,6 +925,7 @@ void EclSubGraph::doExecute(const byte * parentExtract, bool checkDependencies)
         return;
     }
 
+    cycle_t startGraphCycles = get_cycles_now();
     ForEachItemIn(idx, elements)
     {
         EclGraphElement & cur = elements.item(idx);
@@ -945,6 +951,7 @@ void EclSubGraph::doExecute(const byte * parentExtract, bool checkDependencies)
     ForEachItemIn(id, sinks)
         sinks.item(id).done();
 
+    elapsedGraphCycles += (get_cycles_now() - startGraphCycles);
     executed = true;
 }
 
@@ -963,7 +970,8 @@ void EclSubGraph::execute(const byte * parentExtract)
         return;
     }
 
-    unsigned startTime = msTick();
+    startGraphTime = getTimeStampNowValue();
+    cycle_t startGraphCycles = get_cycles_now();
     createActivities();
     if (debugContext)
         debugContext->checkBreakpoint(DebugStateGraphStart, NULL, parent.queryGraphName() );    //debug probes exist so we can now check breakpoints
@@ -979,7 +987,7 @@ void EclSubGraph::execute(const byte * parentExtract)
         cleanupActivities();
 
         {
-            unsigned elapsed = msTick()-startTime;
+            unsigned __int64 elapsed = cycle_to_nanosec(get_cycles_now()-startGraphCycles);
 
             Owned<IWorkUnit> wu(agent->updateWorkUnit());
             StringBuffer timerText;
@@ -988,7 +996,7 @@ void EclSubGraph::execute(const byte * parentExtract)
             //graphn: id
             StringBuffer wuScope;
             formatGraphTimerScope(wuScope, parent.queryGraphName(), seqNo+1, id);
-            updateWorkunitTimeStat(wu, "eclagent", wuScope, "time", timerText.str(), milliToNano(elapsed), 1, 0);
+            updateWorkunitTimeStat(wu, SSTsubgraph, wuScope, StTimeElapsed, timerText.str(), elapsed);
         }
     }
     agent->updateWULogfile();//Update workunit logfile name in case of rollover
@@ -1220,7 +1228,7 @@ void EclGraph::execute(const byte * parentExtract)
         StringBuffer description;
         formatGraphTimerLabel(description, queryGraphName(), 0, 0);
 
-        updateWorkunitTimeStat(wu, "eclagent", queryGraphName(), "time", description.str(), milliToNano(elapsed), 1, 0);
+        updateWorkunitTimeStat(wu, SSTgraph, queryGraphName(), StTimeElapsed, description.str(), milliToNano(elapsed));
     }
 
     if (run)
@@ -1279,11 +1287,11 @@ EclSubGraph * EclGraph::idToGraph(unsigned id)
 void EclGraph::updateLibraryProgress()
 {
     Owned<IConstWUGraphProgress> graphProgress = getGraphProgress();
-    Owned<IWUGraphProgress> progress = graphProgress->update();
     ForEachItemIn(idx, graphs)
     {
         EclSubGraph & cur = graphs.item(idx);
-        cur.updateProgress(*progress);
+        Owned<IWUGraphStats> progress = graphProgress->update(queryStatisticsComponentType(), queryStatisticsComponentName(), cur.id);
+        cur.updateProgress(progress->queryStatsBuilder());
     }
 }
 

ecl/eclcc/eclcc.cpp

@@ -331,6 +331,7 @@ protected:
     StringAttr optOutputDirectory;
     StringAttr optOutputFilename;
     StringAttr optQueryRepositoryReference;
+    StringAttr optComponentName;
     FILE * batchLog;
 
     IFileArray inputFiles;
@@ -452,6 +453,7 @@ int main(int argc, const char *argv[])
     setTerminateOnSEH(true);
     InitModuleObjects();
     queryStderrLogMsgHandler()->setMessageFields(0);
+
     // Turn logging down (we turn it back up if -v option seen)
     Owned<ILogMsgFilter> filter = getCategoryLogMsgFilter(MSGAUD_user, MSGCLS_error);
     queryLogMsgManager()->changeMonitorFilter(queryStderrLogMsgHandler(), filter);
@@ -1043,7 +1045,7 @@ void EclCC::processSingleQuery(EclCompileInstance & instance,
     bool withinRepository = (queryAttributePath && *queryAttributePath);
     bool syntaxChecking = instance.wu->getDebugValueBool("syntaxCheck", false);
     size32_t prevErrs = errorProcessor.errCount();
-    unsigned startTime = msTick();
+    cycle_t startCycles = get_cycles_now();
     const char * sourcePathname = queryContents ? queryContents->querySourcePath()->str() : NULL;
     const char * defaultErrorPathname = sourcePathname ? sourcePathname : queryAttributePath;
 
@@ -1121,10 +1123,11 @@ void EclCC::processSingleQuery(EclCompileInstance & instance,
             if (instance.query && !syntaxChecking && !optGenerateMeta && !optEvaluateResult)
                 instance.query.setown(convertAttributeToQuery(instance.query, ctx));
 
-            instance.stats.parseTime = msTick()-startTime;
+            unsigned __int64 parseTimeNs = cycle_to_nanosec(get_cycles_now() - startCycles);
+            instance.stats.parseTime = nanoToMilli(parseTimeNs);
 
             if (instance.wu->getDebugValueBool("addTimingToWorkunit", true))
-                updateWorkunitTimeStat(instance.wu, "eclcc", "workunit", "parse time", NULL, milliToNano(instance.stats.parseTime), 1, 0);
+                updateWorkunitTimeStat(instance.wu, SSTcompilestage, "compile:parseTime", StTimeElapsed, NULL, parseTimeNs);
 
             if (optIncludeMeta || optGenerateMeta)
                 instance.generatedMeta.setown(parseCtx.getMetaTree());
@@ -1196,10 +1199,11 @@ void EclCC::processSingleQuery(EclCompileInstance & instance,
         }
     }
 
-    unsigned totalTime = msTick() - startTime;
-    instance.stats.generateTime = totalTime - instance.stats.parseTime;
+    unsigned __int64 totalTimeNs = cycle_to_nanosec(get_cycles_now() - startCycles);
+    instance.stats.generateTime = nanoToMilli(totalTimeNs) - instance.stats.parseTime;
+    //MORE: This is done too late..
     if (instance.wu->getDebugValueBool("addTimingToWorkunit", true))
-        updateWorkunitTimeStat(instance.wu, "eclcc", "workunit", "totalTime", NULL, milliToNano(totalTime), 1, 0);
+        updateWorkunitTimeStat(instance.wu, SSTcompilestage, "compile", StTimeElapsed, NULL, totalTimeNs);
 }
 
 void EclCC::processXmlFile(EclCompileInstance & instance, const char *archiveXML)
@@ -1875,6 +1879,9 @@ bool EclCC::parseCommandLineOptions(int argc, const char* argv[])
         else if (iter.matchFlag(optGenerateHeader, "-pch"))
         {
         }
+        else if (iter.matchOption(optComponentName, "--component"))
+        {
+        }
         else if (iter.matchFlag(optSaveQueryText, "-q"))
         {
         }
@@ -1978,6 +1985,11 @@ bool EclCC::parseCommandLineOptions(int argc, const char* argv[])
         return false;
     }
 
+    if (optComponentName.length())
+        setStatisticsComponentName(SCTeclcc, optComponentName, false);
+    else
+        setStatisticsComponentName(SCTeclcc, "eclcc", false);
+
     // Option post processing follows:
     if (optArchive || optWorkUnit || optGenerateMeta || optGenerateDepend || optShowPaths)
         optNoCompile = true;
@@ -2049,6 +2061,7 @@ const char * const helpText[] = {
     "!   -b            Batch mode.  Each source file is processed in turn.  Output",
     "!                 name depends on the input filename",
     "!   -checkVersion Enable/disable ecl version checking from archives",
+    "!   --component   Set the name of the component this is executing on behalf of"
 #ifdef _WIN32
     "!   -brk <n>      Trigger a break point in eclcc after nth allocation",
 #endif

ecl/eclccserver/eclccserver.cpp

@@ -205,14 +205,13 @@ class EclccCompileThread : public CInterface, implements IPooledThread, implemen
                 timings.findstr(ave, 5);
                 if (workunit->getDebugValueBool("addTimingToWorkunit", true))
                 {
-                    section.insert(0, "eclcc: ");
-
-                    unsigned __int64 mval = atoi64(total); // in milliseconds
-                    unsigned __int64 umax = atoi64(max); // in microseconds
+                    unsigned __int64 nval = atoi64(total) * 1000000; // in milliseconds
+                    unsigned __int64 nmax = atoi64(max) * 1000; // in microseconds
                     unsigned __int64 cnt = atoi64(count);
-                    const char * wuScope = section.str(); // should be different
-                    const char * description = section.str();
-                    updateWorkunitTiming(workunit, "eclcc", wuScope, description, milliToNano(mval), cnt, umax*1000);
+                    const char * scope = section.str();
+                    StatisticScopeType scopeType = SSTcompilestage;
+                    StatisticKind kind = StTimeElapsed;
+                    workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, NULL, nval, cnt, nmax, false);
                 }
             }
             else
@@ -311,6 +310,8 @@ class EclccCompileThread : public CInterface, implements IPooledThread, implemen
             return false;
         }
 
+        addTimeStamp(workunit, SSTglobal, NULL, StWhenCompiled);
+
         SCMStringBuffer mainDefinition;
         SCMStringBuffer eclQuery;
         query->getQueryText(eclQuery);
@@ -339,6 +340,7 @@ class EclccCompileThread : public CInterface, implements IPooledThread, implemen
         }
         eclccCmd.appendf(" -o%s", wuid);
         eclccCmd.appendf(" -platform=%s", target);
+        eclccCmd.appendf(" --component=%s", queryStatisticsComponentName());
 
         Owned<IStringIterator> debugValues = &workunit->getDebugValues();
         ForEach (*debugValues)
@@ -354,7 +356,7 @@ class EclccCompileThread : public CInterface, implements IPooledThread, implemen
         }
         try
         {
-            unsigned time = msTick();
+            cycle_t startCycles = get_cycles_now();
             Owned<ErrorReader> errorReader = new ErrorReader(pipe, this);
             Owned<AbortWaiter> abortWaiter = new AbortWaiter(pipe, workunit);
             eclccCmd.insert(0, eclccProgName);
@@ -402,9 +404,10 @@ class EclccCompileThread : public CInterface, implements IPooledThread, implemen
                 Owned<IWUQuery> query = workunit->updateQuery();
                 associateLocalFile(query, FileTypeDll, realdllfilename, "Workunit DLL", crc);
                 queryDllServer().registerDll(realdllname.str(), "Workunit DLL", dllurl.str());
-                time = msTick()-time;
+
+                cycle_t elapsedCycles = get_cycles_now() - startCycles;
                 if (workunit->getDebugValueBool("addTimingToWorkunit", true))
-                    updateWorkunitTimeStat(workunit, "eclccserver", "workunit", "create workunit", NULL, milliToNano(time), 1, 0);
+                    updateWorkunitTimeStat(workunit, SSTcompilestage, "compile", StTimeElapsed, NULL, cycle_to_nanosec(elapsedCycles));
 
                 workunit->commit();
                 return true;
@@ -740,6 +743,8 @@ int main(int argc, const char *argv[])
         return 1;
     }
 
+    const char * processName = globals->queryProp("@name");
+    setStatisticsComponentName(SCTeclcc, processName, true);
     if (globals->getPropBool("@enableSysLog",true))
         UseSysLogForOperatorMessages();
 #ifndef _WIN32
@@ -761,7 +766,7 @@ int main(int argc, const char *argv[])
         initClientProcess(serverGroup, DCR_EclServer);
         openLogFile();
         SCMStringBuffer queueNames;
-        getEclCCServerQueueNames(queueNames, globals->queryProp("@name"));
+        getEclCCServerQueueNames(queueNames, processName);
         if (!queueNames.length())
             throw MakeStringException(0, "No clusters found to listen on");
         // The option has been renamed to avoid confusion with the similarly-named eclcc option, but

ecl/eclscheduler/eclscheduler.cpp

@@ -184,6 +184,7 @@ int main(int argc, const char *argv[])
     }
     openLogFile();
 
+    setStatisticsComponentName(SCThthor, globals->queryProp("@name"), true);
     if (globals->getPropBool("@enableSysLog",true))
         UseSysLogForOperatorMessages();
     const char *daliServers = globals->queryProp("@daliServers");

ecl/hqlcpp/hqlcpp.ipp

@@ -1048,10 +1048,10 @@ public:
     HqlCppOptions const & queryOptions() const { return options; }
     bool needToSerializeToSlave(IHqlExpression * expr) const;
     ITimeReporter * queryTimeReporter() const { return timeReporter; }
-    void updateTimer(const char * name, unsigned timems)
+    void noteFinishedTiming(const char * name, cycle_t startCycles)
     {
         if (options.addTimingToWorkunit)
-            timeReporter->addTiming(name, NULL, timems);
+            timeReporter->addTiming(name, get_cycles_now()-startCycles);
     }
 
     void updateClusterType();

ecl/hqlcpp/hqlcppds.cpp

@@ -1675,24 +1675,25 @@ IHqlExpression * HqlCppTranslator::getResourcedChildGraph(BuildCtx & ctx, IHqlEx
     }
 
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         CompoundSourceTransformer transformer(*this, CSFpreload|csfFlags);
         resourced.setown(transformer.process(resourced));
         checkNormalized(ctx, resourced);
-        updateTimer("workunit;tree transform: optimize disk read", msTick()-time);
+        noteFinishedTiming("workunit;tree transform: optimize disk read", startCycles);
     }
 
     if (options.optimizeGraph)
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         traceExpression("BeforeOptimizeSub", resourced);
         resourced.setown(optimizeHqlExpression(queryErrorProcessor(), resourced, getOptimizeFlags()|HOOcompoundproject));
         traceExpression("AfterOptimizeSub", resourced);
-        updateTimer("workunit;optimize graph", msTick()-time);
+        noteFinishedTiming("workunit;optimize graph", startCycles);
     }
 
     traceExpression("BeforeResourcing Child", resourced);
-    unsigned time = msTick();
+
+    cycle_t startCycles = get_cycles_now();
     HqlExprCopyArray activeRows;
     gatherActiveCursors(ctx, activeRows);
     if (graphKind == no_loop)
@@ -1703,7 +1704,7 @@ IHqlExpression * HqlCppTranslator::getResourcedChildGraph(BuildCtx & ctx, IHqlEx
     else
         resourced.setown(resourceNewChildGraph(*this, activeRows, resourced, targetClusterType, graphIdExpr, numResults));
 
-    updateTimer("workunit;resource graph", msTick()-time);
+    noteFinishedTiming("workunit;resource graph", startCycles);
     checkNormalized(ctx, resourced);
     traceExpression("AfterResourcing Child", resourced);
     

ecl/hqlcpp/hqlecl.cpp

@@ -369,8 +369,7 @@ bool HqlDllGenerator::generateCode(HqlQueryContext & query)
         // ensure warnings/errors are available before we do the processing...
         wu->commit();
 
-        MTIME_SECTION (queryActiveTimer(), "Generate_code");
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         HqlCppTranslator translator(errs, wuname, code, targetClusterType, ctxCallback);
         processMetaCommands(translator, wu, query, ctxCallback);
 
@@ -439,8 +438,8 @@ bool HqlDllGenerator::generateCode(HqlQueryContext & query)
         doExpand(translator);
         if (wu->getDebugValueBool("addTimingToWorkunit", true))
         {
-            unsigned elapsed = msTick()-time;
-            updateWorkunitTimeStat(wu, "eclcc", "workunit", "GenerateCpp", "eclcc: generate code", milliToNano(elapsed), 1, 0);
+            unsigned __int64 elapsed = cycle_to_nanosec(get_cycles_now() - startCycles);
+            updateWorkunitTimeStat(wu, SSTcompilestage, "compile:generate c++", StTimeElapsed, NULL, elapsed);
         }
 
         wu->commit();
@@ -468,7 +467,7 @@ void HqlDllGenerator::insertStandAloneCode()
 
 void HqlDllGenerator::doExpand(HqlCppTranslator & translator)
 {
-    unsigned startExpandTime = msTick();
+    cycle_t startCycles = get_cycles_now();
     unsigned numExtraFiles = translator.getNumExtraCppFiles();
     bool isMultiFile = translator.spanMultipleCppFiles() && (numExtraFiles != 0);
     expandCode(MAIN_MODULE_TEMPLATE, ".cpp", code, isMultiFile, 0, translator.queryOptions().targetCompiler);
@@ -487,9 +486,9 @@ void HqlDllGenerator::doExpand(HqlCppTranslator & translator)
         }
     }
 
-    unsigned endExpandTime = msTick();
+    unsigned elapsedCycles = get_cycles_now() - startCycles;
     if (wu->getDebugValueBool("addTimingToWorkunit", true))
-        updateWorkunitTimeStat(wu, "eclcc", "workunit", "writeCpp", "eclcc: Time to write c++", milliToNano(endExpandTime-startExpandTime), 1, 0);
+        updateWorkunitTimeStat(wu, SSTcompilestage, "compile:write c++", StTimeElapsed, NULL, cycle_to_nanosec(elapsedCycles));
 }
 
 bool HqlDllGenerator::abortRequested()
@@ -499,6 +498,7 @@ bool HqlDllGenerator::abortRequested()
 
 bool HqlDllGenerator::doCompile(ICppCompiler * compiler)
 {
+    cycle_t startCycles = get_cycles_now();
     ForEachItemIn(i, sourceFiles)
         compiler->addSourceFile(sourceFiles.item(i));
 
@@ -539,17 +539,16 @@ bool HqlDllGenerator::doCompile(ICppCompiler * compiler)
     if (okToAbort)
         compiler->setAbortChecker(this);
 
-    MTIME_SECTION (queryActiveTimer(), "Compile_code");
-    unsigned time = msTick();
     PrintLog("Compiling %s", wuname);
     bool ok = compiler->compile();
     if(ok)
         PrintLog("Compiled %s", wuname);
     else
         PrintLog("Failed to compile %s", wuname);
-    time = msTick()-time;
-    if (wu->getDebugValueBool("addTimingToWorkunit", true))
-        updateWorkunitTimeStat(wu, "eclcc", "workunit", "compile", "eclcc: compile code", milliToNano(time), 1, 0);
+
+    unsigned elapsedCycles = get_cycles_now() - startCycles;
+    //For eclcc the workunit has been written to the resource - so any further timings will not be preserved -> need to report differently
+    queryActiveTimer()->addTiming("compile:compile c++", elapsedCycles);
 
     //Keep the files if there was a compile error.
     if (ok && deleteGenerated)

ecl/hqlcpp/hqlhtcpp.cpp

@@ -5736,7 +5736,7 @@ void dumpActivityCounts()
 
 bool HqlCppTranslator::buildCode(HqlQueryContext & query, const char * embeddedLibraryName, bool isEmbeddedLibrary)
 {
-    unsigned time = msTick();
+    cycle_t startCycles = get_cycles_now();
     WorkflowArray workflow;
     bool ok = prepareToGenerate(query, workflow, isEmbeddedLibrary);
     if (ok)
@@ -5745,7 +5745,7 @@ bool HqlCppTranslator::buildCode(HqlQueryContext & query, const char * embeddedL
         if (!isEmbeddedLibrary)
             updateClusterType();
 
-        updateTimer("workunit;tree transform", msTick()-time);
+        noteFinishedTiming("compile:tree transform", startCycles);
 
         if (insideLibrary())
         {
@@ -5788,11 +5788,11 @@ bool HqlCppTranslator::buildCode(HqlQueryContext & query, const char * embeddedL
 
         if (options.calculateComplexity)
         {
-            unsigned time = msTick();
+            cycle_t startCycles = get_cycles_now();
             StringBuffer complexityText;
             complexityText.append(getComplexity(workflow));
             wu()->setDebugValue("__Calculated__Complexity__", complexityText, true);
-            updateTimer("workunit;calculate complexity", msTick()-time);
+            noteFinishedTiming("compile:calculate complexity", startCycles);
         }
     }
 
@@ -5809,8 +5809,6 @@ bool HqlCppTranslator::buildCpp(IHqlCppInstance & _code, HqlQueryContext & query
 
     try
     {
-        unsigned time = msTick();
-
         wu()->setCodeVersion(ACTIVITY_INTERFACE_VERSION,BUILD_TAG,LANGUAGE_VERSION);
         cacheOptions();
 
@@ -5870,9 +5868,9 @@ bool HqlCppTranslator::buildCpp(IHqlCppInstance & _code, HqlQueryContext & query
         code->processIncludes();
         if (options.peephole)
         {
-            cycle_t time = msTick();
+            cycle_t startCycles = get_cycles_now();
             peepholeOptimize(*code, *this);
-            updateTimer("workunit;peephole optimize", msTick()-time);
+            noteFinishedTiming("compile:peephole optimize", startCycles);
         }
     }
     catch (IException * e)
@@ -5901,7 +5899,9 @@ public:
 
     virtual void report(const char * scope, const char * description, const __int64 totaltime, const __int64 maxtime, const unsigned count)
     {
-        updateWorkunitTiming(wu, "eclcc", scope, description, milliToNano(totaltime), count, milliToNano(maxtime));
+        StatisticScopeType scopeType = SSTsection; // MORE?
+        StatisticKind kind = StTimeElapsed;
+        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, description, totaltime, count, maxtime, false);
     }
 
 protected:
@@ -9222,11 +9222,11 @@ Tricky getting this in the correct order, problems are:
 
 IHqlExpression * HqlCppTranslator::optimizeCompoundSource(IHqlExpression * expr, unsigned flags)
 {
-    unsigned time = msTick();
+    cycle_t startCycles = get_cycles_now();
 
     CompoundSourceTransformer transformer(*this, flags);
     OwnedHqlExpr ret = transformer.process(expr);
-    updateTimer("workunit;tree transform: optimize disk read", msTick()-time);
+    noteFinishedTiming("compile:tree transform: optimize disk read", startCycles);
     return ret.getClear();
 }
 
@@ -9239,9 +9239,9 @@ IHqlExpression * HqlCppTranslator::optimizeGraphPostResource(IHqlExpression * ex
     //insert projects after compound created...
     if (options.optimizeResourcedProjects)
     {
-        cycle_t time = msTick();
+        cycle_t startCycles = get_cycles_now();
         OwnedHqlExpr optimized = insertImplicitProjects(*this, resourced.get(), projectBeforeSpill);
-        updateTimer("workunit;implicit projects", msTick()-time);
+        noteFinishedTiming("compile:implicit projects", startCycles);
         traceExpression("AfterResourcedImplicit", resourced);
         checkNormalized(optimized);
 
@@ -9252,11 +9252,11 @@ IHqlExpression * HqlCppTranslator::optimizeGraphPostResource(IHqlExpression * ex
     //Now call the optimizer again - the main purpose is to move projects over limits and into compound index/disk reads
     if (options.optimizeGraph)
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         traceExpression("BeforeOptimize2", resourced);
         resourced.setown(optimizeHqlExpression(queryErrorProcessor(), resourced, getOptimizeFlags()|HOOcompoundproject));
         traceExpression("AfterOptimize2", resourced);
-        updateTimer("workunit;optimize graph", msTick()-time);
+        noteFinishedTiming("compile:optimize graph", startCycles);
     }
     resourced.setown(optimizeCompoundSource(resourced, csfFlags));
     return resourced.getClear();
@@ -9284,11 +9284,11 @@ IHqlExpression * HqlCppTranslator::getResourcedGraph(IHqlExpression * expr, IHql
     checkNormalized(resourced);
     if (options.optimizeGraph)
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         resourced.setown(optimizeHqlExpression(queryErrorProcessor(), resourced, optFlags|HOOfiltersharedproject));
         //have the following on an "aggressive fold" option?  If no_selects extract constants it can be quite impressive (jholt22.hql)
         //resourced.setown(foldHqlExpression(resourced));
-        updateTimer("workunit;optimize graph", msTick()-time);
+        noteFinishedTiming("compile:optimize graph", startCycles);
     }
     traceExpression("AfterOptimize", resourced);
     checkNormalized(resourced);
@@ -9303,7 +9303,7 @@ IHqlExpression * HqlCppTranslator::getResourcedGraph(IHqlExpression * expr, IHql
 
     traceExpression("BeforeResourcing", resourced);
 
-    unsigned time = msTick();
+    cycle_t startCycles = get_cycles_now();
     if (outputLibraryId)
     {
         unsigned numResults = outputLibrary->numResultsUsed();
@@ -9316,7 +9316,7 @@ IHqlExpression * HqlCppTranslator::getResourcedGraph(IHqlExpression * expr, IHql
     if (!resourced)
         return NULL;
 
-    updateTimer("workunit;resource graph", msTick()-time);
+    noteFinishedTiming("compile:resource graph", startCycles);
     traceExpression("AfterResourcing", resourced);
 
     if (options.regressionTest)
@@ -9336,11 +9336,11 @@ IHqlExpression * HqlCppTranslator::getResourcedGraph(IHqlExpression * expr, IHql
     //Finally create a couple of special compound activities.
     //e.g., filtered fetch, limited keyed join
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         CompoundActivityTransformer transformer(targetClusterType);
         resourced.setown(transformer.transformRoot(resourced));
         traceExpression("AfterCompoundActivity", resourced);
-        updateTimer("workunit;tree transform: compound activity", msTick()-time);
+        noteFinishedTiming("compile:tree transform: compound activity", startCycles);
     }
 
     resourced.setown(spotTableInvariant(resourced));
@@ -18449,9 +18449,9 @@ void HqlCppTranslator::spotGlobalCSE(WorkflowItem & curWorkflow)
 {
     if (!insideLibrary() && options.globalAutoHoist)
     {
-        unsigned startTime = msTick();
+        cycle_t startCycles = get_cycles_now();
         spotGlobalCSE(curWorkflow.queryExprs());
-        updateTimer("workunit;tree transform: spot global cse", msTick()-startTime);
+        noteFinishedTiming("compile:tree transform: spot global cse", startCycles);
     }
 }
 
@@ -18717,7 +18717,7 @@ void HqlCppTranslator::pickBestEngine(HqlExprArray & exprs)
 
     if (targetThor())
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         ForEachItemIn(idx, exprs)
         {
             if (needsRealThor(&exprs.item(idx)))
@@ -18726,7 +18726,7 @@ void HqlCppTranslator::pickBestEngine(HqlExprArray & exprs)
         // if we got this far, thor not required
         setTargetClusterType(HThorCluster);
         DBGLOG("Thor query redirected to hthor instead");
-        updateTimer("workunit;tree transform: pick engine", msTick()-time);
+        noteFinishedTiming("compile:tree transform: pick engine", startCycles);
     }
 }
 
@@ -18735,7 +18735,7 @@ void HqlCppTranslator::pickBestEngine(WorkflowArray & workflow)
 {
     if (targetThor())
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         ForEachItemIn(idx2, workflow)
         {
             HqlExprArray & exprs = workflow.item(idx2).queryExprs();
@@ -18748,7 +18748,7 @@ void HqlCppTranslator::pickBestEngine(WorkflowArray & workflow)
         }
         setTargetClusterType(HThorCluster);
         DBGLOG("Thor query redirected to hthor instead");
-        updateTimer("workunit;tree transform: pick engine", msTick()-time);
+        noteFinishedTiming("compile:tree transform: pick engine", startCycles);
     }
 }
 

ecl/hqlcpp/hqlnlp.cpp

@@ -675,7 +675,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivityParse(BuildCtx & ctx, IHqlExpr
 {
     Owned<ABoundActivity> boundDataset = buildCachedActivity(ctx, _expr->queryChild(0));
 
-    unsigned startTime = msTick();
+    cycle_t startCycles = get_cycles_now();
     OwnedHqlExpr expr = optimizeParse(_expr);
 
     Owned<ActivityInstance> instance = new ActivityInstance(*this, ctx, TAKparse, expr, "Parse");
@@ -685,7 +685,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivityParse(BuildCtx & ctx, IHqlExpr
     buildInstancePrefix(instance);
 
     //This will become conditional on the flags....
-    unsigned startPrepareTime = msTick();
+    cycle_t startPrepareCycles = get_cycles_now();
     ITimeReporter * reporter = options.addTimingToWorkunit ? timeReporter : NULL;
     if (expr->hasAttribute(tomitaAtom))
         nlpParse = createTomitaContext(expr, code->workunit, options, reporter);
@@ -716,17 +716,17 @@ ABoundActivity * HqlCppTranslator::doBuildActivityParse(BuildCtx & ctx, IHqlExpr
     doBuildParseSearchText(instance->startctx, expr);
     doBuildParseValidators(instance->nestedctx, expr);
     doBuildParseExtra(instance->startctx, expr);
-    updateTimer("workunit;Generate PARSE: Prepare", msTick()-startPrepareTime);
+    noteFinishedTiming("compile:generate PARSE:prepare", startPrepareCycles);
     
     MemoryBuffer buffer;
-    unsigned startCompileTime = msTick();
+    cycle_t startCompileCycles = get_cycles_now();
     nlpParse->compileSearchPattern();
     nlpParse->queryParser()->serialize(buffer);
     if (nlpParse->isGrammarAmbiguous())
         WARNING1(CategoryEfficiency, HQLWRN_GrammarIsAmbiguous, instance->activityId);
 
     doBuildParseCompiled(instance->classctx, buffer);
-    updateTimer("workunit;Generate PARSE: Compile", msTick()-startCompileTime);
+    noteFinishedTiming("compile:generate PARSE:compile", startCompileCycles);
 
     nlpParse->buildProductions(*this, instance->classctx, instance->startctx);
 
@@ -759,7 +759,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivityParse(BuildCtx & ctx, IHqlExpr
     nlpParse = NULL;
     buildInstanceSuffix(instance);
     buildConnectInputOutput(ctx, instance, boundDataset, 0, 0);
-    updateTimer("workunit;Generate PARSE", msTick()-startTime);
+    noteFinishedTiming("compile:generate PARSE", startCycles);
 
     return instance->getBoundActivity();
 }

ecl/hqlcpp/hqlregex.cpp

@@ -2528,7 +2528,7 @@ HqlRegexExpr * RegexContext::createStructure(IHqlExpression * expr, bool caseSen
 
 void RegexContext::buildStructure()
 {
-    unsigned startTime = msTick();
+    cycle_t startCycles = get_cycles_now();
     IHqlExpression * grammar = expr->queryChild(2);
     assertex(grammar->getOperator() == no_pat_instance);
     OwnedHqlExpr structure = LINK(grammar);//createValue(no_pat_instance, makeRuleType(NULL), LINK(grammar), LINK(grammar->queryChild(1)));
@@ -2538,7 +2538,7 @@ void RegexContext::buildStructure()
     root->setRegexOwn(rootRegex);
     named.append(*LINK(root));
 
-    updateTimer("workunit;Generate PARSE: Create Structure", msTick()-startTime);
+    noteFinishedTiming("compile:generate PARSE:create structure", startCycles);
 }
 
 void RegexContext::expandRecursion()
@@ -2591,7 +2591,7 @@ void RegexContext::optimizeSpotDFA()
 
 void RegexContext::optimizePattern()
 {
-    unsigned startTime = msTick();
+    cycle_t startCycles = get_cycles_now();
     ForEachItemIn(idx1, named)
         named.item(idx1).mergeCreateSets();
     root->expandNamedSymbols();
@@ -2605,7 +2605,7 @@ void RegexContext::optimizePattern()
         }
     }
     optimizeSpotDFA();
-    updateTimer("workunit;Generate PARSE: Optimize", msTick()-startTime);
+    noteFinishedTiming("compile:generate PARSE:optimize", startCycles);
 }
 
 
@@ -2626,7 +2626,8 @@ HqlNamedRegex * RegexContext::queryDefine(IHqlExpression * defineName, bool case
 
 void RegexContext::analysePattern()
 {
-    unsigned startTime = msTick();
+    cycle_t startCycles = get_cycles_now();
+
     //This conversion is based around the description in the Dragon book:
     //3.9 From a regular expression to a DFA
     //even though we don't always convert it, the steps form a useful algorithm
@@ -2642,13 +2643,13 @@ void RegexContext::analysePattern()
     ForEachItemIn(idx3, named)
         named.item(idx3).generateDFAs();
 
-    updateTimer("workunit;Generate PARSE: Analyse", msTick()-startTime);
+    noteFinishedTiming("compile:generate PARSE:analyse", startCycles);
 }
 
 
 void RegexContext::generateRegex()
 {
-    unsigned startTime = msTick();
+    cycle_t startCycles = get_cycles_now();
 
     parser.addedSeparators = info.addedSeparators;
     setParserOptions(parser);
@@ -2663,7 +2664,7 @@ void RegexContext::generateRegex()
     parser.grammar.set(root->queryRootPattern());
     parser.minPatternLength = root->getMinLength();
 
-    updateTimer("workunit;Generate PARSE: Generate", msTick()-startTime);
+    noteFinishedTiming("compile:generate PARSE:generate", startCycles);
 }
 
 
@@ -2744,10 +2745,10 @@ void RegexContext::generateLexer(IDfaPattern * builder)
     lexerRoot->generateDFA(builder);
 }
 
-void RegexContext::updateTimer(const char * name, unsigned timems)
+void RegexContext::noteFinishedTiming(const char * name, cycle_t startCycles)
 {
     if (timeReporter)
-        timeReporter->addTiming(name, NULL, timems);
+        timeReporter->addTiming(name, get_cycles_now() - startCycles);
 }
 
 /*

ecl/hqlcpp/hqlregex.ipp

@@ -330,7 +330,7 @@ protected:
     void insertSeparators();
     void optimizePattern();
     void optimizeSpotDFA();
-    void updateTimer(const char * name, unsigned timems);
+    void noteFinishedTiming(const char * name, cycle_t startCycles);
     HqlNamedRegex * queryNamed(IHqlExpression * defn, IAtom * name, node_operator op, bool caseSensitive);
     HqlNamedRegex * createNamed(IHqlExpression * expr, IAtom * name, node_operator op, bool caseSensitive);
 

ecl/hqlcpp/hqlttcpp.cpp

@@ -3647,7 +3647,7 @@ IHqlExpression * ThorHqlTransformer::normalizeTableGrouping(IHqlExpression * exp
 void HqlCppTranslator::convertLogicalToActivities(WorkflowItem & curWorkflow)
 {
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         ThorHqlTransformer transformer(*this, targetClusterType, wu());
 
         HqlExprArray & exprs = curWorkflow.queryExprs();
@@ -3656,7 +3656,7 @@ void HqlCppTranslator::convertLogicalToActivities(WorkflowItem & curWorkflow)
         transformer.transformRoot(exprs, transformed);
 
         replaceArray(exprs, transformed);
-        updateTimer("workunit;tree transform: convert logical", msTick()-time);
+        noteFinishedTiming("compile:tree transform: convert logical", startCycles);
     }
 
     if (queryOptions().normalizeLocations)
@@ -10138,13 +10138,14 @@ void normalizeAnnotations(HqlCppTranslator & translator, HqlExprArray & exprs)
         queryLocationIndependent(&exprs.item(iInit));
 
     translator.traceExpressions("before annotation normalize", exprs);
-    unsigned time = msTick();
+
+    cycle_t startCycles = get_cycles_now();
     AnnotationNormalizerTransformer normalizer;
     HqlExprArray transformed;
     normalizer.analyseArray(exprs, 0);
     normalizer.transformRoot(exprs, transformed);
     replaceArray(exprs, transformed);
-    translator.updateTimer("workunit;tree transform: normalize.annotations", msTick()-time);
+    translator.noteFinishedTiming("compile:tree transform: normalize.annotations", startCycles);
 }
 
 //---------------------------------------------------------------------------
@@ -12507,7 +12508,7 @@ void normalizeHqlTree(HqlCppTranslator & translator, HqlExprArray & exprs)
 //      ForEachItemIn(iInit, exprs)
 //          queryLocationIndependent(&exprs.item(iInit));
 
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         HqlTreeNormalizer normalizer(translator);
         HqlExprArray transformed;
         normalizer.analyseArray(exprs, 0);
@@ -12518,27 +12519,27 @@ void normalizeHqlTree(HqlCppTranslator & translator, HqlExprArray & exprs)
         replaceArray(exprs, transformed);
         seenForceLocal = normalizer.querySeenForceLocal();
         seenLocalUpload = normalizer.querySeenLocalUpload();
-        translator.updateTimer("workunit;tree transform: normalize.initial", msTick()-time);
+        translator.noteFinishedTiming("compile:tree transform: normalize.initial", startCycles);
     }
 
     if (translator.queryOptions().constantFoldPostNormalize)
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         HqlExprArray transformed;
         quickFoldExpressions(transformed, exprs, NULL, 0);
         replaceArray(exprs, transformed);
-        translator.updateTimer("workunit;tree transform: normalize.fold", msTick()-time);
+        translator.noteFinishedTiming("compile:tree transform: normalize.fold", startCycles);
     }
 
     translator.traceExpressions("before scope tag", exprs);
 
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         HqlScopeTagger normalizer(translator.queryErrorProcessor(), translator.queryLocalOnWarningMapper());
         HqlExprArray transformed;
         normalizer.transformRoot(exprs, transformed);
         replaceArray(exprs, transformed);
-        translator.updateTimer("workunit;tree transform: normalize.scope", msTick()-time);
+        translator.noteFinishedTiming("compile:tree transform: normalize.scope", startCycles);
     }
 
     if (translator.queryOptions().normalizeLocations)
@@ -12547,12 +12548,12 @@ void normalizeHqlTree(HqlCppTranslator & translator, HqlExprArray & exprs)
     translator.traceExpressions("after scope tag", exprs);
 
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         HqlLinkedChildRowTransformer transformer(translator.queryOptions().implicitLinkedChildRows);
         HqlExprArray transformed;
         transformer.transformArray(exprs, transformed);
         replaceArray(exprs, transformed);
-        translator.updateTimer("workunit;tree transform: normalize.linkedChildRows", msTick()-time);;
+        translator.noteFinishedTiming("compile:tree transform: normalize.linkedChildRows", startCycles);;
     }
 
     if (seenLocalUpload)
@@ -12777,15 +12778,18 @@ void HqlCppTranslator::normalizeGraphForGeneration(HqlExprArray & exprs, HqlQuer
     traceExpressions("before transform graph for generation", exprs);
     //Don't change the engine if libraries are involved, otherwise things will get very confused.
 
-    unsigned timeCall = msTick();
-    expandDelayedFunctionCalls(&queryErrorProcessor(), exprs);
-    updateTimer("workunit;tree transform: expand delayed calls", msTick()-timeCall);
-
+    {
+        cycle_t startCycles = get_cycles_now();
+        expandDelayedFunctionCalls(&queryErrorProcessor(), exprs);
+        noteFinishedTiming("compile:tree transform: expand delayed calls", startCycles);
+    }
 
-    unsigned time1 = msTick();
-    traceExpressions("before normalize", exprs);
-    normalizeHqlTree(*this, exprs);
-    updateTimer("workunit;tree transform: normalize", msTick()-time1);
+    {
+        cycle_t startCycles = get_cycles_now();
+        traceExpressions("before normalize", exprs);
+        normalizeHqlTree(*this, exprs);
+        noteFinishedTiming("compile:tree transform: normalize", startCycles);
+    }
 
     if (wu()->getDebugValueBool("dumpIR", false))
         EclIR::dbglogIR(exprs);
@@ -12809,13 +12813,13 @@ void HqlCppTranslator::applyGlobalOptimizations(HqlExprArray & exprs)
     checkNormalized(exprs);
 
     {
-        unsigned startTime = msTick();
+        cycle_t startCycles = get_cycles_now();
         substituteClusterSize(exprs);
-        updateTimer("workunit;tree transform: substituteClusterSize", msTick()-startTime);
+        noteFinishedTiming("compile:tree transform: substituteClusterSize", startCycles);
     }
 
     {
-        unsigned startTime = msTick();
+        cycle_t startCycles = get_cycles_now();
         HqlExprArray folded;
         unsigned foldOptions = DEFAULT_FOLD_OPTIONS;
         if (options.foldConstantDatasets) foldOptions |= HFOconstantdatasets;
@@ -12827,7 +12831,7 @@ void HqlCppTranslator::applyGlobalOptimizations(HqlExprArray & exprs)
 
         foldHqlExpression(queryErrorProcessor(), folded, exprs, foldOptions);
         replaceArray(exprs, folded);
-        updateTimer("workunit;tree transform: global fold", msTick()-startTime);
+        noteFinishedTiming("compile:tree transform: global fold", startCycles);
     }
 
     traceExpressions("after global fold", exprs);
@@ -12835,11 +12839,11 @@ void HqlCppTranslator::applyGlobalOptimizations(HqlExprArray & exprs)
 
     if (options.globalOptimize)
     {
-        unsigned startTime = msTick();
+        cycle_t startCycles = get_cycles_now();
         HqlExprArray folded;
         optimizeHqlExpression(queryErrorProcessor(), folded, exprs, HOOfold);
         replaceArray(exprs, folded);
-        updateTimer("workunit;tree transform: global optimize", msTick()-startTime);
+        noteFinishedTiming("compile:tree transform: global optimize", startCycles);
     }
 
     traceExpressions("alloc", exprs);
@@ -12852,34 +12856,34 @@ void HqlCppTranslator::transformWorkflowItem(WorkflowItem & curWorkflow)
 #ifdef USE_SELSEQ_UID
     if (options.normalizeSelectorSequence)
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         LeftRightTransformer normalizer;
         normalizer.process(curWorkflow.queryExprs());
-        updateTimer("workunit;tree transform: left right", msTick()-time);
+        noteFinishedTiming("compile:tree transform: left right", startCycles);
         //traceExpressions("after implicit alias", workflow);
     }
 #endif
 
     if (queryOptions().createImplicitAliases)
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         ImplicitAliasTransformer normalizer;
         normalizer.process(curWorkflow.queryExprs());
-        updateTimer("workunit;tree transform: implicit alias", msTick()-time);
+        noteFinishedTiming("compile:tree transform: implicit alias", startCycles);
         //traceExpressions("after implicit alias", workflow);
     }
 
     {
-        unsigned startTime = msTick();
+        cycle_t startCycles = get_cycles_now();
         hoistNestedCompound(*this, curWorkflow.queryExprs());
-        updateTimer("workunit;tree transform: hoist nested compound", msTick()-startTime);
+        noteFinishedTiming("compile:tree transform: hoist nested compound", startCycles);
     }
 
     if (options.optimizeNestedConditional)
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         optimizeNestedConditional(curWorkflow.queryExprs());
-        updateTimer("workunit;optimize nested conditional", msTick()-time);
+        noteFinishedTiming("compile:optimize nested conditional", startCycles);
         traceExpressions("nested", curWorkflow);
         checkNormalized(curWorkflow);
     }
@@ -12887,39 +12891,43 @@ void HqlCppTranslator::transformWorkflowItem(WorkflowItem & curWorkflow)
     checkNormalized(curWorkflow);
     //sort(x)[n] -> topn(x, n)[]n, count(x)>n -> count(choosen(x,n+1)) > n and possibly others
     {
-        unsigned startTime = msTick();
+        cycle_t startCycles = get_cycles_now();
         optimizeActivities(curWorkflow.queryExprs(), !targetThor(), options.optimizeNonEmpty);
-        updateTimer("workunit;tree transform: optimize activities", msTick()-startTime);
+        noteFinishedTiming("compile:tree transform: optimize activities", startCycles);
     }
     checkNormalized(curWorkflow);
 
     //----------------------------- Transformations below this mark may have created globals so be very careful with hoisting ---------------------
 
-    unsigned time5 = msTick();
-    migrateExprToNaturalLevel(curWorkflow, wu(), *this);       // Ensure expressions are evaluated at the best level - e.g., counts moved to most appropriate level.
-    updateTimer("workunit;tree transform: migrate", msTick()-time5);
-    //transformToAliases(exprs);
-    traceExpressions("migrate", curWorkflow);
-    checkNormalized(curWorkflow);
+    {
+        cycle_t startCycles = get_cycles_now();
+        migrateExprToNaturalLevel(curWorkflow, wu(), *this);       // Ensure expressions are evaluated at the best level - e.g., counts moved to most appropriate level.
+        noteFinishedTiming("compile:tree transform: migrate", startCycles);
+        //transformToAliases(exprs);
+        traceExpressions("migrate", curWorkflow);
+        checkNormalized(curWorkflow);
+    }
 
-    unsigned time2 = msTick();
-    markThorBoundaries(curWorkflow);                                               // work out which engine is going to perform which operation.
-    updateTimer("workunit;tree transform: thor hole", msTick()-time2);
-    traceExpressions("boundary", curWorkflow);
-    checkNormalized(curWorkflow);
+    {
+        cycle_t startCycles = get_cycles_now();
+        markThorBoundaries(curWorkflow);                                               // work out which engine is going to perform which operation.
+        noteFinishedTiming("compile:tree transform: thor hole", startCycles);
+        traceExpressions("boundary", curWorkflow);
+        checkNormalized(curWorkflow);
+    }
 
     if (options.optimizeGlobalProjects)
     {
-        unsigned time = msTick();
+        cycle_t startCycles = get_cycles_now();
         insertImplicitProjects(*this, curWorkflow.queryExprs());
-        updateTimer("workunit;global implicit projects", msTick()-time);
+        noteFinishedTiming("compile:global implicit projects", startCycles);
         traceExpressions("implicit", curWorkflow);
         checkNormalized(curWorkflow);
     }
 
-    unsigned time3 = msTick();
+    cycle_t startCycles3 = get_cycles_now();
     normalizeResultFormat(curWorkflow, options);
-    updateTimer("workunit;tree transform: normalize result", msTick()-time3);
+    noteFinishedTiming("compile:tree transform: normalize result", startCycles3);
     traceExpressions("results", curWorkflow);
     checkNormalized(curWorkflow);
 
@@ -12931,9 +12939,9 @@ void HqlCppTranslator::transformWorkflowItem(WorkflowItem & curWorkflow)
 //  traceExpressions("flatten", workflow);
 
     {
-        unsigned startTime = msTick();
+        cycle_t startCycles = get_cycles_now();
         mergeThorGraphs(curWorkflow, options.resourceConditionalActions, options.resourceSequential);          // reduces number of graphs sent to thor
-        updateTimer("workunit;tree transform: merge thor", msTick()-startTime);
+        noteFinishedTiming("compile:tree transform: merge thor", startCycles);
     }
 
     traceExpressions("merged", curWorkflow);
@@ -12948,9 +12956,9 @@ void HqlCppTranslator::transformWorkflowItem(WorkflowItem & curWorkflow)
     //expandGlobalDatasets(workflow, wu(), *this);
 
     {
-        unsigned startTime = msTick();
+        cycle_t startCycles = get_cycles_now();
         mergeThorGraphs(curWorkflow, options.resourceConditionalActions, options.resourceSequential);
-        updateTimer("workunit;tree transform: merge thor", msTick()-startTime);
+        noteFinishedTiming("compile:tree transform: merge thor", startCycles);
     }
     checkNormalized(curWorkflow);
 
@@ -12976,12 +12984,12 @@ bool HqlCppTranslator::transformGraphForGeneration(HqlQueryContext & query, Work
     if (exprs.ordinality() == 0)
         return false;   // No action needed
 
-    unsigned time4 = msTick();
+    cycle_t startCycles = get_cycles_now();
     ::extractWorkflow(*this, exprs, workflow);
 
     traceExpressions("workflow", workflow);
     checkNormalized(workflow);
-    updateTimer("workunit;tree transform: stored results", msTick()-time4);
+    noteFinishedTiming("compile:tree transform: stored results", startCycles);
 
     if (outputLibrary && workflow.ordinality() > 1)
     {
@@ -13022,9 +13030,9 @@ bool HqlCppTranslator::transformGraphForGeneration(HqlQueryContext & query, Work
         if (options.regressionTest)
     #endif
         {
-            unsigned startTime = msTick();
+            cycle_t startCycles = get_cycles_now();
             checkDependencyConsistency(curWorkflow.queryExprs());
-            updateTimer("workunit;tree transform: check dependency", msTick()-startTime);
+            noteFinishedTiming("compile:tree transform: check dependency", startCycles);
         }
 
         traceExpressions("end transformGraphForGeneration", curWorkflow);

ecl/hthor/hthor.cpp

@@ -211,27 +211,25 @@ void CHThorActivityBase::done()
         input->done();
 }
 
-void CHThorActivityBase::updateProgress(IWUGraphProgress &progress) const
+void CHThorActivityBase::updateProgress(IStatisticGatherer &progress) const
 {
     updateProgressForOther(progress, activityId, subgraphId);
     if (input)
         input->updateProgress(progress);
 }
 
-void CHThorActivityBase::updateProgressForOther(IWUGraphProgress &progress, unsigned otherActivity, unsigned otherSubgraph) const
+void CHThorActivityBase::updateProgressForOther(IStatisticGatherer &progress, unsigned otherActivity, unsigned otherSubgraph) const
 {
     updateProgressForOther(progress, otherActivity, otherSubgraph, 0, processed);
 }
 
-void CHThorActivityBase::updateProgressForOther(IWUGraphProgress &progress, unsigned otherActivity, unsigned otherSubgraph, unsigned whichOutput, unsigned __int64 numProcessed) const
+void CHThorActivityBase::updateProgressForOther(IStatisticGatherer &progress, unsigned otherActivity, unsigned otherSubgraph, unsigned whichOutput, unsigned __int64 numProcessed) const
 {
-    StringBuffer path;
-    path.append(otherActivity).append("_").append(whichOutput);
-    IPropertyTree &edge = progress.updateEdge(otherSubgraph, path.str());
-    edge.setPropInt64("@count", numProcessed);
-    edge.setPropBool("@started", true);
-    edge.setPropBool("@stopped", true);
-    edge.setPropInt64("@slaves", 1);
+    StatsEdgeScope scope(progress, otherActivity, whichOutput);
+    progress.addStatistic(StNumRowsProcessed, numProcessed);
+    progress.addStatistic(StNumStarted, 1);  // wrong for an activity in a subquery
+    progress.addStatistic(StNumStopped, 1);
+    progress.addStatistic(StNumSlaves, 1);  // MORE: A bit pointless for an hthor graph
 }
 
 ILocalEclGraphResults * CHThorActivityBase::resolveLocalQuery(__int64 graphId)
@@ -6282,7 +6280,7 @@ void CHThorMultiInputActivity::setInput(unsigned index, IHThorInput *_input)
     }
 }
 
-void CHThorMultiInputActivity::updateProgress(IWUGraphProgress &progress) const
+void CHThorMultiInputActivity::updateProgress(IStatisticGatherer &progress) const
 {
     CHThorSimpleActivityBase::updateProgress(progress);
     ForEachItemIn(idx, inputs)
@@ -9545,7 +9543,7 @@ void LibraryCallOutput::done()
     result.clear();
 }
 
-void LibraryCallOutput::updateProgress(IWUGraphProgress &progress) const
+void LibraryCallOutput::updateProgress(IStatisticGatherer &progress) const
 {
     owner->updateOutputProgress(progress, *this, processed);
 }
@@ -9591,7 +9589,7 @@ IHThorInput * CHThorLibraryCallActivity::queryOutput(unsigned idx)
     return &outputs.item(idx);
 }
 
-void CHThorLibraryCallActivity::updateOutputProgress(IWUGraphProgress &progress, const LibraryCallOutput & _output, unsigned __int64 numProcessed) const
+void CHThorLibraryCallActivity::updateOutputProgress(IStatisticGatherer &progress, const LibraryCallOutput & _output, unsigned __int64 numProcessed) const
 {
     LibraryCallOutput & output = const_cast<LibraryCallOutput &>(_output);
     updateProgressForOther(progress, activityId, subgraphId, outputs.find(output), numProcessed);
@@ -9687,7 +9685,7 @@ public:
         throwUnexpected();
     }
 
-    virtual void updateProgress(IWUGraphProgress &progress) const
+    virtual void updateProgress(IStatisticGatherer &progress) const
     {
 //      CHThorSimpleActivityBase::updateProgress(progress);
         ForEachItemIn(i, inputs)

ecl/hthor/hthor.hpp

@@ -56,7 +56,7 @@ struct IHThorInput : public IInputBase
 
     virtual void ready() = 0;
     virtual void done() = 0;
-    virtual void updateProgress(IWUGraphProgress &progress) const = 0;
+    virtual void updateProgress(IStatisticGatherer &progress) const = 0;
     virtual const void * nextGE(const void * seek, unsigned numFields) { throwUnexpected(); }   // can only be called on stepping fields.
     virtual IInputSteppingMeta * querySteppingMeta() { return NULL; }
     virtual bool gatherConjunctions(ISteppedConjunctionCollector & collector) { return false; }
@@ -79,8 +79,8 @@ struct IHThorActivity : implements IActivityBase
     virtual void done() = 0;
     virtual __int64 getCount() = 0;
     virtual unsigned queryOutputs() = 0;
-    virtual void updateProgress(IWUGraphProgress &progress) const = 0;
-    virtual void updateProgressForOther(IWUGraphProgress &progress, unsigned otherActivity, unsigned otherSubgraph) const = 0;
+    virtual void updateProgress(IStatisticGatherer &progress) const = 0;
+    virtual void updateProgressForOther(IStatisticGatherer &progress, unsigned otherActivity, unsigned otherSubgraph) const = 0;
     virtual void extractResult(unsigned & len, void * & ret) = 0;
     virtual void setBoundGraph(IHThorBoundLoopGraph * graph) = 0;
 };

ecl/hthor/hthor.ipp

@@ -219,8 +219,8 @@ public:
     virtual void setBoundGraph(IHThorBoundLoopGraph * graph) { UNIMPLEMENTED; }
     virtual __int64 getCount();
     virtual unsigned queryOutputs() { return 1; }
-    virtual void updateProgress(IWUGraphProgress &progress) const;
-    virtual void updateProgressForOther(IWUGraphProgress &progress, unsigned otherActivity, unsigned otherSubgraph) const;
+    virtual void updateProgress(IStatisticGatherer &progress) const;
+    virtual void updateProgressForOther(IStatisticGatherer &progress, unsigned otherActivity, unsigned otherSubgraph) const;
     unsigned __int64 queryProcessed() const { return processed; }
     virtual unsigned queryId() const { return activityId; }
     virtual ThorActivityKind getKind() const  { return kind; };
@@ -230,7 +230,7 @@ public:
     virtual bool isPassThrough();
 
 protected:
-    void updateProgressForOther(IWUGraphProgress &progress, unsigned otherActivity, unsigned otherSubgraph, unsigned whichOutput, unsigned __int64 numProcessed) const;
+    void updateProgressForOther(IStatisticGatherer &progress, unsigned otherActivity, unsigned otherSubgraph, unsigned whichOutput, unsigned __int64 numProcessed) const;
 
 protected:
     ILocalEclGraphResults * resolveLocalQuery(__int64 graphId);
@@ -842,7 +842,7 @@ public:
     virtual void setInput(unsigned, IHThorInput *);
     virtual void ready();
     virtual void done();
-    virtual void updateProgress(IWUGraphProgress &progress) const
+    virtual void updateProgress(IStatisticGatherer &progress) const
     {
         CHThorSimpleActivityBase::updateProgress(progress);
         inputTrue->updateProgress(progress);
@@ -1270,7 +1270,7 @@ public:
     virtual bool isGrouped();
 
     virtual IOutputMetaData * queryOutputMeta() const { return outputMeta; }
-    virtual void updateProgress(IWUGraphProgress &progress) const
+    virtual void updateProgress(IStatisticGatherer &progress) const
     {
         CHThorActivityBase::updateProgress(progress);
         if (input1)
@@ -1416,7 +1416,7 @@ public:
 
     //interface IHThorInput
     virtual const void * nextInGroup();
-    virtual void updateProgress(IWUGraphProgress &progress) const
+    virtual void updateProgress(IStatisticGatherer &progress) const
     {
         CHThorActivityBase::updateProgress(progress);
         if (input1)
@@ -1470,7 +1470,7 @@ public:
 
     //interface IHThorInput
     virtual const void * nextInGroup();
-    virtual void updateProgress(IWUGraphProgress &progress) const
+    virtual void updateProgress(IStatisticGatherer &progress) const
     {
         CHThorActivityBase::updateProgress(progress);
         if (input1)
@@ -1665,7 +1665,7 @@ public:
     virtual void setInput(unsigned, IHThorInput *);
 
     //interface IHThorInput
-    virtual void updateProgress(IWUGraphProgress &progress) const;
+    virtual void updateProgress(IStatisticGatherer &progress) const;
 };
 
 class CHThorCaseActivity : public CHThorMultiInputActivity
@@ -2668,7 +2668,7 @@ public:
 
     virtual void ready();
     virtual void done();
-    virtual void updateProgress(IWUGraphProgress &progress) const;
+    virtual void updateProgress(IStatisticGatherer &progress) const;
 
 protected:
     IMPLEMENT_IINTERFACE;
@@ -2705,7 +2705,7 @@ public:
     IHThorGraphResult * getResultRows(unsigned whichOutput);
 
 protected:
-    void updateOutputProgress(IWUGraphProgress &progress, const LibraryCallOutput & output, unsigned __int64 numProcessed) const;
+    void updateOutputProgress(IStatisticGatherer &progress, const LibraryCallOutput & output, unsigned __int64 numProcessed) const;
 
 protected:
     virtual void ready();

ecl/hthor/hthorkey.cpp

@@ -282,13 +282,13 @@ public:
     virtual bool outputToFile(const char *) { return false; } 
     virtual IOutputMetaData * queryOutputMeta() const { return outputMeta; }
 
-    virtual void updateProgress(IWUGraphProgress &progress) const
+    virtual void updateProgress(IStatisticGatherer &progress) const
     {
         CHThorActivityBase::updateProgress(progress);
-        IPropertyTree &node = progress.updateNode(subgraphId, activityId);
-        setProgress(node, "postfiltered", queryPostFiltered());
-        setProgress(node, "seeks", querySeeks());
-        setProgress(node, "scans", queryScans());
+        StatsActivityScope scope(progress, activityId);
+        progress.addStatistic(StNumPostFiltered, queryPostFiltered());
+        progress.addStatistic(StNumIndexSeeks, querySeeks());
+        progress.addStatistic(StNumIndexScans, queryScans());
     }
 
     virtual unsigned querySeeks() const
@@ -4010,15 +4010,15 @@ public:
         helper.onLimitExceeded();
     }
 
-    virtual void updateProgress(IWUGraphProgress &progress) const
+    virtual void updateProgress(IStatisticGatherer &progress) const
     {
         CHThorThreadedActivityBase::updateProgress(progress);
-        IPropertyTree &node = progress.updateNode(subgraphId, activityId);
-        setProgress(node, "prefiltered", atomic_read(&prefiltered));
-        setProgress(node, "postfiltered", atomic_read(&postfiltered));
-        setProgress(node, "skips", atomic_read(&skips));
-        setProgress(node, "seeks", seeks);
-        setProgress(node, "scans", scans);
+        StatsActivityScope scope(progress, activityId);
+        progress.addStatistic(StNumPreFiltered, atomic_read(&prefiltered));
+        progress.addStatistic(StNumPostFiltered, atomic_read(&postfiltered));
+        progress.addStatistic(StNumIndexSkips, atomic_read(&skips));
+        progress.addStatistic(StNumIndexSeeks, seeks);
+        progress.addStatistic(StNumIndexScans, scans);
     }
 
 protected:

ecl/hthor/hthorstep.cpp

@@ -105,7 +105,7 @@ void CHThorNaryActivity::ready()
     }
 }
 
-void CHThorNaryActivity::updateProgress(IWUGraphProgress &progress) const
+void CHThorNaryActivity::updateProgress(IStatisticGatherer &progress) const
 {
     //This would only have an effect if progress was updated while the graph was running.
     CHThorMultiInputActivity::updateProgress(progress);

ecl/hthor/hthorstep.ipp

@@ -51,7 +51,7 @@ public:
     //interface IHThorInput
     virtual void done();
     virtual void ready();
-    virtual void updateProgress(IWUGraphProgress &progress) const;
+    virtual void updateProgress(IStatisticGatherer &progress) const;
 };
 
 

ecllibrary/std/system/Workunit.ecl

@@ -25,7 +25,9 @@ WsStatistic := RECORD
     unsigned8 value;
     unsigned8 count;
     unsigned8 maxValue;
+    string creatorType;
     string creator;
+    string scopeType;
     string scope;
     string name;
     string description;
@@ -158,8 +160,8 @@ EXPORT dataset(TimingRecord) WorkunitTimings(varstring wuid) :=
  * @param wuid          the name of the workunit
 */
 
-EXPORT dataset(StatisticRecord) WorkunitStatistics(varstring wuid, boolean includeActivities = false) :=
-  lib_workunitservices.WorkUnitServices.WorkunitStatistics(wuid, includeActivities);
+EXPORT dataset(StatisticRecord) WorkunitStatistics(varstring wuid, boolean includeActivities = false, varstring _filter = '') :=
+  lib_workunitservices.WorkUnitServices.WorkunitStatistics(wuid, includeActivities, _filter);
 
 
 END;

esp/platform/espp.cpp

@@ -21,6 +21,7 @@
 #endif
 //Jlib
 #include "jliball.hpp"
+#include "jstats.h"
 
 //CRT / OS
 #ifndef _WIN32
@@ -318,6 +319,9 @@ int init_main(int argc, char* argv[])
         const char* build_level = BUILD_LEVEL;
         setBuildLevel(build_level);
 
+        const char * processName = procpt->queryProp("@name");
+        setStatisticsComponentName(SCTesp, processName, true);
+
         openEspLogFile(envpt.get(), procpt.get());
 
         DBGLOG("Esp starting %s", BUILD_TAG);

esp/services/ws_workunits/ws_workunitsHelpers.cpp

@@ -337,30 +337,26 @@ void WsWuInfo::getVariables(IEspECLWorkunit &info, unsigned flags)
     }
 }
 
-void WsWuInfo::addTimerToList(SCMStringBuffer& name, unsigned count, unsigned duration, unsigned& totalThorTimerCount,
-    StringBuffer& totalThorTimeValue, IArrayOf<IEspECLTimer>& timers)
+void WsWuInfo::addTimerToList(SCMStringBuffer& name, const char * scope, IConstWUStatistic & stat, IArrayOf<IEspECLTimer>& timers)
 {
     StringBuffer fd;
-    formatDuration(fd, duration);
-
-    if (strieq(name.str(), TOTALTHORTIME))
-    {
-        totalThorTimeValue = fd;
-        totalThorTimerCount = count;
-        return;
-    }
+    formatStatistic(fd, stat.getValue(), stat.getMeasure());
 
     Owned<IEspECLTimer> t= createECLTimer("","");
-    name.s.replace('_', ' ');
+    name.s.replace('_', ' '); // yuk!
     t->setName(name.str());
     t->setValue(fd.str());
-    t->setCount(count);
+    t->setCount(stat.getCount());
 
     if (version > 1.19)
     {
         StringAttr graphName;
-        unsigned graphNum, subGraphNum, subId;
-        if (parseGraphTimerLabel(name.str(), graphName, graphNum, subGraphNum, subId))
+        unsigned graphNum;
+        unsigned subGraphNum;
+        unsigned subId = 0;
+
+        if (parseGraphScope(scope, graphName, graphNum, subGraphNum) ||
+            parseGraphTimerLabel(name.str(), graphName, graphNum, subGraphNum, subId))   // leacy
         {
             if (graphName.length() > 0)
                 t->setGraphName(graphName);
@@ -378,42 +374,53 @@ void WsWuInfo::getTimers(IEspECLWorkunit &info, unsigned flags)
         return;
     try
     {
-        StringBuffer totalThorTimeValue;
+        unsigned __int64 totalThorTimeValue = 0;
         unsigned totalThorTimerCount = 0; //Do we need this?
 
         IArrayOf<IEspECLTimer> timers;
-        Owned<IConstWUStatisticIterator> it = &cw->getStatistics();
+        StatisticsFilter filter;
+        filter.setMergeSources(false);
+        filter.setScopeDepth(1, 2);
+        filter.setMeasure(SMeasureTimeNs);
+        Owned<IConstWUStatisticIterator> it = &cw->getStatistics(&filter);
         if (it->first())
         {
             ForEach(*it)
             {
                 IConstWUStatistic & cur = it->query();
-                //Only interested in timings...
-                if (cur.getKind() != SMEASURE_TIME_NS)
-                    continue;
+                SCMStringBuffer name, scope;
+                cur.getDescription(name, true);
+                cur.getScope(scope);
 
-                SCMStringBuffer name;
-                cur.getDescription(name);
-                addTimerToList(name, cur.getCount(), nanoToMilli(cur.getValue()), totalThorTimerCount, totalThorTimeValue, timers);
-            }
-        }
-        else
-        {//backward compatibility for WU without Statistics
-            Owned<IConstWUTimerIterator> it = &cw->getTimerIterator();
-            ForEach(*it)
-            {
-                IConstWUTimer& timer = it->query();
-                SCMStringBuffer name;
-                timer.getName(name);
-                addTimerToList(name, timer.getCount(), timer.getDuration(), totalThorTimerCount, totalThorTimeValue, timers);
+                bool isThorTiming = false;
+                if ((cur.getCreatorType() == SCTsummary) && (cur.getKind() == StTimeElapsed) && streq(scope.str(), GLOBAL_SCOPE))
+                {
+                    SCMStringBuffer creator;
+                    cur.getCreator(creator);
+                    if (streq(creator.str(), "thor"))
+                        isThorTiming = true;
+                }
+                else if (strieq(name.str(), TOTALTHORTIME)) // legacy
+                    isThorTiming = true;
+
+                if (isThorTiming)
+                {
+                    totalThorTimeValue += cur.getValue();
+                    totalThorTimerCount += cur.getCount();
+                }
+                else
+                    addTimerToList(name, scope.str(), cur, timers);
             }
         }
 
-        if (totalThorTimeValue.length() > 0)
+        if (totalThorTimeValue > 0)
         {
+            StringBuffer totalThorTimeText;
+            formatStatistic(totalThorTimeText, totalThorTimeValue, SMeasureTimeNs);
+
             Owned<IEspECLTimer> t= createECLTimer("","");
             t->setName(TOTALTHORTIME);
-            t->setValue(totalThorTimeValue.str());
+            t->setValue(totalThorTimeText.str());
             t->setCount(totalThorTimerCount);
             timers.append(*t.getLink());
         }
@@ -429,6 +436,29 @@ void WsWuInfo::getTimers(IEspECLWorkunit &info, unsigned flags)
     }
 }
 
+unsigned WsWuInfo::getTimerCount()
+{
+    unsigned numTimers = 0;
+    try
+    {
+        //This filter must match the filter in the function above, otherwise it will be inconsistent
+        StatisticsFilter filter;
+        filter.setMergeSources(false);
+        filter.setScopeDepth(1, 2);
+        filter.setMeasure(SMeasureTimeNs);
+        Owned<IConstWUStatisticIterator> it = &cw->getStatistics(&filter);
+        ForEach(*it)
+            numTimers++;
+    }
+    catch(IException* e)
+    {
+        StringBuffer eMsg;
+        ERRLOG("%s", e->errorMessage(eMsg).str());
+        e->Release();
+    }
+    return numTimers;
+}
+
 struct mapEnums { int val; const char *str; };
 
 mapEnums queryFileTypes[] = {
@@ -656,28 +686,46 @@ const char *getGraphNum(const char *s,unsigned &num)
     return s;
 }
 
+
+bool WsWuInfo::hasSubGraphTimings()
+{
+    StatisticsFilter filter;
+    filter.setScopeType(SSTsubgraph);
+    filter.setKind(StTimeElapsed);
+    Owned<IConstWUStatisticIterator> times = &cw->getStatistics(&filter);
+    return times->first();
+}
+
+bool WsWuInfo::legacyHasSubGraphTimings()
+{
+    StatisticsFilter filter;
+    filter.setScopeDepth(1); // only "global" timers.
+    filter.setMeasure(SMeasureTimeNs);
+    Owned<IConstWUStatisticIterator> times = &cw->getStatistics(&filter);
+    ForEach(*times)
+    {
+        IConstWUStatistic & cur = times->query();
+        SCMStringBuffer name;
+        cur.getDescription(name, false);
+
+        StringAttr graphName;
+        unsigned graphNum;
+        unsigned subGraphNum;
+        unsigned subId;
+        if (parseGraphTimerLabel(name.str(), graphName, graphNum, subGraphNum, subId))
+            return true;
+    }
+    return false;
+}
+
 void WsWuInfo::getGraphInfo(IEspECLWorkunit &info, unsigned flags)
 {
      if (version > 1.01)
      {
         info.setHaveSubGraphTimings(false);
 
-        Owned<IStringIterator> times = &cw->getTimers();
-        ForEach(*times)
-        {
-            SCMStringBuffer name;
-            times->str(name);
-
-            StringAttr graphName;
-            unsigned graphNum;
-            unsigned subGraphNum;
-            unsigned subId;
-            if (parseGraphTimerLabel(name.str(), graphName, graphNum, subGraphNum, subId))
-            {
-                info.setHaveSubGraphTimings(true);
-                break;
-            }
-        }
+        if (hasSubGraphTimings() || legacyHasSubGraphTimings())
+            info.setHaveSubGraphTimings(true);
      }
 
     if (!(flags & WUINFO_IncludeGraphs))
@@ -741,11 +789,51 @@ void WsWuInfo::getGraphInfo(IEspECLWorkunit &info, unsigned flags)
 
 void WsWuInfo::getGraphTimingData(IArrayOf<IConstECLTimingData> &timingData, unsigned flags)
 {
-    Owned<IStringIterator> times = &cw->getTimers();
+    StatisticsFilter filter(SCTall, SSTsubgraph, SMeasureTimeNs, StTimeElapsed);
+    Owned<IConstWUStatisticIterator> times = &cw->getStatistics(&filter);
+    bool matched = false;
     ForEach(*times)
     {
+        IConstWUStatistic & cur = times->query();
+        SCMStringBuffer scope;
+        cur.getScope(scope);
+
+        StringAttr graphName;
+        unsigned graphNum;
+        unsigned subGraphNum;
+        if (parseGraphScope(scope.str(), graphName, graphNum, subGraphNum))
+        {
+            unsigned time = nanoToMilli(cur.getValue());
+
+            SCMStringBuffer name;
+            cur.getDescription(name, true);
+
+            Owned<IEspECLTimingData> g = createECLTimingData();
+            g->setName(name.str());
+            g->setGraphNum(graphNum);
+            g->setSubGraphNum(subGraphNum);
+            g->setMS(time);
+            g->setMin(time/60000);
+            timingData.append(*g.getClear());
+            matched = true;
+        }
+    }
+
+    if (!matched)
+        legacyGetGraphTimingData(timingData, flags);
+}
+
+void WsWuInfo::legacyGetGraphTimingData(IArrayOf<IConstECLTimingData> &timingData, unsigned flags)
+{
+    StatisticsFilter filter;
+    filter.setScopeDepth(1);
+    filter.setMeasure(SMeasureTimeNs);
+    Owned<IConstWUStatisticIterator> times = &cw->getStatistics(&filter);
+    ForEach(*times)
+    {
+        IConstWUStatistic & cur = times->query();
         SCMStringBuffer name;
-        times->str(name);
+        cur.getDescription(name, false); // was previously always filled in.
 
         StringAttr graphName;
         unsigned graphNum;
@@ -754,7 +842,7 @@ void WsWuInfo::getGraphTimingData(IArrayOf<IConstECLTimingData> &timingData, uns
 
         if (parseGraphTimerLabel(name.str(), graphName, graphNum, subGraphNum, subId))
         {
-            unsigned time = cw->getTimerDuration(name.str());
+            unsigned time = nanoToMilli(cur.getValue());
 
             Owned<IEspECLTimingData> g = createECLTimingData();
             g->setName(name.str());
@@ -816,6 +904,41 @@ void WsWuInfo::getEventScheduleFlag(IEspECLWorkunit &info)
     }
 }
 
+unsigned WsWuInfo::getTotalThorTime()
+{
+    StatisticsFilter filter;
+    filter.setCreatorType(SCTsummary);
+    filter.setScope(GLOBAL_SCOPE);
+    filter.setKind(StTimeElapsed);
+
+    //Should only be a single value
+    unsigned totalThorTimeMS = 0;
+    Owned<IConstWUStatisticIterator> times = &cw->getStatistics(&filter);
+    ForEach(*times)
+    {
+        totalThorTimeMS += nanoToMilli(times->query().getValue());
+    }
+
+    return totalThorTimeMS;
+}
+
+unsigned WsWuInfo::getLegacyTotalThorTime()
+{
+    //4.2.x backward compatibility - only scope depth and measure filters work
+    StatisticsFilter filter;
+    filter.setScopeDepth(1); // only global
+    filter.setMeasure(SMeasureTimeNs);
+    Owned<IConstWUStatisticIterator> times = &cw->getStatistics(&filter);
+    SCMStringBuffer oldname;
+    ForEach(*times)
+    {
+        times->query().getDescription(oldname, false);      // description will be set up
+        if (streq(oldname.str(), TOTALTHORTIME))
+            return nanoToMilli(times->query().getValue());
+    }
+    return 0;
+}
+
 void WsWuInfo::getCommon(IEspECLWorkunit &info, unsigned flags)
 {
     SCMStringBuffer s;
@@ -844,10 +967,16 @@ void WsWuInfo::getCommon(IEspECLWorkunit &info, unsigned flags)
 
     if (version > 1.27)
     {
-        StringBuffer totalThorTimeStr;
-        unsigned totalThorTimeMS = cw->getTimerDuration(TOTALTHORTIME);
-        formatDuration(totalThorTimeStr, totalThorTimeMS);
-        info.setTotalThorTime(totalThorTimeStr.str());
+        unsigned totalThorTimeMS = getTotalThorTime();
+        if (totalThorTimeMS == 0)
+            totalThorTimeMS = getTotalThorTime();
+
+        if (totalThorTimeMS)
+        {
+            StringBuffer totalThorTimeStr;
+            formatDuration(totalThorTimeStr, totalThorTimeMS);
+            info.setTotalThorTime(totalThorTimeStr.str());
+        }
     }
 
     WsWuDateTime dt;
@@ -886,7 +1015,7 @@ void WsWuInfo::getInfo(IEspECLWorkunit &info, unsigned flags)
     info.setGraphCount(cw->getGraphCount());
     info.setSourceFileCount(cw->getSourceFileCount());
     info.setVariableCount(cw->getVariableCount());
-    info.setTimerCount(cw->getTimerCount());
+    info.setTimerCount(getTimerCount());
     info.setSourceFileCount(cw->getSourceFileCount());
     info.setApplicationValueCount(cw->getApplicationValueCount());
     info.setHasDebugValue(cw->hasDebugValue("__calculated__complexity__"));

esp/services/ws_workunits/ws_workunitsHelpers.hpp

@@ -158,6 +158,7 @@ public:
     void getApplicationValues(IEspECLWorkunit &info, unsigned flags);
     void getExceptions(IEspECLWorkunit &info, unsigned flags);
     void getSourceFiles(IEspECLWorkunit &info, unsigned flags);
+    unsigned getTimerCount();
     void getTimers(IEspECLWorkunit &info, unsigned flags);
     void getHelpers(IEspECLWorkunit &info, unsigned flags);
     void getGraphInfo(IEspECLWorkunit &info, unsigned flags);
@@ -187,7 +188,14 @@ public:
     void getEventScheduleFlag(IEspECLWorkunit &info);
     unsigned getWorkunitThorLogInfo(IArrayOf<IEspECLHelpFile>& helpers, IEspECLWorkunit &info);
     IDistributedFile* getLogicalFileData(IEspContext& context, const char* logicalName, bool& showFileContent);
-    void addTimerToList(SCMStringBuffer& name, unsigned count, unsigned duration, unsigned& totalThorTimerCount, StringBuffer& totalThorTimeValue, IArrayOf<IEspECLTimer>& timers);
+
+protected:
+    void addTimerToList(SCMStringBuffer& name, const char * scope, IConstWUStatistic & stat, IArrayOf<IEspECLTimer>& timers);
+    unsigned getTotalThorTime();
+    unsigned getLegacyTotalThorTime();
+    bool hasSubGraphTimings();
+    bool legacyHasSubGraphTimings();
+    void legacyGetGraphTimingData(IArrayOf<IConstECLTimingData> &timingData, unsigned flags);
 
 public:
     IEspContext &context;

esp/services/ws_workunits/ws_workunitsQuerySets.cpp

@@ -1556,11 +1556,13 @@ bool CWsWorkunitsEx::onWUQueryDetails(IEspContext &context, IEspWUQueryDetailsRe
         resp.setIsLibrary(query->getPropBool("@isLibrary"));
         SCMStringBuffer s;
         resp.setWUSnapShot(cw->getSnapshot(s).str()); //Label
-        cw->getTimeStamp("Compiled", "EclCCServer", s);
-        if (!s.length())
-            cw->getTimeStamp("Compiled", "EclServer", s);
-        if (s.length())
+        Owned<IConstWUStatistic> whenCompiled = cw->getStatistic(NULL, NULL, StWhenCompiled);
+        if (whenCompiled)
+        {
+            whenCompiled->getFormattedValue(s);
             resp.setCompileTime(s.str());
+        }
+
         StringArray libUsed, graphIds;
         Owned<IConstWULibraryIterator> libs = &cw->getLibraries();
         ForEach(*libs)

esp/smc/SMCLib/WUXMLInfo.cpp

@@ -308,6 +308,7 @@ bool CWUXMLInfo::buildXmlResultList(IConstWorkUnit &wu,IPropertyTree& XMLStructu
     return true;
 }
 
+/*
 //GH: MORE - this whole class looks as if it is unused, and should be deleted.  If that is not true the
 //following function needs to be rewritten to take into account the statistics
 bool CWUXMLInfo::buildXmlTimimgList(IConstWorkUnit &wu,IPropertyTree& XMLStructure)
@@ -315,22 +316,20 @@ bool CWUXMLInfo::buildXmlTimimgList(IConstWorkUnit &wu,IPropertyTree& XMLStructu
     try{
 
         IPropertyTree* timingTree = XMLStructure.addPropTree("Timings", createPTree(ipt_caseInsensitive));
-        Owned<IStringIterator> times = &wu.getTimers();
-        ForEach(*times)
+        Owned<IConstWUStatisticIterator> stats = &wu.getStatistics(NULL, NULL, "Time*");
+        ForEach(*stats)
         {
-            SCMStringBuffer name;
-            times->str(name);
+            IConstWUStatistic & cur = stats->query();
+            SCMStringBuffer description;
+            cur.getDescription(description);
             SCMStringBuffer value;
-            unsigned count = wu.getTimerCount(name.str());
-            unsigned duration = wu.getTimerDuration(name.str());
+            unsigned count = cur.getCount();
+            unsigned __int64 duration = cur.getValue();
             StringBuffer fd;
-            formatDuration(fd, duration);
-            for (unsigned i = 0; i < name.length(); i++)
-                if (name.s.charAt(i)=='_') 
-                    name.s.setCharAt(i, ' ');
+            formatDuration(fd, nanoToMilli(duration));
 
             IPropertyTree* Timer = timingTree->addPropTree("Timer", createPTree(ipt_caseInsensitive));
-            Timer->setProp("Name",name.str());
+            Timer->setProp("Name",description.str());
             Timer->setProp("Value",fd.str());
             Timer->setPropInt("Count",count);
         }
@@ -347,6 +346,7 @@ bool CWUXMLInfo::buildXmlTimimgList(IConstWorkUnit &wu,IPropertyTree& XMLStructu
 
     return true;
 }
+*/
 
 bool CWUXMLInfo::buildXmlLogList(IConstWorkUnit &wu,IPropertyTree& XMLStructure)
 {

esp/smc/SMCLib/WUXMLInfo.hpp

@@ -48,7 +48,7 @@ public:
     bool buildXmlWuidInfo(IConstWorkUnit &wu, StringBuffer& wuStructure,bool bDescription = false);
     bool buildXmlWuidInfo(const char* wu, IEspECLWorkunit& wuStructure,bool bDescription = false);
     bool buildXmlExceptionList(IConstWorkUnit &wu,IPropertyTree& XMLStructure);
-    bool buildXmlTimimgList(IConstWorkUnit &wu,IPropertyTree& XMLStructure);
+//    bool buildXmlTimimgList(IConstWorkUnit &wu,IPropertyTree& XMLStructure);
     bool buildXmlLogList(IConstWorkUnit &wu,IPropertyTree& XMLStructure);
     void buildXmlActiveWuidStatus(const char* ClusterName, IEspECLWorkunit& wuStructure);
 };

plugins/fileservices/fileservices.cpp

@@ -544,8 +544,8 @@ static void blockUntilComplete(const char * label, IClientFileSpray &server, ICo
             RemainingLabel.append(wuScope).append(" (Remaining) ");
 
             //MORE: I think this are intended to replace the timing information, but will currently combine
-            updateWorkunitTimeStat(wu, "fileservices", wuScope, "elapsed", ElapsedLabel, milliToNano(time.elapsed()), 1, 0);
-            updateWorkunitTimeStat(wu, "fileservices", wuScope, "remaining", RemainingLabel, milliToNano(dfuwu.getSecsLeft()*1000), 1, 0);
+            updateWorkunitTimeStat(wu, SSTdfuworkunit, wuScope, StTimeElapsed, ElapsedLabel, milliToNano(time.elapsed()));
+            updateWorkunitTimeStat(wu, SSTdfuworkunit, wuScope, StTimeRemaining, RemainingLabel, milliToNano(dfuwu.getSecsLeft()*1000));
             wu->setApplicationValue(label, dfuwu.getID(), dfuwu.getSummaryMessage(), true);
             wu->commit();
         }

plugins/workunitservices/workunitservices.cpp

@@ -37,10 +37,12 @@ Persists changed?
 
 #include "workunit.hpp"
 #include "agentctx.hpp"
+#include "enginecontext.hpp"
 #include "portlist.h"
 
 #include "jio.hpp"
 #include "jmisc.hpp"
+#include "jstring.hpp"
 #include "dasess.hpp"
 #include "dasds.hpp"
 #include "dautils.hpp"
@@ -112,7 +114,9 @@ static const char * EclDefinition =
                             " unsigned8 value;"
                             " unsigned8 count;"
                             " unsigned8 maxValue;"
+                            " string creatorType;"
                             " string creator;"
+                            " string scopeType;"
                             " string scope;"
                             " string name;"
                             " string description;"
@@ -142,7 +146,7 @@ static const char * EclDefinition =
 "  dataset(WsFileRead) WorkunitFilesRead(const varstring wuid) : c,context,entrypoint='wsWorkunitFilesRead'; \n"
 "  dataset(WsFileWritten) WorkunitFilesWritten(const varstring wuid) : c,context,entrypoint='wsWorkunitFilesWritten'; \n"
 "  dataset(WsTiming) WorkunitTimings(const varstring wuid) : c,context,entrypoint='wsWorkunitTimings'; \n"
-"  streamed dataset(WsStatistic) WorkunitStatistics(const varstring wuid, boolean includeActivities = false) : c,context,entrypoint='wsWorkunitStatistics'; \n"
+"  streamed dataset(WsStatistic) WorkunitStatistics(const varstring wuid, boolean includeActivities = false, const varstring _filter = '') : c,context,entrypoint='wsWorkunitStatistics'; \n"
     
 "END;";
 
@@ -196,12 +200,33 @@ static void getSashaNodes(SocketEndpointArray &epa)
 }
 
 
+static IWorkUnitFactory * getWorkunitFactory(ICodeContext * ctx)
+{
+    IEngineContext *engineCtx = ctx->queryEngineContext();
+    if (engineCtx && !engineCtx->allowDaliAccess())
+    {
+        Owned<IException> e = MakeStringException(-1, "wokunitservices cannot access Dali in this context - this normally means it is being called from a thor slave");
+        EXCLOG(e, NULL);
+        throw e.getClear();
+    }
+
+    //MORE: These should really be set up correctly - probably should be returned from IEngineContext
+    ISecManager *secmgr = NULL;
+    ISecUser *secuser = NULL;
+    return getWorkUnitFactory(secmgr, secuser);
+}
+
+static IConstWorkUnit * getWorkunit(ICodeContext * ctx, const char * wuid)
+{
+    Owned<IWorkUnitFactory> wuFactory = getWorkunitFactory(ctx);
+    return wuFactory->openWorkUnit(wuid, false);
+}
+
 static IConstWorkUnit * getWorkunit(ICodeContext * ctx)
 {
-    Owned<IWorkUnitFactory> factory = getWorkUnitFactory();
     StringAttr wuid;
     wuid.setown(ctx->getWuid());
-    return factory->openWorkUnit(wuid, false);
+    return getWorkunit(ctx, wuid);
 }
 
 static IWorkUnit * updateWorkunit(ICodeContext * ctx)
@@ -693,42 +718,34 @@ WORKUNITSERVICES_API void wsWorkunitFilesWritten( ICodeContext *ctx, size32_t &
 
 WORKUNITSERVICES_API void wsWorkunitTimings( ICodeContext *ctx, size32_t & __lenResult, void * & __result, const char *wuid )
 {
-    unsigned tmp;
+    Owned<IConstWorkUnit> wu = getWorkunit(ctx, wuid);
     MemoryBuffer mb;
-    Owned<IPropertyTree> st = getWorkUnitBranch(ctx,wuid,"Statistics");
-    if (st)
+    if (wu)
     {
-        Owned<IPropertyTreeIterator> iter = st->getElements("Statistic[@unit=\"ns\"]");
-        ForEach(*iter) {
-            IPropertyTree &item = iter->query();
-            if (&item==NULL)
-                continue; // paranoia
-            tmp = (unsigned)item.getPropInt("@count");
+        StatisticsFilter filter;
+        filter.setMergeSources(false);
+        filter.setScopeDepth(1, 2);
+        filter.setMeasure(SMeasureTimeNs);
+
+        SCMStringBuffer desc;
+        unsigned tmp;
+        Owned<IConstWUStatisticIterator> iter = &wu->getStatistics(&filter);
+        ForEach(*iter)
+        {
+            IConstWUStatistic & cur = iter->query();
+
+            unsigned __int64 value = cur.getValue();
+            unsigned __int64 count = cur.getCount();
+            unsigned __int64 max = cur.getMax();
+            cur.getDescription(desc, true);
+
+            tmp = (unsigned)count;
             mb.append(sizeof(tmp),&tmp);
-            tmp = (unsigned)(item.getPropInt64("@value") / 1000000);
+            tmp = (unsigned)(value / 1000000);
             mb.append(sizeof(tmp),&tmp);
-            tmp = (unsigned)item.getPropInt("@max");
+            tmp = (unsigned)max;
             mb.append(sizeof(tmp),&tmp);
-            varAppend(mb, 64, item, "@desc");
-        }
-    }
-    else
-    {
-        Owned<IPropertyTree> pt = getWorkUnitBranch(ctx,wuid,"Timings");
-        if (pt) {
-            Owned<IPropertyTreeIterator> iter = pt->getElements("Timing");
-            ForEach(*iter) {
-                IPropertyTree &item = iter->query();
-                if (&item==NULL)
-                    continue; // paranoia
-                tmp = (unsigned)item.getPropInt("@count");
-                mb.append(sizeof(tmp),&tmp);
-                tmp = (unsigned)item.getPropInt("@duration");
-                mb.append(sizeof(tmp),&tmp);
-                tmp = (unsigned)item.getPropInt("@max");
-                mb.append(sizeof(tmp),&tmp);
-                varAppend(mb, 64, item, "@name");
-            }
+            varAppend(mb, desc.str());
         }
     }
     __lenResult = mb.length();
@@ -739,8 +756,8 @@ WORKUNITSERVICES_API void wsWorkunitTimings( ICodeContext *ctx, size32_t & __len
 class StreamedStatistics : public CInterfaceOf<IRowStream>
 {
 public:
-    StreamedStatistics(IEngineRowAllocator * _resultAllocator, IPropertyTreeIterator * _iter)
-    : resultAllocator(_resultAllocator),iter(_iter)
+    StreamedStatistics(IConstWorkUnit * _wu, IEngineRowAllocator * _resultAllocator, IConstWUStatisticIterator * _iter)
+    : wu(_wu), resultAllocator(_resultAllocator),iter(_iter)
     {
     }
 
@@ -749,33 +766,30 @@ public:
         if (!iter || !iter->isValid())
             return NULL;
 
-        IPropertyTree & cur = iter->query();
-        unsigned __int64 value = cur.getPropInt64("@value", 0);
-        unsigned __int64 count = cur.getPropInt64("@count", 0);
-        unsigned __int64 max = cur.getPropInt64("@max", 0);
-        const char * uid = cur.queryProp("@name");
-        const char * sep1 = strchr(uid, ';');
-        const char * scope = sep1+1;
-        const char * sep2 = strchr(scope, ';');
-        const char * name = sep2+1;
-        const char * desc = cur.queryProp("@desc");
-        const char * unit = cur.queryProp("@unit");
-        if (!desc) desc = "";
-
-        size32_t lenComponent = sep1-uid;
-        size32_t lenScope = sep2-scope;
-        size32_t lenName = strlen(name);
-        size32_t lenUnit = strlen(unit);
+        IConstWUStatistic & cur = iter->query();
+
+        unsigned __int64 value = cur.getValue();
+        unsigned __int64 count = cur.getCount();
+        unsigned __int64 max = cur.getMax();
+        StatisticCreatorType creatorType = cur.getCreatorType();
+        cur.getCreator(creator);
+        StatisticScopeType scopeType = cur.getScopeType();
+        cur.getScope(scope);
+        cur.getDescription(description, true);
+        StatisticMeasure measure = cur.getMeasure();
+        StatisticKind kind = cur.getKind();
 
         MemoryBuffer mb;
         mb.append(sizeof(value),&value);
         mb.append(sizeof(count),&count);
         mb.append(sizeof(max),&max);
-        varAppend(mb, lenComponent, uid);
-        varAppend(mb, lenScope, scope);
-        varAppend(mb, lenName, name);
-        varAppend(mb, desc);
-        varAppend(mb, unit);
+        varAppend(mb, queryCreatorTypeName(creatorType));
+        varAppend(mb, creator.str());
+        varAppend(mb, queryScopeTypeName(scopeType));
+        varAppend(mb, scope.str());
+        varAppend(mb, queryStatisticName(kind));
+        varAppend(mb, description.str());
+        varAppend(mb, queryMeasureName(measure));
 
         size32_t len = mb.length();
         size32_t newSize;
@@ -793,23 +807,25 @@ public:
 
 
 protected:
+    Linked<IConstWorkUnit> wu;
     Linked<IEngineRowAllocator> resultAllocator;
-    Linked<IPropertyTreeIterator> iter;
+    Linked<IConstWUStatisticIterator> iter;
+    SCMStringBuffer creator;
+    SCMStringBuffer scope;
+    SCMStringBuffer description;
 };
 
-WORKUNITSERVICES_API IRowStream * wsWorkunitStatistics( ICodeContext *ctx, IEngineRowAllocator * allocator, const char *wuid, bool includeActivities)
+WORKUNITSERVICES_API IRowStream * wsWorkunitStatistics( ICodeContext *ctx, IEngineRowAllocator * allocator, const char *wuid, bool includeActivities, const char * filterText)
 {
-    MemoryBuffer mb;
-    Owned<IPropertyTree> pt = getWorkUnitBranch(ctx,wuid,"Statistics");
-    Owned<IPropertyTreeIterator> iter;
-    if (pt)
-    {
-        iter.setown(pt->getElements("Statistic"));
-
-        //MORE - it includeActivities create an iterator over the progress information, and create a union iterator.
-        iter->first();
-    }
-    return new StreamedStatistics(allocator, iter);
+    Owned<IConstWorkUnit> wu = getWorkunit(ctx, wuid);
+    if (!wu)
+        return createNullRowStream();
+    //Filter needs to be allocated because the iterator outlasts it.
+    Owned<StatisticsFilter> filter = new StatisticsFilter(filterText);
+    if (!includeActivities)
+        filter->setMergeSources(false);
+    Owned<IConstWUStatisticIterator> stats = &wu->getStatistics(filter);
+    return new StreamedStatistics(wu, allocator, stats);
 }
 
 

plugins/workunitservices/workunitservices.hpp

@@ -67,7 +67,7 @@ WORKUNITSERVICES_API void WORKUNITSERVICES_CALL wsWorkunitMessages( ICodeContext
 WORKUNITSERVICES_API void WORKUNITSERVICES_CALL wsWorkunitFilesRead( ICodeContext *ctx, size32_t & __lenResult, void * & __result, const char *wuid );
 WORKUNITSERVICES_API void WORKUNITSERVICES_CALL wsWorkunitFilesWritten( ICodeContext *ctx, size32_t & __lenResult, void * & __result, const char *wuid );
 WORKUNITSERVICES_API void WORKUNITSERVICES_CALL wsWorkunitTimings( ICodeContext *ctx, size32_t & __lenResult, void * & __result, const char *wuid );
-WORKUNITSERVICES_API IRowStream * WORKUNITSERVICES_CALL wsWorkunitStatistics( ICodeContext *ctx, IEngineRowAllocator * allocator, const char *wuid, bool includeActivities);
+WORKUNITSERVICES_API IRowStream * WORKUNITSERVICES_CALL wsWorkunitStatistics( ICodeContext *ctx, IEngineRowAllocator * allocator, const char *wuid, bool includeActivities, const char * filterText);
 
 
 }

roxie/ccd/ccd.hpp

@@ -620,18 +620,6 @@ class StatsCollector : public CInterface, implements IInterface
         }
     }
 
-    inline static const char *getStatCombineModeName(StatisticCombineType type)
-    {
-        switch(type)
-        {
-            case STATSMODE_COMBINE_SUM: return "sum";
-            case STATSMODE_COMBINE_MAX: return "max";
-            case STATSMODE_COMBINE_MIN: return "min";
-            default:
-                throwUnexpected();
-        }
-    }
-
 public:
     IMPLEMENT_IINTERFACE;
     StatsCollector()
@@ -656,20 +644,7 @@ public:
             throw MakeStringException(ROXIE_ABORT_ERROR, "Roxie server requested abort for running activity");
         init();
         assert (statIdx < STATS_SIZE);
-        switch (getStatCombineMode(statIdx))
-        {
-        case STATSMODE_COMBINE_SUM:
-            cumulative[statIdx] += value;
-            break;
-        case STATSMODE_COMBINE_MAX:
-            if (!counts[statIdx] || cumulative[statIdx] <= value)
-                cumulative[statIdx] = value;
-            break;
-        case STATSMODE_COMBINE_MIN:
-            if (!counts[statIdx] || cumulative[statIdx] >= value)
-                cumulative[statIdx] = value;
-            break;
-        }
+        cumulative[statIdx] += value;
         counts[statIdx] += count;
     }
 
@@ -697,7 +672,8 @@ public:
                 {
                     StringBuffer prefix, text;
                     logctx.getLogPrefix(prefix);
-                    text.appendf("%s - %"I64F"d (%d instances)", getStatName(i), cumulative[i], counts[i]);
+                    StatisticKind kind = mapRoxieStatKind(i);
+                    text.appendf("%s - %"I64F"d (%d instances)", queryStatisticName(kind), cumulative[i], counts[i]);
                     logctx.CTXLOGa(LOG_STATISTICS, prefix.str(), text.str());
                 }
             }
@@ -709,10 +685,11 @@ public:
         SpinBlock b(lock);
         if (cumulative)
         {
+            const char * whoami = queryStatisticsComponentName();
             for (unsigned i = 0; i < STATS_SIZE; i++)
             {
                 if (counts[i])
-                    wu->setStatistic("roxie", "workunit", getStatShortName(i), getStatName(i), getStatMeasure(i), cumulative[i], counts[i], 0, false);
+                    wu->setStatistic(SCTroxie, whoami, SSTglobal, NULL, mapRoxieStatKind(i), NULL, cumulative[i], counts[i], 0, false);
             }
         }
     }
@@ -726,12 +703,29 @@ public:
             {
                 if (counts[i])
                 {
-                    putStatsValue(reply, getStatName(i), getStatCombineModeName(getStatCombineMode(i)), counts[i]);
+                    StatisticKind kind = mapRoxieStatKind(i);
+                    putStatsValue(reply, queryStatisticName(kind), "sum", counts[i]);
                 }
             }
         }
     }
 
+    void getProgressInfo(IStatisticGatherer & builder) const
+    {
+        SpinBlock b(lock);
+        if (cumulative)
+        {
+            for (unsigned i = 0; i < STATS_SIZE; i++)
+            {
+                if (counts[i])
+                {
+                    builder.addStatistic(mapRoxieStatKind(i), counts[i]);
+                }
+            }
+        }
+    }
+
+
     void getNodeProgressInfo(IPropertyTree &node) const
     {
         SpinBlock b(lock);
@@ -741,7 +735,9 @@ public:
             {
                 if (counts[i])
                 {
-                    putStatsValue(&node, getStatShortName(i), getStatCombineModeName(getStatCombineMode(i)), counts[i]);
+                    StatisticKind kind = mapRoxieStatKind(i);
+                    const char * statsName = queryStatisticName(kind);
+                    putStatsValue(&node, statsName, "sum", counts[i]);
                 }
             }
         }

roxie/ccd/ccdcontext.cpp

@@ -1242,17 +1242,27 @@ public:
             activityContext.getLogPrefix(prefix);
             CTXLOGa(LOG_TIMING, prefix.str(), text.str());
         }
-        if (graphProgress)
+        if (graphStats)
         {
-            IPropertyTree& nodeProgress = graphProgress->updateNode(activity->querySubgraphId(), activity->queryId());
-            nodeProgress.setPropInt64("@totalTime", (unsigned) (cycle_to_nanosec(_totalCycles)/1000));
-            nodeProgress.setPropInt64("@localTime", (unsigned) (cycle_to_nanosec(_localCycles)/1000));
+            IStatisticGatherer & builder = graphStats->queryStatsBuilder();
+            StatsSubgraphScope graphScope(builder, activity->querySubgraphId());
+
+            {
+                StatsActivityScope scope(builder, activity->queryId());
+                //MORE: This is potentially problematic if noteProcessed is called for multiple edges => check if totalCycles is 0.
+                //There should really be two separate functions - one to update activity statistics, and another for edge statistics
+                if (_totalCycles)
+                {
+                    builder.addStatistic(StTimeTotalExecute, cycle_to_nanosec(_totalCycles));
+                    builder.addStatistic(StTimeLocalExecute, cycle_to_nanosec(_localCycles));
+                }
+                //MORE: Should this be done via a callback instead - so the activity can add stats for when started + other interesting info
+            }
+
             if (_processed)
             {
-                StringBuffer edgeId;
-                edgeId.append(activity->queryId()).append('_').append(_idx);
-                IPropertyTree& edgeProgress = graphProgress->updateEdge(activity->querySubgraphId(), edgeId.str());
-                edgeProgress.setPropInt64("@count", _processed);
+                StatsEdgeScope scope(builder, activity->queryId(), _idx);
+                builder.addStatistic(StNumRowsProcessed, _processed);
             }
         }
     }
@@ -1395,7 +1405,7 @@ public:
             debugContext->checkBreakpoint(DebugStateGraphStart, NULL, graphName);
     }
 
-    Owned<IWUGraphProgress> graphProgress; // could make local to endGraph and pass to reset - might be cleaner
+    Owned<IWUGraphStats> graphStats; // could make local to endGraph and pass to reset - might be cleaner
     virtual void endGraph(cycle_t startCycles, bool aborting)
     {
         if (graph)
@@ -1411,17 +1421,17 @@ public:
             {
                 progressWorkUnit.setown(&workUnit->lock());
                 progress.setown(progressWorkUnit->getGraphProgress(graph->queryName()));
-                graphProgress.setown(progress->update());
+                graphStats.setown(progress->update(SCTroxie, queryStatisticsComponentName(), 0));
 
                 const char * graphName = graph->queryName();
                 StringBuffer graphDesc;
                 formatGraphTimerLabel(graphDesc, graphName);
-                updateWorkunitTimeStat(progressWorkUnit, "roxie", graphName, "time", graphDesc, elapsedTime, 1, 0);
+                updateWorkunitTimeStat(progressWorkUnit, SSTgraph, graphName, StTimeElapsed, graphDesc, elapsedTime);
             }
             graph->reset();
-            if (graphProgress)
+            if (graphStats)
             {
-                graphProgress.clear();
+                graphStats.clear();
                 progress.clear();
             }
             graph.clear();
@@ -2593,7 +2603,7 @@ protected:
     {
         WorkunitUpdate wu(&workUnit->lock());
         wu->subscribe(SubscribeOptionAbort);
-        wu->addTimeStamp("Roxie", GetCachedHostName(), "Started");
+        addTimeStamp(wu, SSTglobal, NULL, StWhenQueryStarted);
         if (!context->getPropBool("@outputToSocket", false))
             client = NULL;
         updateSuppliedXmlParams(wu);
@@ -2845,9 +2855,9 @@ public:
         {
             WorkunitUpdate w(&workUnit->lock());
             w->setState(aborted ? WUStateAborted : (failed ? WUStateFailed : WUStateCompleted));
-            w->addTimeStamp("Roxie", GetCachedHostName(), "Finished");
+            addTimeStamp(w, SSTglobal, NULL, StWhenQueryFinished);
             ITimeReporter *timer = logctx.queryTimer();
-            updateWorkunitTimings(w, timer, "roxie");
+            updateWorkunitTimings(w, timer);
             logctx.dumpStats(w);
 
             WuStatisticTarget statsTarget(w, "roxie");

roxie/ccd/ccdmain.cpp

@@ -529,6 +529,11 @@ int STARTQUERY_API start_query(int argc, const char *argv[])
             }
         }
         topology->getProp("@name", roxieName);
+        if (roxieName.length())
+            setStatisticsComponentName(SCTroxie, roxieName, true);
+        else
+            setStatisticsComponentName(SCTroxie, "roxie", true);
+
         Owned<const IQueryDll> standAloneDll;
         if (globals->hasProp("--loadWorkunit"))
         {

roxie/roxiemem/roxiemem.cpp

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

system/include/platform.h

@@ -472,6 +472,7 @@ typedef unsigned __int64 hash64_t;
 typedef unsigned __int64 __uint64;
 typedef __uint64 offset_t;
 typedef unsigned char byte;
+typedef __int64 cycle_t;
 
 // BUILD_TAG not needed here anymore - defined in build_tag.h
 //#define BUILD_TAG "build_0000" // Will get substituted during pre-build

system/jlib/jbroadcast.cpp

@@ -840,7 +840,7 @@ public:
         unsigned offset = 0;
 
 #ifdef _DEBUG
-        MTimeSection * mt = new MTimeSection(queryActiveTimer(), "ServerBroadcast", "SERVER BROADCAST"); // MORE is ServerBroadcast a scope (where) or a name (what)?
+        MTimeSection * mt = new MTimeSection(queryActiveTimer(), "ServerBroadcast"); // MORE is ServerBroadcast a scope (where) or a name (what)?
 #endif
 
         unsigned maxDataSz = MC_PACKET_SIZE-sizeof(MCPacketHeader);

system/jlib/jdebug.cpp

@@ -1,6 +1,5 @@
 /*##############################################################################
 
-    HPCC SYSTEMS software Copyright (C) 2012 HPCC Systems.
 
     Licensed under the Apache License, Version 2.0 (the "License");
     you may not use this file except in compliance with the License.
@@ -263,6 +262,16 @@ __int64 cycle_to_nanosec(cycle_t cycles)
     return (__int64)((double)cycles * cycleToNanoScale);
 }
 
+__int64 jlib_decl cycle_to_microsec(cycle_t cycles)
+{
+    return (__int64)((double)cycles * cycleToNanoScale) / 1000;
+}
+
+__int64 jlib_decl cycle_to_millisec(cycle_t cycles)
+{
+    return (__int64)((double)cycles * cycleToNanoScale) / 1000000;
+}
+
 cycle_t nanosec_to_cycle(__int64 ns)
 {
     return (__int64)((double)ns / cycleToNanoScale);
@@ -288,7 +297,9 @@ static bool use_gettimeofday=false;
 #if defined(_ARCH_X86_) || defined(_ARCH_X86_64_)
 static bool useRDTSC = _USE_RDTSC;
 #endif
-static double cycleToNanoScale; 
+static double cycleToNanoScale;
+static double cycleToMicroScale;
+static double cycleToMilliScale;
 
 void calibrate_timing()
 {
@@ -328,6 +339,8 @@ void calibrate_timing()
             if (numPerUS>0)
             {
                 cycleToNanoScale = 1000.0 / numPerUS;
+                cycleToMicroScale = 1.0 / numPerUS;
+                cycleToMilliScale = 0.001 / numPerUS;
                 return;
             }
         }
@@ -368,6 +381,24 @@ __int64 jlib_decl cycle_to_nanosec(cycle_t cycles)
     return cycles;
 }
 
+__int64 jlib_decl cycle_to_microsec(cycle_t cycles)
+{
+#if defined(_ARCH_X86_) || defined(_ARCH_X86_64_)
+    if (useRDTSC)
+        return (__int64)((double)cycles * cycleToMicroScale);
+#endif
+    return cycles / 1000;
+}
+
+__int64 jlib_decl cycle_to_millisec(cycle_t cycles)
+{
+#if defined(_ARCH_X86_) || defined(_ARCH_X86_64_)
+    if (useRDTSC)
+        return (__int64)((double)cycles * cycleToMilliScale);
+#endif
+    return cycles / 1000000;
+}
+
 cycle_t nanosec_to_cycle(__int64 ns)
 {
 #if defined(_ARCH_X86_) || defined(_ARCH_X86_64_)
@@ -402,16 +433,16 @@ TimeSection::~TimeSection()
     display_time(title, end_time-start_time);
 }
 
-MTimeSection::MTimeSection(ITimeReporter *_master, const char * _scope, const char * _title) : scope(_scope), title(_title), master(_master)
+MTimeSection::MTimeSection(ITimeReporter *_master, const char * _scope) : scope(_scope), master(_master)
 {
-  start_time = get_cycles_now();
+    start_time = get_cycles_now();
 }
 
 MTimeSection::~MTimeSection()
 {
     cycle_t end_time = get_cycles_now();
     if (master)
-        master->addTiming(scope, title, end_time-start_time);
+        master->addTiming(scope, end_time-start_time);
     else
         display_time(title, end_time-start_time);
 }
@@ -482,10 +513,10 @@ public:
         for(iter.first(); iter.isValid(); iter.next())
         {
             TimeSectionInfo &ts = (TimeSectionInfo &)iter.query();
-            cb.report(ts.scope, ts.description, ts.totalcycles, ts.maxcycles, ts.count);
+            cb.report(ts.scope, ts.description, cycle_to_nanosec(ts.totalcycles), cycle_to_nanosec(ts.maxcycles), ts.count);
         }
     }
-    virtual void addTiming(const char * scope, const char *desc, unsigned __int64 cycles)
+    virtual void addTiming(const char * scope, unsigned __int64 cycles)
     {
         CriticalBlock b(c);
         TimeSectionInfo *info = sections->find(scope);
@@ -497,7 +528,7 @@ public:
         }
         else
         {
-            TimeSectionInfo &newinfo = * new TimeSectionInfo(scope, desc, cycles);
+            TimeSectionInfo &newinfo = * new TimeSectionInfo(scope, NULL, cycles);
             sections->replaceOwn(newinfo);
         }
     }
@@ -506,6 +537,14 @@ public:
         CriticalBlock b(c);
         return sections->count();
     }
+    virtual StatisticKind getTimerType(unsigned idx)
+    {
+        return StTimeElapsed;
+    }
+    virtual StatisticScopeType getScopeType(unsigned idx)
+    {
+        return SSTsection;
+    }
     virtual __int64 getTime(unsigned idx)
     {
         CriticalBlock b(c);
@@ -526,11 +565,6 @@ public:
         CriticalBlock b(c);
         return s.append(findSection(idx).scope);
     }
-    virtual StringBuffer &getDescription(unsigned idx, StringBuffer &s)
-    {
-        CriticalBlock b(c);
-        return s.append(findSection(idx).description);
-    }
     virtual void reset()
     {
         CriticalBlock b(c);
@@ -543,7 +577,8 @@ public:
         if (numSections())
         {
             for (unsigned i = 0; i < numSections(); i++)
-                getDescription(i, str.append("Timing: ")).append(" total=")
+            {
+                getScope(i, str.append("Timing: ")).append(" total=")
                                          .append(getTime(i)/1000000)
                                          .append("ms max=")
                                          .append(getMaxTime(i)/1000)
@@ -552,6 +587,7 @@ public:
                                          .append(" ave=")
                                          .append((getTime(i)/1000)/getCount(i))
                                          .append("us\n");
+            }
         }
         return str;
     }
@@ -564,13 +600,13 @@ public:
             PrintLog(getTimings(str).str());
         }
     }
-    virtual void mergeTiming(const char * scope, const char *desc, const __int64 totalcycles, const __int64 maxcycles, const unsigned count)
+    virtual void mergeTiming(const char * scope, const __int64 totalcycles, const __int64 maxcycles, const unsigned count)
     {
         CriticalBlock b(c);
         TimeSectionInfo *info = sections->find(scope);
         if (!info)
         {
-            info = new TimeSectionInfo(scope, desc, totalcycles, maxcycles, count);
+            info = new TimeSectionInfo(scope, NULL, totalcycles, maxcycles, count);
             sections->replaceOwn(*info);
         }
         else
@@ -587,7 +623,7 @@ public:
         for(iter.first(); iter.isValid(); iter.next())
         {
             TimeSectionInfo &ts = (TimeSectionInfo &) iter.query();
-            other.mergeTiming(ts.scope, ts.description, ts.totalcycles, ts.maxcycles, ts.count);
+            other.mergeTiming(ts.scope, ts.totalcycles, ts.maxcycles, ts.count);
         }
     }
     virtual void merge(ITimeReporter &other)

system/jlib/jdebug.hpp

@@ -21,12 +21,13 @@
 #define JDEBUG_HPP
 
 #include "jiface.hpp"
+#include "jstats.h"
 
 #define TIMING
 
-typedef __int64 cycle_t;
-
 __int64 jlib_decl cycle_to_nanosec(cycle_t cycles);
+__int64 jlib_decl cycle_to_microsec(cycle_t cycles);
+__int64 jlib_decl cycle_to_millisec(cycle_t cycles);
 cycle_t jlib_decl nanosec_to_cycle(__int64 cycles);
 cycle_t jlib_decl get_cycles_now();  // equivalent to getTSC when available
 double jlib_decl getCycleToNanoScale();
@@ -90,14 +91,15 @@ class StringBuffer;
 class MemoryBuffer;
 struct ITimeReporter : public IInterface
 {
-  virtual void addTiming(const char * scope, const char *desc, unsigned __int64 cycles) = 0;
-  virtual void mergeTiming(const char * scope, const char *desc, const __int64 totalcycles, const __int64 maxcycles, const unsigned count) = 0;
+  virtual void addTiming(const char * scope, unsigned __int64 cycles) = 0;
+  virtual void mergeTiming(const char * scope, const __int64 totalcycles, const __int64 maxcycles, const unsigned count) = 0;
   virtual unsigned numSections() = 0;
   virtual __int64 getTime(unsigned idx) = 0;
   virtual __int64 getMaxTime(unsigned idx) = 0;
   virtual unsigned getCount(unsigned idx) = 0;
+  virtual StatisticKind getTimerType(unsigned idx) = 0;
+  virtual StatisticScopeType getScopeType(unsigned idx) = 0;
   virtual StringBuffer &getScope(unsigned idx, StringBuffer &s) = 0;
-  virtual StringBuffer &getDescription(unsigned idx, StringBuffer &s) = 0;
   virtual StringBuffer &getTimings(StringBuffer &s) = 0;
   virtual void printTimings() = 0;
   virtual void reset() = 0;
@@ -126,7 +128,7 @@ public:
     }
     inline unsigned elapsedMs()
     {
-        return static_cast<unsigned>(cycle_to_nanosec(elapsedCycles())/1000000);
+        return static_cast<unsigned>(cycle_to_millisec(elapsedCycles()));
     }
 };
 inline cycle_t queryOneSecCycles() { return oneSecInCycles; }
@@ -145,7 +147,7 @@ protected:
 class jlib_decl MTimeSection
 {
 public:
-  MTimeSection(ITimeReporter *_master, const char * scope, const char * _title);
+  MTimeSection(ITimeReporter *_master, const char * scope);
   ~MTimeSection();
 protected:
   const char * scope;
@@ -160,7 +162,7 @@ extern jlib_decl ITimeReporter * queryActiveTimer();
 extern jlib_decl ITimeReporter *createStdTimeReporter();
 extern jlib_decl ITimeReporter *createStdTimeReporter(MemoryBuffer &mb);
 #define TIME_SECTION(title)   TimeSection   glue(_timer,__LINE__)(title);
-#define MTIME_SECTION(master,title)  MTimeSection   glue(mtimer,__LINE__)(master, "workunit;" title, title);
+#define MTIME_SECTION(master,title)  MTimeSection   glue(mtimer,__LINE__)(master, title);
 #else
 #define TIME_SECTION(title)   
 #define MTIME_SECTION(master,title)

system/jlib/jiter.ipp

@@ -39,7 +39,7 @@ public:
   virtual IInterface &_query();
 };
 
-class jlib_decl CArrayIterator : public CArrayIteratorBase , implements IIterator
+class jlib_decl CArrayIterator : public CArrayIteratorBase, implements IIterator
 {
 public:
   IMPLEMENT_IINTERFACE;
@@ -72,11 +72,9 @@ public:
     ~COwnedArrayIterator();
 };
 
-class jlib_decl CNullIterator : public CInterface, public IIterator
+class jlib_decl CNullIterator : public CInterfaceOf<IIterator>
 {
 public:
-    IMPLEMENT_IINTERFACE
-
     virtual bool first() { return false; }
     virtual bool next()  { return false; }
     virtual bool isValid() { return false; }
@@ -84,4 +82,50 @@ public:
     virtual IInterface & get()   { IInterface * i = 0; return *i; }
 };
 
+template<class X, class Y> class jlib_decl CNullIteratorOf : public CInterfaceOf<Y>
+{
+public:
+    virtual bool first() { return false; }
+    virtual bool next()  { return false; }
+    virtual bool isValid() { return false; }
+    virtual X & query() { X * i = 0; return *i; }
+    virtual X & get()   { X * i = 0; return *i; }
+};
+
+template<class X, class Y> class CCompoundIteratorOf : public CInterfaceOf<X>
+{
+public:
+    CCompoundIteratorOf(X * _left, X * _right) : left(_left), right(_right)
+    {
+        doneLeft = true;
+    }
+    virtual bool first()
+    {
+        doneLeft = false;
+        if (left->first())
+            return true;
+        doneLeft = true;
+        return right->first();
+    }
+    virtual bool next()
+    {
+        if (!doneLeft)
+        {
+            if (left->next())
+                return true;
+            doneLeft = true;
+            return right->first();
+        }
+        return right->next();
+    }
+    virtual bool isValid() { return doneLeft ? right->isValid() : left->isValid(); }
+    virtual Y & query() { return doneLeft ? right->query() : left->query();}
+
+protected:
+    Linked<X> left;
+    Linked<X> right;
+    bool doneLeft;
+};
+
+
 #endif

system/jlib/jregexp.cpp

@@ -1300,6 +1300,23 @@ bool jlib_decl WildMatch(const char *src, const char *pat, bool nocase)
     return WildMatch(src,(size32_t)strlen(src),pat,(size32_t)strlen(pat),nocase);
 }
 
+bool jlib_decl containsWildcard(const char * pattern)
+{
+    loop
+    {
+        char c = *pattern++;
+        switch (c)
+        {
+        case 0:
+            return false;
+        case '?':
+        case '*':
+            return true;
+        }
+    }
+}
+
+
 static bool WildMatchNreplace ( const char *src, int srclen, int srcidx,
                                const char *pat, int patlen, int patidx,
                                int nocase,

system/jlib/jregexp.hpp

@@ -103,6 +103,7 @@ bool jlib_decl WildMatch(const char *src, int srclen, const char *pat, int patle
 bool jlib_decl WildMatch(const char *src, const char *pat, bool nocase=false);
 bool jlib_decl WildMatchReplace(const char *src, const char *pat, const char *repl, bool nocase, StringBuffer &out);
 bool jlib_decl SoundexMatch(const char *src, const char *pat);
+bool jlib_decl containsWildcard(const char * pattern);
 
 
 class jlib_decl StringMatcher

system/jlib/jstats.h

@@ -21,14 +21,11 @@
 
 #include "jlib.hpp"
 
-enum StatisticCombineType
-{
-    STATSMODE_COMBINE_SUM,
-    STATSMODE_COMBINE_MAX,
-    STATSMODE_COMBINE_MIN
-};
+#define ActivityScopePrefix "a"
+#define EdgeScopePrefix "e"
+#define SubGraphScopePrefix "sg"
 
-enum StatisticType
+enum OldStatsKind
 {
     STATS_INDEX_SEEKS,
     STATS_INDEX_SCANS,
@@ -60,25 +57,375 @@ enum StatisticType
     STATS_SIZE
 };
 
+enum CombineStatsAction
+{
+    MergeStats,
+    ReplaceStats,
+    AppendStats,
+};
+
+enum StatisticCreatorType
+{
+    SCTnone,
+    SCTall,
+    SCTunknown,
+    SCThthor,
+    SCTroxie,
+    SCTroxieSlave,
+    SCTthor,
+    SCTthorMaster,
+    SCTthorSlave,
+    SCTeclcc,
+    SCTesp,
+    SCTsummary,                         // used to maintain the summary time over all thors (mainly for sorting)
+    SCTmax,
+};
+
+enum StatisticScopeType
+{
+    SSTnone,
+    SSTall,
+    SSTglobal,                          // root scope
+    SSTgraph,                           // identifies a graph
+    SSTsubgraph,
+    SSTactivity,
+    SSTallocator,                       // identifies an allocator
+    SSTsection,                         // A section within the query - not a great differentiator
+    SSTcompilestage,                    // a stage within the compilation process
+    SSTdfuworkunit,                     // a reference to an executing dfu workunit
+    SSTedge,
+    SSTmax
+};
+
 enum StatisticMeasure
 {
-    SMEASURE_TIME_NS,
-    SMEASURE_COUNT,
-    SMEASURE_MEM_KB,
-    SMEASURE_MAX
+    SMeasureNone,
+    SMeasureAll,
+    SMeasureTimeNs,                     // Elapsed time in nanoseconds
+    SMeasureTimestampUs,                // timestamp/when - a point in time (to the microsecond)
+    SMeasureCount,                      // a count of the number of occurrences
+    SMeasureSize,                       // a quantity of memory (or disk) measured in bytes
+    SMeasureLoad,                       // measure of cpu activity (stored as 1/1000000 core)
+    SMeasureSkew,                       // a measure of skew. 0 = perfectly balanced, range [-10000..infinity]
+    SMeasureNode,                       // A node number within a cluster (0 = master)
+    SMeasurePercent,                    // actually stored as parts per million, displayed as a percentage
+    SMeasureIPV4,
+    SMeasureMax,
+};
+
+//This macro can be used to generate multiple variations of a statistics kind, but probably not needed any more
+//e.g.,     DEFINE_SKEW_STAT(Time, Elapsed)
+
+#define DEFINE_SKEW_STAT(x, y) \
+    St ## x ## Min ## y = (St ## x ## y | StMinX), \
+    St ## x ## Max ## y = (St ## x ## y | StMaxX), \
+    St ## x ## Ave ## y = (St ## x ## y | StAvgX), \
+    St ## Skew ## y = (St ## x ## y | StSkew), \
+    St ## SkewMin ## y = (St ## x ## y | StSkewMin), \
+    St ## SkewMax ## y = (St ## x ## y | StSkewMax), \
+    St ## NodeMin ## y = (St ## x ## y | StNodeMin), \
+    St ## NodeMax ## y = (St ## x ## y | StNodeMax),
+
+//The values in this enumeration are stored persistently.  The associated values must not be changed.
+//If you add an entry here you must also update queryMeasure(), queryStatisticName() and queryTreeTag()
+//NOTE: All statistic names should be unique with the type prefix removed. Since the prefix is replaced with Skew/Min/etc.
+enum StatisticKind
+{
+    StKindNone,
+    StKindAll,
+
+    StWhenGraphStarted,                 // When a graph starts
+    StWhenGraphFinished,                // When a graph stopped
+    StWhenFirstRow,                     // When the first row is processed by slave activity
+    StWhenQueryStarted,
+    StWhenQueryFinished,
+    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,                   // Is measurement in K appropriate?
+
+    StNumRowsProcessed,                 // on edge
+    StNumSlaves,                        // on edge
+    StNumStarted,                       // on edge
+    StNumStopped,                       // on edge
+    StNumIndexSeeks,
+    StNumIndexScans,
+    StNumIndexWildSeeks,
+    StNumIndexSkips,
+    StNumIndexNullSkips,
+    StNumIndexMerges,
+    StNumIndexMergeCompares,
+    StNumPreFiltered,
+    StNumPostFiltered,
+    StNumBlobCacheHits,
+    StNumLeafCacheHits,
+    StNumNodeCacheHits,
+    StNumBlobCacheAdds,
+    StNumLeafCacheAdds,
+    StNumNodeCacheAdds,
+    StNumPreloadCacheHits,
+    StNumPreloadCacheAdds,
+    StNumServerCacheHits,
+    StNumIndexAccepted,
+    StNumIndexRejected,
+    StNumAtmostTriggered,
+    StNumDiskSeeks,
+    StNumIterations,
+    StLoadWhileSorting,                 // Average load while processing a sort?
+    StNumLeftRows,
+    StNumRightRows,
+    StPerReplicated,
+    StNumDiskRowsRead,
+    StNumIndexRowsRead,
+    StNumDiskAccepted,
+    StNumDiskRejected,
+
+    StMax,
+
+    //For any quantity there is potentially the following variants.
+    //These modifiers ORd with the values above to form a compound type.
+    StKindMask                          = 0x0ffff,
+    StMinX                              = 0x10000,  // the minimum value
+    StMaxX                              = 0x20000,  // the maximum value
+    StAvgX                              = 0x30000,  // the average value
+    StSkew                              = 0x40000,  // the skew on a particular node
+    StSkewMin                           = 0x50000,  // the minimum skew
+    StSkewMax                           = 0x60000,  // the maximum skew
+    StNodeMin                           = 0x70000,  // the node containing the minimum
+    StNodeMax                           = 0x80000,  // the node containing the maximum
+    StDeltaX                            = 0x90000,  // a difference in the value of X
+
+};
+
+interface IStatistic : extends IInterface
+{
+public:
+    virtual StatisticKind queryKind() const = 0;
+    virtual unsigned __int64 queryValue() const = 0;
+};
+
+interface IStatisticFilter
+{
+    virtual bool matches(IStatistic * stats) = 0;
+    virtual void getFilter(StringBuffer & out) = 0;
+};
+
+interface IStatisticIterator : public IIteratorOf<IStatistic>
+{
+};
+
+interface IStatisticCollectionIterator;
+interface IStatisticCollection : public IInterface
+{
+public:
+    virtual StatisticScopeType queryScopeType() const = 0;
+    virtual IStringVal & getFullScope(IStringVal & str) const = 0;
+    virtual const char * queryScope(IStringVal & str) const = 0;                    // optional if the argument is used.
+    virtual unsigned __int64 queryStatistic(StatisticKind kind) const = 0;
+    virtual IStatisticCollection * queryCollection(const char * scope) = 0;
+    virtual IStatisticIterator & getStatistics(/*filter*/) = 0;
+    virtual IStatisticCollectionIterator & getScopes(const char * filter) = 0;
+    virtual void getMinMaxScope(IStringVal & minValue, IStringVal & maxValue, StatisticScopeType searchScopeType) const = 0;
+    virtual void getMinMaxActivity(unsigned & minValue, unsigned & maxValue) const = 0;
+    virtual void serialize(MemoryBuffer & out) const = 0;
+    virtual unsigned __int64 queryWhenCreated() const = 0;
+};
+
+interface IStatisticCollectionIterator : public IIteratorOf<IStatisticCollection>
+{
+};
+
+interface IStatisticGatherer : public IInterface
+{
+public:
+    virtual void beginScope(StatisticScopeType scopeType, const char * scope) = 0;
+    virtual void beginSubGraphScope(unsigned id) = 0;
+    virtual void beginActivityScope(unsigned id) = 0;
+    virtual void beginEdgeScope(unsigned id, unsigned oid) = 0;
+    virtual void endScope() = 0;
+    virtual void addStatistic(StatisticKind kind, unsigned __int64 value) = 0;
+    virtual IStatisticCollection * getResult() = 0;
+};
+
+class StatsScopeBlock
+{
+public:
+    inline StatsScopeBlock(IStatisticGatherer & _gatherer) : gatherer(_gatherer)
+    {
+    }
+    inline ~StatsScopeBlock()
+    {
+        gatherer.endScope();
+    }
+
+protected:
+    IStatisticGatherer & gatherer;
+};
+
+class StatsSubgraphScope : public StatsScopeBlock
+{
+public:
+    inline StatsSubgraphScope(IStatisticGatherer & _gatherer, unsigned id) : StatsScopeBlock(_gatherer)
+    {
+        gatherer.beginSubGraphScope(id);
+    }
+};
+
+class StatsActivityScope : public StatsScopeBlock
+{
+public:
+    inline StatsActivityScope(IStatisticGatherer & _gatherer, unsigned id) : StatsScopeBlock(_gatherer)
+    {
+        gatherer.beginActivityScope(id);
+    }
+};
+
+class StatsEdgeScope : public StatsScopeBlock
+{
+public:
+    inline StatsEdgeScope(IStatisticGatherer & _gatherer, unsigned id, unsigned oid) : StatsScopeBlock(_gatherer)
+    {
+        gatherer.beginEdgeScope(id, oid);
+    }
+};
+
+//All filtering should go through this interface - so we can extend and allow AND/OR filters at a later date.
+interface IStatisticsFilter : public IInterface
+{
+public:
+    virtual bool matches(StatisticCreatorType curCreatorType, const char * curCreator, StatisticScopeType curScopeType, const char * curScope, StatisticMeasure curMeasure, StatisticKind curKind) const = 0;
+    //These are a bit arbitrary...
+    virtual bool queryMergeSources() const = 0;
+    virtual const char * queryScope() const = 0;
+
+};
+
+class ScopedItemFilter
+{
+public:
+    ScopedItemFilter() : minDepth(0), maxDepth(0), hasWildcard(false) {}
+
+    bool match(const char * search) const;
+    bool matchDepth(unsigned low, unsigned high) const;
+
+    const char * queryValue() const { return value ? value.get() : "*"; }
+
+    void set(const char * value);
+    void setDepth(unsigned _minDepth);
+    void setDepth(unsigned _minDepth, unsigned _maxDepth);
+
+protected:
+    unsigned minDepth;
+    unsigned maxDepth;
+    StringAttr value;
+    bool hasWildcard;
 };
 
-extern jlib_decl const char *getStatName(unsigned i);
-extern jlib_decl const char *getStatShortName(unsigned i);
+class jlib_decl StatisticsFilter : public CInterfaceOf<IStatisticsFilter>
+{
+public:
+    StatisticsFilter();
+    StatisticsFilter(const char * filter);
+    StatisticsFilter(StatisticCreatorType _creatorType, StatisticScopeType _scopeType, StatisticMeasure _measure, StatisticKind _kind);
+    StatisticsFilter(const char * _creatorType, const char * _scopeType, const char * _kind);
+    StatisticsFilter(const char * _creatorTypeText, const char * _creator, const char * _scopeTypeText, const char * _scope, const char * _measureText, const char * _kindText);
+    StatisticsFilter(StatisticCreatorType _creatorType, const char * _creator, StatisticScopeType _scopeType, const char * _scope, StatisticMeasure _measure, StatisticKind _kind);
+
+    virtual bool matches(StatisticCreatorType curCreatorType, const char * curCreator, StatisticScopeType curScopeType, const char * curScope, StatisticMeasure curMeasure, StatisticKind curKind) const;
+    virtual bool queryMergeSources() const { return mergeSources && scopeFilter.matchDepth(2,0); }
+    virtual const char * queryScope() const { return scopeFilter.queryValue(); }
+
+    void set(const char * _creatorTypeText, const char * _scopeTypeText, const char * _kindText);
+    void set(const char * _creatorTypeText, const char * _creator, const char * _scopeTypeText, const char * _scope, const char * _measureText, const char * _kindText);
+
+    void setCreatorDepth(unsigned _minCreatorDepth, unsigned _maxCreatorDepth);
+    void setCreator(const char * _creator);
+    void setCreatorType(StatisticCreatorType _creatorType);
+    void setFilter(const char * filter);
+    void setScopeDepth(unsigned _minScopeDepth);
+    void setScopeDepth(unsigned _minScopeDepth, unsigned _maxScopeDepth);
+    void setScope(const char * _scope);
+    void setScopeType(StatisticScopeType _scopeType);
+    void setKind(StatisticKind _kind);
+    void setKind(const char * _kind);
+    void setMeasure(StatisticMeasure _measure);
+    void setMergeSources(bool _value);      // set to false for legacy timing semantics
+
+protected:
+    void init();
+
+protected:
+    StatisticCreatorType creatorType;
+    StatisticScopeType scopeType;
+    StatisticMeasure measure;
+    StatisticKind kind;
+    ScopedItemFilter creatorFilter;
+    ScopedItemFilter scopeFilter;
+    bool mergeSources;
+};
+
+//A class for minimizing the overhead of collecting timestamps.
+class jlib_decl OptimizedTimestamp
+{
+public:
+    OptimizedTimestamp();
+
+    unsigned __int64 getTimeStampNowValue();
+
+protected:
+    cycle_t lastCycles;
+    unsigned __int64 lastTimestamp;
+};
+
+class IpAddress;
+
+extern jlib_decl unsigned __int64 getTimeStampNowValue();
+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 StatisticMeasure queryMeasure(StatisticKind kind);
+extern jlib_decl const char * queryStatisticName(StatisticKind kind);
+extern jlib_decl void queryLongStatisticName(StringBuffer & out, StatisticKind kind);
+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 StatisticMeasure queryMeasure(const char *  measure);
+extern jlib_decl StatisticKind queryStatisticKind(const char *  kind);
+extern jlib_decl StatisticCreatorType queryCreatorType(const char * sct);
+extern jlib_decl StatisticScopeType queryScopeType(const char * sst);
+
+extern IStatisticGatherer * createStatisticsGatherer(StatisticCreatorType creatorType, const char * creator, StatisticScopeType scopeType, const char * rootScope);
+extern jlib_decl void serializeStatisticCollection(MemoryBuffer & out, IStatisticCollection * collection);
+extern jlib_decl IStatisticCollection * createStatisticCollection(MemoryBuffer & in);
+
+
+extern jlib_decl StatisticKind mapRoxieStatKind(unsigned i); // legacy
 extern jlib_decl StatisticMeasure getStatMeasure(unsigned i);
-extern jlib_decl StatisticCombineType getStatCombineMode(unsigned i);
 inline unsigned __int64 milliToNano(unsigned __int64 value) { return value * 1000000; } // call avoids need to upcast values
 inline unsigned __int64 nanoToMilli(unsigned __int64 value) { return value / 1000000; }
 
+extern jlib_decl StatisticCreatorType queryStatisticsComponentType();
+extern jlib_decl const char * queryStatisticsComponentName();
+extern jlib_decl void setStatisticsComponentName(StatisticCreatorType processType, const char * processName, bool appendIP);
+
+extern jlib_decl void verifyStatisticFunctions();
+
 //This interface is primarily here to reduce the dependency between the different components.
 interface IStatisticTarget
 {
-    virtual void addStatistic(const char * creator_who, const char * wuScope_where, const char * stat_what, const char * description, StatisticMeasure kind, 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, bool merge) = 0;
 };
 
 #endif

testing/regress/ecl/loopthor.ecl

@@ -16,9 +16,7 @@
 ############################################################################## */
 
 //nohthor
-//nothor
 
-#option ('newChildQueries', true)
 
 namesRecord := 
             RECORD

testing/regress/ecl/loopthor2.ecl

@@ -15,10 +15,6 @@
     limitations under the License.
 ############################################################################## */
 
-//nothor
-
-#option ('newChildQueries', true)
-
 export namesRecord := 
             RECORD
 string20        surname;

testing/unittests/unittests.cpp

@@ -17,6 +17,7 @@
 
 #ifdef _USE_CPPUNIT
 #include "unittests.hpp"
+#include "jstats.h"
 
 /*
  * This is the main unittest driver for HPCC. From here,
@@ -66,4 +67,21 @@ int main(int argc, char* argv[])
     return wasSucessful;
 }
 
+
+//MORE: This can't be included in jlib because of the dll dependency
+class InternalStatisticsTest : public CppUnit::TestFixture
+{
+    CPPUNIT_TEST_SUITE( InternalStatisticsTest  );
+        CPPUNIT_TEST(testMappings);
+    CPPUNIT_TEST_SUITE_END();
+
+    void testMappings()
+    {
+        verifyStatisticFunctions();
+    }
+};
+
+CPPUNIT_TEST_SUITE_REGISTRATION( InternalStatisticsTest );
+CPPUNIT_TEST_SUITE_NAMED_REGISTRATION( InternalStatisticsTest, "StatisticsTest" );
+
 #endif // _USE_CPPUNIT

thorlcr/activities/hashdistrib/thhashdistrib.cpp

@@ -97,18 +97,16 @@ public:
         lhsProgress->set(node, lhsProgressCount);
         rhsProgress->set(node, rhsProgressCount);
     }
-    virtual void getXGMML(unsigned idx, IPropertyTree *edge)
+    virtual void getEdgeStats(IStatisticGatherer & stats, unsigned idx)
     {
-        HashDistributeActivityMaster::getXGMML(idx, edge);
+        //This should be an activity stats
+        HashDistributeActivityMaster::getEdgeStats(stats, idx);
         assertex(0 == idx);
         lhsProgress->processInfo();
         rhsProgress->processInfo();
 
-        StringBuffer label;
-        label.append("@progressInput-").append(container.queryInput(0)->queryId());
-        edge->setPropInt64(label.str(), lhsProgress->queryTotal());
-        label.clear().append("@progressInput-").append(container.queryInput(1)->queryId());
-        edge->setPropInt64(label.str(), rhsProgress->queryTotal());
+        stats.addStatistic(StNumLeftRows, lhsProgress->queryTotal());
+        stats.addStatistic(StNumRightRows, rhsProgress->queryTotal());
     }
 };
 

thorlcr/activities/indexread/thindexread.cpp

@@ -34,7 +34,7 @@ protected:
     Owned<CSlavePartMapping> mapping;
     bool nofilter;
     ProgressInfoArray progressInfoArr;
-    StringArray progressLabels;
+    UnsignedArray progressKinds;
     Owned<ProgressInfo> inputProgress;
     StringBuffer fileName;
 
@@ -184,9 +184,9 @@ public:
         limit = RCMAX;
         if (!container.queryLocalOrGrouped())
             mpTag = container.queryJob().allocateMPTag();
-        progressLabels.append("seeks");
-        progressLabels.append("scans");
-        ForEachItemIn(l, progressLabels)
+        progressKinds.append(StNumIndexSeeks);
+        progressKinds.append(StNumIndexScans);
+        ForEachItemIn(l, progressKinds)
             progressInfoArr.append(*new ProgressInfo);
         inputProgress.setown(new ProgressInfo);
         reInit = 0 != (indexBaseHelper->getFlags() & (TIRvarfilename|TIRdynamicfilename));
@@ -261,26 +261,24 @@ public:
         rowcount_t progress;
         mb.read(progress);
         inputProgress->set(node, progress);
-        ForEachItemIn(p, progressLabels)
+        ForEachItemIn(p, progressKinds)
         {
             unsigned __int64 st;
             mb.read(st);
             progressInfoArr.item(p).set(node, st);
         }
     }
-    virtual void getXGMML(unsigned idx, IPropertyTree *edge)
+    virtual void getEdgeStats(IStatisticGatherer & stats, unsigned idx)
     {
-        CMasterActivity::getXGMML(idx, edge);
-        StringBuffer label;
-        label.append("@inputProgress");
-        edge->setPropInt64(label.str(), inputProgress->queryTotal());
+        //This should be an activity stats
+        CMasterActivity::getEdgeStats(stats, idx);
+
+        stats.addStatistic(StNumIndexRowsRead, inputProgress->queryTotal());
         ForEachItemIn(p, progressInfoArr)
         {
             ProgressInfo &progress = progressInfoArr.item(p);
             progress.processInfo();
-            StringBuffer attr("@");
-            attr.append(progressLabels.item(p));
-            edge->setPropInt64(attr.str(), progress.queryTotal());
+            stats.addStatistic((StatisticKind)progressKinds.item(p), progress.queryTotal());
         }
     }
     virtual void abort()

thorlcr/activities/indexwrite/thindexwrite.cpp

@@ -323,15 +323,17 @@ public:
         mb.read(repPerc);
         replicateProgress->set(node, repPerc);
     }
-    virtual void getXGMML(IWUGraphProgress *progress, IPropertyTree *node)
+    virtual void getActivityStats(IStatisticGatherer & stats)
     {
-        CMasterActivity::getXGMML(progress, node);
+        CMasterActivity::getActivityStats(stats);
         if (publishReplicatedDone)
         {
             replicateProgress->processInfo();
-            replicateProgress->addAttribute(node, "replicatedPercentage", replicateProgress->queryAverage());
+            //GC->JCS An average of percentages doesn't give you a very accurate answer..
+            stats.addStatistic(StPerReplicated, replicateProgress->queryAverage() * 10000);
         }
     }
+
 };
 
 CActivityBase *createIndexWriteActivityMaster(CMasterGraphElement *container)

thorlcr/activities/join/thjoin.cpp

@@ -308,21 +308,18 @@ public:
             rhsProgress->set(node, rhsProgressCount);
         }
     }
-    virtual void getXGMML(unsigned idx, IPropertyTree *edge)
+    virtual void getEdgeStats(IStatisticGatherer & stats, unsigned idx)
     {
-        CMasterActivity::getXGMML(idx, edge);
-
+        //This should be an activity stats
+        CMasterActivity::getEdgeStats(stats, idx);
         assertex(0 == idx);
-        StringBuffer label;
-        lhsProgress->processInfo();
-        label.append("@progressInput-").append(container.queryInput(0)->queryId());
-        edge->setPropInt64(label.str(), lhsProgress->queryTotal());
 
+        lhsProgress->processInfo();
+        stats.addStatistic(StNumLeftRows, lhsProgress->queryTotal());
         if (TAKselfjoin != container.getKind() && TAKselfjoinlight != container.getKind())
         {
             rhsProgress->processInfo();
-            label.clear().append("@progressInput-").append(container.queryInput(1)->queryId());
-            edge->setPropInt64(label.str(), rhsProgress->queryTotal());
+            stats.addStatistic(StNumRightRows, rhsProgress->queryTotal());
         }
     }
 #define MSGTIME (5*60*1000)

thorlcr/activities/keyedjoin/thkeyedjoin.cpp

@@ -32,26 +32,27 @@ class CKeyedJoinMaster : public CMasterActivity
     unsigned numTags;
     mptag_t tags[4];
     ProgressInfoArray progressInfoArr;
-    StringArray progressLabels;
+    UnsignedArray progressKinds;
 
 
 public:
     CKeyedJoinMaster(CMasterGraphElement *info) : CMasterActivity(info)
     {
         helper = (IHThorKeyedJoinArg *) queryHelper();
-        progressLabels.append("seeks");
-        progressLabels.append("scans");
-        progressLabels.append("accepted");
-        progressLabels.append("postfiltered");
-        progressLabels.append("prefiltered");
+        //GH->JCS a bit wasteful creating this array each time.
+        progressKinds.append(StNumIndexSeeks);
+        progressKinds.append(StNumIndexScans);
+        progressKinds.append(StNumIndexAccepted);
+        progressKinds.append(StNumPostFiltered);
+        progressKinds.append(StNumPreFiltered);
 
         if (helper->diskAccessRequired())
         {
-            progressLabels.append("diskSeeks");
-            progressLabels.append("diskAccepted");
-            progressLabels.append("diskRejected");
+            progressKinds.append(StNumDiskSeeks);
+            progressKinds.append(StNumDiskAccepted);
+            progressKinds.append(StNumDiskRejected);
         }
-        ForEachItemIn(l, progressLabels)
+        ForEachItemIn(l, progressKinds)
             progressInfoArr.append(*new ProgressInfo);
         localKey = false;
         numTags = 0;
@@ -270,24 +271,23 @@ public:
     virtual void deserializeStats(unsigned node, MemoryBuffer &mb)
     {
         CMasterActivity::deserializeStats(node, mb);
-        ForEachItemIn(p, progressLabels)
+        ForEachItemIn(p, progressKinds)
         {
             unsigned __int64 st;
             mb.read(st);
             progressInfoArr.item(p).set(node, st);
         }
     }
-    virtual void getXGMML(unsigned idx, IPropertyTree *edge)
+    virtual void getEdgeStats(IStatisticGatherer & stats, unsigned idx)
     {
-        CMasterActivity::getXGMML(idx, edge);
+        //This should be an activity stats
+        CMasterActivity::getEdgeStats(stats, idx);
         assertex(0 == idx);
         ForEachItemIn(p, progressInfoArr)
         {
             ProgressInfo &progress = progressInfoArr.item(p);
             progress.processInfo();
-            StringBuffer attr("@");
-            attr.append(progressLabels.item(p));
-            edge->setPropInt64(attr.str(), progress.queryTotal());
+            stats.addStatistic((StatisticKind)progressKinds.item(p), progress.queryTotal());
         }
     }
 };

thorlcr/activities/loop/thloop.cpp

@@ -89,7 +89,7 @@ protected:
 public:
     CLoopActivityMasterBase(CMasterGraphElement *info) : CMasterActivity(info)
     {
-        loopCounterProgress.setown(new CThorStats("loopCounter-"));
+        loopCounterProgress.setown(new CThorStats(StNumIterations));
         if (!container.queryLocalOrGrouped())
             mpTag = container.queryJob().allocateMPTag();
         loopGraph = NULL;
@@ -144,11 +144,12 @@ public:
         mb.read(loopCounter);
         loopCounterProgress->set(node, loopCounter);
     }
-    virtual void getXGMML(IWUGraphProgress *progress, IPropertyTree *node)
+    virtual void getActivityStats(IStatisticGatherer & stats)
     {
-        CMasterActivity::getXGMML(progress, node);
-        loopCounterProgress->getXGMML(node, false);
+        CMasterActivity::getActivityStats(stats);
+        loopCounterProgress->getStats(stats, false);
     }
+
 };
 
 

thorlcr/activities/thdiskbase.cpp

@@ -122,13 +122,12 @@ void CDiskReadMasterBase::deserializeStats(unsigned node, MemoryBuffer &mb)
     inputProgress->set(node, progress);
 }
 
-void CDiskReadMasterBase::getXGMML(unsigned idx, IPropertyTree *edge)
+void CDiskReadMasterBase::getEdgeStats(IStatisticGatherer & stats, unsigned idx)
 {
-    CMasterActivity::getXGMML(idx, edge);
+    //This should be an activity stats
+    CMasterActivity::getEdgeStats(stats, idx);
     inputProgress->processInfo();
-    StringBuffer label;
-    label.append("@inputProgress");
-    edge->setPropInt64(label.str(), inputProgress->queryTotal());
+    stats.addStatistic(StNumDiskRowsRead, inputProgress->queryTotal());
 }
 
 /////////////////
@@ -247,13 +246,13 @@ void CWriteMasterBase::deserializeStats(unsigned node, MemoryBuffer &mb)
     replicateProgress->set(node, repPerc);
 }
 
-void CWriteMasterBase::getXGMML(IWUGraphProgress *progress, IPropertyTree *node)
+void CWriteMasterBase::getActivityStats(IStatisticGatherer & stats)
 {
-    CMasterActivity::getXGMML(progress, node);
+    CMasterActivity::getActivityStats(stats);
     if (publishReplicatedDone)
     {
         replicateProgress->processInfo();
-        replicateProgress->addAttribute(node, "replicatedPercentage", replicateProgress->queryAverage());
+        stats.addStatistic(StPerReplicated, replicateProgress->queryAverage() * 10000);
     }
 }
 

thorlcr/activities/thdiskbase.ipp

@@ -39,8 +39,8 @@ public:
     virtual void init();
     virtual void serializeSlaveData(MemoryBuffer &dst, unsigned slave);
     virtual void validateFile(IDistributedFile *file) { }
-    void deserializeStats(unsigned node, MemoryBuffer &mb);
-    void getXGMML(unsigned idx, IPropertyTree *edge);
+    virtual void deserializeStats(unsigned node, MemoryBuffer &mb);
+    virtual void getEdgeStats(IStatisticGatherer & stats, unsigned idx);
 };
 
 class CWriteMasterBase : public CMasterActivity
@@ -61,7 +61,7 @@ protected:
 public:
     CWriteMasterBase(CMasterGraphElement *info);
     virtual void deserializeStats(unsigned node, MemoryBuffer &mb);
-    virtual void getXGMML(IWUGraphProgress *progress, IPropertyTree *node);
+    virtual void getActivityStats(IStatisticGatherer & stats);
     virtual void preStart(size32_t parentExtractSz, const byte *parentExtract);
     virtual void init();
     virtual void serializeSlaveData(MemoryBuffer &dst, unsigned slave);

thorlcr/graph/thgraphmaster.cpp

@@ -486,7 +486,7 @@ void CMasterActivity::deserializeStats(unsigned node, MemoryBuffer &mb)
     CriticalBlock b(progressCrit); // don't think needed
     unsigned __int64 localTimeNs;
     mb.read(localTimeNs);
-    timingInfo.set(node, localTimeNs/1000000); // to milliseconds
+    timingInfo.set(node, localTimeNs);
     rowcount_t count;
     ForEachItemIn(p, progressInfo)
     {
@@ -495,16 +495,16 @@ void CMasterActivity::deserializeStats(unsigned node, MemoryBuffer &mb)
     }
 }
 
-void CMasterActivity::getXGMML(IWUGraphProgress *progress, IPropertyTree *node)
+void CMasterActivity::getActivityStats(IStatisticGatherer & stats)
 {
-    timingInfo.getXGMML(node);
+    timingInfo.getStats(stats);
 }
 
-void CMasterActivity::getXGMML(unsigned idx, IPropertyTree *edge)
+void CMasterActivity::getEdgeStats(IStatisticGatherer & stats, unsigned idx)
 {
     CriticalBlock b(progressCrit);
     if (progressInfo.isItem(idx))
-        progressInfo.item(idx).getXGMML(edge);
+        progressInfo.item(idx).getStats(stats);
 }
 
 void CMasterActivity::done()
@@ -2630,16 +2630,17 @@ void CMasterGraph::done()
                     {
                         wu.setown(&graph.queryJob().queryWorkUnit().lock());
                     }
-                    virtual void report(const char * stat, const char *description, const __int64 totaltime, const __int64 maxtime, const unsigned count)
+                    virtual void report(const char * timerScope, const char *description, const __int64 totaltime, const __int64 maxtime, const unsigned count)
                     {
                         StringBuffer timerStr(graph.queryJob().queryGraphName());
                         timerStr.append("(").append(graph.queryGraphId()).append("): ");
                         timerStr.append(description);
 
-                        StringBuffer wuScope;
-                        wuScope.append(graph.queryJob().queryGraphName()).append("(").append(graph.queryGraphId()).append(")");
-
-                        updateWorkunitTimeStat(wu, "thor", wuScope, stat, timerStr.str(), totaltime, count, maxtime);
+                        StringBuffer scope;
+                        //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);
 
                     }
                 } wureport(*this);
@@ -2755,30 +2756,10 @@ IThorResult *CMasterGraph::createGraphLoopResult(CActivityBase &activity, IRowIn
 
 ///////////////////////////////////////////////////
 
-CThorStats::CThorStats(const char *_prefix)
+CThorStats::CThorStats(StatisticKind _kind) : kind(_kind)
 {
     unsigned c = queryClusterWidth();
     while (c--) counts.append(0);
-    if (_prefix)
-    {
-        prefix.set(_prefix);
-        StringBuffer tmp;
-        labelMin.set(tmp.append(_prefix).append("Min"));
-        labelMax.set(tmp.clear().append(_prefix).append("Max"));
-        labelMinSkew.set(tmp.clear().append(_prefix).append("MinSkew"));
-        labelMaxSkew.set(tmp.clear().append(_prefix).append("MaxSkew"));
-        labelMinEndpoint.set(tmp.clear().append(_prefix).append("MinEndpoint"));
-        labelMaxEndpoint.set(tmp.clear().append(_prefix).append("MaxEndpoint"));
-    }
-    else
-    {
-        labelMin.set("min");
-        labelMax.set("max");
-        labelMinSkew.set("minskew");
-        labelMaxSkew.set("maxskew");
-        labelMinEndpoint.set("minEndpoint");
-        labelMaxEndpoint.set("maxEndpoint");
-    }
 }
 
 void CThorStats::set(unsigned node, unsigned __int64 count)
@@ -2786,102 +2767,86 @@ void CThorStats::set(unsigned node, unsigned __int64 count)
     counts.replace(count, node);
 }
 
-void CThorStats::removeAttribute(IPropertyTree *node, const char *name)
-{
-    StringBuffer aName("@");
-    node->removeProp(aName.append(name).str());
-}
-
-void CThorStats::addAttribute(IPropertyTree *node, const char *name, unsigned __int64 val)
-{
-    StringBuffer aName("@");
-    node->setPropInt64(aName.append(name).str(), val);
-}
-
-void CThorStats::addAttribute(IPropertyTree *node, const char *name, const char *val)
-{
-    StringBuffer aName("@");
-    node->setProp(aName.append(name).str(), val);
-}
-
 void CThorStats::reset()
 {
     tot = max = avg = 0;
     min = (unsigned __int64) -1;
-    minNode = maxNode = hi = lo = maxNode = minNode = 0;
+    minNode = maxNode = maxSkew = minSkew = maxNode = minNode = 0;
 }
 
-void CThorStats::processInfo()
+void CThorStats::calculateSkew()
 {
-    reset();
-    ForEachItemIn(n, counts)
-    {
-        unsigned __int64 thiscount = counts.item(n);
-        tot += thiscount;
-        if (thiscount > max)
-        {
-            max = thiscount;
-            maxNode = n;
-        }
-        if (thiscount < min)
-        {
-            min = thiscount;
-            minNode = n;
-        }
-    }
     if (max)
     {
         unsigned count = counts.ordinality();
-        avg = tot/count;
-        if (avg)
+        double _avg = (double)tot/count;
+        if (_avg)
         {
-            hi = (unsigned)((100 * (max-avg))/avg);
-            lo = (unsigned)((100 * (avg-min))/avg);
+            //MORE: Range protection on maxSkew?
+            maxSkew = (unsigned)(10000.0 * (((double)max-_avg)/_avg));
+            minSkew = (unsigned)(10000.0 * ((_avg-(double)min)/_avg));
+            avg = (unsigned __int64)_avg;
         }
     }
 }
 
-void CThorStats::getXGMML(IPropertyTree *node, bool suppressMinMaxWhenEqual)
+void CThorStats::tallyValue(unsigned __int64 thiscount, unsigned n)
 {
-    processInfo();
-    if (suppressMinMaxWhenEqual && (hi == lo))
+    tot += thiscount;
+    if (thiscount > max)
     {
-        removeAttribute(node, labelMin);
-        removeAttribute(node, labelMax);
+        max = thiscount;
+        maxNode = n;
     }
-    else
+    if (thiscount < min)
     {
-        addAttribute(node, labelMin, min);
-        addAttribute(node, labelMax, max);
+        min = thiscount;
+        minNode = n;
     }
-    if (hi == lo)
+}
+
+void CThorStats::processInfo()
+{
+    reset();
+    ForEachItemIn(n, counts)
     {
-        removeAttribute(node, labelMinEndpoint);
-        removeAttribute(node, labelMaxEndpoint);
-        removeAttribute(node, labelMinSkew);
-        removeAttribute(node, labelMaxSkew);
+        unsigned __int64 thiscount = counts.item(n);
+        tallyValue(thiscount, n);
     }
-    else
+    calculateSkew();
+}
+
+void CThorStats::getStats(IStatisticGatherer & stats, bool suppressMinMaxWhenEqual)
+{
+    processInfo();
+    //MORE: For most measures (not time stamps etc.) it would be sensible to output the total here....
+    if (!suppressMinMaxWhenEqual || (maxSkew != minSkew))
     {
-        addAttribute(node, labelMinSkew, lo);
-        addAttribute(node, labelMaxSkew, hi);
-        StringBuffer epStr;
-        addAttribute(node, labelMinEndpoint, querySlaveGroup().queryNode(minNode).endpoint().getUrlStr(epStr).str());
-        addAttribute(node, labelMaxEndpoint, querySlaveGroup().queryNode(maxNode).endpoint().getUrlStr(epStr.clear()).str());
+        stats.addStatistic((StatisticKind)(kind|StMinX), min);
+        stats.addStatistic((StatisticKind)(kind|StMaxX), max);
+        stats.addStatistic((StatisticKind)(kind|StAvgX), avg);
+    }
+
+    if (maxSkew != minSkew)
+    {
+        stats.addStatistic((StatisticKind)(kind|StSkewMin), -(__int64)minSkew); // Save minimum as a negative value so consistent
+        stats.addStatistic((StatisticKind)(kind|StSkewMax), maxSkew);
+        stats.addStatistic((StatisticKind)(kind|StNodeMin), minNode);
+        stats.addStatistic((StatisticKind)(kind|StNodeMax), maxNode);
     }
 }
 
 ///////////////////////////////////////////////////
 
-CTimingInfo::CTimingInfo() : CThorStats("time")
+CTimingInfo::CTimingInfo() : CThorStats(StTimeLocalExecute)
 {
-    StringBuffer tmp;
-    labelMin.set(tmp.append(labelMin).append("Ms"));
-    labelMax.set(tmp.clear().append(labelMax).append("Ms"));
 }
 
 ///////////////////////////////////////////////////
 
+ProgressInfo::ProgressInfo() : CThorStats(StNumRowsProcessed)
+{
+}
 void ProgressInfo::processInfo() // reimplement as counts have special flags (i.e. stop/start)
 {
     reset();
@@ -2894,38 +2859,18 @@ void ProgressInfo::processInfo() // reimplement as counts have special flags (i.
         if (thiscount & THORDATALINK_STOPPED)
             stopcount++;
         thiscount = thiscount & THORDATALINK_COUNT_MASK;
-        tot += thiscount;
-        if (thiscount > max)
-        {
-            max = thiscount;
-            maxNode = n;
-        }
-        if (thiscount < min)
-        {
-            min = thiscount;
-            minNode = n;
-        }
-    }
-    if (max)
-    {
-        unsigned count = counts.ordinality();
-        double _avg = (double)tot/count;
-        if (_avg)
-        {
-            hi = (unsigned)(100.0 * (((double)max-_avg)/_avg));
-            lo = (unsigned)(100.0 * ((_avg-(double)min)/_avg));
-            avg = (unsigned __int64)_avg;
-        }
+        tallyValue(thiscount, n);
     }
+    calculateSkew();
 }
 
-void ProgressInfo::getXGMML(IPropertyTree *node)
+void ProgressInfo::getStats(IStatisticGatherer & stats)
 {
-    CThorStats::getXGMML(node, true);
-    addAttribute(node, "slaves", counts.ordinality());
-    addAttribute(node, "count", tot);
-    addAttribute(node, "started", startcount);
-    addAttribute(node, "stopped", stopcount);
+    CThorStats::getStats(stats, true);
+    stats.addStatistic(kind, tot);
+    stats.addStatistic(StNumSlaves, counts.ordinality());
+    stats.addStatistic(StNumStarted, startcount);
+    stats.addStatistic(StNumStopped, stopcount);
 }
 
 

thorlcr/graph/thgraphmaster.ipp

@@ -183,51 +183,54 @@ public:
     bool queryCreatedFile(const char *file);
 };
 
+
 class graphmaster_decl CThorStats : public CInterface, implements IInterface
 {
 protected:
     unsigned __int64 max, min, tot, avg;
-    unsigned hi, lo, minNode, maxNode;
+    unsigned maxSkew, minSkew, minNode, maxNode;
     UInt64Array counts;
-    StringAttr prefix;
-    StringAttr labelMin, labelMax, labelMinSkew, labelMaxSkew, labelMinEndpoint, labelMaxEndpoint;
+    StatisticKind kind;
 
 public:
     IMPLEMENT_IINTERFACE;
 
-    CThorStats(const char *prefix=NULL);
+    CThorStats(StatisticKind _kind);
     void reset();
     virtual void processInfo();
-    static void removeAttribute(IPropertyTree *node, const char *name);
-    static void addAttribute(IPropertyTree *node, const char *name, unsigned __int64 val);
-    static void addAttribute(IPropertyTree *node, const char *name, const char *val);
 
     unsigned __int64 queryTotal() { return tot; }
     unsigned __int64 queryAverage() { return avg; }
     unsigned __int64 queryMin() { return min; }
     unsigned __int64 queryMax() { return max; }
-    unsigned queryMinSkew() { return lo; }
-    unsigned queryMaxSkew() { return hi; }
+    unsigned queryMinSkew() { return minSkew; }
+    unsigned queryMaxSkew() { return maxSkew; }
     unsigned queryMaxNode() { return maxNode; }
     unsigned queryMinNode() { return minNode; }
 
     void set(unsigned node, unsigned __int64 count);
-    void getXGMML(IPropertyTree *node, bool suppressMinMaxWhenEqual);
+    void getStats(IStatisticGatherer & stats, bool suppressMinMaxWhenEqual);
+
+protected:
+    void calculateSkew();
+    void tallyValue(unsigned __int64 value, unsigned node);
 };
 
 class graphmaster_decl CTimingInfo : public CThorStats
 {
 public:
     CTimingInfo();
-    void getXGMML(IPropertyTree *node) { CThorStats::getXGMML(node, false); }
+    void getStats(IStatisticGatherer & stats) { CThorStats::getStats(stats, false); }
 };
 
 class graphmaster_decl ProgressInfo : public CThorStats
 {
     unsigned startcount, stopcount;
 public:
+    ProgressInfo();
+
     virtual void processInfo();
-    void getXGMML(IPropertyTree *node);
+    void getStats(IStatisticGatherer & stats);
 };
 typedef IArrayOf<ProgressInfo> ProgressInfoArray;
 
@@ -254,8 +257,8 @@ public:
     ~CMasterActivity();
 
     virtual void deserializeStats(unsigned node, MemoryBuffer &mb);
-    virtual void getXGMML(unsigned idx, IPropertyTree *edge);
-    virtual void getXGMML(IWUGraphProgress *progress, IPropertyTree *node);
+    virtual void getActivityStats(IStatisticGatherer & stats);
+    virtual void getEdgeStats(IStatisticGatherer & stats, unsigned idx);
     virtual void init();
     virtual void handleSlaveMessage(CMessageBuffer &msg) { }
     virtual void reset();

thorlcr/master/thdemonserver.cpp

@@ -39,7 +39,7 @@ private:
     CIArrayOf<CGraphBase> activeGraphs;
     UnsignedArray graphStarts;
     
-    void doReportGraph(IWUGraphProgress *progress, CGraphBase *graph, bool finished)
+    void doReportGraph(IStatisticGatherer & stats, CGraphBase *graph, bool finished)
     {
         Owned<IThorActivityIterator> iter;
         if (graph->queryOwner() && !graph->isGlobal())
@@ -53,30 +53,30 @@ private:
             if (activity) // may not be created (if within child query)
             {
                 activity_id id = container.queryId();
-                graph_id sourceGraphId = container.queryOwner().queryGraphId();
+
                 unsigned outputs = container.getOutputs();
                 unsigned oid = 0;
                 for (; oid < outputs; oid++)
                 {
-                    StringBuffer edgeId;
-                    edgeId.append(id).append('_').append(oid);
-                    IPropertyTree &edge = progress->updateEdge(sourceGraphId, edgeId.str());
-                    activity->getXGMML(oid, &edge); // for subgraph, may recursively call reportGraph
+                    StatsEdgeScope edgeScope(stats, id, oid);
+                    activity->getEdgeStats(stats, oid); // for subgraph, may recursively call reportGraph
                 }
-                IPropertyTree &node = progress->updateNode(sourceGraphId, id);
-                activity->getXGMML(progress, &node);
+
+                StatsActivityScope scope(stats, id);
+                activity->getActivityStats(stats);
             }
         }
     }
-    void reportGraph(IWUGraphProgress *progress, CGraphBase *graph, bool finished)
+    void reportGraph(IStatisticGatherer & stats, CGraphBase *graph, bool finished)
     {
         try
         {
+            StatsSubgraphScope subgraph(stats, graph->queryGraphId());
             if (graph->isCreated())
-                doReportGraph(progress, graph, finished);
+                doReportGraph(stats, graph, finished);
             Owned<IThorGraphIterator> graphIter = graph->getChildGraphs();
             ForEach (*graphIter)
-                reportGraph(progress, &graphIter->query(), finished);
+                reportGraph(stats, &graphIter->query(), finished);
         }
         catch (IException *e)
         {
@@ -92,7 +92,7 @@ private:
         formatGraphTimerLabel(timer, graphname, 0, graph.queryGraphId());
         formatGraphTimerScope(graphScope, graphname, 0, graph.queryGraphId());
         unsigned duration = msTick()-startTime;
-        updateWorkunitTimeStat(wu, "thor", graphScope, "totalTime", timer, milliToNano(duration), 1, 0);
+        updateWorkunitTimeStat(wu, SSTsubgraph, graphScope, StTimeElapsed, timer, milliToNano(duration));
 
         if (finished)
         {
@@ -129,13 +129,12 @@ private:
             {
                 IConstWorkUnit &currentWU = activeGraphs.item(0).queryJob().queryWorkUnit();
                 Owned<IConstWUGraphProgress> graphProgress = ((CJobMaster &)activeGraphs.item(0).queryJob()).getGraphProgress();
-                Owned<IWUGraphProgress> progress = graphProgress->update();
                 ForEachItemIn (g, activeGraphs)
                 {
                     CGraphBase &graph = activeGraphs.item(g);
-                    reportGraph(progress, &graph, finished);
+                    Owned<IWUGraphStats> stats = graphProgress->update(SCTthor, queryStatisticsComponentName(), graph.queryGraphId());
+                    reportGraph(stats->queryStatsBuilder(), &graph, finished);
                 }
-                progress.clear(); // clear progress(lock) now, before attempting to get lock on wu, potentially delaying progress unlock.
                 graphProgress.clear();
                 Owned<IWorkUnit> wu = &currentWU.lock();
                 ForEachItemIn (g2, activeGraphs)
@@ -160,11 +159,12 @@ private:
         {
             IConstWorkUnit &currentWU = graph->queryJob().queryWorkUnit();
             Owned<IConstWUGraphProgress> graphProgress = ((CJobMaster &)graph->queryJob()).getGraphProgress();
-            Owned<IWUGraphProgress> progress = graphProgress->update();
 
-            reportGraph(progress, graph, finished);
+            {
+                Owned<IWUGraphStats> stats = graphProgress->update(SCTthor, queryStatisticsComponentName(), graph->queryGraphId());
+                reportGraph(stats->queryStatsBuilder(), graph, finished);
+            }
 
-            progress.clear(); // clear progress(lock) now, before attempting to get lock on wu, potentially delaying progress unlock.
             graphProgress.clear();
 
             Owned<IWorkUnit> wu = &currentWU.lock();

thorlcr/master/thdemonserver.hpp

@@ -28,7 +28,6 @@ interface IDeMonServer : extends IInterface
 {
     virtual void takeHeartBeat(const SocketEndpoint &sender, MemoryBuffer &progressMbb) = 0;
     virtual void startGraph(CGraphBase *graph) = 0;
-    virtual void reportGraph(IWUGraphProgress *progress, CGraphBase *graph, bool finished) = 0;
     virtual void endGraph(CGraphBase *graph, bool success) = 0;
     virtual void endGraphs() = 0;
 };

thorlcr/master/thgraphmanager.cpp

@@ -654,8 +654,7 @@ bool CJobManager::executeGraph(IConstWorkUnit &workunit, const char *graphName,
     {
         Owned<IWorkUnit> wu = &workunit.lock();
         wu->setTracingValue("ThorBuild", BUILD_TAG);
-        StringBuffer tsStr("Thor - ");
-        wu->setTimeStamp(tsStr.append(graphName).str(), GetCachedHostName(), "Started");
+        addTimeStamp(wu, SSTgraph, graphName, StWhenGraphStarted);
         updateWorkUnitLog(*wu);
     }
     Owned<IException> exception;
@@ -663,8 +662,16 @@ bool CJobManager::executeGraph(IConstWorkUnit &workunit, const char *graphName,
     workunit.forceReload();
     workunit.getWuid(wuid);
     const char *totalTimeStr = "Total thor time";
-    unsigned startTime = msTick();
-    unsigned totalTimeMs = workunit.getTimerDuration(totalTimeStr);
+    cycle_t startCycles = get_cycles_now();
+    unsigned totalTimeNs = 0;
+    unsigned totalThisTimeNs = 0;
+    StatisticsFilter summaryTimeFilter(SCTsummary, "thor", SSTglobal, GLOBAL_SCOPE, SMeasureTimeNs, StTimeElapsed);
+    Owned<IConstWUStatistic> totalThorTime = getStatistic(&workunit, summaryTimeFilter);
+    Owned<IConstWUStatistic> totalThisThorTime = workunit.getStatistic(queryStatisticsComponentName(), GLOBAL_SCOPE, StTimeElapsed);
+    if (totalThorTime)
+        totalTimeNs = totalThorTime->getValue();
+    if (totalThisThorTime)
+        totalThisTimeNs = totalThisThorTime->getValue();
 
     Owned<IConstWUQuery> query = workunit.getQuery(); 
     SCMStringBuffer soName;
@@ -739,15 +746,15 @@ bool CJobManager::executeGraph(IConstWorkUnit &workunit, const char *graphName,
         allDone = job->go();
 
         Owned<IWorkUnit> wu = &workunit.lock();
-        unsigned graphTimeMs = msTick()-startTime;
+        unsigned __int64 graphTimeNs = cycle_to_nanosec(get_cycles_now()-startCycles);
         StringBuffer graphTimeStr;
         formatGraphTimerLabel(graphTimeStr, graphName);
 
-        updateWorkunitTimeStat(wu, "thor", graphName, "time", graphTimeStr, milliToNano(graphTimeMs), 1, 0);
-        updateWorkunitTimeStat(wu, "thor", "workunit", "ThorTime", totalTimeStr, milliToNano(totalTimeMs+graphTimeMs), 1, 0);
+        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);
 
-        StringBuffer tsStr("Thor - ");
-        wu->setTimeStamp(tsStr.append(graphName).str(), GetCachedHostName(), "Finished");
+        addTimeStamp(wu, SSTgraph, graphName, StWhenGraphFinished);
         
         removeJob(*job);
     }

thorlcr/master/thmastermain.cpp

@@ -452,6 +452,8 @@ int main( int argc, char *argv[]  )
         Owned<IFile> iFile = createIFile("thor.xml");
         globals = iFile->exists() ? createPTree(*iFile, ipt_caseInsensitive) : createPTree("Thor", ipt_caseInsensitive);
     }
+    setStatisticsComponentName(SCTthor, globals->queryProp("@name"), false);
+
     globals->setProp("@masterBuildTag", BUILD_TAG);
     char **pp = argv+1;
     while (*pp)