From 3bd0f560aa1c1e006e46a66a615af14e72283bb8 Mon Sep 17 00:00:00 2001 From: Richard Chapman <rchapman@hpccsystems.com> Date: Wed, 16 Aug 2023 14:59:04 +0100 Subject: [PATCH] WIP Signed-off-by: Richard Chapman <rchapman@hpccsystems.com> --- devdoc/roxie.md | 25 +++++++++++++++++++ roxie/ccd/ccdmain.cpp | 56 +++++++++++++++++++++---------------------- tools/doperf/doperf | 1 + 3 files changed, 54 insertions(+), 28 deletions(-) diff --git a/devdoc/roxie.md b/devdoc/roxie.md index cfcbadf92b9..e840f9d3bf3 100644 --- a/devdoc/roxie.md +++ b/devdoc/roxie.md @@ -281,3 +281,28 @@ Should the scope of the blacklist be different? Possible scopes are: Options 2 and 4 above would allow all aspects of the blacklisting behaviour to be specified by options on the SOAPCALL. We could control whether or not the blacklister is to be used at all via a SOAPCALL option with any of the above... + +perftrace options +================= + +The HPCC Platform includes a rudimentary performance tracing feature using periodic stack capture to generate flame graphs. Roxie supports this in 3 ways: + +1. If expert/@profileStartup is set in roxie config, a flame graph is generated for operations during Roxie startup phase. +2. If @perf is set on an incoming query, a flame graph is generated for the lifetime of that query's execution, and returned along with the query results +3. If expert/perftrace is set in roxie config, one-shot roxie queries (e.g. eclagent mode) generate a flame graph (currently just to a text file). + +The perf trace operates as follows: + +1. A child process is launched that runs the doperf script. This samples the current stack(s) every 0.2s (configurable) to a series of text files. +2. When tracing is done, these text files are "folded" via a perl script that notes every unique stack and how many times it was seen, one line per unique stack +3. This folded stack list is filtered to suppress some stacks that are not very interesting +4. The filtered folded stack list is passed to another perl script that generates an svg file. + +Gavin has indicated that the basic info captured at step 1 (or maybe 2) might also be analysed to give other insights: + +1. A list of "time in function, time in children of function". +2. An expanded list of callers to __GI___lll_lock_wait and __GI___lll_lock_wake, to help spot contended critsecs. + +Seems like there may also be some info present in the original stack text files that is lost in the folded summary - in particular related to the TID that the stack is on. Can we spot lifetimes of threads and/or should we treat "stacks" on different threads as different? Thread pools might render this difficult though. + +I suspect to proceed I will need to recreate something not unlike stackcollapose-elfutils.pl, in Python (perl being too opaque...), thien consider extending it. \ No newline at end of file diff --git a/roxie/ccd/ccdmain.cpp b/roxie/ccd/ccdmain.cpp index dbe66ddf498..83fd6f2c0e7 100644 --- a/roxie/ccd/ccdmain.cpp +++ b/roxie/ccd/ccdmain.cpp @@ -1420,6 +1420,10 @@ int CCD_API roxie_main(int argc, const char *argv[], const char * defaultYaml) if (runOnce) { // Avoid delaying the release of packages or queries - otherwise stand-alone queries can take a while to terminate + PerfTracer oneShotTracer; + bool traceOneShot = topology->getPropBool("expert/@perftrace", false); // MORE - check wu options too? + if (traceOneShot) + oneShotTracer.start(); agentQueryReleaseDelaySeconds = 0; if (wuid) { @@ -1454,35 +1458,7 @@ int CCD_API roxie_main(int argc, const char *argv[], const char * defaultYaml) } StringBuffer query; query.appendf("<roxie format='%s'/>", format); - PerfTracer oneShotTracer; - bool traceOneShot = topology->getPropBool("expert/@perftrace", false); // MORE - check wu options too? - if (traceOneShot) - oneShotTracer.start(); roxieServer->runOnce(query.str()); // MORE - should use the wu listener instead I suspect - if (traceOneShot) - { - oneShotTracer.stop(); - const char *fname = topology->queryProp("expert/@perftraceFileName"); - if (!fname) - fname = "perftrace.svg"; - Owned<IFile> iFile = createIFile(fname); - try - { - Owned<IFileIO> iFileIO = iFile->open(IFOcreate); - if (iFileIO) - { - StringBuffer &svg = oneShotTracer.queryResult(); - iFileIO->write(0, svg.length(), svg.str()); - DBGLOG("Flame graph for query written to %s", fname); - } - } - catch (IException *E) - { - VStringBuffer msg("Failed to write flame graph to %s", fname); - EXCLOG(E, msg); - ::Release(E); - } - } fflush(stdout); // in windows if output is redirected results don't appear without flushing } catch (IException *E) @@ -1491,6 +1467,30 @@ int CCD_API roxie_main(int argc, const char *argv[], const char * defaultYaml) E->Release(); } } + if (traceOneShot) + { + oneShotTracer.stop(); + const char *fname = topology->queryProp("expert/@perftraceFileName"); + if (!fname) + fname = "perftrace.svg"; + Owned<IFile> iFile = createIFile(fname); + try + { + Owned<IFileIO> iFileIO = iFile->open(IFOcreate); + if (iFileIO) + { + StringBuffer &svg = oneShotTracer.queryResult(); + iFileIO->write(0, svg.length(), svg.str()); + DBGLOG("Flame graph for query written to %s", fname); + } + } + catch (IException *E) + { + VStringBuffer msg("Failed to write flame graph to %s", fname); + EXCLOG(E, msg); + ::Release(E); + } + } } else { diff --git a/tools/doperf/doperf b/tools/doperf/doperf index 4e9c4045e9a..ff84f4a969a 100755 --- a/tools/doperf/doperf +++ b/tools/doperf/doperf @@ -73,6 +73,7 @@ EOF finish_perf() { + wait 2>/dev/null stackcollapse-elfutils.pl ${tmpdir}/stack.* > ${tmpdir}/folded grep -f ${tmpdir}/suppress -v ${tmpdir}/folded > ${tmpdir}/suppressed flamegraph.pl ${tmpdir}/suppressed