Merge pull request #10270 from ghalliday/issue18030

HPCC-18030 Simplify ITimeReporter and refactor inefficient code

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

common/workunit/workunit.cpp

@@ -11786,18 +11786,38 @@ extern WORKUNIT_API void updateWorkunitTimeStat(IWorkUnit * wu, StatisticScopeTy
     wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, description, value, 1, 0, StatsMergeReplace);
 }
 
-extern WORKUNIT_API void updateWorkunitTimings(IWorkUnit * wu, ITimeReporter *timer)
+class WuTimingUpdater : implements ITimeReportInfo
 {
-    StringBuffer scope;
-    for (unsigned i = 0; i < timer->numSections(); i++)
+public:
+    WuTimingUpdater(IWorkUnit * _wu, StatisticScopeType _scopeType, StatisticKind _kind)
+    : wu(_wu), scopeType(_scopeType), kind(_kind)
+    { }
+
+    virtual void report(const char * scope, const __int64 totaltime, const __int64 maxtime, const unsigned count)
     {
-        StatisticScopeType scopeType= timer->getScopeType(i);
-        timer->getScope(i, scope.clear());
-        StatisticKind kind = timer->getTimerType(i);
-        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, NULL, timer->getTime(i), timer->getCount(i), timer->getMaxTime(i), StatsMergeReplace);
+        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, nullptr, totaltime, count, maxtime, StatsMergeReplace);
     }
+
+protected:
+    IWorkUnit * wu;
+    StatisticScopeType scopeType;
+    StatisticKind kind;
+};
+
+
+extern WORKUNIT_API void updateWorkunitTimings(IWorkUnit * wu, ITimeReporter *timer)
+{
+    WuTimingUpdater target(wu, SSTsection, StTimeTotalExecute);
+    timer->report(target);
 }
 
+extern WORKUNIT_API void updateWorkunitTimings(IWorkUnit * wu, StatisticScopeType scopeType, StatisticKind kind, ITimeReporter *timer)
+{
+    WuTimingUpdater target(wu, scopeType, kind);
+    timer->report(target);
+}
+
+
 extern WORKUNIT_API void getWorkunitTotalTime(IConstWorkUnit* workunit, const char* creator, unsigned __int64 & totalTimeNs, unsigned __int64 & totalThisTimeNs)
 {
     StatisticsFilter summaryTimeFilter(SCTsummary, creator, SSTglobal, GLOBAL_SCOPE, SMeasureTimeNs, StTimeElapsed);

common/workunit/workunit.hpp

@@ -1554,6 +1554,7 @@ extern WORKUNIT_API void associateLocalFile(IWUQuery * query, WUFileType type, c
 interface ITimeReporter;
 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 void updateWorkunitTimings(IWorkUnit * wu, StatisticScopeType scopeType, StatisticKind kind, ITimeReporter *timer);
 extern WORKUNIT_API void getWorkunitTotalTime(IConstWorkUnit* workunit, const char* creator, unsigned __int64 & totalTimeNs, unsigned __int64 & totalThisTimeNs);
 extern WORKUNIT_API IConstWUStatistic * getStatistic(IConstWorkUnit * wu, const IStatisticsFilter & filter);
 

ecl/hqlcpp/hqlhtcpp.cpp

@@ -5945,30 +5945,10 @@ bool HqlCppTranslator::buildCpp(IHqlCppInstance & _code, HqlQueryContext & query
     return true;
 }
 
-class WuTimingUpdater : implements ITimeReportInfo
-{
-public:
-    WuTimingUpdater(IWorkUnit * _wu) { wu = _wu; }
-
-    virtual void report(const char * scope, const char * description, const __int64 totaltime, const __int64 maxtime, const unsigned count)
-    {
-        StatisticScopeType scopeType = SSTcompilestage;
-        StatisticKind kind = StTimeTotalExecute;
-        wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), scopeType, scope, kind, description, totaltime, count, maxtime, StatsMergeReplace);
-    }
-
-protected:
-    IWorkUnit * wu;
-};
-
-
 void HqlCppTranslator::ensureWorkUnitUpdated()
 {
     if (timeReporter)
-    {
-        WuTimingUpdater updater(wu());
-        timeReporter->report(updater);
-    }
+        updateWorkunitTimings(wu(), SSTcompilestage, StTimeTotalExecute, timeReporter);
 }
 
 double HqlCppTranslator::getComplexity(IHqlExpression * expr, ClusterType cluster)

ecl/hqlcpp/hqlnlp.cpp

@@ -687,7 +687,6 @@ ABoundActivity * HqlCppTranslator::doBuildActivityParse(BuildCtx & ctx, IHqlExpr
 
     //This will become conditional on the flags....
     cycle_t startPrepareCycles = get_cycles_now();
-    ITimeReporter * reporter = timeReporter;
     if (expr->hasAttribute(tomitaAtom))
         nlpParse = createTomitaContext(expr, code->workunit, options);
     else

system/jlib/jdebug.cpp

@@ -476,20 +476,16 @@ MTimeSection::~MTimeSection()
 class TimeSectionInfo : public MappingBase 
 {
 public:
-    TimeSectionInfo(const char * _scope, const char *_description, __int64 _cycles) : scope(_scope), description(_description), totalcycles(_cycles), maxcycles(_cycles), count(1) {};
-    TimeSectionInfo(const char * _scope, const char *_description, __int64 _cycles, __int64 _maxcycles, unsigned _count)
-    : scope(_scope), description(_description), totalcycles(_cycles), maxcycles(_maxcycles), count(_count) {};
-    TimeSectionInfo(MemoryBuffer &mb)
-    {
-        mb.read(scope).read(description).read(totalcycles).read(maxcycles).read(count);
-    }
-    void serialize(MemoryBuffer &mb)
-    {
-        mb.read(scope).read(description).append(totalcycles).append(maxcycles).append(count);
-    }
+    TimeSectionInfo(const char * _scope, __int64 _cycles) : scope(_scope), totalcycles(_cycles), maxcycles(_cycles), count(1) {};
+    TimeSectionInfo(const char * _scope, __int64 _cycles, __int64 _maxcycles, unsigned _count)
+    : scope(_scope), totalcycles(_cycles), maxcycles(_maxcycles), count(_count) {};
     virtual const void * getKey() const { return scope.get(); }
+
+    __int64 getTime() const { return cycle_to_nanosec(totalcycles); }
+    __int64 getMaxTime() const { return cycle_to_nanosec(maxcycles); }
+    unsigned getCount() const { return count; }
+
     StringAttr  scope;
-    StringAttr  description;
     __int64 totalcycles;
     __int64 maxcycles;
     unsigned count;
@@ -516,17 +512,6 @@ public:
     {
         sections = new StringMapOf<TimeSectionInfo>(true);
     }
-    DefaultTimeReporter(MemoryBuffer &mb)
-    {
-        sections = new StringMapOf<TimeSectionInfo>(true);
-        unsigned ns;
-        mb.read(ns);
-        while (ns--)
-        {
-            TimeSectionInfo &newinfo = * new TimeSectionInfo(mb);
-            sections->replaceOwn(newinfo);
-        }
-    }
     ~DefaultTimeReporter() 
     {
 //      printTimings();                     // Must explicitly call printTimings - no automatic print (too late here!)
@@ -539,7 +524,7 @@ public:
         for(iter.first(); iter.isValid(); iter.next())
         {
             TimeSectionInfo &ts = (TimeSectionInfo &)iter.query();
-            cb.report(ts.scope, ts.description, cycle_to_nanosec(ts.totalcycles), cycle_to_nanosec(ts.maxcycles), ts.count);
+            cb.report(ts.scope, ts.getTime(), ts.getMaxTime(), ts.count);
         }
     }
     virtual void addTiming(const char * scope, cycle_t cycles)
@@ -554,43 +539,10 @@ public:
         }
         else
         {
-            TimeSectionInfo &newinfo = * new TimeSectionInfo(scope, NULL, cycles);
+            TimeSectionInfo &newinfo = * new TimeSectionInfo(scope, cycles);
             sections->replaceOwn(newinfo);
         }
     }
-    virtual unsigned numSections()
-    {
-        CriticalBlock b(c);
-        return sections->count();
-    }
-    virtual StatisticKind getTimerType(unsigned idx __attribute__((unused)))
-    {
-        return StTimeTotalExecute;
-    }
-    virtual StatisticScopeType getScopeType(unsigned idx __attribute__((unused)))
-    {
-        return SSTsection;
-    }
-    virtual __int64 getTime(unsigned idx)
-    {
-        CriticalBlock b(c);
-        return cycle_to_nanosec(findSection(idx).totalcycles);
-    }
-    virtual __int64 getMaxTime(unsigned idx)
-    {
-        CriticalBlock b(c);
-        return cycle_to_nanosec(findSection(idx).maxcycles);
-    }
-    virtual unsigned getCount(unsigned idx)
-    {
-        CriticalBlock b(c);
-        return findSection(idx).count;
-    }
-    virtual StringBuffer &getScope(unsigned idx, StringBuffer &s)
-    {
-        CriticalBlock b(c);
-        return s.append(findSection(idx).scope);
-    }
     virtual void reset()
     {
         CriticalBlock b(c);
@@ -600,19 +552,25 @@ public:
     virtual StringBuffer &getTimings(StringBuffer &str)
     {
         CriticalBlock b(c);
+        HashIterator iter(*sections);
+        for(iter.first(); iter.isValid(); iter.next())
+        {
+            TimeSectionInfo &ts = (TimeSectionInfo &)iter.query();
+            str.append("Timing: ").append(ts.scope)
+                    .append(" total=")
+                    .append(ts.getTime()/1000000)
+                    .append("ms max=")
+                    .append(ts.getMaxTime()/1000)
+                    .append("us count=")
+                    .append(ts.getCount())
+                    .append(" ave=")
+                    .append((ts.getTime()/1000)/ts.getCount())
+                    .append("us\n");
+        }
         if (numSections())
         {
             for (unsigned i = 0; i < numSections(); i++)
             {
-                getScope(i, str.append("Timing: ")).append(" total=")
-                                         .append(getTime(i)/1000000)
-                                         .append("ms max=")
-                                         .append(getMaxTime(i)/1000)
-                                         .append("us count=")
-                                         .append(getCount(i))
-                                         .append(" ave=")
-                                         .append((getTime(i)/1000)/getCount(i))
-                                         .append("us\n");
             }
         }
         return str;
@@ -632,7 +590,7 @@ public:
         TimeSectionInfo *info = sections->find(scope);
         if (!info)
         {
-            info = new TimeSectionInfo(scope, NULL, totalcycles, maxcycles, count);
+            info = new TimeSectionInfo(scope, totalcycles, maxcycles, count);
             sections->replaceOwn(*info);
         }
         else
@@ -657,16 +615,10 @@ public:
         CriticalBlock b(c);
         other.mergeInto(*this);
     }
-    virtual void serialize(MemoryBuffer &mb)
+protected:
+    unsigned numSections()
     {
-        CriticalBlock b(c);
-        mb.append(numSections());
-        HashIterator iter(*sections);
-        for(iter.first(); iter.isValid(); iter.next())
-        {
-            TimeSectionInfo &ts = (TimeSectionInfo &) iter.query();
-            ts.serialize(mb);
-        }
+        return sections->count();
     }
 };
 
@@ -678,7 +630,6 @@ ITimeReporter * queryActiveTimer()
 
 
 ITimeReporter *createStdTimeReporter() { return new DefaultTimeReporter(); }
-ITimeReporter *createStdTimeReporter(MemoryBuffer &mb) { return new DefaultTimeReporter(mb); }
 
 cycle_t oneSecInCycles;
 MODULE_INIT(INIT_PRIORITY_JDEBUG1)

system/jlib/jdebug.hpp

@@ -123,7 +123,7 @@ public:
 
 interface ITimeReportInfo
 {
-    virtual void report(const char * scope, const char * description, const __int64 totaltime, const __int64 maxtime, const unsigned count) = 0;
+    virtual void report(const char * scope, const __int64 totaltime, const __int64 maxtime, const unsigned count) = 0;
 };
 class StringBuffer;
 class MemoryBuffer;
@@ -131,20 +131,12 @@ struct ITimeReporter : public IInterface
 {
   virtual void addTiming(const char * scope, cycle_t cycles) = 0;
   virtual void mergeTiming(const char * scope, cycle_t totalcycles, cycle_t 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 &getTimings(StringBuffer &s) = 0;
   virtual void printTimings() = 0;
   virtual void reset() = 0;
-  virtual void mergeInto(ITimeReporter &other) = 0;
+  virtual void mergeInto(ITimeReporter &other) = 0; // Used internally
   virtual void merge(ITimeReporter &other)= 0;
   virtual void report(ITimeReportInfo &cb) = 0;
-  virtual void serialize(MemoryBuffer &mb) = 0;
 };
 
 extern jlib_decl cycle_t oneSecInCycles;
@@ -202,11 +194,10 @@ protected:
 #if defined(TIMING)
 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, title);
 #else
-#define TIME_SECTION(title)   
+#define TIME_SECTION(title)
 #define MTIME_SECTION(master,title)
 #endif