HPCC-19644 Add some stats for simplification

Signed-off-by: Shamser Ahmed <shamser.ahmed@lexisnexis.co.uk>

Signed-off-by: Shamser Ahmed <shamser.ahmed@lexisnexis.co.uk>

common/workunit/workunit.cpp

@@ -12952,7 +12952,7 @@ extern WORKUNIT_API void descheduleWorkunit(char const * wuid)
         doDescheduleWorkkunit(wuid);
 }
 
-extern WORKUNIT_API void updateWorkunitTimeStat(IWorkUnit * wu, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * description, unsigned __int64 value, unsigned wfid)
+extern WORKUNIT_API void updateWorkunitStat(IWorkUnit * wu, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * description, unsigned __int64 value, unsigned wfid)
 {
     StringBuffer scopestr;
     if (wfid && scope && *scope)

common/workunit/workunit.hpp

@@ -1672,7 +1672,7 @@ 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, unsigned minActivity=0, unsigned maxActivity=0);
 
 interface ITimeReporter;
-extern WORKUNIT_API void updateWorkunitTimeStat(IWorkUnit * wu, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * description, unsigned __int64 value, unsigned wfid=0);
+extern WORKUNIT_API void updateWorkunitStat(IWorkUnit * wu, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * description, unsigned __int64 value, unsigned wfid=0);
 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 aggregateStatistic(StatsAggregation & result, IConstWorkUnit * wu, const WuScopeFilter & filter, StatisticKind search);

ecl/eclagent/eclagent.cpp

@@ -1929,7 +1929,7 @@ void EclAgent::doProcess()
         WorkunitUpdate w = updateWorkUnit();
 
         addTimeStamp(w, SSTglobal, NULL, StWhenFinished);
-        updateWorkunitTimeStat(w, SSTglobal, NULL, StTimeElapsed, nullptr, elapsedTimer.elapsedNs());
+        updateWorkunitStat(w, SSTglobal, NULL, StTimeElapsed, nullptr, elapsedTimer.elapsedNs());
         addTimings();
 
         switch (w->getState())

ecl/eclagent/eclgraph.cpp

@@ -1224,7 +1224,7 @@ void EclGraph::execute(const byte * parentExtract)
             formatGraphTimerLabel(description, queryGraphName(), 0, 0);
 
             unsigned __int64 elapsedNs = milliToNano(elapsed);
-            updateWorkunitTimeStat(wu, SSTgraph, queryGraphName(), StTimeElapsed, description.str(), elapsedNs, agent->getWorkflowId());
+            updateWorkunitStat(wu, SSTgraph, queryGraphName(), StTimeElapsed, description.str(), elapsedNs, agent->getWorkflowId());
         }
 
         if (agent->queryRemoteWorkunit())
@@ -1440,7 +1440,7 @@ IWUGraphStats *EclGraph::updateStats(StatisticCreatorType creatorType, const cha
 
 void EclGraph::updateWUStatistic(IWorkUnit *lockedwu, StatisticScopeType scopeType, const char * scope, StatisticKind kind, const char * descr, unsigned __int64 value)
 {
-    updateWorkunitTimeStat(lockedwu, scopeType, scope, kind, descr, value, agent->getWorkflowId());
+    updateWorkunitStat(lockedwu, scopeType, scope, kind, descr, value, agent->getWorkflowId());
 }
 
 IThorChildGraph * EclGraph::resolveChildQuery(unsigned subgraphId)

ecl/eclcc/eclcc.cpp

@@ -410,6 +410,7 @@ protected:
     bool optVerifySimplified = false;
     bool optRegenerateCache = false;
     bool optIgnoreCache = false;
+    bool optExtraStats = false;
 
     mutable bool daliConnected = false;
     mutable bool disconnectReported = false;
@@ -1304,7 +1305,14 @@ void EclCC::processSingleQuery(EclCompileInstance & instance,
             unsigned __int64 parseTimeNs = cycle_to_nanosec(get_cycles_now() - startCycles);
             instance.stats.parseTime = (unsigned)nanoToMilli(parseTimeNs);
 
-            updateWorkunitTimeStat(instance.wu, SSTcompilestage, "compile:parse", StTimeElapsed, NULL, parseTimeNs);
+            updateWorkunitStat(instance.wu, SSTcompilestage, "compile:parse", StTimeElapsed, NULL, parseTimeNs);
+
+            if (optExtraStats)
+            {
+                updateWorkunitStat(instance.wu, SSTcompilestage, "compile:cache", StNumAttribsSimplified, NULL, parseCtx.numAttribsSimplified);
+                updateWorkunitStat(instance.wu, SSTcompilestage, "compile:cache", StNumAttribsProcessed, NULL, parseCtx.numAttribsProcessed);
+                updateWorkunitStat(instance.wu, SSTcompilestage, "compile:cache", StNumAttribsFromCache, NULL, parseCtx.numAttribsFromCache);
+            }
 
             if (exportDependencies)
             {
@@ -1321,7 +1329,6 @@ void EclCC::processSingleQuery(EclCompileInstance & instance,
                 saveXML(dependenciesName.str(), parseCtx.nestedDependTree);
             }
 
-
             if (optGenerateMeta)
                 instance.generatedMeta.setown(parseCtx.getClearMetaTree());
             else if (optIncludeMeta && instance.metaOutputFilename)
@@ -1411,7 +1418,7 @@ void EclCC::processSingleQuery(EclCompileInstance & instance,
     unsigned __int64 totalTimeNs = cycle_to_nanosec(get_cycles_now() - startCycles);
     instance.stats.generateTime = (unsigned)nanoToMilli(totalTimeNs) - instance.stats.parseTime;
     //MORE: This is done too late..
-    updateWorkunitTimeStat(instance.wu, SSTcompilestage, "compile", StTimeElapsed, NULL, totalTimeNs);
+    updateWorkunitStat(instance.wu, SSTcompilestage, "compile", StTimeElapsed, NULL, totalTimeNs);
 }
 
 void EclCC::processDefinitions(EclRepositoryArray & repositories)
@@ -2663,6 +2670,9 @@ int EclCC::parseCommandLineOptions(int argc, const char* argv[])
         else if (iter.matchFlag(optIgnoreCache, "--internalignorecache"))  // may generate cache but don't use to simplified expressions
         {
         }
+        else if (iter.matchFlag(optExtraStats, "--internalextrastats"))
+        {
+        }
         else if (iter.matchFlag(logVerbose, "-v") || iter.matchFlag(logVerbose, "--verbose"))
         {
             Owned<ILogMsgFilter> filter = getDefaultLogMsgFilter();

ecl/eclccserver/eclccserver.cpp

@@ -413,7 +413,7 @@ class EclccCompileThread : implements IPooledThread, implements IErrorReporter,
                 queryDllServer().registerDll(realdllname.str(), "Workunit DLL", dllurl.str());
 
                 cycle_t elapsedCycles = get_cycles_now() - startCycles;
-                updateWorkunitTimeStat(workunit, SSTcompilestage, "compile", StTimeElapsed, NULL, cycle_to_nanosec(elapsedCycles));
+                updateWorkunitStat(workunit, SSTcompilestage, "compile", StTimeElapsed, NULL, cycle_to_nanosec(elapsedCycles));
 
                 workunit->commit();
                 return true;

ecl/hql/hqlexpr.cpp

@@ -1070,7 +1070,7 @@ bool HqlParseContext::checkEndMeta()
     return wasGathering;
 }
 
-void HqlParseContext::createCache(IHqlExpression * simplifiedDefinition, bool isMacro)
+bool HqlParseContext::createCache(IHqlExpression * simplifiedDefinition, bool isMacro)
 {
     assertex(simplifiedDefinition);
 
@@ -1079,13 +1079,13 @@ void HqlParseContext::createCache(IHqlExpression * simplifiedDefinition, bool is
 
     getCacheBaseFilename(fullName, baseFilename);
     if (!baseFilename)
-        return;
+        return false;
 
     if (!regenerateCache)
     {
         Owned<IEclCachedDefinition> cached = cache->getDefinition(fullName);
         if (cached->isUpToDate(optionHash))
-            return;
+            return false;
     }
 
     StringBuffer ecl;
@@ -1126,6 +1126,7 @@ void HqlParseContext::createCache(IHqlExpression * simplifiedDefinition, bool is
         stream->flush();
     }
     cacheFile->rename(filename);
+    return true;
 }
 
 void HqlParseContext::finishMeta(bool isSeparateFile, bool success, bool generateMeta)

ecl/hql/hqlexpr.hpp

@@ -918,7 +918,7 @@ public:
     void beginMetaScope() { metaStack.append(*new FileParseMeta); }
     void beginMetaScope(FileParseMeta & active) { metaStack.append(OLINK(active)); }
     void endMetaScope() { metaStack.pop(); }
-    void createCache(IHqlExpression * simplifiedDefinition, bool isMacro);
+    bool createCache(IHqlExpression * simplifiedDefinition, bool isMacro);
     inline FileParseMeta & curMeta() { return metaStack.tos(); }
     inline bool hasCacheLocation( ) const { return !metaOptions.cacheLocation.isEmpty();}
 public:
@@ -947,6 +947,9 @@ public:
     CIArrayOf<FileParseMeta> metaStack;
     IEclCachedDefinitionCollection * cache = nullptr;
     hash64_t optionHash = 0;
+    unsigned numAttribsSimplified = 0;
+    unsigned numAttribsProcessed = 0;
+    unsigned numAttribsFromCache = 0;
 
 private:
     void createDependencyEntry(IHqlScope * scope, IIdAtom * name);
@@ -1017,8 +1020,11 @@ public:
     inline bool hasCacheLocation() const { return parseCtx.hasCacheLocation();}
     inline bool checkSimpleDef() const { return parseCtx.checkSimpleDef; }
     inline bool ignoreCache() const { return parseCtx.ignoreCache; }
-    inline void createCache(IHqlExpression * simplified, bool isMacro) { parseCtx.createCache(simplified, isMacro); }
+    inline bool createCache(IHqlExpression * simplified, bool isMacro) { return parseCtx.createCache(simplified, isMacro); }
     void reportTiming(const char * name);
+    inline void incrementAttribsSimplified() { ++parseCtx.numAttribsSimplified; };
+    inline void incrementAttribsProcessed() { ++parseCtx.numAttribsProcessed; };
+    inline void incrementAttribsFromCache() { ++parseCtx.numAttribsFromCache; };
 protected:
 
     inline IPropertyTree * queryArchive() const { return parseCtx.archive; }

ecl/hql/hqlgram2.cpp

@@ -12373,6 +12373,7 @@ void parseAttribute(IHqlScope * scope, IFileContents * contents, HqlLookupContex
             {
                 contents = cachecontents;
                 alreadySimplified = true;
+                ctx.incrementAttribsFromCache();
             }
         }
     }
@@ -12398,17 +12399,21 @@ void parseAttribute(IHqlScope * scope, IFileContents * contents, HqlLookupContex
     OwnedHqlExpr parsed = scope->lookupSymbol(name, LSFsharedOK|LSFnoreport, ctx);
     bool canCache = parsed && (parsed->getOperator() != no_forwardscope) && !alreadySimplified;
     bool isMacro = parsed && parsed->isMacro();
-    OwnedHqlExpr simplified;
+    ctx.incrementAttribsProcessed();
     if (canCache && (ctx.syntaxChecking() || ctx.hasCacheLocation()))
     {
-        simplified.setown(createSimplifiedDefinition(parsed));
+        OwnedHqlExpr simplified = createSimplifiedDefinition(parsed);
 
         if (simplified)
         {
+            ctx.incrementAttribsSimplified();
+
             if (ctx.hasCacheLocation())
                 attrCtx.createCache(simplified, isMacro);
+
             if (ctx.checkSimpleDef())
                 verifySimpifiedDefinition(parsed, simplified, attrCtx);
+
             if (simplified != parsed && ctx.syntaxChecking() && !ctx.ignoreCache())
                 scope->defineSymbol(LINK(simplified));
         }

ecl/hqlcpp/hqlecl.cpp

@@ -481,7 +481,7 @@ bool HqlDllGenerator::generateCode(HqlQueryContext & query)
 
         doExpand(translator);
         unsigned __int64 elapsed = cycle_to_nanosec(get_cycles_now() - startCycles);
-        updateWorkunitTimeStat(wu, SSTcompilestage, "compile:generate", StTimeElapsed, NULL, elapsed);
+        updateWorkunitStat(wu, SSTcompilestage, "compile:generate", StTimeElapsed, NULL, elapsed);
 
         if (wu->getDebugValueBool("addMemoryToWorkunit", true))
         {
@@ -537,7 +537,7 @@ void HqlDllGenerator::doExpand(HqlCppTranslator & translator)
         }
     }
 
-    updateWorkunitTimeStat(wu, SSTcompilestage, "compile:write c++", StTimeElapsed, NULL, elapsedTimer.elapsedNs());
+    updateWorkunitStat(wu, SSTcompilestage, "compile:write c++", StTimeElapsed, NULL, elapsedTimer.elapsedNs());
 }
 
 bool HqlDllGenerator::abortRequested()
@@ -609,7 +609,7 @@ bool HqlDllGenerator::doCompile(ICppCompiler * compiler)
     }
 
     unsigned __int64 elapsed = cycle_to_nanosec(get_cycles_now() - startCycles);
-    updateWorkunitTimeStat(wu, SSTcompilestage, "compile:compile c++", StTimeElapsed, NULL, elapsed);
+    updateWorkunitStat(wu, SSTcompilestage, "compile:compile c++", StTimeElapsed, NULL, elapsed);
 
     //Keep the files if there was a compile error.
     if (ok && deleteGenerated)

plugins/fileservices/fileservices.cpp

@@ -640,8 +640,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, SSTdfuworkunit, wuScope, StTimeElapsed, ElapsedLabel, milliToNano(time.elapsed()));
-            updateWorkunitTimeStat(wu, SSTdfuworkunit, wuScope, StTimeRemaining, RemainingLabel, milliToNano(dfuwu.getSecsLeft()*1000));
+            updateWorkunitStat(wu, SSTdfuworkunit, wuScope, StTimeElapsed, ElapsedLabel, milliToNano(time.elapsed()));
+            updateWorkunitStat(wu, SSTdfuworkunit, wuScope, StTimeRemaining, RemainingLabel, milliToNano(dfuwu.getSecsLeft()*1000));
             wu->setApplicationValue(label, dfuwu.getID(), dfuwu.getSummaryMessage(), true);
             wu->commit();
             wu.clear();

roxie/ccd/ccdcontext.cpp

@@ -1493,7 +1493,7 @@ public:
                     StringBuffer graphScope;
                     graphScope.append(WorkflowScopePrefix).append(getWorkflowId()).append(":").append(graphName);
                     progressWorkUnit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTgraph, graphScope, StWhenStarted, NULL, startTimeStamp, 1, 0, StatsMergeAppend);
-                    updateWorkunitTimeStat(progressWorkUnit, SSTgraph, graphScope, StTimeElapsed, graphDesc, elapsedTime);
+                    updateWorkunitStat(progressWorkUnit, SSTgraph, graphScope, StTimeElapsed, graphDesc, elapsedTime);
                     addTimeStamp(progressWorkUnit, SSTgraph, graphName, StWhenFinished, getWorkflowId());
                 }
                 graph->reset();

system/jlib/jstatcodes.h

@@ -207,6 +207,9 @@ enum StatisticKind
     StNumUniqueAnalyseExprs,
     StNumUniqueTransformExprs,
     StNumDuplicateKeys,                 // When generating index, number of duplicate keys found
+    StNumAttribsProcessed,
+    StNumAttribsSimplified,
+    StNumAttribsFromCache,
     StMax,
 
     //For any quantity there is potentially the following variants.

system/jlib/jstats.cpp

@@ -839,6 +839,9 @@ static const StatisticMeta statsMetaData[StMax] = {
     { NUMSTAT(UniqueAnalyseExprs) },
     { NUMSTAT(UniqueTransformExprs) },
     { NUMSTAT(DuplicateKeys) },
+    { NUMSTAT(AttribsProcessed) },
+    { NUMSTAT(AttribsSimplified) },
+    { NUMSTAT(AttribsFromCache) },
 };
 
 

thorlcr/master/thdemonserver.cpp

@@ -93,7 +93,7 @@ private:
         formatGraphTimerLabel(timer, graphname, 0, graph.queryGraphId());
         formatGraphTimerScope(graphScope, wfid, graphname, 0, graph.queryGraphId());
         unsigned duration = msTick()-startTime;
-        updateWorkunitTimeStat(wu, SSTsubgraph, graphScope, StTimeElapsed, timer, milliToNano(duration));
+        updateWorkunitStat(wu, SSTsubgraph, graphScope, StTimeElapsed, timer, milliToNano(duration));
 
         if (finished)
         {

thorlcr/master/thgraphmanager.cpp

@@ -915,7 +915,7 @@ bool CJobManager::executeGraph(IConstWorkUnit &workunit, const char *graphName,
         StringBuffer graphTimeStr;
         formatGraphTimerLabel(graphTimeStr, graphName);
 
-        updateWorkunitTimeStat(wu, SSTgraph, graphName, StTimeElapsed, graphTimeStr, graphTimeNs, wfid);
+        updateWorkunitStat(wu, SSTgraph, graphName, StTimeElapsed, graphTimeStr, graphTimeNs, wfid);
 
         addTimeStamp(wu, SSTgraph, graphName, StWhenFinished, wfid);