Merge pull request #10127 from jakesmith/hpcc-17829

HPCC-17829 Add run time option to enable slow transaction tracing.

Reviewed-by: Gavin Halliday <ghalliday@hpccsystems.com>

dali/base/dadiags.cpp

@@ -205,14 +205,27 @@ public:
                 }
                 else if (0 == stricmp(id, "settracetransactions")) {
                     PROGLOG("Dalidiag requests Trace Transactions");
-                    if(traceAllTransactions(true))
+                    if (traceAllTransactions())
+                        mb.append("OK - transaction tracing enabled");
+                    else
                         mb.append("OK - no change");
+                }
+                else if (0 == stricmp(id, "settraceslowtransactions")) {
+                    unsigned thresholdMs;
+                    params.read(thresholdMs);
+                    PROGLOG("Dalidiag requests Trace Slow Transactions (ms = %u)", thresholdMs);
+                    if (traceSlowTransactions(thresholdMs)) {
+                        if (thresholdMs)
+                            mb.append("OK - slow transaction tracing enabled");
+                        else
+                            mb.append("OK - transaction tracing disabled");
+                    }
                     else
-                        mb.append("OK - transaction tracing enabled");
+                        mb.append("OK - no change");
                 }
                 else if (0 == stricmp(id, "cleartracetransactions")) {
                     PROGLOG("Dalidiag requests Trace Transactions stopped");
-                    if(traceAllTransactions(false))
+                    if (clearAllTransactions())
                         mb.append("OK - transaction tracing disabled");
                     else
                         mb.append("OK - no change");

dali/base/dasds.hpp

@@ -272,7 +272,9 @@ enum
 };
 extern da_decl IStoreHelper *createStoreHelper(const char *storeName, const char *location, const char *remoteBackupLocation, unsigned configFlags, unsigned keepStores=0, unsigned delay=5000, const bool *abort=NULL);
 extern da_decl bool applyXmlDeltas(IPropertyTree &root, IIOStream &stream, bool stopOnError=false);
-extern da_decl bool traceAllTransactions(bool on); // server only 
+extern da_decl bool traceAllTransactions(); // server only
+extern da_decl bool traceSlowTransactions(unsigned thresholdMs); // server only
+extern da_decl bool clearAllTransactions(); // server only
 
 extern da_decl void LogRemoteConn(IRemoteConnection *conn); // logs info about a connection
 

dali/base/dautils.cpp

@@ -3181,12 +3181,44 @@ ILocalOrDistributedFile* createLocalOrDistributedFile(const char *fname,IUserDes
 }
 
 static bool transactionLoggingOn=false;
+static cycle_t slowTransactionThreshold=0;
 const bool &queryTransactionLogging() { return transactionLoggingOn; }
-bool traceAllTransactions(bool on)
+cycle_t querySlowTransactionThreshold() { return slowTransactionThreshold; }
+bool traceAllTransactions()
 {
-    bool ret = transactionLoggingOn;
-    transactionLoggingOn = on;
-    return ret;
+    if (transactionLoggingOn)
+        return false; // no change
+    transactionLoggingOn = true;
+    return true;
+}
+
+bool clearAllTransactions()
+{
+    if (!transactionLoggingOn)
+        return false; // no change
+    transactionLoggingOn = false;
+    slowTransactionThreshold = 0;
+    return true;
+}
+
+bool traceSlowTransactions(unsigned thresholdMs)
+{
+    if (thresholdMs)
+    {
+        cycle_t newSlowTransactionThreshold = nanosec_to_cycle(((unsigned __int64)thresholdMs)*1000000);
+        bool changed = !transactionLoggingOn || (slowTransactionThreshold != newSlowTransactionThreshold);
+        slowTransactionThreshold = newSlowTransactionThreshold;
+        transactionLoggingOn = true;
+        return changed;
+    }
+    else if (transactionLoggingOn) // was on, turning off
+    {
+        transactionLoggingOn = false;
+        slowTransactionThreshold = 0;
+        return true; // changed
+    }
+    else // was already off
+        return false;
 }
 
 class CLockInfo : public CSimpleInterfaceOf<ILockInfo>

dali/base/dautils.hpp

@@ -179,10 +179,11 @@ public:
 };
 
 extern da_decl const bool &queryTransactionLogging();
+extern da_decl cycle_t querySlowTransactionThreshold();
 struct da_decl TransactionLog
 {
     CTransactionLogTracker &owner;
-    unsigned startMs, extraStartMs;
+    cycle_t startCycles, extraStartCycles;
     StringBuffer msg;
     unsigned cmd;
     const SocketEndpoint &ep;
@@ -192,36 +193,49 @@ struct da_decl TransactionLog
         {
             if (cmd > owner.getMax())
                 cmd = owner.getMax(); // unknown
-            extraStartMs = 0;
             owner.startTransaction(cmd);
             owner.getCmdText(cmd, msg);
             msg.append(", endpoint=");
             ep.getUrlStr(msg);
-            startMs = msTick();
+            startCycles = get_cycles_now();
         }
         else
-            startMs = 0;
+            startCycles = 0;
+        extraStartCycles = 0;
     }
     inline ~TransactionLog()
     {
-        if (startMs)
+        if (startCycles)
         {
-            unsigned now = msTick();
-            unsigned transCount = owner.getTransactionCount(cmd);
             owner.endTransaction(cmd);
-            if (extraStartMs)
-                PROGLOG("<<<[%d] (Timing: total=%d, from mark=%d) %s", transCount, now-startMs, extraStartMs-startMs, msg.str());
+            cycle_t slowTransactionThreshold = querySlowTransactionThreshold();
+            cycle_t cyclesNow = get_cycles_now();
+            if (slowTransactionThreshold)
+            {
+                cycle_t elapsedCycles = cyclesNow - startCycles;
+                if (elapsedCycles < slowTransactionThreshold)
+                    return;
+            }
+            unsigned transCount = owner.getTransactionCount(cmd)+1; // +1 = this one
+            unsigned elapsedSinceStartMs = static_cast<unsigned>(cycle_to_millisec(cyclesNow - startCycles));
+            if (extraStartCycles)
+            {
+                unsigned elapsedSinceExtraMs = static_cast<unsigned>(cycle_to_millisec(extraStartCycles - startCycles));
+                PROGLOG("<<<[%d] (Timing: total=%u, from mark=%u) %s", transCount, elapsedSinceStartMs, elapsedSinceExtraMs, msg.str());
+            }
             else
-                PROGLOG("<<<[%d] (Timing: total=%d) %s", transCount, now-startMs, msg.str());
+                PROGLOG("<<<[%d] (Timing: total=%u) %s", transCount, elapsedSinceStartMs, msg.str());
         }
     }
     inline void log()
     {
+        if (querySlowTransactionThreshold()) return; // suppress if only logging exit of slow transactions
         unsigned transCount = owner.getTransactionCount(cmd);
         PROGLOG(">>>[%d] %s", transCount, msg.str());
     }
     inline void log(const char *formatMsg, ...) __attribute__((format(printf, 2, 3)))
     {
+        if (querySlowTransactionThreshold()) return; // suppress if only logging exit of slow transactions
         va_list args;
         va_start(args, formatMsg);
         msg.append(" ");
@@ -231,8 +245,8 @@ struct da_decl TransactionLog
     }
     inline void markExtra()
     {
-        if (!extraStartMs)
-            extraStartMs = msTick();
+        if (!extraStartCycles)
+            extraStartCycles = get_cycles_now();
     }
     inline void extra(const char *formatMsg, ...) __attribute__((format(printf, 2, 3)))
     {

dali/dalidiag/dalidiag.cpp

@@ -64,6 +64,7 @@ void usage(const char *exe)
     printf("-unlock <connection_id> [close] -- forcibly disconnect an sds lock\n"); 
     printf("                                   (use id's given by '-locks'\n");
     printf("-settracetransactions    -- trace dali transactions\n");
+    printf("-settraceslowtransactions <millisecond-threshold> -- trace slow dali transactions\n");
     printf("-cleartracetransactions  -- stop tracing dali transactions\n");
     printf("-setldapflags <val>      -- set LDAP flags\n");
     printf("-getldapflags            -- get LDAP flags\n");
@@ -694,6 +695,17 @@ int main(int _argc, char* argv[])
                     printf("\n%s:\n%s",arg,buf.str());
                     break;
                 }
+                if ((stricmp(arg,"settraceslowtransactions")==0)) {
+                    MemoryBuffer mb;
+                    mb.append("settraceslowtransactions");
+                    unsigned slowThresholdMs = atoi(argv[++i]);
+                    mb.append(slowThresholdMs);
+                    getDaliDiagnosticValue(mb);
+                    StringAttr response;
+                    mb.read(response);
+                    printf("\nsettraceslowtransactions:\n%s", response.get());
+                    break;
+                }
                 else {
                     for (;;) {
                         getDaliDiagnosticValue(arg,buf.clear());