HPCC-32941 Log warning if input time is more than total time

* Track when timers active on ActivityAccumulators * Report when timers inactive and input time is more than total time This ensures that the false reports are suppressed (input time may be more than total time if the upstream activity is busy processing). Signed-off-by: Shamser Ahmed <[email protected]>
hpcc-systems · Nov 5, 2024 · 9118981 · 9118981
1 parent 0e602df
commit 9118981
Show file tree

Hide file tree

Showing 2 changed files with 9 additions and 3 deletions.
diff --git a/common/thorhelper/thorcommon.hpp b/common/thorhelper/thorcommon.hpp
@@ -246,12 +246,13 @@ class THORHELPER_API ActivityTimeAccumulator
     cycle_t firstExitCycles;    // Wall clock time of first exit from this activity
     cycle_t blockedCycles;  // Time spent blocked
     cycle_t lookAheadCycles;  // Time spent by lookahead thread
-
+    unsigned activeActivityTimers = 0; // Number of active activity timers
     // Return the total amount of time (in nanoseconds) spent in this activity (first entry to last exit)
     inline unsigned __int64 elapsed() const { return cycle_to_nanosec(endCycles-startCycles); }
     // Return the total amount of time (in nanoseconds) spent in the first call of this activity (first entry to first exit)
     inline unsigned __int64 latency() const { return cycle_to_nanosec(latencyCycles()); }
     inline cycle_t latencyCycles() const { return firstExitCycles-startCycles; }
+    inline unsigned queryNumActiveTimers() const { return activeActivityTimers; }
 
     void addStatistics(IStatisticGatherer & builder) const;
     void addStatistics(CRuntimeStatisticCollection & merged) const;
@@ -291,6 +292,7 @@ class ActivityTimer
                 accumulator.startCycles = startCycles;
                 accumulator.firstRow = getTimeStampNowValue();
             }
+            ++accumulator.activeActivityTimers;
         }
         else
             startCycles = 0;
@@ -306,6 +308,7 @@ class ActivityTimer
             accumulator.totalCycles += elapsedCycles;
             if (unlikely(isFirstRow))
                 accumulator.firstExitCycles = nowCycles;
+            --accumulator.activeActivityTimers;
         }
     }
 };

diff --git a/thorlcr/graph/thgraphslave.cpp b/thorlcr/graph/thgraphslave.cpp
@@ -588,11 +588,14 @@ unsigned __int64 CSlaveActivity::queryLocalCycles() const
         }
     }
     unsigned __int64 processCycles = queryTotalCycles() + queryLookAheadCycles();
-    if (processCycles < inputCycles) // not sure how/if possible, but guard against
+    if (processCycles < inputCycles && slaveTimerStats.queryNumActiveTimers()==0) // not sure how/if possible, but guard against
+    {
+        ActPrintLog("CSlaveActivity::queryLocalCycles - process %" I64F "uns < inputCycles %" I64F "uns", cycle_to_nanosec(processCycles), cycle_to_nanosec(inputCycles));
         return 0;
+    }
     processCycles -= inputCycles;
     const unsigned __int64 blockedCycles = queryBlockedCycles();
-    if (processCycles < blockedCycles)
+    if (processCycles < blockedCycles && slaveTimerStats.queryNumActiveTimers()==0)
     {
         ActPrintLog("CSlaveActivity::queryLocalCycles - process %" I64F "uns < blocked %" I64F "uns", cycle_to_nanosec(processCycles), cycle_to_nanosec(blockedCycles));
         return 0;