Merge pull request #9443 from wangkx/h16787

HPCC-16787 Add ESP Logging timing to TxSummary, etc

Reviewed-By: Rodrigo Pastrana <rodrigo.pastrana@lexisnexis.com>
Reviewed-By: Richard Chapman <rchapman@hpccsystems.com>

esp/logging/loggingagent/espserverloggingagent/loggingagent.cpp

@@ -495,7 +495,7 @@ void CESPServerLoggingAgent::filterLogContent(IEspUpdateLogRequestWrap* req)
 
     StringBuffer updateLogRequestXML;
     toXML(updateLogRequestTree, updateLogRequestXML);
-    DBGLOG("filtered content and option: <%s>", updateLogRequestXML.str());
+    ESPLOG(LogMax, "filtered content and option: <%s>", updateLogRequestXML.str());
     req->clearOriginalContent();
     req->setUpdateLogRequest(updateLogRequestXML.str());
 }

esp/logging/logginglib/loggingagentbase.cpp

@@ -91,6 +91,7 @@ bool CDBLogAgentBase::getTransactionSeed(IEspGetTransactionSeedRequest& req, IEs
 
 bool CDBLogAgentBase::updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp)
 {
+    unsigned startTime = (getEspLogLevel()>=LogNormal) ? msTick() : 0;
     bool ret = false;
     try
     {
@@ -120,10 +121,11 @@ bool CDBLogAgentBase::updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResp
             if(!buildUpdateLogStatement(logRequestTree, logDB.str(), table, logID, updateDBStatement))
                 throw MakeStringException(EspLoggingErrors::UpdateLogFailed, "Failed in creating SQL statement.");
 
-            if (getEspLogLevel() >= LogMax)
-                DBGLOG("UpdateLog: %s\n", updateDBStatement.str());
+            ESPLOG(LogNormal, "LAgent UpdateLog BuildStat %d done: %dms\n", i, msTick() -  startTime);
+            ESPLOG(LogMax, "UpdateLog: %s\n", updateDBStatement.str());
 
             executeUpdateLogStatement(updateDBStatement);
+            ESPLOG(LogNormal, "LAgent UpdateLog ExecStat %d done: %dms\n", i, msTick() -  startTime);
         }
         resp.setStatusCode(0);
         ret = true;
@@ -137,6 +139,7 @@ bool CDBLogAgentBase::updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResp
         resp.setStatusCode(-1);
         resp.setStatusMessage(errorMessage.str());
     }
+    ESPLOG(LogNormal, "LAgent UpdateLog total=%dms\n", msTick() -  startTime);
     return ret;
 }
 

esp/logging/logginglib/logthread.cpp

@@ -83,8 +83,8 @@ CLogThread::CLogThread(IPropertyTree* _cfg , const char* _service, const char* _
     maxLogQueueLength = _cfg->getPropInt(PropMaxLogQueueLength, MaxLogQueueLength);
     signalGrowingQueueAt = _cfg->getPropInt(PropQueueSizeSignal, QueueSizeSignal);
     maxLogRetries = _cfg->getPropInt(PropMaxTriesRS, DefaultMaxTriesRS);
-    failSafeLogging = _cfg->getPropBool(PropFailSafe);
-    if(failSafeLogging)
+    ensureFailSafe = _cfg->getPropBool(PropFailSafe);
+    if(ensureFailSafe)
     {
         const char * logsDir = _cfg->queryProp(PropFailSafeLogsDir);
         if (!logsDir || !*logsDir)
@@ -155,7 +155,9 @@ bool CLogThread::queueLog(IEspUpdateLogRequest* logRequest)
 
 bool CLogThread::queueLog(IEspUpdateLogRequestWrap* logRequest)
 {
+    unsigned startTime = (getEspLogLevel()>=LogNormal) ? msTick() : 0;
     logAgent->filterLogContent(logRequest);
+    ESPLOG(LogNormal, "LThread:filterLog: %dms\n", msTick() -  startTime);
     return enqueue(logRequest);
 }
 
@@ -164,10 +166,12 @@ bool CLogThread::enqueue(IEspUpdateLogRequestWrap* logRequest)
     if (logFailSafe.get())
     {
         StringBuffer GUID, reqBuf;
+        unsigned startTime = (getEspLogLevel()>=LogNormal) ? msTick() : 0;
         logFailSafe->GenerateGUID(GUID, NULL);
         logRequest->setGUID(GUID.str());
         if (serializeLogRequestContent(logRequest, reqBuf))
             logFailSafe->Add(GUID, reqBuf.str());
+        ESPLOG(LogNormal, "LThread:addToFailSafe: %dms\n", msTick() -  startTime);
     }
 
     writeJobQueue(logRequest);
@@ -192,11 +196,12 @@ void CLogThread::sendLog()
                 break;
 
             const char* GUID= logRequest->getGUID();
-            if ((!GUID || !*GUID) && failSafeLogging && logFailSafe.get())
+            if ((!GUID || !*GUID) && ensureFailSafe && logFailSafe.get())
                 continue;
 
             try
             {
+                unsigned startTime = (getEspLogLevel()>=LogNormal) ? msTick() : 0;
                 Owned<IEspUpdateLogResponse> logResponse = createUpdateLogResponse();
                 logAgent->updateLog(*logRequest, *logResponse);
                 if (!logResponse)
@@ -209,9 +214,14 @@ void CLogThread::sendLog()
                     else
                         throw MakeStringException(EspLoggingErrors::UpdateLogFailed, "Unknown error");
                 }
+                ESPLOG(LogNormal, "LThread:updateLog: %dms\n", msTick() -  startTime);
 
-                if(failSafeLogging && logFailSafe.get())
+                if(ensureFailSafe && logFailSafe.get())
+                {
+                    unsigned startTime1 = (getEspLogLevel()>=LogNormal) ? msTick() : 0;
                     logFailSafe->AddACK(GUID);
+                    ESPLOG(LogNormal, "LThread:AddACK: %dms\n", msTick() -  startTime1);
+                }
                 logRequest->Release();//Make sure that no data (such as GUID) is needed before releasing the logRequest.
             }
             catch(IException* e)
@@ -235,7 +245,7 @@ void CLogThread::sendLog()
                 }
                 if (!willRetry)
                 {
-                    if(failSafeLogging && logFailSafe.get())
+                    if(ensureFailSafe && logFailSafe.get())
                         logFailSafe->AddACK(GUID);
                     logRequest->Release();
                 }
@@ -288,6 +298,7 @@ void CLogThread::checkRollOver()
             return;
 
         ESPLOG(LogMax, "writing %d requests in the queue to the rolled over tank file.", numNewArrivals);
+        unsigned startTime = (getEspLogLevel()>=LogNormal) ? msTick() : 0;
         for(unsigned i = 0; i < numNewArrivals; i++)
         {
             IInterface* pRequest = logQueue.item(i);
@@ -303,6 +314,7 @@ void CLogThread::checkRollOver()
             if(GUID && *GUID && serializeLogRequestContent(pEspRequest, reqBuf))
                 logFailSafe->Add(GUID, reqBuf.str());
         }
+        ESPLOG(LogNormal, "LThread:AddFailSafe: %dms\n", msTick() -  startTime);
     }
     catch(IException* Ex)
     {
@@ -405,7 +417,10 @@ void CLogThread::writeJobQueue(IEspUpdateLogRequestWrap* jobToWrite)
 {
     if (jobToWrite)
     {
+        unsigned startTime = (getEspLogLevel()>=LogNormal) ? msTick() : 0;
         CriticalBlock b(logQueueCrit);
+        ESPLOG(LogNormal, "LThread:waitWQ: %dms\n", msTick() -  startTime);
+
         int QueueSize = logQueue.ordinality();
         if(QueueSize > maxLogQueueLength)
             ERRLOG("LOGGING QUEUE SIZE %d EXECEEDED MaxLogQueueLength %d, check the logging server.",QueueSize, maxLogQueueLength);
@@ -419,6 +434,8 @@ void CLogThread::writeJobQueue(IEspUpdateLogRequestWrap* jobToWrite)
 
 IEspUpdateLogRequestWrap* CLogThread::readJobQueue()
 {
+    unsigned startTime = (getEspLogLevel()>=LogNormal) ? msTick() : 0;
     CriticalBlock b(logQueueCrit);
+    ESPLOG(LogNormal, "LThread:waitRQ: %dms\n", msTick() -  startTime);
     return (IEspUpdateLogRequestWrap*)logQueue.dequeue();
 }

esp/logging/logginglib/logthread.hpp

@@ -51,7 +51,7 @@ class CLogThread : public Thread , implements IUpdateLogThread
     CriticalSection logQueueCrit;
     Semaphore       m_sem;
 
-    bool failSafeLogging;
+    bool ensureFailSafe;
     Owned<ILogFailSafe> logFailSafe;
     struct tm         m_startTime;
 

esp/logging/loggingmanager/loggingmanager.cpp

@@ -83,7 +83,7 @@ IEspLogAgent* CLoggingManager::loadLoggingAgent(const char* name, const char* dl
     return (IEspLogAgent*) xproc();
 }
 
-bool CLoggingManager::updateLog(const char* option, const char* logContent, StringBuffer& status)
+bool CLoggingManager::updateLog(IEspContext& espContext, const char* option, const char* logContent, StringBuffer& status)
 {
     if (!initialized)
         throw MakeStringException(-1,"LoggingManager not initialized");
@@ -93,7 +93,7 @@ bool CLoggingManager::updateLog(const char* option, const char* logContent, Stri
     {
         Owned<IEspUpdateLogRequestWrap> req =  new CUpdateLogRequestWrap(NULL, option, logContent);
         Owned<IEspUpdateLogResponse> resp =  createUpdateLogResponse();
-        bRet = updateLog(*req, *resp, status);
+        bRet = updateLog(espContext, *req, *resp, status);
     }
     catch (IException* e)
     {
@@ -129,7 +129,7 @@ bool CLoggingManager::updateLog(const char* option, IEspContext& espContext, IPr
         Owned<IEspUpdateLogRequestWrap> req =  new CUpdateLogRequestWrap(NULL, option, espContextTree.getClear(), LINK(userContext), LINK(userRequest),
             backEndResp, userResp, logDatasets);
         Owned<IEspUpdateLogResponse> resp =  createUpdateLogResponse();
-        bRet = updateLog(*req, *resp, status);
+        bRet = updateLog(espContext, *req, *resp, status);
     }
     catch (IException* e)
     {
@@ -141,9 +141,9 @@ bool CLoggingManager::updateLog(const char* option, IEspContext& espContext, IPr
     return bRet;
 }
 
-bool CLoggingManager::updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp, StringBuffer& status)
+bool CLoggingManager::updateLog(IEspContext& espContext, IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp, StringBuffer& status)
 {
-    bool bRet = updateLog(req, resp);
+    bool bRet = updateLog(espContext, req, resp);
     if (bRet)
         status.set("Log request has been sent.");
     else
@@ -157,7 +157,7 @@ bool CLoggingManager::updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResp
     return bRet;
 }
 
-bool CLoggingManager::updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp)
+bool CLoggingManager::updateLog(IEspContext& espContext, IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp)
 {
     if (!initialized)
         throw MakeStringException(-1,"LoggingManager not initialized");
@@ -165,6 +165,7 @@ bool CLoggingManager::updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResp
     bool bRet = false;
     try
     {
+        espContext.addTraceSummaryTimeStamp("LMgr:startQLog");
         for (unsigned int x = 0; x < loggingAgentThreads.size(); x++)
         {
             IUpdateLogThread* loggingThread = loggingAgentThreads[x];
@@ -174,6 +175,7 @@ bool CLoggingManager::updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResp
                 bRet = true;
             }
         }
+        espContext.addTraceSummaryTimeStamp("LMgr:endQLog");
     }
     catch (IException* e)
     {

esp/logging/loggingmanager/loggingmanager.h

@@ -28,10 +28,10 @@
 interface ILoggingManager : implements IInterface
 {
     virtual bool init(IPropertyTree* loggingConfig, const char* service) = 0;
-    virtual bool updateLog(const char* option, const char* logContent, StringBuffer& status) = 0;
+    virtual bool updateLog(IEspContext& espContext, const char* option, const char* logContent, StringBuffer& status) = 0;
     virtual bool updateLog(const char* option, IEspContext& espContext, IPropertyTree* userContext, IPropertyTree* userRequest,
         const char* backEndResp, const char* userResp, const char* logDatasets, StringBuffer& status) = 0;
-    virtual bool updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp) = 0;
+    virtual bool updateLog(IEspContext& espContext, IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp) = 0;
     virtual bool getTransactionSeed(StringBuffer& transactionSeed, StringBuffer& status) = 0;
     virtual bool getTransactionSeed(IEspGetTransactionSeedRequest& req, IEspGetTransactionSeedResponse& resp) = 0;
     virtual bool getTransactionID(StringAttrMapping* transFields, StringBuffer& transactionID, StringBuffer& status) = 0;

esp/logging/loggingmanager/loggingmanager.hpp

@@ -43,7 +43,7 @@ class CLoggingManager : implements ILoggingManager, public CInterface
     bool initialized;
 
     IEspLogAgent* loadLoggingAgent(const char* name, const char* dll, const char* type, IPropertyTree* cfg);
-    bool updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp, StringBuffer& status);
+    bool updateLog(IEspContext& espContext, IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp, StringBuffer& status);
 
 public:
     IMPLEMENT_IINTERFACE;
@@ -55,8 +55,8 @@ public:
 
     virtual bool updateLog(const char* option, IEspContext& espContext, IPropertyTree* userContext, IPropertyTree* userRequest,
         const char* backEndResp, const char* userResp, const char* logDatasets, StringBuffer& status);
-    virtual bool updateLog(const char* option, const char* logContent, StringBuffer& status);
-    virtual bool updateLog(IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp);
+    virtual bool updateLog(IEspContext& espContext, const char* option, const char* logContent, StringBuffer& status);
+    virtual bool updateLog(IEspContext& espContext, IEspUpdateLogRequestWrap& req, IEspUpdateLogResponse& resp);
     virtual bool getTransactionSeed(StringBuffer& transactionSeed, StringBuffer& status);
     virtual bool getTransactionSeed(IEspGetTransactionSeedRequest& req, IEspGetTransactionSeedResponse& resp);
     virtual bool getTransactionID(StringAttrMapping* transFields, StringBuffer& transactionID, StringBuffer& status);

esp/logging/test/logging_test.cpp

@@ -136,7 +136,7 @@ void sendRequest()
         printf("userRespXML: <%s>.\n", userRespXML.str());
         printf("backEndResp: <%s>.\n", backEndResp);
 
-        //Sleep(5000); //Waiting for loggingManager to start
+        Sleep(5000); //Waiting for loggingManager to start
         loggingManager->updateLog(option.str(), *espContext, userContextTree, userRequestTree, backEndResp, userRespXML.str(), logDatasetsXML.str(), status);
     }
     else if (action.length() && strieq(action.str(), "UpdateLog1"))
@@ -151,7 +151,13 @@ void sendRequest()
         toXML(logContentTree, logContentXML);
         printf("log content: <%s>.\n", logContentXML.str());
         //Sleep(5000); //Waiting for loggingManager to start
-        loggingManager->updateLog(option.str(), logContentXML.str(), status);
+        Owned<IEspContext> espContext =  createEspContext();
+        const char* userName = logContentTree->queryProp("ESPContext/UserName");
+        const char* sourceIP = logContentTree->queryProp("ESPContext/SourceIP");
+        short servPort = logContentTree->getPropInt("ESPContext/Port");
+        espContext->setUserID(userName);
+        espContext->setServAddress(sourceIP, servPort);
+        loggingManager->updateLog(*espContext, option.str(), logContentXML.str(), status);
     }
     else
         printf("Invalid action.\n");

esp/platform/espcontext.cpp

@@ -466,9 +466,6 @@ public:
     {
         if (m_txSummary)
         {
-            if (!m_hasException && (getEspLogLevel() <= LogNormal))
-                m_txSummary->clear();
-
             updateTraceSummaryHeader();
             m_txSummary->append("total", m_processingTime, "ms");
         }

esp/services/ws_loggingservice/loggingservice.cpp

@@ -85,6 +85,7 @@ bool CWsLoggingServiceEx::onUpdateLog(IEspContext& context, IEspUpdateLogRequest
         if (!context.validateFeatureAccess(WSLOGGING_ACCESS, SecAccess_Write, false))
             throw MakeStringException(EspLoggingErrors::WSLoggingAccessDenied, "Failed to update log. Permission denied.");
 
+        context.addTraceSummaryTimeStamp("startQLog");
         for (unsigned int x = 0; x < loggingAgentThreads.size(); x++)
         {
             IUpdateLogThread* loggingThread = loggingAgentThreads[x];
@@ -92,6 +93,7 @@ bool CWsLoggingServiceEx::onUpdateLog(IEspContext& context, IEspUpdateLogRequest
                 continue;
             loggingThread->queueLog(&req);
         }
+        context.addTraceSummaryTimeStamp("endQLog");
         resp.setStatusCode(0);
         resp.setStatusMessage("Log will be updated.");
     }