Merge pull request #8399 from timothyklemm/hpcc-15191-txsummary-migration

HPCC-15191 Extend TxSummary functionality to support timing milestones

Reviewed-By: Gavin Halliday <gavin.halliday@lexisnexis.com>
Reviewed-By: Rodrigo Pastrana <rodrigo.pastrana@lexisnexis.com>
Reviewed-By: Richard Chapman <rchapman@hpccsystems.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,39 @@ 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;
+
+    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 +134,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 +150,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;