HPCC-30156 Instrument CriticalSection

CMakeLists.txt

@@ -85,6 +85,8 @@ unset ( ENV{CC} )
 unset ( ENV{CXX} )
 
 set(TOP_LEVEL_PROJECT ON)
+unset(PROFILING)
+set(PROFILING ON)
 if(NOT CMAKE_PROJECT_NAME STREQUAL PROJECT_NAME)
     set(TOP_LEVEL_PROJECT OFF)
 endif(NOT CMAKE_PROJECT_NAME STREQUAL PROJECT_NAME)

cmake_modules/commonSetup.cmake

@@ -257,8 +257,9 @@ IF ("${COMMONSETUP_DONE}" STREQUAL "")
       endif()
     endif()
   endif ()
-  if (PROFILING AND (CMAKE_COMPILER_IS_GNUCXX OR CMAKE_COMPILER_IS_CLANGXX))
+  if (CMAKE_COMPILER_IS_GNUCXX OR CMAKE_COMPILER_IS_CLANGXX)
     add_definitions (-fno-omit-frame-pointer)
+    add_definitions (-D_PROFILING)
   endif ()
 
   if (WIN32)

cmake_modules/options.cmake

@@ -68,7 +68,7 @@ option(SKIP_ECLWATCH "Skip building ECL Watch" OFF)
 option(USE_ADDRESS_SANITIZER "Use address sanitizer to spot leaks" OFF)
 option(INSTALL_VCPKG_CATALOG "Install vcpkg-catalog.txt" ON)
 option(PORTALURL "Set url to hpccsystems portal download page")
-option(PROFILING "Set to true if planning to profile so stacks are informative" OFF)
+option(PROFILING "Set to true if planning to profile so stacks are informative" ON)
 
 if ( NOT PORTALURL )
   set( PORTALURL "http://hpccsystems.com/download" )

common/thorhelper/roxiehelper.cpp

@@ -1795,7 +1795,7 @@ bool CSafeSocket::sendHeartBeat(const IContextLogger &logctx)
 class HttpResponseHandler
 {
 private:
-    CriticalBlock c; // should not be anyone writing but better to be safe
+    ICriticalBlock c; // should not be anyone writing but better to be safe
     StringBuffer header;
     StringBuffer content;
     ISocket *sock = nullptr;

common/workunit/wujobq.cpp

@@ -972,13 +972,13 @@ class CJobQueue: public CJobQueueBase, implements IJobQueue
         }
     }
 
-    class Cconnlockblock: public CriticalBlock
+    class Cconnlockblock: public ICriticalBlock
     {
         CJobQueue *parent;
         bool rollback;
     public:
         Cconnlockblock(CJobQueue *_parent,bool exclusive)
-            : CriticalBlock(_parent->crit)
+            : ICriticalBlock(_parent->crit)
         {
             parent = _parent;
             parent->connlock(exclusive);

ecl/hql/hqlexpr.ipp

@@ -65,7 +65,7 @@ public:
 };
 
 #ifdef HQLEXPR_MULTI_THREADED
-typedef CriticalBlock HqlCriticalBlock;
+typedef ICriticalBlock HqlCriticalBlock;
 #else
 typedef NullCriticalBlock HqlCriticalBlock;
 #endif

plugins/Rembed/Rembed.cpp

@@ -1437,7 +1437,7 @@ class REmbedFunctionContext: public CInterfaceOf<IEmbedFunctionContext>
     RInside &R;
     RInside::Proxy result;
     StringAttr func;
-    CriticalBlock block;
+    ICriticalBlock block;
     Owned<REnvironment> env;
 };
 

roxie/roxiemem/roxiemem.cpp

@@ -3465,7 +3465,7 @@ class HeapCompactState
         }
     }
 public:
-    CriticalBlock lock;
+    ICriticalBlock lock;
     unsigned numPagesEmptied;
     CHeap * heap;
     Heaplet * next; // which heaplet to try to compact into next.  Not so good if > 1 heaps in use.
@@ -3516,7 +3516,7 @@ class NewHeapCompactState
     bool processHeap(unsigned low, unsigned max);
 
 protected:
-    CriticalBlock lock;
+    ICriticalBlock lock;
     PointerArrayOf<ChunkedHeaplet> heaplets;
 };
 

system/jlib/jdebug.hpp

@@ -23,78 +23,7 @@
 #include "jiface.hpp"
 #include "jstats.h"
 #include <atomic>
-
-#define TIMING
-
-__int64 jlib_decl cycle_to_nanosec(cycle_t cycles);
-__int64 jlib_decl cycle_to_microsec(cycle_t cycles);
-__int64 jlib_decl cycle_to_millisec(cycle_t cycles);
-cycle_t jlib_decl nanosec_to_cycle(__int64 cycles);
-cycle_t jlib_decl millisec_to_cycle(unsigned ms);
-double jlib_decl getCycleToNanoScale();
-void jlib_decl display_time(const char * title, cycle_t diff);
-
-// X86 / X86_64
-#if defined(_ARCH_X86_64_) || defined(_ARCH_X86_)
-
-#define HAS_GOOD_CYCLE_COUNTER
-
-#if defined(_WIN32) && defined (_ARCH_X86_)
-#pragma warning(push)
-#pragma warning(disable:4035)
-inline cycle_t getTSC() { __asm { __asm _emit 0x0f __asm _emit 0x31 } }
-#pragma warning(pop)
-#elif !defined(_WIN32)
-inline cycle_t getTSC() { return __builtin_ia32_rdtsc(); }
-#else
-#include <intrin.h>
-inline cycle_t getTSC() { return __rdtsc(); }
-#endif // WIN32
-
-#elif defined(_ARCH_PPC)
-
-#define HAS_GOOD_CYCLE_COUNTER
-
-static inline cycle_t getTSC()
-{
-    int64_t result;
-#ifdef _ARCH_PPC64
-    /*
-        This reads timebase in one 64bit go.  Does *not* include a workaround for the cell (see 
-        http://ozlabs.org/pipermail/linuxppc-dev/2006-October/027052.html)
-    */
-    __asm__ volatile(
-        "mftb    %0"
-        : "=r" (result));
-#else
-    /*
-        Read the high 32bits of the timer, then the lower, and repeat if high order has changed in the meantime.  See
-        http://ozlabs.org/pipermail/linuxppc-dev/1999-October/003889.html
-    */
-    unsigned long dummy;
-    __asm__ volatile(
-        "mfspr   %1,269\n\t"  /* mftbu */
-        "mfspr   %L0,268\n\t" /* mftb */
-        "mfspr   %0,269\n\t"  /* mftbu */
-        "cmpw    %0,%1\n\t"   /* check if the high order word has chanegd */
-        "bne     $-16"
-        : "=r" (result), "=r" (dummy));
-#endif
-    return result;
-}
-
-#else
-// ARMFIX: cycle-count is not always available in user mode
-// http://infocenter.arm.com/help/index.jsp?topic=/com.arm.doc.ddi0338g/Bihbeabc.html
-// http://neocontra.blogspot.co.uk/2013/05/user-mode-performance-counters-for.html
-inline cycle_t getTSC() { return 0; }
-#endif // X86
-
-#if defined(INLINE_GET_CYCLES_NOW) && defined(HAS_GOOD_CYCLE_COUNTER)
-inline cycle_t get_cycles_now() { return getTSC(); }
-#else
-cycle_t jlib_decl get_cycles_now();  // equivalent to getTSC when available
-#endif
+#include <jtiming.hpp>
 
 struct HardwareInfo
 {

system/jlib/jexcept.cpp

@@ -37,7 +37,7 @@
 #include <sys/types.h>
 #include <stddef.h>
 #include <errno.h>
-#ifdef __linux__
+#if defined(__linux__) || defined(__APPLE__)
 #include <execinfo.h> // comment out if not present
 #endif
 #ifdef __APPLE__
@@ -1702,7 +1702,7 @@ void printStackReport(__int64 startIP)
 #ifdef _WIN32
     unsigned onstack=1234;
     doPrintStackReport(0, 0,(unsigned)&onstack);
-#elif defined(__linux__)
+#elif defined(__linux__) || defined(__APPLE__)
     DBGLOG("Backtrace:");
     void *btarray[100];
     unsigned btn = backtrace (btarray, 100);

system/jlib/jmutex.cpp

@@ -118,8 +118,135 @@ int Mutex::unlockAll()
     return ret;
 }
 
+static CriticalBlockInstrumentation *critBlocks[10000];
+static RelaxedAtomic<unsigned> nextCritBlock;
 
+int compareCI (const void * a, const void * b) 
+{
+   return - (*(CriticalBlockInstrumentation **)a)->compare(*(CriticalBlockInstrumentation **)b);
+}
+
+MODULE_EXIT()
+{
+    unsigned numCritBlocks = nextCritBlock;
+    qsort(critBlocks, numCritBlocks, sizeof(CriticalBlockInstrumentation*), compareCI);
+    for (unsigned i = 0; i < numCritBlocks; i++)
+    {
+        critBlocks[i]->describe(i < 10);
+    }
+}
+
+thread_local CriticalBlockInstrumentation *__cbinst = nullptr;
+
+std::size_t CriticalBlockInstrumentation::StackHash::operator()(const Stack& k) const
+{
+    return hashc((const byte *) k.stack, sizeof(k.stack), 0);
+}
 
+std::string humanTime(unsigned long cycles)
+{
+    if (!cycles)
+        return "0 ns";
+    unsigned long v = cycle_to_nanosec(cycles);
+    if (v < 1000)
+        return std::to_string(v) + " ns";
+    else if (v < 1000000)
+        return std::to_string(v/1000) + " us";
+    else
+        return std::to_string(v/1000000) + " ms";
+}
+
+CriticalBlockInstrumentation::CriticalBlockInstrumentation(const char *_file, const char *_func, unsigned _line)
+: file(strdup(_file)), func(strdup(_func)), line(_line), waitCycles(0), holdCycles(0), uncontended(0), contended(0)
+{
+    unsigned idx = nextCritBlock++;
+    if (idx < 10000)
+        critBlocks[idx] = this;
+}
+
+void CriticalBlockInstrumentation::addStat(cycle_t wait, cycle_t hold, bool wasContended)
+{
+#ifdef HAS_BACKTRACE
+    void *lbtBuff[numStackEntries+3];
+    unsigned nFrames = backtrace(lbtBuff, numStackEntries+3);
+    NonReentrantSpinBlock b(lock);
+    if (nFrames == numStackEntries+3)
+    {
+        Stack *a = (Stack *) (lbtBuff+3);
+        stacks[*a]++;
+    }
+#else
+    NonReentrantSpinBlock b(lock);
+#endif
+    if (wasContended)
+        contended++;
+    else
+        uncontended++;
+    waitCycles += wait;
+    holdCycles += hold;
+}
+
+CriticalBlockInstrumentation::~CriticalBlockInstrumentation() 
+{
+}
+
+void CriticalBlockInstrumentation::describe(bool includeStack) const
+{
+    DBGLOG("CritBlock %s (%s:%u): wait %s hold %s, entered %u times, contended %u times", func, strrchr(file, PATHSEPCHAR)+1, line, humanTime(waitCycles).c_str(), humanTime(holdCycles).c_str(), contended+uncontended, contended);
+    if (includeStack)
+    {
+        std::vector<std::pair<Stack, int>> sorted_stacks(stacks.begin(), stacks.end());
+        std::sort(sorted_stacks.begin(), sorted_stacks.end(), [](auto &left, auto &right) { return left.second > right.second; });
+        unsigned printed = 0;
+        for (auto &stack: sorted_stacks)
+        {
+            if (printed == 3)
+                break;
+            DBGLOG("Stack appeared %u times:", stack.second);
+            char** strs = backtrace_symbols(stack.first.stack, 4);
+            for (unsigned i = 0; i < 4; ++i)
+                DBGLOG("%s", strs[i]);
+            free(strs);
+            printed++;
+        }
+    }
+}
+
+int CriticalBlockInstrumentation::compare(const CriticalBlockInstrumentation *other) const
+{
+    if (waitCycles < other->waitCycles)
+        return -1;
+    if (waitCycles > other->waitCycles)
+        return 1;
+    if (holdCycles < other->holdCycles)
+        return -1;
+    if (holdCycles > other->holdCycles)
+        return 1;
+    if (contended < other->contended)
+        return -1;
+    if (contended > other->contended)
+        return 1;
+    if (uncontended < other->uncontended)
+        return -1;
+    if (uncontended > other->uncontended)
+        return 1;
+    return 0;
+}
+
+InstrumentedCriticalBlock::InstrumentedCriticalBlock(InstrumentedCriticalSection &c) : crit(c)
+{
+    inst = __cbinst;
+    start = get_cycles_now();
+    c.enter();
+    in = get_cycles_now();
+}
+
+InstrumentedCriticalBlock::~InstrumentedCriticalBlock()
+{
+    bool wasContended = crit.leave();
+    cycle_t out = get_cycles_now();
+    inst->addStat(in-start, out-in, wasContended);
+}
 
 inline bool read_data(int fd, void *buf, size_t nbytes) 
 {