HPCC-17252 Track which activities take a long time to generate

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

ecl/hqlcpp/hqlcpp.cpp

@@ -1589,6 +1589,7 @@ void HqlCppTranslator::cacheOptions()
         DebugOption(options.defaultPersistExpiry, "defaultPersistExpiry", DEFAULT_PERSIST_EXPIRY_PERIOD),
         DebugOption(options.defaultExpiry, "defaultExpiry", DEFAULT_EXPIRY_PERIOD),
         DebugOption(options.searchDistanceThreshold, "searchDistanceThreshold", 1000000),
+        DebugOption(options.generateActivityThreshold, "generateActivityThreshold", 0),  // most users are not interested so disable by default
 
         DebugOption(options.checkAsserts,"checkAsserts", true),
         DebugOption(options.assertSortedDistributed,"assertSortedDistributed", false),
@@ -1897,6 +1898,8 @@ void HqlCppTranslator::postProcessOptions()
     if (options.resourceSequential)
         options.resourceConditionalActions = true;
 
+    options.generateActivityThresholdCycles = nanosec_to_cycle(options.generateActivityThreshold * I64C(1000000));
+
     //Probably best to ignore this warning. - possibly configure it based on some other option
     globalOnWarnings->addOnWarning(HQLWRN_FoldRemoveKeyed, ignoreAtom);
 

ecl/hqlcpp/hqlcpp.ipp

@@ -582,6 +582,8 @@ struct HqlCppOptions
     unsigned            defaultPersistExpiry;
     unsigned            defaultExpiry;
     unsigned            searchDistanceThreshold;
+    unsigned            generateActivityThreshold;    // Record activities which take more than this value (in ms) to generate (0 disables)
+    cycle_t             generateActivityThresholdCycles;
     int                 defaultNumPersistInstances;
     unsigned            reportDFSinfo;
     CompilerType        targetCompiler;

ecl/hqlcpp/hqlhtcpp.cpp

@@ -2179,6 +2179,10 @@ void ActivityInstance::noteChildActivityLocation(IHqlExpression * pass)
 
 void ActivityInstance::buildPrefix()
 {
+    const HqlCppOptions & options = translator.queryOptions();
+    if (options.generateActivityThresholdCycles != 0)
+        startTime = get_cycles_now();
+
     startDistance = querySearchDistance();
     StringBuffer s;
 
@@ -2301,6 +2305,24 @@ void ActivityInstance::buildSuffix()
             addAttributeInt("approxClassSize", approxSize);
     }
 
+    if (options.generateActivityThresholdCycles != 0)
+    {
+        cycle_t totalTime = get_cycles_now() - startTime;
+        cycle_t localTime = totalTime - nestedTime;
+        if (localTime > options.generateActivityThresholdCycles)
+        {
+            if (containerActivity)
+                containerActivity->nestedTime += totalTime;
+
+            unsigned __int64 generateTime = cycle_to_nanosec(localTime);
+            //Record as a statistic rather than a graph attribute to avoid stats iterators needing to walk the graph
+            //We could also record local and totalTime if they differ - but that would then need another stats kind
+            StringBuffer scope;
+            getScope(scope);
+            translator.wu()->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTactivity, scope, StTimeGenerate, nullptr, generateTime, 1, 0, StatsMergeReplace);
+        }
+    }
+
     unsigned __int64 searchDistance = querySearchDistance() - startDistance;
     if (searchDistance > options.searchDistanceThreshold)
         addAttributeInt("searchDistance", searchDistance);
@@ -2361,6 +2383,21 @@ void ActivityInstance::buildMetaMember()
 }
 
 
+void ActivityInstance::getScope(StringBuffer & scope) const
+{
+    if (containerActivity)
+    {
+        containerActivity->getScope(scope);
+        scope.append(":");
+    }
+    else if (translator.activeGraph)
+        scope.append(translator.activeGraph->name).append(":");
+
+    if (subgraph)
+        scope.append(SubGraphScopePrefix).append(subgraph->id).append(":");
+    scope.append(ActivityScopePrefix).append(activityId);
+}
+
 void ActivityInstance::addConstructorMetaParameter()
 {
     translator.buildMetaInfo(meta);

ecl/hqlcpp/hqlhtcpp.ipp

@@ -145,6 +145,7 @@ public:
     void buildPrefix();
     void buildSuffix();
     void buildMetaMember();
+    void getScope(StringBuffer & scope) const; // return the full scope name of this activity
 
     void addAttribute(const char * name, const char * value);
     void addAttribute(const char * name, IHqlExpression * expr);
@@ -229,6 +230,8 @@ public:
     OwnedHqlExpr colocalMember;
     Owned<ParentExtract> nestedExtract;
     SubGraphInfo * subgraph;
+    cycle_t startTime = 0;
+    cycle_t nestedTime = 0;
     unsigned __int64 startDistance = 0;
 };
 

ecl/hqlcpp/hqlstmt.cpp

@@ -824,6 +824,38 @@ HqlExprAssociation * BuildCtx::queryFirstCommonAssociation(AssocKind searchKind)
 }
 
 
+void BuildCtx::walkAssociations(AssocKind searchMask, IAssociationVisitor & visitor)
+{
+    HqlStmts * searchStmts = curStmts;
+
+    // search all statements in the tree before this one, to see
+    // if an expression already exists...  If so return the target
+    // of the assignment.
+    for (;;)
+    {
+        if (searchStmts->associationMask & searchMask)
+        {
+            CIArray & defs = searchStmts->defs;
+            ForEachItemInRev(idx, searchStmts->defs)
+            {
+                HqlExprAssociation & cur = (HqlExprAssociation &)searchStmts->defs.item(idx);
+                if (cur.getKind() & searchMask)
+                {
+                    if (visitor.visit(cur))
+                        return;
+                }
+            }
+        }
+
+        HqlStmt * limitStmt = searchStmts->queryStmt();
+        if (!limitStmt)
+            break;
+        searchStmts = limitStmt->queryContainer();
+    }
+}
+
+
+
 HqlExprAssociation * BuildCtx::queryMatchExpr(IHqlExpression * search)
 {
     HqlExprCopyArray selectors;

ecl/hqlcpp/hqlstmt.hpp

@@ -139,6 +139,7 @@ public:
     HqlExprAssociation *        queryAssociation(IHqlExpression * dataset, AssocKind kind, HqlExprCopyArray * selectors);
     HqlExprAssociation *        queryFirstAssociation(AssocKind kind);
     HqlExprAssociation *        queryFirstCommonAssociation(AssocKind kind);
+    void                        walkAssociations(AssocKind searchMask, IAssociationVisitor & visitor); // Function to walk associations filtered by kind
     HqlExprAssociation *        queryMatchExpr(IHqlExpression * expr);
     bool                        getMatchExpr(IHqlExpression * expr, CHqlBoundExpr & bound);
     IHqlExpression *            getTempDeclare(ITypeInfo * type, IHqlExpression * value);

system/jlib/jstatcodes.h

@@ -184,6 +184,8 @@ enum StatisticKind
     StNumAllocations,
     StNumAllocationScans,
     StNumDiskRetries,
+    StTimeGenerate,
+    StCycleGenerateCycles,
 
     StMax,
 

system/jlib/jstats.cpp

@@ -617,6 +617,8 @@ static const StatisticMeta statsMetaData[StMax] = {
     { NUMSTAT(Allocations) },
     { NUMSTAT(AllocationScans) },
     { NUMSTAT(DiskRetries) },
+    { TIMESTAT(Generate) },
+    { CYCLESTAT(Generate) },
 };