more lock instrumentation

arangod/Cluster/ClusterComm.cpp

@@ -255,7 +255,7 @@ ClusterCommResult* ClusterComm::asyncRequest (
   *res = *static_cast<ClusterCommResult*>(op);
 
   {
-    basics::ConditionLocker locker(&somethingToSend);
+    CONDITION_LOCKER(guard, somethingToSend);
     toSend.push_back(op);
     TRI_ASSERT(nullptr != op);
     list<ClusterCommOperation*>::iterator i = toSend.end();
@@ -463,7 +463,8 @@ ClusterCommResult const* ClusterComm::enquire (OperationID const operationID) {
 
   // First look into the send queue:
   {
-    basics::ConditionLocker locker(&somethingToSend);
+    CONDITION_LOCKER(guard, somethingToSend);
+
     i = toSendByOpID.find(operationID);
     if (i != toSendByOpID.end()) {
       res = new ClusterCommResult();
@@ -482,7 +483,8 @@ ClusterCommResult const* ClusterComm::enquire (OperationID const operationID) {
 
   // If the above did not give anything, look into the receive queue:
   {
-    basics::ConditionLocker locker(&somethingReceived);
+    CONDITION_LOCKER(guard, somethingReceived);
+
     i = receivedByOpID.find(operationID);
     if (i != receivedByOpID.end()) {
       res = new ClusterCommResult();
@@ -542,12 +544,14 @@ ClusterCommResult* ClusterComm::wait (
 
   if (0 != operationID) {
     // In this case we only have to look into at most one operation.
-    basics::ConditionLocker locker(&somethingReceived);
+    CONDITION_LOCKER(guard, somethingReceived);
+
     while (true) {   // will be left by return or break on timeout
       i = receivedByOpID.find(operationID);
       if (i == receivedByOpID.end()) {
         // It could be that the operation is still in the send queue:
-        basics::ConditionLocker sendlocker(&somethingToSend);
+        CONDITION_LOCKER(guard, somethingToSend);
+
         i = toSendByOpID.find(operationID);
         if (i == toSendByOpID.end()) {
           // Nothing known about this operation, return with failure:
@@ -591,7 +595,8 @@ ClusterCommResult* ClusterComm::wait (
     // here, operationID == 0, so we have to do matching, we are only
     // interested, if at least one operation matches, if it is ready,
     // we return it immediately, otherwise, we report an error or wait.
-    basics::ConditionLocker locker(&somethingReceived);
+    CONDITION_LOCKER(locker, somethingReceived);
+
     while (true) {   // will be left by return or break on timeout
       bool found = false;
       for (q = received.begin(); q != received.end(); q++) {
@@ -616,7 +621,8 @@ ClusterCommResult* ClusterComm::wait (
       }
       // If we found nothing, we have to look through the send queue:
       if (! found) {
-        basics::ConditionLocker sendlocker(&somethingToSend);
+        CONDITION_LOCKER(sendLocker, somethingReceived);
+
         for (q = toSend.begin(); q != toSend.end(); q++) {
           op = *q;
           if (match(clientTransactionID, coordTransactionID, shardID, op)) {
@@ -689,7 +695,8 @@ void ClusterComm::drop (
 
   // First look through the send queue:
   {
-    basics::ConditionLocker sendlocker(&somethingToSend);
+    CONDITION_LOCKER(sendLocker, somethingToSend);
+
     for (q = toSend.begin(); q != toSend.end(); ) {
       op = *q;
       if ((0 != operationID && operationID == op->operationID) ||
@@ -716,7 +723,8 @@ void ClusterComm::drop (
   }
   // Now look through the receive queue:
   {
-    basics::ConditionLocker locker(&somethingReceived);
+    CONDITION_LOCKER(locker, somethingReceived);
+
     for (q = received.begin(); q != received.end(); ) {
       op = *q;
       if ((0 != operationID && operationID == op->operationID) ||
@@ -849,7 +857,8 @@ string ClusterComm::processAnswer (string& coordinatorHeader,
 
   // Finally find the ClusterCommOperation record for this operation:
   {
-    basics::ConditionLocker locker(&somethingReceived);
+    CONDITION_LOCKER(locker, somethingReceived);
+
     ClusterComm::IndexIterator i;
     i = receivedByOpID.find(operationID);
     if (i != receivedByOpID.end()) {
@@ -873,7 +882,8 @@ string ClusterComm::processAnswer (string& coordinatorHeader,
       // We have to look in the send queue as well, as it might not yet
       // have been moved to the received queue. Note however that it must
       // have been fully sent, so this is highly unlikely, but not impossible.
-      basics::ConditionLocker sendlocker(&somethingToSend);
+      CONDITION_LOCKER(sendLocker, somethingToSend);
+
       i = toSendByOpID.find(operationID);
       if (i != toSendByOpID.end()) {
         ClusterCommOperation* op = *(i->second);
@@ -910,8 +920,10 @@ string ClusterComm::processAnswer (string& coordinatorHeader,
 
 bool ClusterComm::moveFromSendToReceived (OperationID operationID) {
   LOG_DEBUG("In moveFromSendToReceived %llu", (unsigned long long) operationID);
-  basics::ConditionLocker locker(&somethingReceived);
+
-  basics::ConditionLocker sendlocker(&somethingToSend);
+  CONDITION_LOCKER(guard1, somethingReceived);
+  CONDITION_LOCKER(guard2, somethingToSend);
+
   IndexIterator i = toSendByOpID.find(operationID);   // cannot fail
   TRI_ASSERT(i != toSendByOpID.end());
 
@@ -944,15 +956,18 @@ bool ClusterComm::moveFromSendToReceived (OperationID operationID) {
 void ClusterComm::cleanupAllQueues() {
   QueueIterator i;
   {
-    basics::ConditionLocker locker(&somethingToSend);
+    CONDITION_LOCKER(guard, somethingToSend);
+
     for (auto& it : toSend) {
       delete it;
     }
     toSendByOpID.clear();
     toSend.clear();
   }
+
   {
-    basics::ConditionLocker locker(&somethingReceived);
+    CONDITION_LOCKER(guard, somethingReceived);
+
     for (auto& it : received) {
       delete it;
     }
@@ -1014,7 +1029,8 @@ void ClusterCommThread::run () {
       }
 
       {
-        basics::ConditionLocker locker(&cc->somethingToSend);
+        CONDITION_LOCKER(guard, cc->somethingToSend);
+
         if (cc->toSend.empty()) {
           break;
         }
@@ -1133,7 +1149,8 @@ void ClusterCommThread::run () {
 
     {
       double currentTime = TRI_microtime();
-      basics::ConditionLocker locker(&cc->somethingReceived);
+      CONDITION_LOCKER(guard, cc->somethingReceived);
+
       ClusterComm::QueueIterator q;
       for (q = cc->received.begin(); q != cc->received.end(); ++q) {
         op = *q;
@@ -1148,8 +1165,8 @@ void ClusterCommThread::run () {
     // Finally, wait for some time or until something happens using
     // the condition variable:
     {
-      basics::ConditionLocker locker(&cc->somethingToSend);
+      CONDITION_LOCKER(guard, cc->somethingToSend);
-      locker.wait(100000);
+      guard.wait(100000);
     }
   }
 

arangosh/Benchmark/BenchmarkThread.h

@@ -32,17 +32,16 @@
 
 #include "Basics/Common.h"
 
-#include "Basics/hashes.h"
-
 #include "Basics/ConditionLocker.h"
 #include "Basics/ConditionVariable.h"
-#include "Basics/Thread.h"
+#include "Basics/hashes.h"
 #include "Basics/logging.h"
+#include "Basics/Thread.h"
+#include "Benchmark/BenchmarkCounter.h"
+#include "Benchmark/BenchmarkOperation.h"
 #include "Rest/HttpResponse.h"
 #include "SimpleHttpClient/SimpleHttpClient.h"
 #include "SimpleHttpClient/GeneralClientConnection.h"
-#include "Benchmark/BenchmarkCounter.h"
-#include "Benchmark/BenchmarkOperation.h"
 
 namespace triagens {
   namespace arangob {
@@ -176,7 +175,7 @@ namespace triagens {
 
           // wait for start condition to be broadcasted
           {
-            basics::ConditionLocker guard(_startCondition);
+            CONDITION_LOCKER(guard, (*_startCondition));
             guard.wait();
           }
 

arangosh/Benchmark/arangob.cpp

@@ -388,7 +388,7 @@ int main (int argc, char* argv[]) {
 
   // broadcast the start signal to all threads
   {
-    ConditionLocker guard(&startCondition);
+    CONDITION_LOCKER(guard, startCondition);
     guard.broadcast();
   }
 

lib/Basics/Common.h

@@ -263,6 +263,9 @@ namespace triagens {
   typedef TRI_msec_t msec_t;
 }
 
+#undef TRI_SHOW_LOCK_TIME 
+#define TRI_SHOW_LOCK_THRESHOLD 0.000199
+
 #endif
 
 // -----------------------------------------------------------------------------

lib/Basics/ConditionLocker.cpp

@@ -30,8 +30,9 @@
 
 #include "ConditionLocker.h"
 
-#include "Basics/Exceptions.h"
+#ifdef TRI_SHOW_LOCK_TIME
-#include "Basics/StringUtils.h"
+#include "Basics/logging.h"
+#endif
 
 using namespace triagens::basics;
 
@@ -46,29 +47,38 @@ using namespace triagens::basics;
 /// the condition variable
 ////////////////////////////////////////////////////////////////////////////////
 
-ConditionLocker::ConditionLocker (ConditionVariable* conditionVariable)
+#ifdef TRI_SHOW_LOCK_TIME
-  : _conditionVariable(conditionVariable), _file(0), _line(0) {
-  _conditionVariable->lock();
-}
-
-////////////////////////////////////////////////////////////////////////////////
-/// @brief locks the condition variable
-///
-/// The constructors locks the condition variable, the destructors unlocks
-/// the condition variable
-////////////////////////////////////////////////////////////////////////////////
 
 ConditionLocker::ConditionLocker (ConditionVariable* conditionVariable, char const* file, int line)
-  : _conditionVariable(conditionVariable), _file(file), _line(line) {
+  : _conditionVariable(conditionVariable), _file(file), _line(line), _time(0.0) {
+
+  double t = TRI_microtime();
+  _conditionVariable->lock();
+  _time = TRI_microtime() - t;
+}
+
+#else
+
+ConditionLocker::ConditionLocker (ConditionVariable* conditionVariable)
+  : _conditionVariable(conditionVariable) {
+
   _conditionVariable->lock();
 }
 
+#endif
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief unlocks the condition variable
 ////////////////////////////////////////////////////////////////////////////////
 
 ConditionLocker::~ConditionLocker () {
   _conditionVariable->unlock();
+
+#ifdef TRI_SHOW_LOCK_TIME
+  if (_time > TRI_SHOW_LOCK_THRESHOLD) {
+    LOG_WARNING("ConditionLocker %s:%d took %f s", _file, _line, _time);
+  }
+#endif  
 }
 
 // -----------------------------------------------------------------------------

lib/Basics/ConditionLocker.h

@@ -32,7 +32,6 @@
 #define ARANGODB_BASICS_CONDITION_LOCKER_H 1
 
 #include "Basics/Common.h"
-
 #include "Basics/ConditionVariable.h"
 
 // -----------------------------------------------------------------------------
@@ -43,11 +42,20 @@
 /// @brief construct locker with file and line information
 ////////////////////////////////////////////////////////////////////////////////
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 #define CONDITION_LOCKER(a, b) \
   triagens::basics::ConditionLocker a(&b, __FILE__, __LINE__)
 
+#else
+
+#define CONDITION_LOCKER(a, b) \
+  triagens::basics::ConditionLocker a(&b)
+
+#endif
+
 // -----------------------------------------------------------------------------
-// --SECTION--                                                  class ReadLocker
+// --SECTION--                                             class ConditionLocker
 // -----------------------------------------------------------------------------
 
 namespace triagens {
@@ -74,21 +82,20 @@ namespace triagens {
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief locks the condition variable
 ///
-/// The constructors locks the condition variable, the destructors unlocks
+/// The constructor locks the condition variable, the destructor unlocks
 /// the condition variable
 ////////////////////////////////////////////////////////////////////////////////
 
+#ifdef TRI_SHOW_LOCK_TIME
+
+        ConditionLocker (ConditionVariable* conditionVariable, char const* file, int line);
+
+#else
+
         explicit
         ConditionLocker (ConditionVariable* conditionVariable);
 
-////////////////////////////////////////////////////////////////////////////////
+#endif        
-/// @brief locks the condition variable
-///
-/// The constructors locks the condition variable, the destructors unlocks
-/// the condition variable
-////////////////////////////////////////////////////////////////////////////////
-
-        ConditionLocker (ConditionVariable* conditionVariable, char const* file, int line);
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief unlocks the condition variable
@@ -150,6 +157,8 @@ namespace triagens {
 
         ConditionVariable* _conditionVariable;
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief file
 ////////////////////////////////////////////////////////////////////////////////
@@ -161,6 +170,14 @@ namespace triagens {
 ////////////////////////////////////////////////////////////////////////////////
 
         int _line;
+
+////////////////////////////////////////////////////////////////////////////////
+/// @brief lock time
+////////////////////////////////////////////////////////////////////////////////
+
+        double _time;
+
+#endif        
     };
   }
 }

lib/Basics/MutexLocker.cpp

@@ -30,6 +30,10 @@
 
 #include "MutexLocker.h"
 
+#ifdef TRI_SHOW_LOCK_TIME
+#include "Basics/logging.h"
+#endif
+
 using namespace triagens::basics;
 
 // -----------------------------------------------------------------------------
@@ -42,27 +46,38 @@ using namespace triagens::basics;
 /// The constructor aquires a lock, the destructors releases the lock.
 ////////////////////////////////////////////////////////////////////////////////
 
-MutexLocker::MutexLocker (Mutex* mutex)
+#ifdef TRI_SHOW_LOCK_TIME
-  : MutexLocker(mutex, nullptr, 0) {
-}
-
-////////////////////////////////////////////////////////////////////////////////
-/// @brief aquires a lock
-///
-/// The constructor aquires a lock, the destructors releases the lock.
-////////////////////////////////////////////////////////////////////////////////
 
 MutexLocker::MutexLocker (Mutex* mutex, char const* file, int line)
-  : _mutex(mutex), _file(file), _line(line) {
+  : _mutex(mutex), _file(file), _line(line), _time(0.0) {
+  
+  double t = TRI_microtime();
+  _mutex->lock();
+  _time = TRI_microtime() - t;
+}
+
+#else
+
+MutexLocker::MutexLocker (Mutex* mutex)
+  : _mutex(mutex) {
+  
   _mutex->lock();
 }
 
+#endif
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief releases the lock
 ////////////////////////////////////////////////////////////////////////////////
 
 MutexLocker::~MutexLocker () {
   _mutex->unlock();
+
+#ifdef TRI_SHOW_LOCK_TIME
+  if (_time > TRI_SHOW_LOCK_THRESHOLD) {
+    LOG_WARNING("MutexLocker %s:%d took %f s", _file, _line, _time);
+  }
+#endif  
 }
 
 // -----------------------------------------------------------------------------

lib/Basics/MutexLocker.h

@@ -48,9 +48,18 @@
 #define MUTEX_LOCKER_VAR_A(a) _mutex_lock_variable_ ## a
 #define MUTEX_LOCKER_VAR_B(a) MUTEX_LOCKER_VAR_A(a)
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 #define MUTEX_LOCKER(b) \
   triagens::basics::MutexLocker MUTEX_LOCKER_VAR_B(__LINE__)(&b, __FILE__, __LINE__)
 
+#else
+
+#define MUTEX_LOCKER(b) \
+  triagens::basics::MutexLocker MUTEX_LOCKER_VAR_B(__LINE__)(&b)
+
+#endif
+
 // -----------------------------------------------------------------------------
 // --SECTION--                                                 class MutexLocker
 // -----------------------------------------------------------------------------
@@ -81,16 +90,16 @@ namespace triagens {
 /// The constructor aquires a lock, the destructor releases the lock.
 ////////////////////////////////////////////////////////////////////////////////
 
+#ifdef TRI_SHOW_LOCK_TIME
+
+        MutexLocker (Mutex* mutex, char const* file, int line);
+
+#else
+
         explicit
         MutexLocker (Mutex* mutex);
 
-////////////////////////////////////////////////////////////////////////////////
+#endif        
-/// @brief aquires a lock
-///
-/// The constructor aquires a lock, the destructor releases the lock.
-////////////////////////////////////////////////////////////////////////////////
-
-        MutexLocker (Mutex* mutex, char const* file, int line);
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief releases the lock
@@ -110,6 +119,8 @@ namespace triagens {
 
         Mutex* _mutex;
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief file
 ////////////////////////////////////////////////////////////////////////////////
@@ -122,6 +133,13 @@ namespace triagens {
 
         int _line;
 
+////////////////////////////////////////////////////////////////////////////////
+/// @brief lock time
+////////////////////////////////////////////////////////////////////////////////
+
+        double _time;
+
+#endif        
     };
   }
 }

lib/Basics/ReadLocker.cpp

@@ -30,6 +30,10 @@
 
 #include "ReadLocker.h"
 
+#ifdef TRI_SHOW_LOCK_TIME
+#include "Basics/logging.h"
+#endif
+
 using namespace triagens::basics;
 
 // -----------------------------------------------------------------------------
@@ -42,53 +46,71 @@ using namespace triagens::basics;
 /// The constructors read-lock the lock, the destructors unlock the lock.
 ////////////////////////////////////////////////////////////////////////////////
 
-ReadLocker::ReadLocker (ReadWriteLock* readWriteLock)
+#ifdef TRI_SHOW_LOCK_TIME
-  : ReadLocker(readWriteLock, nullptr, 0) {
-}
-
-////////////////////////////////////////////////////////////////////////////////
-/// @brief acquires a read-lock
-///
-/// The constructors read-lock the lock, the destructors unlock the lock.
-////////////////////////////////////////////////////////////////////////////////
 
 ReadLocker::ReadLocker (ReadWriteLock* readWriteLock, char const* file, int line)
   : _readWriteLock(readWriteLock), _file(file), _line(line) {
+  
+  double t = TRI_microtime();
+  _readWriteLock->readLock();
+  _time = TRI_microtime() - t;
+}
+
+#else 
+
+ReadLocker::ReadLocker (ReadWriteLock* readWriteLock)
+  : _readWriteLock(readWriteLock) {
+  
   _readWriteLock->readLock();
 }
 
-////////////////////////////////////////////////////////////////////////////////
+#endif
-/// @brief aquires a read-lock, with periodic sleeps while not acquired
-/// sleep time is specified in nanoseconds
-////////////////////////////////////////////////////////////////////////////////
-
-ReadLocker::ReadLocker (ReadWriteLock* readWriteLock, 
-                          uint64_t sleepTime) 
-  : ReadLocker(readWriteLock, sleepTime, nullptr, 0) {
-}
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief aquires a read-lock, with periodic sleeps while not acquired
 /// sleep time is specified in nanoseconds
 ////////////////////////////////////////////////////////////////////////////////
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 ReadLocker::ReadLocker (ReadWriteLock* readWriteLock, 
                         uint64_t sleepTime,
                         char const* file,
                         int line) 
   : _readWriteLock(readWriteLock), _file(file), _line(line) {
   
+  double t = TRI_microtime();
+  while (! _readWriteLock->tryReadLock()) {
+    usleep(sleepTime);
+  }
+  _time = TRI_microtime() - t;
+}
+
+#else
+
+ReadLocker::ReadLocker (ReadWriteLock* readWriteLock, 
+                        uint64_t sleepTime) 
+  : _readWriteLock(readWriteLock) {
+  
   while (! _readWriteLock->tryReadLock()) {
     usleep(sleepTime);
   }
 }
 
+#endif
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief releases the read-lock
 ////////////////////////////////////////////////////////////////////////////////
 
 ReadLocker::~ReadLocker () {
   _readWriteLock->unlock();
+
+#ifdef TRI_SHOW_LOCK_TIME
+  if (_time > TRI_SHOW_LOCK_THRESHOLD) {
+    LOG_WARNING("ReadLocker %s:%d took %f s", _file, _line, _time);
+  }
+#endif  
 }
 
 // -----------------------------------------------------------------------------

lib/Basics/ReadLocker.h

@@ -48,12 +48,24 @@
 #define READ_LOCKER_VAR_A(a) _read_lock_variable ## a
 #define READ_LOCKER_VAR_B(a) READ_LOCKER_VAR_A(a)
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 #define READ_LOCKER(b) \
   triagens::basics::ReadLocker READ_LOCKER_VAR_B(__LINE__)(&b, __FILE__, __LINE__)
 
 #define READ_LOCKER_EVENTUAL(b, t) \
   triagens::basics::ReadLocker READ_LOCKER_VAR_B(__LINE__)(&b, t, __FILE__, __LINE__)
 
+#else
+
+#define READ_LOCKER(b) \
+  triagens::basics::ReadLocker READ_LOCKER_VAR_B(__LINE__)(&b)
+
+#define READ_LOCKER_EVENTUAL(b, t) \
+  triagens::basics::ReadLocker READ_LOCKER_VAR_B(__LINE__)(&b, t)
+
+#endif
+
 // -----------------------------------------------------------------------------
 // --SECTION--                                                  class ReadLocker
 // -----------------------------------------------------------------------------
@@ -84,32 +96,31 @@ namespace triagens {
 /// The constructors read-locks the lock, the destructors unlocks the lock.
 ////////////////////////////////////////////////////////////////////////////////
 
-        explicit
+#ifdef TRI_SHOW_LOCK_TIME
-        ReadLocker (ReadWriteLock*);
-
-////////////////////////////////////////////////////////////////////////////////
-/// @brief aquires a read-lock
-///
-/// The constructors read-locks the lock, the destructors unlocks the lock.
-////////////////////////////////////////////////////////////////////////////////
 
         ReadLocker (ReadWriteLock* readWriteLock, char const* file, int line);
 
+#else
+
+        explicit
+        ReadLocker (ReadWriteLock*);
+
+#endif
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief aquires a read-lock, with periodic sleeps while not acquired
 /// sleep time is specified in nanoseconds
 ////////////////////////////////////////////////////////////////////////////////
 
-        explicit
+#ifdef TRI_SHOW_LOCK_TIME
+
+        ReadLocker (ReadWriteLock* readWriteLock, uint64_t sleepDelay, char const* file, int line);
+
+#else
+
         ReadLocker (ReadWriteLock*, uint64_t);
 
-////////////////////////////////////////////////////////////////////////////////
+#endif
-/// @brief aquires a read-lock, with periodic sleeps while not acquired
-/// sleep time is specified in nanoseconds
-////////////////////////////////////////////////////////////////////////////////
-
-        explicit
-        ReadLocker (ReadWriteLock* readWriteLock, uint64_t sleepDelay, char const* file, int line);
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief releases the read-lock
@@ -129,6 +140,8 @@ namespace triagens {
 
         ReadWriteLock* _readWriteLock;
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief file
 ////////////////////////////////////////////////////////////////////////////////
@@ -141,6 +154,14 @@ namespace triagens {
 
         int _line;
 
+////////////////////////////////////////////////////////////////////////////////
+/// @brief lock time
+////////////////////////////////////////////////////////////////////////////////
+
+        double _time;
+
+#endif        
+
     };
   }
 }

lib/Basics/SpinLocker.cpp

@@ -30,6 +30,10 @@
 
 #include "SpinLocker.h"
 
+#ifdef TRI_SHOW_LOCK_TIME
+#include "Basics/logging.h"
+#endif
+
 using namespace triagens::basics;
 
 // -----------------------------------------------------------------------------
@@ -42,9 +46,7 @@ using namespace triagens::basics;
 /// The constructor aquires a lock, the destructor releases the lock.
 ////////////////////////////////////////////////////////////////////////////////
 
-SpinLocker::SpinLocker (SpinLock* lock)
+#ifdef TRI_SHOW_LOCK_TIME
-  : SpinLocker(lock, nullptr, 0) {
-}
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief aquires a lock
@@ -54,15 +56,34 @@ SpinLocker::SpinLocker (SpinLock* lock)
 
 SpinLocker::SpinLocker (SpinLock* lock, char const* file, int line)
   : _lock(lock), _file(file), _line(line) {
+  
+  double t = TRI_microtime();
+  _lock->lock();
+  _time = TRI_microtime() - t;
+}
+
+#else
+
+SpinLocker::SpinLocker (SpinLock* lock)
+  : _lock(lock) {
+  
   _lock->lock();
 }
 
+#endif
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief releases the lock
 ////////////////////////////////////////////////////////////////////////////////
 
 SpinLocker::~SpinLocker () {
   _lock->unlock();
+
+#ifdef TRI_SHOW_LOCK_TIME
+  if (_time > TRI_SHOW_LOCK_THRESHOLD) {
+    LOG_WARNING("SpinLocker %s:%d took %f s", _file, _line, _time);
+  }
+#endif  
 }
 
 // -----------------------------------------------------------------------------

lib/Basics/SpinLocker.h

@@ -48,9 +48,18 @@
 #define SPIN_LOCKER_VAR_A(a) _spin_lock_variable_ ## a
 #define SPIN_LOCKER_VAR_B(a) SPIN_LOCKER_VAR_A(a)
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 #define SPIN_LOCKER(b) \
   triagens::basics::SpinLocker SPIN_LOCKER_VAR_B(__LINE__)(&b, __FILE__, __LINE__)
 
+#else
+
+#define SPIN_LOCKER(b) \
+  triagens::basics::SpinLocker SPIN_LOCKER_VAR_B(__LINE__)(&b)
+
+#endif
+
 // -----------------------------------------------------------------------------
 // --SECTION--                                                  class SpinLocker
 // -----------------------------------------------------------------------------
@@ -81,16 +90,16 @@ namespace triagens {
 /// The constructor aquires a lock, the destructors releases the lock.
 ////////////////////////////////////////////////////////////////////////////////
 
+#ifdef TRI_SHOW_LOCK_TIME
+
+        SpinLocker (SpinLock*, char const* file, int line);
+
+#else
+
         explicit
         SpinLocker (SpinLock*);
 
-////////////////////////////////////////////////////////////////////////////////
+#endif
-/// @brief aquires a lock
-///
-/// The constructor aquires a lock, the destructors releases the lock.
-////////////////////////////////////////////////////////////////////////////////
-
-        SpinLocker (SpinLock*, char const* file, int line);
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief releases the lock
@@ -110,6 +119,8 @@ namespace triagens {
 
         SpinLock* _lock;
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief file
 ////////////////////////////////////////////////////////////////////////////////
@@ -122,6 +133,13 @@ namespace triagens {
 
         int _line;
 
+////////////////////////////////////////////////////////////////////////////////
+/// @brief lock time
+////////////////////////////////////////////////////////////////////////////////
+
+        double _time;
+
+#endif
     };
   }
 }

lib/Basics/WriteLocker.cpp

@@ -30,21 +30,16 @@
 
 #include "WriteLocker.h"
 
+#ifdef TRI_SHOW_LOCK_TIME
+#include "Basics/logging.h"
+#endif
+
 using namespace triagens::basics;
 
 // -----------------------------------------------------------------------------
 // --SECTION--                                      constructors and destructors
 // -----------------------------------------------------------------------------
 
-////////////////////////////////////////////////////////////////////////////////
-/// @brief aquires a write-lock
-///
-/// The constructors aquires a write lock, the destructors unlocks the lock.
-////////////////////////////////////////////////////////////////////////////////
-
-WriteLocker::WriteLocker (ReadWriteLock* readWriteLock)
-  : WriteLocker(readWriteLock, nullptr, 0) {
-}
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief aquires a write-lock
@@ -52,43 +47,71 @@ WriteLocker::WriteLocker (ReadWriteLock* readWriteLock)
 /// The constructors aquires a write lock, the destructors unlocks the lock.
 ////////////////////////////////////////////////////////////////////////////////
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 WriteLocker::WriteLocker (ReadWriteLock* readWriteLock, char const* file, int line)
   : _readWriteLock(readWriteLock), _file(file), _line(line) {
+
+  double t = TRI_microtime();
+  _readWriteLock->writeLock();
+  _time = TRI_microtime() - t;
+}
+
+#else 
+
+WriteLocker::WriteLocker (ReadWriteLock* readWriteLock)
+  : _readWriteLock(readWriteLock) {
+  
   _readWriteLock->writeLock();
 }
 
-////////////////////////////////////////////////////////////////////////////////
+#endif
-/// @brief aquires a write-lock, with periodic sleeps while not acquired
-/// sleep time is specified in nanoseconds
-////////////////////////////////////////////////////////////////////////////////
-
-WriteLocker::WriteLocker (ReadWriteLock* readWriteLock, 
-                          uint64_t sleepTime) 
-  : WriteLocker(readWriteLock, sleepTime, nullptr, 0) {
-}
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief aquires a write-lock, with periodic sleeps while not acquired
 /// sleep time is specified in nanoseconds
 ////////////////////////////////////////////////////////////////////////////////
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 WriteLocker::WriteLocker (ReadWriteLock* readWriteLock, 
                           uint64_t sleepTime,
                           char const* file,
                           int line) 
   : _readWriteLock(readWriteLock), _file(file), _line(line) {
   
+  double t = TRI_microtime();
+  while (! _readWriteLock->tryWriteLock()) {
+    usleep(sleepTime);
+  }
+  _time = TRI_microtime() - t;
+}
+
+#else
+
+WriteLocker::WriteLocker (ReadWriteLock* readWriteLock, 
+                          uint64_t sleepTime) 
+  : _readWriteLock(readWriteLock) {
+  
   while (! _readWriteLock->tryWriteLock()) {
     usleep(sleepTime);
   }
 }
 
+#endif
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief releases the write-lock
 ////////////////////////////////////////////////////////////////////////////////
 
 WriteLocker::~WriteLocker () {
   _readWriteLock->unlock();
+
+#ifdef TRI_SHOW_LOCK_TIME
+  if (_time > TRI_SHOW_LOCK_THRESHOLD) {
+    LOG_WARNING("WriteLocker %s:%d took %f s", _file, _line, _time);
+  }
+#endif  
 }
 
 // -----------------------------------------------------------------------------

lib/Basics/WriteLocker.h

@@ -48,12 +48,24 @@
 #define WRITE_LOCKER_VAR_A(a) _write_lock_variable ## a
 #define WRITE_LOCKER_VAR_B(a) WRITE_LOCKER_VAR_A(a)
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 #define WRITE_LOCKER(b) \
   triagens::basics::WriteLocker WRITE_LOCKER_VAR_B(__LINE__)(&b, __FILE__, __LINE__)
 
 #define WRITE_LOCKER_EVENTUAL(b, t) \
   triagens::basics::WriteLocker WRITE_LOCKER_VAR_B(__LINE__)(&b, t, __FILE__, __LINE__)
 
+#else
+
+#define WRITE_LOCKER(b) \
+  triagens::basics::WriteLocker WRITE_LOCKER_VAR_B(__LINE__)(&b)
+
+#define WRITE_LOCKER_EVENTUAL(b, t) \
+  triagens::basics::WriteLocker WRITE_LOCKER_VAR_B(__LINE__)(&b, t)
+
+#endif
+
 // -----------------------------------------------------------------------------
 // --SECTION--                                                 class WriteLocker
 // -----------------------------------------------------------------------------
@@ -84,33 +96,31 @@ namespace triagens {
 /// The constructors aquires a write lock, the destructors unlocks the lock.
 ////////////////////////////////////////////////////////////////////////////////
 
+#ifdef TRI_SHOW_LOCK_TIME
+
+        WriteLocker (ReadWriteLock* readWriteLock, char const* file, int line);
+
+#else
+
         explicit
         WriteLocker (ReadWriteLock*);
 
-////////////////////////////////////////////////////////////////////////////////
+#endif
-/// @brief aquires a write-lock
-///
-/// The constructors aquires a write lock, the destructors unlocks the lock.
-////////////////////////////////////////////////////////////////////////////////
-
-        explicit
-        WriteLocker (ReadWriteLock* readWriteLock, char const* file, int line);
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief aquires a write-lock, with periodic sleeps while not acquired
 /// sleep time is specified in nanoseconds
 ////////////////////////////////////////////////////////////////////////////////
 
-        explicit
+#ifdef TRI_SHOW_LOCK_TIME
+        
+        WriteLocker (ReadWriteLock* readWriteLock, uint64_t sleepDelay, char const* file, int line);
+
+#else
+
         WriteLocker (ReadWriteLock*, uint64_t);
 
-////////////////////////////////////////////////////////////////////////////////
+#endif        
-/// @brief aquires a write-lock, with periodic sleeps while not acquired
-/// sleep time is specified in nanoseconds
-////////////////////////////////////////////////////////////////////////////////
-
-        explicit
-        WriteLocker (ReadWriteLock* readWriteLock, uint64_t sleepDelay, char const* file, int line);
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief releases the write-lock
@@ -130,6 +140,8 @@ namespace triagens {
 
         ReadWriteLock* _readWriteLock;
 
+#ifdef TRI_SHOW_LOCK_TIME
+
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief file
 ////////////////////////////////////////////////////////////////////////////////
@@ -142,6 +154,14 @@ namespace triagens {
 
         int _line;
 
+////////////////////////////////////////////////////////////////////////////////
+/// @brief lock time
+////////////////////////////////////////////////////////////////////////////////
+
+        double _time;
+
+#endif        
+
     };
   }
 }