HPCC-7970 Include eclcc timing information in workunits

The workunit embedded in the .so file contains timing info, but it was
not copied into the dali workunit by eclccserver.

Also, some interesting timing (like the time to compile the c++) does
not get captured because the workunit has already been dumped to XML
so that it can be included in the .so - capture this info via a
different mechanism.

Signed-off-by: Richard Chapman <rchapman@hpccsystems.com>

common/workunit/workunit.cpp

@@ -657,7 +657,7 @@ public:
     virtual void requestAbort();
     virtual void subscribe(WUSubscribeOptions options);
     virtual unsigned calculateHash(unsigned prevHash);
-    virtual void copyWorkUnit(IConstWorkUnit *cached);
+    virtual void copyWorkUnit(IConstWorkUnit *cached, bool all);
     virtual unsigned queryFileUsage(const char *filename) const;
     virtual bool getCloneable() const;
     virtual IUserDescriptor * queryUserDescriptor() const;
@@ -1076,8 +1076,8 @@ public:
             { c->requestAbort(); }
     virtual unsigned calculateHash(unsigned prevHash)
             { return c->calculateHash(prevHash); }
-    virtual void copyWorkUnit(IConstWorkUnit *cached)
-            { c->copyWorkUnit(cached); }
+    virtual void copyWorkUnit(IConstWorkUnit *cached, bool all)
+            { c->copyWorkUnit(cached, all); }
     virtual bool archiveWorkUnit(const char *base,bool del,bool deldll,bool deleteOwned)
             { return c->archiveWorkUnit(base,del,deldll,deleteOwned); }
     virtual void packWorkUnit(bool pack)
@@ -4524,7 +4524,7 @@ static void copyTree(IPropertyTree * to, const IPropertyTree * from, const char
         to->setPropTree(xpath, match);
 }
 
-void CLocalWorkUnit::copyWorkUnit(IConstWorkUnit *cached)
+void CLocalWorkUnit::copyWorkUnit(IConstWorkUnit *cached, bool all)
 {
     CLocalWorkUnit *from = QUERYINTERFACE(cached, CLocalWorkUnit);
     if (!from)
@@ -4575,6 +4575,17 @@ void CLocalWorkUnit::copyWorkUnit(IConstWorkUnit *cached)
     copyTree(p, fromP, "Results");
     copyTree(p, fromP, "Graphs");
     copyTree(p, fromP, "Workflow");
+    if (all)
+    {
+        // Merge timing info from both branches
+        pt = fromP->getBranch("Timings");
+        if (pt)
+        {
+            IPropertyTree *tgtTimings = ensurePTree(p, "Timings");
+            mergePTree(tgtTimings, pt);
+            pt->Release();
+        }
+    }
 
     updateProp(p, fromP, "@clusterName");
     updateProp(p, fromP, "allowedclusters");

common/workunit/workunit.hpp

@@ -1120,7 +1120,7 @@ interface IWorkflowScheduleConnection : extends IInterface
 interface IExtendedWUInterface
 {
     virtual unsigned calculateHash(unsigned prevHash) = 0;
-    virtual void copyWorkUnit(IConstWorkUnit *cached) = 0;
+    virtual void copyWorkUnit(IConstWorkUnit *cached, bool all) = 0;
     virtual bool archiveWorkUnit(const char *base,bool del,bool ignoredllerrors,bool deleteOwned) = 0;
     virtual void packWorkUnit(bool pack=true) = 0;
     

ecl/eclagent/eclagent.cpp

@@ -3262,7 +3262,7 @@ extern int HTHOR_API eclagent_main(int argc, const char *argv[], StringBuffer *
                 Owned<IWorkUnitFactory> factory = getWorkUnitFactory();
                 Owned<IWorkUnit> daliWu = factory->createWorkUnit(NULL, "eclagent", "eclagent");
                 IExtendedWUInterface * extendedWu = queryExtendedWU(daliWu);
-                extendedWu->copyWorkUnit(standAloneWorkUnit);
+                extendedWu->copyWorkUnit(standAloneWorkUnit, true);
                 daliWu->getWuid(wuid);
                 globals->setProp("WUID", wuid.str());
                 standAloneWorkUnit.clear();

ecl/eclcc/eclcc.cpp

@@ -194,6 +194,7 @@ public:
         argc = _argc;
         argv = _argv;
         logVerbose = false;
+        logTimings = false;
         optArchive = false;
         optGenerateMeta = false;
         optGenerateDepend = false;
@@ -281,6 +282,7 @@ protected:
     unsigned batchSplit;
     unsigned optLogDetail;
     bool logVerbose;
+    bool logTimings;
     bool optArchive;
     bool optGenerateMeta;
     bool optGenerateDepend;
@@ -1305,8 +1307,11 @@ bool EclCC::processFiles()
         ok = (errs->errCount() == 0);
     }
 
-    if (logVerbose)
-        defaultTimer->printTimings();
+    if (logTimings)
+    {
+        StringBuffer s;
+        fprintf(stderr, "%s", defaultTimer->getTimings(s).str());
+    }
     return ok;
 }
 
@@ -1472,6 +1477,9 @@ bool EclCC::parseCommandLineOptions(int argc, const char* argv[])
             if (batchPart >= batchSplit)
                 batchPart = 0;
         }
+        else if (iter.matchFlag(logTimings, "--timings"))
+        {
+        }
         else if (iter.matchOption(tempArg, "-platform") || /*deprecated*/ iter.matchOption(tempArg, "-target"))
         {
             if (!setTargetPlatformOption(tempArg.get(), optTargetClusterType))
@@ -1607,6 +1615,7 @@ const char * const helpText[] = {
     "!   -split m:n    Process a subset m of n input files (only with -b option)",
     "    -v --verbose  Output additional tracing information while compiling",
     "    --version     Output version information",
+    "!   --timings     Output additional timing information",
     "!",
     "!#options",
     "! -factivitiesPerCpp      Number of activities in each c++ file",

ecl/eclccserver/eclccserver.cpp

@@ -52,41 +52,58 @@ class EclccCompileThread : public CInterface, implements IPooledThread
 
     void reportError(const char *errStr, unsigned retcode)
     {
-        // MORE - if copyWorkUnit copied errors this would not be needed... should it?
         // A typical error looks like this: stdin:(385,29): warning C1041: Record doesn't have an explicit maximum record size
         // we will also see (and want to skip) nn error(s), nn warning(s)
-        RegExpr errCount, errParse;
+        RegExpr errCount, errParse, timings;
+        timings.init("Timing: {.+} total={[0-9]+}ms max={[0-9]+}us count={[0-9]+} ave={[0-9]+}us");
         errCount.init("[0-9]+ errors?, [0-9]+ warnings?.*");
         errParse.init("^{.+}\\({[0-9]+},{[0-9]+}\\): {[a-z]+} [A-Za-z]*{[0-9]+}:{.*$}");
         if (!errCount.find(errStr))
         {
-            Owned<IWUException> err = workunit->createException();
-            err->setExceptionSource("eclcc");
-            if (errParse.find(errStr))
+            if (timings.find(errStr))
             {
-                StringBuffer file, line, col, errClass, errCode, errText;
-                errParse.findstr(file, 1);
-                errParse.findstr(line, 2);
-                errParse.findstr(col, 3);
-                errParse.findstr(errClass, 4);
-                errParse.findstr(errCode, 5);
-                errParse.findstr(errText, 6);
-                err->setExceptionFileName(file);
-                err->setExceptionLineNo(atoi(line));
-                err->setExceptionColumn(atoi(col));
-                if (stricmp(errClass, "warning")==0)
-                    err->setSeverity(ExceptionSeverityWarning);
-                else
-                    err->setSeverity(ExceptionSeverityError);
-                err->setExceptionCode(atoi(errCode));
-                err->setExceptionMessage(errText);
-                err->setExceptionFileName(file); // any point if it just says stdin?
+                StringBuffer section, total, max, count, ave;
+                timings.findstr(section, 1);
+                timings.findstr(total, 2);
+                timings.findstr(max, 3);
+                timings.findstr(count, 4);
+                timings.findstr(ave, 5);
+                if (workunit->getDebugValueBool("addTimingToWorkunit", true))
+                {
+                    section.insert(0, "eclcc: ");
+                    workunit->setTimerInfo(section.str(), NULL, atoi(total), atoi(count), 0);
+                }
             }
             else
             {
-                err->setSeverity(retcode ? ExceptionSeverityError : ExceptionSeverityWarning);
-                err->setExceptionMessage(errStr);
-                DBGLOG("%s", errStr);
+                Owned<IWUException> err = workunit->createException();
+                err->setExceptionSource("eclcc");
+                if (errParse.find(errStr))
+                {
+                    StringBuffer file, line, col, errClass, errCode, errText;
+                    errParse.findstr(file, 1);
+                    errParse.findstr(line, 2);
+                    errParse.findstr(col, 3);
+                    errParse.findstr(errClass, 4);
+                    errParse.findstr(errCode, 5);
+                    errParse.findstr(errText, 6);
+                    err->setExceptionFileName(file);
+                    err->setExceptionLineNo(atoi(line));
+                    err->setExceptionColumn(atoi(col));
+                    if (stricmp(errClass, "warning")==0)
+                        err->setSeverity(ExceptionSeverityWarning);
+                    else
+                        err->setSeverity(ExceptionSeverityError);
+                    err->setExceptionCode(atoi(errCode));
+                    err->setExceptionMessage(errText);
+                    err->setExceptionFileName(file); // any point if it just says stdin?
+                }
+                else
+                {
+                    err->setSeverity(retcode ? ExceptionSeverityError : ExceptionSeverityWarning);
+                    err->setExceptionMessage(errStr);
+                    DBGLOG("%s", errStr);
+                }
             }
         }
     }
@@ -110,6 +127,8 @@ class EclccCompileThread : public CInterface, implements IPooledThread
             eclccCmd.append(" -");
         if (mainDefinition.length())
             eclccCmd.append(" -main ").append(mainDefinition);
+        if (workunit->getDebugValueBool("addTimingToWorkunit", true))
+            eclccCmd.append(" --timings");
 
         Owned<IPropertyTreeIterator> options = globals->getElements("./Option");
         ForEach(*options)
@@ -169,6 +188,7 @@ class EclccCompileThread : public CInterface, implements IPooledThread
         }
         try
         {
+            unsigned time = msTick();
             Owned<IPipeProcess> pipe = createPipeProcess();
             Owned<ErrorReader> errorReader = new ErrorReader(pipe, this);
             pipe->run("eclcc", eclccCmd, ".", true, false, true, 0);
@@ -198,7 +218,7 @@ class EclccCompileThread : public CInterface, implements IPooledThread
                 {
                     Owned<ILocalWorkUnit> embeddedWU = createLocalWorkUnit();
                     embeddedWU->loadXML(wuXML);
-                    queryExtendedWU(workunit)->copyWorkUnit(embeddedWU);
+                    queryExtendedWU(workunit)->copyWorkUnit(embeddedWU, true);
                     SCMStringBuffer jobname;
                     if (embeddedWU->getJobName(jobname).length()) //let ECL win naming job during initial compile
                         workunit->setJobName(jobname.str());
@@ -212,6 +232,9 @@ class EclccCompileThread : public CInterface, implements IPooledThread
                 Owned<IWUQuery> query = workunit->updateQuery();
                 associateLocalFile(query, FileTypeDll, realdllfilename, "Workunit DLL", crc);
                 queryDllServer().registerDll(realdllname.str(), "Workunit DLL", dllurl.str());
+                time = msTick()-time;
+                if (workunit->getDebugValueBool("addTimingToWorkunit", true))
+                    workunit->setTimerInfo("eclccserver: create workunit", NULL, time, 1, 0);
 
                 workunit->commit();
                 return true;

esp/services/ws_ecl/ws_ecl_service.cpp

@@ -2128,7 +2128,7 @@ int CWsEclBinding::submitWsEclWorkunit(IEspContext & context, WsEclWuInfo &wsinf
     Owned <IWorkUnit> workunit = factory->createWorkUnit(NULL, "wsecl", context.queryUserId());
 
     IExtendedWUInterface *ext = queryExtendedWU(workunit);
-    ext->copyWorkUnit(wsinfo.wu);
+    ext->copyWorkUnit(wsinfo.wu, false);
 
     workunit->clearExceptions();
     workunit->resetWorkflow();

esp/services/ws_workunits/ws_workunitsService.cpp

@@ -267,7 +267,7 @@ void copyWsWorkunit(IEspContext &context, IWorkUnit &wu, const char *srcWuid)
     SCMStringBuffer wuid;
     wu.getWuid(wuid);
 
-    queryExtendedWU(&wu)->copyWorkUnit(src);
+    queryExtendedWU(&wu)->copyWorkUnit(src, false);
 
     SCMStringBuffer token;
     wu.setSecurityToken(createToken(wuid.str(), context.queryUserId(), context.queryPassword(), token).str());
@@ -1103,7 +1103,7 @@ bool CWsWorkunitsEx::onWUResubmit(IEspContext &context, IEspWUResubmitRequest &r
                     Owned<IConstWorkUnit> src(factory->openWorkUnit(wuid.str(), false));
                     NewWsWorkunit wu(factory, context);
                     wu->getWuid(wuid);
-                    queryExtendedWU(wu)->copyWorkUnit(src);
+                    queryExtendedWU(wu)->copyWorkUnit(src, false);
 
                     SCMStringBuffer token;
                     wu->setSecurityToken(createToken(wuid.str(), context.queryUserId(), context.queryPassword(), token).str());
@@ -3764,7 +3764,7 @@ void CWsWorkunitsEx::deploySharedObject(IEspContext &context, StringBuffer &wuid
     {
         Owned<ILocalWorkUnit> embeddedWU = createLocalWorkUnit();
         embeddedWU->loadXML(dllXML.str());
-        queryExtendedWU(wu)->copyWorkUnit(embeddedWU);
+        queryExtendedWU(wu)->copyWorkUnit(embeddedWU, true);
     }
 
     wu.associateDll(dllpath.str(), dllname.str());

roxie/ccd/ccddali.cpp

@@ -425,7 +425,7 @@ public:
             {
                 Owned<ILocalWorkUnit> localWU = createLocalWorkUnit();
                 localWU->loadXML(wuXML);
-                queryExtendedWU(w)->copyWorkUnit(localWU);
+                queryExtendedWU(w)->copyWorkUnit(localWU, true);
             }
             else
                 throw MakeStringException(ROXIE_DALI_ERROR, "Failed to locate dll workunit info");

system/jlib/jdebug.cpp

@@ -519,9 +519,8 @@ public:
         CriticalBlock b(c);
         if (numSections())
         {
-            str.append("Timings:\n");
             for (unsigned i = 0; i < numSections(); i++)
-                getSection(i, str.append("  ")).append(" total=")
+                getSection(i, str.append("Timing: ")).append(" total=")
                                          .append(getTime(i)/1000000)
                                          .append("ms max=")
                                          .append(getMaxTime(i)/1000)