HPCC-15191 Extend TxSummary functionality to support timing milestones

Add timer class to track total elapsed time reported in one or more steps.

Update TxSummary to manage a collection of timer instances, referenced by name,
Extend the summary API to permit lookup of, and updates to, managed timers.
Add managed timer values to the serialized summary.

Extend the IEspContext interface to provide pass-through functions comparable
to its existing "trace summary" interface.

Signed-off-by: Tim Klemm <tim.klemm@lexisnexis.com>

esp/platform/cumulativetimer.hpp

@@ -0,0 +1,110 @@
+/*##############################################################################
+
+    HPCC SYSTEMS software Copyright (C) 2016 HPCC Systems®.
+
+    Licensed under the Apache License, Version 2.0 (the "License");
+    you may not use this file except in compliance with the License.
+    You may obtain a copy of the License at
+
+       http://www.apache.org/licenses/LICENSE-2.0
+
+    Unless required by applicable law or agreed to in writing, software
+    distributed under the License is distributed on an "AS IS" BASIS,
+    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+    See the License for the specific language governing permissions and
+    limitations under the License.
+############################################################################## */
+
+#ifndef CUMULATIVETIMER_HPP
+#define CUMULATIVETIMER_HPP
+
+#include "jiface.hpp"
+#include "jutil.hpp"
+
+// Utility class for tracking cumulative elapsed time. Once instantiated, an
+// instance's total time can be updated multiple times. When used with the
+// TxSummary, the time spent in multiple related (or repeated) function calls
+// can be presented as a single milestone.
+//
+// See CumulativeTimer::Scope for a simplified method of timing a code block.
+//
+// This class is NOT thread safe. Timing concurrent code blocks with a single
+// instance is not supported.
+class CumulativeTimer : public CInterface
+{
+public:
+
+    CumulativeTimer()
+        : mNestingDepth(0)
+        , mTotalTime(0)
+    {
+    }
+
+    CumulativeTimer(const CumulativeTimer& t)
+        : mNestingDepth(t.mNestingDepth)
+        , mTotalTime(t.mTotalTime)
+    {}
+
+    ~CumulativeTimer()
+    {
+    }
+
+    inline unsigned __int64 getTotalMillis() const { return mTotalTime; }
+    inline void reset() { mTotalTime = 0; }
+
+public:
+
+    // Given a cumulative timer on construction, add the milliseconds elapsed
+    // between construction and destruction to the timer. If multiple instances
+    // are nested, only the first instance will count.
+    struct Scope
+    {
+        Scope(CumulativeTimer* t)
+            : mTimer(t), mStart(0)
+        {
+            if (mTimer)
+                mTimer->incNesting();
+            mStart = msTick();
+        }
+
+        ~Scope()
+        {
+            if (mTimer)
+            {
+                mTimer->decNesting(msTick() - mStart);
+            }
+        }
+
+    private:
+        unsigned __int64    mStart;
+        CumulativeTimer*    mTimer;
+
+    private:
+        Scope(const Scope& t) = delete;
+        Scope& operator =(const Scope&) = delete;
+    };
+
+    void add(unsigned __int64 delta)
+    {
+        if (mNestingDepth == 0)
+            mTotalTime += delta;
+    }
+
+private:
+    friend struct CumulativeTimer::Scope;
+
+    inline void incNesting() { ++mNestingDepth; }
+    inline void decNesting(unsigned __int64 delta)
+    {
+        if (--mNestingDepth == 0)
+            mTotalTime += delta;
+    }
+
+    unsigned __int64 mNestingDepth;
+    unsigned __int64 mTotalTime;
+
+private:
+    CumulativeTimer& operator =(const CumulativeTimer&) = delete;
+};
+
+#endif // CUMULATIVETIMER_HPP

esp/platform/espbasesecurecontext.hpp

@@ -33,7 +33,7 @@ public:
 
     virtual const char* getProtocol() const override { UNIMPLEMENTED; }
 
-    virtual CTxSummary* getTxSummary() const override { return (queryContext() ? queryContext()->getTxSummary() : NULL); }
+    virtual CTxSummary* queryTxSummary() const override { return (queryContext() ? queryContext()->queryTxSummary() : NULL); }
 
     virtual bool getProp(int type, const char* name, StringBuffer& value) override { UNIMPLEMENTED; }
 

esp/platform/espcontext.cpp

@@ -433,7 +433,7 @@ public:
         servMethod.set(method);
     }
 
-    virtual CTxSummary* getTxSummary()
+    virtual CTxSummary* queryTxSummary()
     {
         return m_txSummary.get();
     }
@@ -466,6 +466,15 @@ public:
             m_txSummary->append("total", m_processingTime, "ms");
         }
     }
+    virtual void addTraceSummaryCumulativeTime(const char* name, unsigned __int64 time)
+    {
+        if (m_txSummary)
+            m_txSummary->updateTimer(name, time);
+    }
+    virtual CumulativeTimer* queryTraceSummaryCumulativeTimer(const char* name)
+    {
+        return (m_txSummary ? m_txSummary->queryTimer(name) : NULL);
+    }
 
     virtual ESPSerializationFormat getResponseFormat(){return respSerializationFormat;}
     virtual void setResponseFormat(ESPSerializationFormat fmt){respSerializationFormat = fmt;}

esp/platform/espsecurecontext.hpp

@@ -39,7 +39,7 @@ interface IEspSecureContext : extends IInterface
     virtual const char* getProtocol() const = 0;
 
     // Returns the TxSummary object to be used for a request.
-    virtual CTxSummary* getTxSummary() const = 0;
+    virtual CTxSummary* queryTxSummary() const = 0;
 
     // Fetches a data value based on a given type and name. If the requested
     // value exists it is stored in the supplied value buffer and true is

esp/platform/txsummary.cpp

@@ -21,10 +21,16 @@
 #include <algorithm>
 
 using std::find_if;
+using std::for_each;
 
 #define VALIDATE_KEY(k) if (!(k) || !(*k)) return false
 #define MATCH_KEY       [&](const Entry& entry) { return stricmp(entry.key.str(), key) == 0; }
 
+bool operator < (const StringAttr& a, const StringAttr& b)
+{
+    return (stricmp(a.str(), b.str()) < 0);
+}
+
 CTxSummary::CTxSummary(unsigned creationTime)
 : m_creationTime(creationTime ? creationTime : msTick())
 {
@@ -38,12 +44,15 @@ CTxSummary::~CTxSummary()
 
 unsigned __int64 CTxSummary::size() const
 {
-    return m_entries.size();
+    CriticalBlock block(m_sync);
+    return m_entries.size() + m_timers.size();
 }
 
 void CTxSummary::clear()
 {
+    CriticalBlock block(m_sync);
     m_entries.clear();
+    m_timers.clear();
 }
 
 unsigned CTxSummary::getElapsedTime() const
@@ -53,14 +62,17 @@ unsigned CTxSummary::getElapsedTime() const
 
 bool CTxSummary::contains(const char* key) const
 {
-    return find_if(m_entries.begin(), m_entries.end(), MATCH_KEY) != m_entries.end();
+    CriticalBlock block(m_sync);
+    return __contains(key);
 }
 
 bool CTxSummary::append(const char* key, const char* value)
 {
     VALIDATE_KEY(key);
 
-    if (contains(key))
+    CriticalBlock block(m_sync);
+
+    if (__contains(key))
         return false;
 
     m_entries.push_back({key, value});
@@ -71,6 +83,7 @@ bool CTxSummary::set(const char* key, const char* value)
 {
     VALIDATE_KEY(key);
 
+    CriticalBlock block(m_sync);
     Entries::iterator it = find_if(m_entries.begin(), m_entries.end(), MATCH_KEY);
 
     if (it != m_entries.end())
@@ -81,8 +94,40 @@ bool CTxSummary::set(const char* key, const char* value)
     return true;
 }
 
+CumulativeTimer* CTxSummary::queryTimer(const char* name)
+{
+    if (!name || !*name)
+        return NULL;
+
+    CriticalBlock block(m_sync);
+    TimerValue& timer = m_timers[name];
+
+    if (!timer)
+    {
+        timer.setown(new CumulativeTimer());
+    }
+
+    return timer;
+}
+
+bool CTxSummary::updateTimer(const char* name, unsigned long long delta)
+{
+    Owned<CumulativeTimer> timer;
+    CriticalBlock block(m_sync);
+
+    timer.set(queryTimer(name));
+
+    if (!timer)
+        return false;
+
+    timer->add(delta);
+    return true;
+}
+
 void CTxSummary::serialize(StringBuffer& buffer) const
 {
+    CriticalBlock block(m_sync);
+
     for (const Entry& entry : m_entries)
     {
         if (entry.value.length())
@@ -90,6 +135,11 @@ void CTxSummary::serialize(StringBuffer& buffer) const
         else
             buffer.appendf("%s;", entry.key.str());
     }
+
+    for (const std::pair<TimerKey, TimerValue>& entry : m_timers)
+    {
+        buffer.appendf("%s=%" I64F "ums;", entry.first.str(), entry.second->getTotalMillis());
+    }
 }
 
 void CTxSummary::log()
@@ -101,3 +151,8 @@ void CTxSummary::log()
         DBGLOG("TxSummary[%s]", summary.str());
     }
 }
+
+bool CTxSummary::__contains(const char* key) const
+{
+    return find_if(m_entries.begin(), m_entries.end(), MATCH_KEY) != m_entries.end();
+}

esp/platform/txsummary.hpp

@@ -19,9 +19,12 @@
 #define TXSUMMARY_HPP
 
 #include "jiface.hpp"
+#include "jmutex.hpp"
+#include "cumulativetimer.hpp"
 #include "tokenserialization.hpp"
 #include "esphttp.hpp"
 #include <list>
+#include <map>
 
 class CTxSummary : extends CInterface
 {
@@ -64,12 +67,23 @@ public:
     template <typename TValue, typename TSuffix = const char*, class TSerializer = TokenSerializer>
     bool set(const char* key, const TValue& value, const TSuffix& suffix = "", const TSerializer& serializer = TSerializer());
 
+    // Fetches an existing or new instance of a named CumulativeTime. The name
+    // must not be NULL or empty, but it may be a duplicate of an existing
+    // key-value pair. Duplication, while permitted, should be avoided due to
+    // the potential for confusion.
+    virtual CumulativeTimer* queryTimer(const char* name);
+
+    // Adds the given milliseconds to an existing or new named CumulativeTimer.
+    // The same conditions as for getTimer apply.
+    virtual bool updateTimer(const char* name, unsigned long long delta);
+
 protected:
     // Log the summary contents on destruction.
     ~CTxSummary();
 
 private:
     void log();
+    bool __contains(const char* key) const;
 
     struct Entry
     {
@@ -78,9 +92,14 @@ private:
     };
 
     using Entries = std::list<Entry>;
-
-    Entries   m_entries;
-    unsigned  m_creationTime;
+    using TimerKey = StringAttr;
+    using TimerValue = Linked<CumulativeTimer>;
+    using Timers = std::map<TimerKey, TimerValue>;
+
+    mutable CriticalSection m_sync;
+    Entries         m_entries;
+    Timers          m_timers;
+    unsigned        m_creationTime;
 };
 
 

esp/scm/esp.ecm

@@ -62,6 +62,7 @@ typedef enum ESPSerializationFormat_
 
 class CTxSummary;
 interface IEspSecureContext;
+class CumulativeTimer;
 
 interface IEspContext : extends IInterface
 {
@@ -146,10 +147,12 @@ interface IEspContext : extends IInterface
     virtual StringArray& queryCustomHeaders() = 0;
     virtual void addCustomerHeader(const char* name, const char* val) = 0;
 
-    virtual CTxSummary* getTxSummary()=0;
+    virtual CTxSummary* queryTxSummary()=0;
     virtual void addTraceSummaryValue(const char *name, const char *value)=0;
     virtual void addTraceSummaryValue(const char *name, __int64 value)=0;
     virtual void addTraceSummaryTimeStamp(const char *name)=0;
+    virtual void addTraceSummaryCumulativeTime(const char* name, unsigned __int64 time)=0;
+    virtual CumulativeTimer* queryTraceSummaryCumulativeTimer(const char* name)=0;
 
     virtual ESPSerializationFormat getResponseFormat()=0;
     virtual void setResponseFormat(ESPSerializationFormat fmt)=0;