HPCC-9789 Add the option to add summary stats to the log file

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

ecl/eclcc/eclcc.cpp

@@ -200,8 +200,13 @@ public:
         legacyMode = _legacyMode;
         ignoreUnknownImport = false;
         fromArchive = false;
+        stats.parseTime = 0;
+        stats.generateTime = 0;
+        stats.xmlSize = 0;
+        stats.cppSize = 0;
     }
 
+    void logStats();
     bool reportErrorSummary();
 
 public:
@@ -219,6 +224,12 @@ public:
     bool legacyMode;
     bool fromArchive;
     bool ignoreUnknownImport;
+    struct {
+        unsigned parseTime;
+        unsigned generateTime;
+        offset_t xmlSize;
+        offset_t cppSize;
+    } stats;
 };
 
 class EclCC : public CInterfaceOf<ICodegenContextCallback>
@@ -692,6 +703,7 @@ void EclCC::instantECL(EclCompileInstance & instance, IWorkUnit *wu, const char
                 generator->setSaveGeneratedFiles(optSaveCpp);
 
                 bool generateOk = generator->processQuery(instance.query, target);  // NB: May clear instance.query
+                instance.stats.cppSize = generator->getGeneratedSize();
                 if (generateOk && !optNoCompile)
                 {
                     Owned<ICppCompiler> compiler = createCompiler(processName.toCharArray());
@@ -1042,8 +1054,10 @@ void EclCC::processSingleQuery(EclCompileInstance & instance,
             if (instance.query && !syntaxChecking && !optGenerateMeta && !optEvaluateResult)
                 instance.query.setown(convertAttributeToQuery(instance.query, ctx));
 
+            instance.stats.parseTime = msTick()-startTime;
+
             if (instance.wu->getDebugValueBool("addTimingToWorkunit", true))
-                instance.wu->setTimerInfo("EclServer: parse query", NULL, msTick()-startTime, 1, 0);
+                instance.wu->setTimerInfo("EclServer: parse query", NULL, instance.stats.parseTime, 1, 0);
 
             if (optIncludeMeta || optGenerateMeta)
                 instance.generatedMeta.setown(parseCtx.getMetaTree());
@@ -1115,8 +1129,10 @@ void EclCC::processSingleQuery(EclCompileInstance & instance,
         }
     }
 
+    unsigned totalTime = msTick() - startTime;
+    instance.stats.generateTime = totalTime - instance.stats.parseTime;
     if (instance.wu->getDebugValueBool("addTimingToWorkunit", true))
-        instance.wu->setTimerInfo("EclServer: totalTime", NULL, msTick()-startTime, 1, 0);
+        instance.wu->setTimerInfo("EclServer: totalTime", NULL, totalTime, 1, 0);
 }
 
 void EclCC::processXmlFile(EclCompileInstance & instance, const char *archiveXML)
@@ -1558,12 +1574,16 @@ bool EclCC::processFiles()
         EclCompileInstance info(NULL, *errs, stderr, optOutputFilename, optLegacy);
         processReference(info, optQueryRepositoryReference);
         ok = (errs->errCount() == 0);
+
+        info.logStats();
     }
     else
     {
         EclCompileInstance info(&inputFiles.item(0), *errs, stderr, optOutputFilename, optLegacy);
         processFile(info);
         ok = (errs->errCount() == 0);
+
+        info.logStats();
     }
 
     if (logTimings)
@@ -1582,6 +1602,19 @@ void EclCC::setDebugOption(const char * name, bool value)
 }
 
 
+void EclCompileInstance::logStats()
+{
+    if (wu && wu->getDebugValueBool("logCompileStats", false))
+    {
+        memsize_t peakVm, peakResident;
+        getPeakMemUsage(peakVm, peakResident);
+        //Stats: added as a prefix so it is easy to grep, and a comma so can be read as a csv list.
+        DBGLOG("Stats:,parse,%u,generate,%u,peakmem,%u,xml,%"I64F"u,cpp,%"I64F"u",
+                stats.parseTime, stats.generateTime, (unsigned)(peakResident / 0x100000),
+                (unsigned __int64)stats.xmlSize, (unsigned __int64)stats.cppSize);
+    }
+}
+
 bool EclCompileInstance::reportErrorSummary()
 {
     if (errs->errCount() || errs->warnCount())
@@ -2019,7 +2052,13 @@ void EclCC::processBatchedFile(IFile & file, bool multiThreaded)
             dbglogTransformStats(true);
             if (info.wu &&
                 (info.wu->getDebugValueBool("generatePartialOutputOnError", false) || info.errs->errCount() == 0))
+            {
                 exportWorkUnitToXMLFile(info.wu, xmlFilename, XML_NoBinaryEncode64, true);
+                Owned<IFile> xml = createIFile(xmlFilename);
+                info.stats.xmlSize = xml->size();
+            }
+
+            info.logStats();
         }
     }
     catch (IException * e)

ecl/hqlcpp/hqlecl.cpp

@@ -70,6 +70,7 @@ public:
         generateTarget = EclGenerateNone;
         code.setown(createCppInstance(wu, wuname));
         deleteGenerated = false;
+        totalGeneratedSize = 0;
     }
     IMPLEMENT_IINTERFACE
 
@@ -98,6 +99,7 @@ protected:
     bool generateCode(HqlQueryContext & query);
     bool generateFullFieldUsageStatistics(HqlCppTranslator & translator, IHqlExpression * query);
     IPropertyTree * generateSingleFieldUsageStatistics(IHqlExpression * expr, const char * variety, const IPropertyTree * exclude);
+    offset_t getGeneratedSize() const;
     void insertStandAloneCode();
     void setWuState(bool ok);
     inline bool abortRequested();
@@ -114,6 +116,7 @@ protected:
     unsigned defaultMaxCompileThreads;
     StringArray sourceFiles;
     StringArray libraries;
+    offset_t totalGeneratedSize;
     bool checkForLocalFileUploads;
     bool noOutput;
     EclGenerateTarget generateTarget;
@@ -181,6 +184,8 @@ void HqlDllGenerator::expandCode(const char * templateName, const char * ext, IH
 
     expander->generate(*writer, pass, props);
 
+    totalGeneratedSize += out->size();
+
     if (!deleteGenerated)
         addCppName(fullname);
 }
@@ -593,6 +598,10 @@ double HqlDllGenerator::getECLcomplexity(IHqlExpression * exprs)
     return translator.getComplexity(*code, query.expr);
 }
 
+offset_t HqlDllGenerator::getGeneratedSize() const
+{
+    return totalGeneratedSize;
+}
 
 extern HQLCPP_API double getECLcomplexity(IHqlExpression * exprs, IErrorReceiver * errs, IWorkUnit *wu, ClusterType targetClusterType)
 {
@@ -600,6 +609,7 @@ extern HQLCPP_API double getECLcomplexity(IHqlExpression * exprs, IErrorReceiver
     return generator.getECLcomplexity(exprs);
 }
 
+
 extern HQLCPP_API IHqlExprDllGenerator * createDllGenerator(IErrorReceiver * errs, const char *wuname, const char * targetdir, IWorkUnit *wu, const char * template_dir, ClusterType targetClusterType, ICodegenContextCallback *ctxCallback, bool checkForLocalFileUploads)
 {
     return new HqlDllGenerator(errs, wuname, targetdir, wu, template_dir, targetClusterType, ctxCallback, checkForLocalFileUploads);

ecl/hqlcpp/hqlecl.hpp

@@ -42,6 +42,7 @@ public:
     virtual bool generateDll(ICppCompiler * _compiler) = 0;
     virtual bool generateExe(ICppCompiler * _compiler) = 0;
     virtual bool generatePackage(const char * packageName) = 0;
+    virtual offset_t getGeneratedSize() const = 0;
     virtual bool processQuery(OwnedHqlExpr & parsedQuery, EclGenerateTarget generateTarget) = 0;
     virtual void setMaxCompileThreads(unsigned max) = 0;
     virtual void addManifest(const char *filename) = 0;

system/jlib/jdebug.cpp

@@ -982,6 +982,65 @@ static void getMemUsage(unsigned &inuse,unsigned &active,unsigned &total,unsigne
     swapinuse = swaptotal-swapfree-swapcached;
 }
 
+static bool matchExtract(const char * prefix, const char * line, memsize_t & value)
+{
+    size32_t len = strlen(prefix);
+    if (strncmp(prefix, line, len)==0)
+    {
+        char * tail = NULL;
+        value = strtol(line+len, &tail, 10);
+        while (isspace(*tail))
+            tail++;
+        if (strncmp(tail, "kB", 2) == 0)
+            value *= 0x400;
+        else if (strncmp(tail, "mB", 2) == 0)
+            value *= 0x100000;
+        return true;
+    }
+    return false;
+}
+
+void getPeakMemUsage(memsize_t &peakVm,memsize_t &peakResident)
+{
+    peakVm = 0;
+    peakResident = 0;
+
+#ifdef _WIN32
+    PROCESS_MEMORY_COUNTERS pmc;
+    if (GetProcessMemoryInfo(GetCurrentProcess(), &pmc, sizeof(pmc)))
+    {
+        peakVM = pmc.PeakWorkingSetSize;
+        peakResident = pmc.PeakWorkingSetSize;
+
+    }
+#else
+    static int memfd = -1;
+    if (memfd==-1)
+        memfd = open("/proc/self/status",O_RDONLY);
+    if (memfd==-1)
+        return;
+    lseek(memfd, 0L, 0);
+
+    char buf[2048];
+    size32_t l = read(memfd, buf, sizeof(buf)-1);
+    if ((int)l<=0)
+        return;
+    buf[l] = 0;
+
+    const char *bufptr = buf;
+    while (bufptr) {
+        if (*bufptr =='\n')
+            bufptr++;
+        if (!matchExtract("VmPeak:", bufptr, peakVm) &&
+            !matchExtract("VmHWM:", bufptr, peakResident))
+        {
+            //ignore this line
+        }
+        bufptr = strchr(bufptr, '\n');
+    }
+#endif
+}
+
 class CInt64fix 
 {
     __int64 val;

system/jlib/jdebug.hpp

@@ -278,6 +278,7 @@ unsigned jlib_decl setAllocHook(bool on);  // bwd compat returns unsigned
 extern jlib_decl void getHardwareInfo(HardwareInfo &hdwInfo, const char *primDiskPath = NULL, const char *secDiskPath = NULL);
 extern jlib_decl memsize_t getMapInfo(const char *type);
 extern jlib_decl void getCpuInfo(unsigned &numCPUs, unsigned &CPUSpeed);
+extern jlib_decl void getPeakMemUsage(memsize_t &peakVm,memsize_t &peakResident);
 extern jlib_decl unsigned getAffinityCpus();
 extern jlib_decl void printProcMap(const char *fn, bool printbody, bool printsummary, StringBuffer *lnout, MemoryBuffer *mb, bool useprintf);
 extern jlib_decl void PrintMemoryReport(bool full=true);