From 7a190fbdaed3ece3ef5cf37548e598b6df89e78c Mon Sep 17 00:00:00 2001 From: Gavin Halliday Date: Thu, 4 Jan 2024 10:36:12 +0000 Subject: [PATCH] HPCC-29790 Use '>' as a prefix for stage names in stats scopes Signed-off-by: Gavin Halliday --- common/workunit/workunit.cpp | 4 +- devdoc/Workunits.md | 4 +- ecl/eclcc/eclcc.cpp | 34 +++++++------- ecl/eclccserver/eclccserver.cpp | 22 ++++----- ecl/hql/hqlexpr.cpp | 6 +-- ecl/hql/hqltrans.cpp | 16 +++---- ecl/hqlcpp/hqlecl.cpp | 14 +++--- ecl/hqlcpp/hqlhtcpp.cpp | 8 ++-- ecl/hqlcpp/hqlnlp.cpp | 6 +-- ecl/hqlcpp/hqlttcpp.cpp | 6 +-- ecllibrary/std/system/Debug.ecl | 2 +- esp/src/eclwatch/TimingTreeMapWidget.js | 1 + esp/src/src-react/util/metricGraph.ts | 5 +- system/jlib/jcomp.cpp | 2 +- system/jlib/jptree-attrvalues.hpp | 59 ++++++++---------------- system/jlib/jstatcodes.h | 4 +- system/jlib/jstats.cpp | 61 ++++++++++++++++++++++--- system/jlib/jstats.h | 3 ++ 18 files changed, 146 insertions(+), 111 deletions(-) diff --git a/common/workunit/workunit.cpp b/common/workunit/workunit.cpp index 3e76d6d078a..c7405521830 100644 --- a/common/workunit/workunit.cpp +++ b/common/workunit/workunit.cpp @@ -3405,7 +3405,7 @@ void WuScopeFilter::finishedFilter() { sourceFlags &= ~(SSFsearchWorkflow); } - else if (matchOnly(SSTcompilestage)) + else if (matchOnly(SSToperation)) { //compile stages are not stored in the graph sourceFlags &= ~(SSFsearchGraphStats|SSFsearchGraph|SSFsearchWorkflow); @@ -12346,7 +12346,7 @@ extern WORKUNIT_API void submitWorkUnit(const char *wuid, const char *username, { Owned wu = &cw->lock(); - addTimeStamp(wu, SSTcompilestage, "compile", StWhenQueued, 0); + addTimeStamp(wu, SSToperation, ">compile", StWhenQueued, 0); } cw.clear(); diff --git a/devdoc/Workunits.md b/devdoc/Workunits.md index aeff41ec704..408843ba972 100644 --- a/devdoc/Workunits.md +++ b/devdoc/Workunits.md @@ -365,7 +365,7 @@ workunit dll: creator="eclcc" kind="SizePeakMemory" s="compile" - scope="compile" + scope=">compile" ts="1428933081084000" unit="sz" value="27885568"/> @@ -1083,7 +1083,7 @@ the same time (the output filenames are derived from the input name). creator="eclcc" kind="SizePeakMemory" s="compile" - scope="compile" + scope=">compile" ts="1428933081084000" unit="sz" value="27885568" /> diff --git a/ecl/eclcc/eclcc.cpp b/ecl/eclcc/eclcc.cpp index 878b574c332..30341d3e4cd 100644 --- a/ecl/eclcc/eclcc.cpp +++ b/ecl/eclcc/eclcc.cpp @@ -1282,7 +1282,7 @@ void EclCC::processSingleQuery(const EclRepositoryManager & localRepositoryManag systemIoStartInfo.setown(new OsDiskStats(true)); if (optCompileBatchOut.isEmpty()) - addTimeStamp(instance.wu, SSTcompilestage, "compile", StWhenStarted); + addTimeStamp(instance.wu, SSToperation, ">compile", StWhenStarted); const char * sourcePathname = queryContents ? str(queryContents->querySourcePath()) : NULL; const char * defaultErrorPathname = sourcePathname ? sourcePathname : queryAttributePath; @@ -1411,7 +1411,7 @@ void EclCC::processSingleQuery(const EclRepositoryManager & localRepositoryManag if (exportDependencies || optMetaLocation) parseCtx.nestedDependTree.setown(createPTree("Dependencies", ipt_fast)); - addTimeStamp(instance.wu, SSTcompilestage, "compile:parse", StWhenStarted); + addTimeStamp(instance.wu, SSToperation, ">compile:>parse", StWhenStarted); try { HqlLookupContext ctx(parseCtx, &errorProcessor, instance.dataServer); @@ -1464,14 +1464,14 @@ void EclCC::processSingleQuery(const EclRepositoryManager & localRepositoryManag unsigned __int64 parseTimeNs = cycle_to_nanosec(get_cycles_now() - startCycles); instance.stats.parseTime = (unsigned)nanoToMilli(parseTimeNs); - updateWorkunitStat(instance.wu, SSTcompilestage, "compile:parse", StTimeElapsed, NULL, parseTimeNs); + updateWorkunitStat(instance.wu, SSToperation, ">compile:>parse", StTimeElapsed, NULL, parseTimeNs); stat_type sourceDownloadTime = localRepositoryManager.getStatistic(StTimeElapsed); if (sourceDownloadTime) - updateWorkunitStat(instance.wu, SSTcompilestage, "compile:parse:download", StTimeElapsed, NULL, sourceDownloadTime); + updateWorkunitStat(instance.wu, SSToperation, ">compile:>parse:>download", StTimeElapsed, NULL, sourceDownloadTime); if (optExtraStats) { - updateWorkunitStat(instance.wu, SSTcompilestage, "compile:cache", StNumAttribsProcessed, NULL, parseCtx.numAttribsProcessed); + updateWorkunitStat(instance.wu, SSToperation, ">compile:>parse", StNumAttribsProcessed, NULL, parseCtx.numAttribsProcessed); } if (exportDependencies) @@ -1576,35 +1576,35 @@ void EclCC::processSingleQuery(const EclRepositoryManager & localRepositoryManag if (optGatherDiskStats) systemIoFinishInfo.setown(new OsDiskStats(true)); instance.stats.generateTime = (unsigned)nanoToMilli(totalTimeNs) - instance.stats.parseTime; - const char *scopeName = optCompileBatchOut.isEmpty() ? "compile" : "compile:generate"; + const char *scopeName = optCompileBatchOut.isEmpty() ? ">compile" : ">compile:>generate"; if (optCompileBatchOut.isEmpty()) - updateWorkunitStat(instance.wu, SSTcompilestage, scopeName, StTimeElapsed, NULL, totalTimeNs); + updateWorkunitStat(instance.wu, SSToperation, scopeName, StTimeElapsed, NULL, totalTimeNs); const cost_type cost = money2cost_type(calcCost(getMachineCostRate(), nanoToMilli(totalTimeNs))); if (cost) - instance.wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTcompilestage, scopeName, StCostCompile, NULL, cost, 1, 0, StatsMergeReplace); + instance.wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSToperation, scopeName, StCostCompile, NULL, cost, 1, 0, StatsMergeReplace); if (systemFinishTime.getTotal()) { SystemProcessInfo systemElapsed = systemFinishTime - systemStartTime; SystemProcessInfo processElapsed = processFinishTime - processStartTime; - updateWorkunitStat(instance.wu, SSTcompilestage, scopeName, StNumSysContextSwitches, NULL, systemElapsed.getNumContextSwitches()); - updateWorkunitStat(instance.wu, SSTcompilestage, scopeName, StTimeOsUser, NULL, systemElapsed.getUserNs()); - updateWorkunitStat(instance.wu, SSTcompilestage, scopeName, StTimeOsSystem, NULL, systemElapsed.getSystemNs()); - updateWorkunitStat(instance.wu, SSTcompilestage, scopeName, StTimeOsTotal, NULL, systemElapsed.getTotalNs()); - updateWorkunitStat(instance.wu, SSTcompilestage, scopeName, StTimeUser, NULL, processElapsed.getUserNs()); - updateWorkunitStat(instance.wu, SSTcompilestage, scopeName, StTimeSystem, NULL, processElapsed.getSystemNs()); + updateWorkunitStat(instance.wu, SSToperation, scopeName, StNumSysContextSwitches, NULL, systemElapsed.getNumContextSwitches()); + updateWorkunitStat(instance.wu, SSToperation, scopeName, StTimeOsUser, NULL, systemElapsed.getUserNs()); + updateWorkunitStat(instance.wu, SSToperation, scopeName, StTimeOsSystem, NULL, systemElapsed.getSystemNs()); + updateWorkunitStat(instance.wu, SSToperation, scopeName, StTimeOsTotal, NULL, systemElapsed.getTotalNs()); + updateWorkunitStat(instance.wu, SSToperation, scopeName, StTimeUser, NULL, processElapsed.getUserNs()); + updateWorkunitStat(instance.wu, SSToperation, scopeName, StTimeSystem, NULL, processElapsed.getSystemNs()); if (processFinishTime.getPeakResidentMemory()) - updateWorkunitStat(instance.wu, SSTcompilestage, scopeName, StSizePeakMemory, NULL, processFinishTime.getPeakResidentMemory()); + updateWorkunitStat(instance.wu, SSToperation, scopeName, StSizePeakMemory, NULL, processFinishTime.getPeakResidentMemory()); } if (optGatherDiskStats) { const BlockIoStats summaryIo = systemIoFinishInfo->querySummaryStats() - systemIoStartInfo->querySummaryStats(); if (summaryIo.rd_sectors) - updateWorkunitStat(instance.wu, SSTcompilestage, scopeName, StSizeOsDiskRead, NULL, summaryIo.rd_sectors * summaryIo.getSectorSize()); + updateWorkunitStat(instance.wu, SSToperation, scopeName, StSizeOsDiskRead, NULL, summaryIo.rd_sectors * summaryIo.getSectorSize()); if (summaryIo.wr_sectors) - updateWorkunitStat(instance.wu, SSTcompilestage, scopeName, StSizeOsDiskWrite, NULL, summaryIo.wr_sectors * summaryIo.getSectorSize()); + updateWorkunitStat(instance.wu, SSToperation, scopeName, StSizeOsDiskWrite, NULL, summaryIo.wr_sectors * summaryIo.getSectorSize()); } } diff --git a/ecl/eclccserver/eclccserver.cpp b/ecl/eclccserver/eclccserver.cpp index 858eb2dc67d..37837589bcf 100644 --- a/ecl/eclccserver/eclccserver.cpp +++ b/ecl/eclccserver/eclccserver.cpp @@ -408,8 +408,8 @@ class EclccCompileThread : implements IPooledThread, implements IErrorReporter, if (!extension || strncmp(extension, ".o", 2) == 0) filename.set("link"); - scope.append("compile:compile c++:").append(filename); - workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTcompilestage, scope, StTimeElapsed, NULL, compileTimer.elapsedNs(), 1, 0, StatsMergeReplace); + scope.append(">compile:>compile c++:").append(filename); + workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSToperation, scope, StTimeElapsed, NULL, compileTimer.elapsedNs(), 1, 0, StatsMergeReplace); } return ret; @@ -683,7 +683,7 @@ class EclccCompileThread : implements IPooledThread, implements IErrorReporter, bool compileCppSeparately = config->getPropBool("@compileCppSeparately", true); if (compileCppSeparately) { - workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTcompilestage, "compile", StWhenStarted, NULL, getTimeStampNowValue(), 1, 0, StatsMergeAppend); + workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSToperation, ">compile", StWhenStarted, NULL, getTimeStampNowValue(), 1, 0, StatsMergeAppend); eclccCmd.appendf(" -Sx %s.cc", wuid); } if (workunit->getResultLimit()) @@ -717,15 +717,15 @@ class EclccCompileThread : implements IPooledThread, implements IErrorReporter, if (retcode == 0 && compileCppSeparately) { cycle_t startCompileCpp = get_cycles_now(); - workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTcompilestage, "compile:compile c++", StWhenStarted, NULL, getTimeStampNowValue(), 1, 0, StatsMergeAppend); + workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSToperation, ">compile:>compile c++", StWhenStarted, NULL, getTimeStampNowValue(), 1, 0, StatsMergeAppend); retcode = doCompileCpp(abortWaiter, wuid, workunit->getDebugValueInt("maxCompileThreads", defaultMaxCompileThreads)); unsigned __int64 elapsed_compilecpp = cycle_to_nanosec(get_cycles_now() - startCompileCpp); - workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTcompilestage, "compile:compile c++", StTimeElapsed, NULL, elapsed_compilecpp, 1, 0, StatsMergeReplace); + workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSToperation, ">compile:>compile c++", StTimeElapsed, NULL, elapsed_compilecpp, 1, 0, StatsMergeReplace); } if (compileCppSeparately) { unsigned __int64 elapsed_compile = cycle_to_nanosec(get_cycles_now() - startCompile); - workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTcompilestage, "compile", StTimeElapsed, NULL, elapsed_compile, 1, 0, StatsMergeReplace); + workunit->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSToperation, ">compile", StTimeElapsed, NULL, elapsed_compile, 1, 0, StatsMergeReplace); } bool processKilled = (retcode >= 128); //If the process is killed it is probably because it ran out of memory - so try to compile as a K8s job @@ -859,8 +859,8 @@ class EclccCompileThread : implements IPooledThread, implements IErrorReporter, Owned factory = getWorkUnitFactory(); Owned wu = factory->updateWorkUnit(wuid.get()); if (noteDequeued) - addTimeStamp(wu, SSTcompilestage, "compile", StWhenDequeued, 0); - addTimeStamp(wu, SSTcompilestage, "compile", StWhenK8sLaunched, 0); + addTimeStamp(wu, SSToperation, ">compile", StWhenDequeued, 0); + addTimeStamp(wu, SSToperation, ">compile", StWhenK8sLaunched, 0); } k8s::runJob("compile", wuid, wuid); } @@ -934,12 +934,12 @@ class EclccCompileThread : implements IPooledThread, implements IErrorReporter, if (isContainerized()) { if (config->getPropBool("@k8sJob")) - addTimeStamp(workunit, SSTcompilestage, "compile", StWhenK8sStarted, 0); + addTimeStamp(workunit, SSToperation, ">compile", StWhenK8sStarted, 0); else - addTimeStamp(workunit, SSTcompilestage, "compile", StWhenDequeued, 0); + addTimeStamp(workunit, SSToperation, ">compile", StWhenDequeued, 0); } else - addTimeStamp(workunit, SSTcompilestage, "compile", StWhenDequeued, 0); + addTimeStamp(workunit, SSToperation, ">compile", StWhenDequeued, 0); CSDSServerStatus serverstatus("ECLCCserverThread"); serverstatus.queryProperties()->setProp("@cluster", config->queryProp("@name")); diff --git a/ecl/hql/hqlexpr.cpp b/ecl/hql/hqlexpr.cpp index 57529bce0ae..324fce4dd7b 100644 --- a/ecl/hql/hqlexpr.cpp +++ b/ecl/hql/hqlexpr.cpp @@ -1464,9 +1464,9 @@ void HqlLookupContext::reportTiming(const char * name) __uint64 localTime = cycle_to_nanosec(elapsedCycles - childCycles); StringBuffer scope; - scope.append("compiler::parse::").append(name); - parseCtx.statsTarget.addStatistic(SSTcompilestage, scope, StTimeTotalExecute, nullptr, totalTime, 1, 0, StatsMergeSum); - parseCtx.statsTarget.addStatistic(SSTcompilestage, scope, StTimeLocalExecute, nullptr, localTime, 1, 0, StatsMergeSum); + scope.append(">compile:>parse:>").append(name); + parseCtx.statsTarget.addStatistic(SSToperation, scope, StTimeTotalExecute, nullptr, totalTime, 1, 0, StatsMergeSum); + parseCtx.statsTarget.addStatistic(SSToperation, scope, StTimeLocalExecute, nullptr, localTime, 1, 0, StatsMergeSum); childCycles = 0; } diff --git a/ecl/hql/hqltrans.cpp b/ecl/hql/hqltrans.cpp index 622b6f668c8..164b43e4b98 100644 --- a/ecl/hql/hqltrans.cpp +++ b/ecl/hql/hqltrans.cpp @@ -166,18 +166,18 @@ void HqlTransformStats::add(const HqlTransformStats & other) void HqlTransformStats::gatherTransformStats(IStatisticTarget & target, const char * scope) const { #ifdef TRANSFORM_STATS_TIME - target.addStatistic(SSTcompilestage, scope, StTimeTotalExecute, nullptr, cycle_to_nanosec(totalTime), 1, 0, StatsMergeSum); - target.addStatistic(SSTcompilestage, scope, StTimeLocalExecute, nullptr, cycle_to_nanosec(totalTime-(childTime-recursiveTime)), 1, 0, StatsMergeSum); + target.addStatistic(SSToperation, scope, StTimeTotalExecute, nullptr, cycle_to_nanosec(totalTime), 1, 0, StatsMergeSum); + target.addStatistic(SSToperation, scope, StTimeLocalExecute, nullptr, cycle_to_nanosec(totalTime-(childTime-recursiveTime)), 1, 0, StatsMergeSum); #endif #ifdef TRANSFORM_STATS_DETAILS if (numAnalyseCalls) - target.addStatistic(SSTcompilestage, scope, StNumAnalyseExprs, nullptr, numAnalyseCalls, 1, 0, StatsMergeSum); + target.addStatistic(SSToperation, scope, StNumAnalyseExprs, nullptr, numAnalyseCalls, 1, 0, StatsMergeSum); if (numAnalyse) - target.addStatistic(SSTcompilestage, scope, StNumUniqueAnalyseExprs, nullptr, numAnalyse, 1, 0, StatsMergeSum); + target.addStatistic(SSToperation, scope, StNumUniqueAnalyseExprs, nullptr, numAnalyse, 1, 0, StatsMergeSum); if (numTransformCalls) - target.addStatistic(SSTcompilestage, scope, StNumTransformExprs, nullptr, numTransformCalls, 1, 0, StatsMergeSum); + target.addStatistic(SSToperation, scope, StNumTransformExprs, nullptr, numTransformCalls, 1, 0, StatsMergeSum); if (numTransforms) - target.addStatistic(SSTcompilestage, scope, StNumUniqueTransformExprs, nullptr, numTransforms, 1, 0, StatsMergeSum); + target.addStatistic(SSToperation, scope, StNumUniqueTransformExprs, nullptr, numTransforms, 1, 0, StatsMergeSum); #endif } @@ -247,8 +247,8 @@ void HqlTransformerInfo::gatherTransformStats(IStatisticTarget & target) const if (numInstances) { StringBuffer scope; - scope.append("compile:transform:").append(name); - target.addStatistic(SSTcompilestage, scope, StNumStarts, nullptr, numInstances, 1, 0, StatsMergeSum); + scope.append(">compile:>transform:>").append(name); + target.addStatistic(SSToperation, scope, StNumStarts, nullptr, numInstances, 1, 0, StatsMergeSum); stats.gatherTransformStats(target, scope); } #endif diff --git a/ecl/hqlcpp/hqlecl.cpp b/ecl/hqlcpp/hqlecl.cpp index 2cd7471b0de..673ad1ecbf9 100644 --- a/ecl/hqlcpp/hqlecl.cpp +++ b/ecl/hqlcpp/hqlecl.cpp @@ -512,7 +512,7 @@ bool HqlDllGenerator::generateCode(HqlQueryContext & query) noOutput = true; { // ensure warnings/errors are available before we do the processing... - addTimeStamp(wu, SSTcompilestage, "compile:generate", StWhenStarted); + addTimeStamp(wu, SSToperation, ">compile:>generate", StWhenStarted); wu->commit(); cycle_t startCycles = get_cycles_now(); @@ -583,13 +583,13 @@ bool HqlDllGenerator::generateCode(HqlQueryContext & query) doExpand(translator); unsigned __int64 elapsed = cycle_to_nanosec(get_cycles_now() - startCycles); - updateWorkunitStat(wu, SSTcompilestage, "compile:generate", StTimeElapsed, NULL, elapsed); + updateWorkunitStat(wu, SSToperation, ">compile:>generate", StTimeElapsed, NULL, elapsed); if (wu->getDebugValueBool("addMemoryToWorkunit", true)) { ProcessInfo info(ReadMemoryInfo); if (info.getPeakResidentMemory()) - wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSTcompilestage, "compile", StSizePeakMemory, NULL, info.getPeakResidentMemory(), 1, 0, StatsMergeReplace); + wu->setStatistic(queryStatisticsComponentType(), queryStatisticsComponentName(), SSToperation, ">compile", StSizePeakMemory, NULL, info.getPeakResidentMemory(), 1, 0, StatsMergeReplace); } @@ -633,7 +633,7 @@ void HqlDllGenerator::insertStandAloneCode() void HqlDllGenerator::doExpand(HqlCppTranslator & translator) { CCycleTimer elapsedTimer; - addTimeStamp(wu, SSTcompilestage, "compile:generate:write c++", StWhenStarted); + addTimeStamp(wu, SSToperation, ">compile:>generate:>write c++", StWhenStarted); bool isMultiFile = translator.spanMultipleCppFiles(); CompilerType targetCompiler = translator.queryOptions().targetCompiler; @@ -655,7 +655,7 @@ void HqlDllGenerator::doExpand(HqlCppTranslator & translator) } } - updateWorkunitStat(wu, SSTcompilestage, "compile:generate:write c++", StTimeElapsed, NULL, elapsedTimer.elapsedNs()); + updateWorkunitStat(wu, SSToperation, ">compile:>generate:>write c++", StTimeElapsed, NULL, elapsedTimer.elapsedNs()); } bool HqlDllGenerator::abortRequested() @@ -666,7 +666,7 @@ bool HqlDllGenerator::abortRequested() bool HqlDllGenerator::doCompile(ICppCompiler * compiler) { cycle_t startCycles = get_cycles_now(); - addTimeStamp(wu, SSTcompilestage, "compile:compile c++", StWhenStarted); + addTimeStamp(wu, SSToperation, ">compile:>compile c++", StWhenStarted); ForEachItemIn(i, sourceFiles) compiler->addSourceFile(sourceFiles.item(i), sourceFlags.item(i)); @@ -735,7 +735,7 @@ bool HqlDllGenerator::doCompile(ICppCompiler * compiler) } unsigned __int64 elapsed = cycle_to_nanosec(get_cycles_now() - startCycles); - updateWorkunitStat(wu, SSTcompilestage, "compile:compile c++", StTimeElapsed, NULL, elapsed); + updateWorkunitStat(wu, SSToperation, ">compile:>compile c++", StTimeElapsed, NULL, elapsed); } //Keep the files if there was a compile error. if (ok && deleteGenerated) diff --git a/ecl/hqlcpp/hqlhtcpp.cpp b/ecl/hqlcpp/hqlhtcpp.cpp index f2939a87576..d0f3b57628e 100644 --- a/ecl/hqlcpp/hqlhtcpp.cpp +++ b/ecl/hqlcpp/hqlhtcpp.cpp @@ -6130,7 +6130,7 @@ bool HqlCppTranslator::buildCode(HqlQueryContext & query, const char * embeddedL complexityText.append(getComplexity(workflow)); wu()->setDebugValue("__Calculated__Complexity__", complexityText, true); if (options.timeTransforms) - noteFinishedTiming("compile:complexity", startCycles); + noteFinishedTiming(">compile:>complexity", startCycles); } buildRowAccessors(); @@ -6220,7 +6220,7 @@ bool HqlCppTranslator::buildCpp(IHqlCppInstance & _code, HqlQueryContext & query cycle_t startCycles = get_cycles_now(); peepholeOptimize(*code, *this); if (options.timeTransforms) - noteFinishedTiming("compile:transform:peephole", startCycles); + noteFinishedTiming(">compile:>transform:>peephole", startCycles); } } catch (IException * e) @@ -6245,7 +6245,7 @@ bool HqlCppTranslator::buildCpp(IHqlCppInstance & _code, HqlQueryContext & query void HqlCppTranslator::ensureWorkUnitUpdated() { if (timeReporter) - updateWorkunitTimings(wu(), SSTcompilestage, StTimeTotalExecute, timeReporter); + updateWorkunitTimings(wu(), SSToperation, StTimeTotalExecute, timeReporter); } double HqlCppTranslator::getComplexity(IHqlExpression * expr, ClusterType cluster) @@ -9767,7 +9767,7 @@ IHqlExpression * HqlCppTranslator::getResourcedGraph(IHqlExpression * expr, IHql return NULL; if (options.timeTransforms) - noteFinishedTiming("compile:resource graph", startCycles); + noteFinishedTiming(">compile:>resource graph", startCycles); traceExpression("AfterResourcing", resourced); if (options.regressionTest) diff --git a/ecl/hqlcpp/hqlnlp.cpp b/ecl/hqlcpp/hqlnlp.cpp index 3db91e7b14c..480b5c01b5c 100644 --- a/ecl/hqlcpp/hqlnlp.cpp +++ b/ecl/hqlcpp/hqlnlp.cpp @@ -718,7 +718,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivityParse(BuildCtx & ctx, IHqlExpr doBuildParseValidators(instance->nestedctx, expr); doBuildParseExtra(instance->startctx, expr); if (options.timeTransforms) - noteFinishedTiming("compile:PARSE:prepare", startPrepareCycles); + noteFinishedTiming(">compile:>PARSE:>prepare", startPrepareCycles); MemoryBuffer buffer; cycle_t startCompileCycles = get_cycles_now(); @@ -729,7 +729,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivityParse(BuildCtx & ctx, IHqlExpr doBuildParseCompiled(instance->classctx, buffer); if (options.timeTransforms) - noteFinishedTiming("compile:PARSE:compile", startCompileCycles); + noteFinishedTiming(">compile:>PARSE:>compile", startCompileCycles); nlpParse->buildProductions(*this, instance->classctx, instance->startctx); @@ -763,7 +763,7 @@ ABoundActivity * HqlCppTranslator::doBuildActivityParse(BuildCtx & ctx, IHqlExpr buildInstanceSuffix(instance); buildConnectInputOutput(ctx, instance, boundDataset, 0, 0); if (options.timeTransforms) - noteFinishedTiming("compile:PARSE", startCycles); + noteFinishedTiming(">compile:>PARSE", startCycles); return instance->getBoundActivity(); } diff --git a/ecl/hqlcpp/hqlttcpp.cpp b/ecl/hqlcpp/hqlttcpp.cpp index bfc019b04ac..6dadd057d3f 100644 --- a/ecl/hqlcpp/hqlttcpp.cpp +++ b/ecl/hqlcpp/hqlttcpp.cpp @@ -14168,7 +14168,7 @@ void HqlCppTranslator::normalizeGraphForGeneration(HqlExprArray & exprs, HqlQuer cycle_t startCycles = get_cycles_now(); pickBestEngine(exprs); if (options.timeTransforms) - noteFinishedTiming("compile:transform:pick engine", startCycles); + noteFinishedTiming(">compile:>transform:>pick engine", startCycles); } #endif @@ -14375,7 +14375,7 @@ bool HqlCppTranslator::transformGraphForGeneration(HqlQueryContext & query, Work cycle_t startCycles = get_cycles_now(); pickBestEngine(workflow); if (options.timeTransforms) - noteFinishedTiming("compile:transform:pick engine", startCycles); + noteFinishedTiming(">compile:>transform:>pick engine", startCycles); } #endif updateClusterType(); @@ -14397,7 +14397,7 @@ bool HqlCppTranslator::transformGraphForGeneration(HqlQueryContext & query, Work cycle_t startCycles = get_cycles_now(); checkDependencyConsistency(curWorkflow.queryExprs()); if (options.timeTransforms) - noteFinishedTiming("compile:transform:check dependency", startCycles); + noteFinishedTiming(">compile:>transform:>check dependency", startCycles); } traceExpressions("afterTransformGraphForGeneration", curWorkflow); diff --git a/ecllibrary/std/system/Debug.ecl b/ecllibrary/std/system/Debug.ecl index 663cbe5954c..a7f8adbea51 100644 --- a/ecllibrary/std/system/Debug.ecl +++ b/ecllibrary/std/system/Debug.ecl @@ -6,7 +6,7 @@ rtl := SERVICE unsigned4 msTick() : eclrtl,library='eclrtl',entrypoint='rtlTick'; - unsigned4 sleep(unsigned4 _delay) : eclrtl,action,library='eclrtl',entrypoint='rtlSleep'; + unsigned4 sleep(unsigned4 _delay) : eclrtl,action,library='eclrtl',entrypoint='rtlSleep',time; printStackReport(integer startIP) : cpp,action,library='jlib'; END; diff --git a/esp/src/eclwatch/TimingTreeMapWidget.js b/esp/src/eclwatch/TimingTreeMapWidget.js index fba7550ef94..a9a59e015fa 100644 --- a/esp/src/eclwatch/TimingTreeMapWidget.js +++ b/esp/src/eclwatch/TimingTreeMapWidget.js @@ -198,6 +198,7 @@ define([ } return (timer.Name !== "Process" && timer.Name !== "compile" && + timer.Name !== ">compile" && timer.Name !== "Total thor time" && timer.Name !== "Total cluster time" && timer.Name.indexOf(":TimeElapsed") < 0); diff --git a/esp/src/src-react/util/metricGraph.ts b/esp/src/src-react/util/metricGraph.ts index 1aa7b0f1c0b..19f79f7eb53 100644 --- a/esp/src/src-react/util/metricGraph.ts +++ b/esp/src/src-react/util/metricGraph.ts @@ -225,7 +225,10 @@ export class MetricGraph extends Graph2 { } vertexLabel(v: IScope, options: MetricsOptions): string { - return v.type === "activity" ? format(options.activityTpl, v) : v.Label || v.id; + return v.type === "activity" ? format(options.activityTpl, v) : + v.type === "function" ? v.id + "()" : + v.type === "operation" && v.id.charAt(0) === ">" ? v.id.substring(1) : + v.Label || v.id; } vertexStatus(v: IScope): ScopeStatus { diff --git a/system/jlib/jcomp.cpp b/system/jlib/jcomp.cpp index 339682c15e4..4d0f218f253 100644 --- a/system/jlib/jcomp.cpp +++ b/system/jlib/jcomp.cpp @@ -483,7 +483,7 @@ bool CppCompiler::compile() if (abortChecker && abortChecker->abortRequested()) return false; - TIME_SECTION(!verbose ? NULL : onlyCompile ? "compile" : "compile/link"); + TIME_SECTION(!verbose ? NULL : ">compile"); Owned pool = createThreadPool("CCompilerWorker", this, this, maxCompileThreads && !reportOnly() ? maxCompileThreads : 1, INFINITE); addCompileOption(COMPILE_ONLY[targetCompiler]); diff --git a/system/jlib/jptree-attrvalues.hpp b/system/jlib/jptree-attrvalues.hpp index 6c7850f946f..bacf626d023 100644 --- a/system/jlib/jptree-attrvalues.hpp +++ b/system/jlib/jptree-attrvalues.hpp @@ -66,47 +66,26 @@ "cnt", "coLocal", "compile", - "compile:compile c++", + ">compile", "compiled", - "compile:generate c++", - "compile:generate PARSE", - "compile:generate PARSE:analyse", - "compile:generate PARSE:compile", - "compile:generate PARSE:create structure", - "compile:generate PARSE:generate", - "compile:generate PARSE:optimize", - "compile:generate PARSE:prepare", - "compile:global implicit projects", - "compile:implicit projects", - "compile:optimize graph", - "compile:parseTime", - "compile:peephole optimize", - "compile:resource graph", - "compile:tree transform", - "compile:tree transform: check dependency", - "compile:tree transform: compound activity", - "compile:tree transform: convert logical", - "compile:tree transform: convert SetResult to Extract", - "compile:tree transform: expand delayed calls", - "compile:tree transform: global fold", - "compile:tree transform: hoist nested compound", - "compile:tree transform: merge thor", - "compile:tree transform: migrate", - "compile:tree transform: normalize", - "compile:tree transform: normalize.annotations", - "compile:tree transform: normalize.DFStransform", - "compile:tree transform: normalize.initial", - "compile:tree transform: normalize.KeyedProjectTransformer", - "compile:tree transform: normalize.linkedChildRows", - "compile:tree transform: normalize result", - "compile:tree transform: normalize.scope", - "compile:tree transform: optimize activities", - "compile:tree transform: optimize disk read", - "compile:tree transform: spot global cse", - "compile:tree transform: stored results", - "compile:tree transform: substituteClusterSize", - "compile:tree transform: thor hole", - "compile:write c++", + "compile:>compile c++", + ">compile:>compile c++", + "compile:>generate", + ">compile:>generate", + "compile:>generate:>write c++", + ">compile:>generate:>write c++", + "compile:>parse", + ">compile:>parse", + "compile:>parse:>download", + ">compile:>parse:>download", + "compile:>resource graph", + ">compile:>resource graph", + "compile:>transform", + ">compile:>transform", + "compile:>transform:>peephole", + ">compile:>transform:>peephole", + "compile:>transform:>pick engine", + ">compile:>transform:>pick engine", "compiling", "completed", "componentfiles/configxml", diff --git a/system/jlib/jstatcodes.h b/system/jlib/jstatcodes.h index 82ac4722aec..0f264acc92f 100644 --- a/system/jlib/jstatcodes.h +++ b/system/jlib/jstatcodes.h @@ -29,6 +29,8 @@ #define FileScopePrefix "p" #define ChannelScopePrefix "x" #define DFUWorkunitScopePrefix "D" +#define SectionScopePrefix "n" +#define OperationScopePrefix ">" #define MATCHES_CONST_PREFIX(search, prefix) (strncmp(search, prefix, strlen(prefix)) == 0) @@ -66,7 +68,7 @@ enum StatisticScopeType SSTactivity, SSTallocator, // identifies an allocator SSTsection, // A section within the query - not a great differentiator - SSTcompilestage, // a stage within the compilation process + SSToperation, // an operation or stage in processing SSTdfuworkunit, // a reference to an executing dfu workunit SSTedge, SSTfunction, // a function call diff --git a/system/jlib/jstats.cpp b/system/jlib/jstats.cpp index fda622c753a..f3e4e8f2c3d 100644 --- a/system/jlib/jstats.cpp +++ b/system/jlib/jstats.cpp @@ -72,7 +72,7 @@ void setStatisticsComponentName(StatisticCreatorType processType, const char * p // Textual forms of the different enumerations, first items are for none and all. static constexpr const char * const measureNames[] = { "", "all", "ns", "ts", "cnt", "sz", "cpu", "skw", "node", "ppm", "ip", "cy", "en", "txt", "bool", "id", "fname", "cost", NULL }; static constexpr const char * const creatorTypeNames[]= { "", "all", "unknown", "hthor", "roxie", "roxie:s", "thor", "thor:m", "thor:s", "eclcc", "esp", "summary", NULL }; -static constexpr const char * const scopeTypeNames[] = { "", "all", "global", "graph", "subgraph", "activity", "allocator", "section", "compile", "dfu", "edge", "function", "workflow", "child", "file", "channel", "unknown", nullptr }; +static constexpr const char * const scopeTypeNames[] = { "", "all", "global", "graph", "subgraph", "activity", "allocator", "section", "operation", "dfu", "edge", "function", "workflow", "child", "file", "channel", "unknown", nullptr }; static unsigned matchString(const char * const * names, const char * search, unsigned dft) { @@ -106,7 +106,7 @@ static const StatisticScopeType scoreOrder[] = { SSTsubgraph, SSTallocator, SSTsection, - SSTcompilestage, + SSToperation, SSTdfuworkunit, SSTfunction, SSTworkflow, @@ -554,7 +554,7 @@ StatisticScopeType getScopeType(const char * scope) if (nullptr == scope) id.setId(SSTglobal, 0); else if (startsWith(scope, "compile")) - id.setId(SSTcompilestage, 0); + id.setId(SSToperation, 0); else { const char * colon = strchr(scope, ':'); @@ -1432,6 +1432,10 @@ StringBuffer & StatsScopeId::getScopeText(StringBuffer & out) const return out.append(ChannelScopePrefix).append(id); case SSTdfuworkunit: return out.append(DFUWorkunitScopePrefix).append(name); + case SSTsection: + return out.append(SectionScopePrefix).append(name); + case SSToperation: + return out.append(OperationScopePrefix).append(name); case SSTunknown: return out.append(name); case SSTglobal: @@ -1449,8 +1453,11 @@ unsigned StatsScopeId::getHash() const switch (scopeType) { case SSTfunction: - case SSTunknown: case SSTdfuworkunit: + case SSTfile: + case SSTsection: + case SSToperation: + case SSTunknown: return hashcz((const byte *)name.get(), (unsigned)scopeType); default: return hashc((const byte *)&id, sizeof(id), (unsigned)scopeType); @@ -1498,9 +1505,11 @@ void StatsScopeId::describe(StringBuffer & description) const case SSTedge: description.append(' ').append(id).append(',').append(extra); break; - case SSTfile: case SSTfunction: case SSTdfuworkunit: + case SSTfile: + case SSTsection: + case SSToperation: description.append(' ').append(name); break; default: @@ -1547,9 +1556,11 @@ void StatsScopeId::deserialize(MemoryBuffer & in, unsigned version) in.read(id); in.read(extra); break; - case SSTfile: case SSTfunction: case SSTdfuworkunit: + case SSTfile: + case SSTsection: + case SSToperation: in.read(name); break; default: @@ -1575,9 +1586,11 @@ void StatsScopeId::serialize(MemoryBuffer & out) const out.append(id); out.append(extra); break; - case SSTfile: case SSTfunction: case SSTdfuworkunit: + case SSTfile: + case SSTsection: + case SSToperation: out.append(name); break; default: @@ -1674,6 +1687,11 @@ bool StatsScopeId::setScopeText(const char * text, const char * * _next) setChildGraphId(strtoul(text+ strlen(ChildGraphScopePrefix), next, 10)); return true; } + if (MATCHES_CONST_PREFIX(text, "compile")) + { + setOperationId("compile"); + return true; + } break; case ChannelScopePrefix[0]: if (MATCHES_CONST_PREFIX(text, ChannelScopePrefix) && isdigit(text[strlen(ChannelScopePrefix)])) @@ -1691,6 +1709,24 @@ bool StatsScopeId::setScopeText(const char * text, const char * * _next) return true; } break; + case SectionScopePrefix[0]: + if (MATCHES_CONST_PREFIX(text, SectionScopePrefix)) + { + setSectionId(text+strlen(SectionScopePrefix)); + if (_next) + *_next = text + strlen(text); + return true; + } + break; + case OperationScopePrefix[0]: + if (MATCHES_CONST_PREFIX(text, OperationScopePrefix)) + { + setOperationId(text+strlen(OperationScopePrefix)); + if (_next) + *_next = text + strlen(text); + return true; + } + break; case '\0': setId(SSTglobal, 0); return true; @@ -1761,6 +1797,17 @@ void StatsScopeId::setDfuWorkunitId(const char * _name) scopeType = SSTdfuworkunit; name.set(_name); } +void StatsScopeId::setSectionId(const char * _name) +{ + scopeType = SSTsection; + name.set(_name); +} +void StatsScopeId::setOperationId(const char * _name) +{ + scopeType = SSToperation; + name.set(_name); +} + //-------------------------------------------------------------------------------------------------------------------- enum diff --git a/system/jlib/jstats.h b/system/jlib/jstats.h index 4fa1f8e08f0..187cb9a2f11 100644 --- a/system/jlib/jstats.h +++ b/system/jlib/jstats.h @@ -88,6 +88,9 @@ class jlib_decl StatsScopeId void setWorkflowId(unsigned _id); void setChildGraphId(unsigned _id); void setDfuWorkunitId(const char * _name); + void setSectionId(const char * _name); + void setOperationId(const char * _name); + int compare(const StatsScopeId & other) const; bool operator == (const StatsScopeId & other) const { return matches(other); }