SERVER-16799 Report locking stats in the slow query log

(cherry picked from commit a4ed524990f23821df57fbd4c8aafbcff574823e)

5 files changed, 43 insertions, 14 deletions

diff --git a/src/mongo/db/client.cpp b/src/mongo/db/client.cpp
index 6f12fb20be2..82e94faff1f 100644
--- a/src/mongo/db/client.cpp
+++ b/src/mongo/db/client.cpp
@@ -449,7 +449,7 @@ namespace {
 
 #define OPDEBUG_TOSTRING_HELP(x) if( x >= 0 ) s << " " #x ":" << (x)
 #define OPDEBUG_TOSTRING_HELP_BOOL(x) if( x ) s << " " #x ":" << (x)
-    string OpDebug::report( const CurOp& curop ) const {
+    string OpDebug::report(const CurOp& curop, const SingleThreadedLockStats& lockStats) const {
         StringBuilder s;
         if ( iscommand )
             s << "command ";
@@ -519,8 +519,16 @@ namespace {
         s << " numYields:" << curop.numYields();
         
         OPDEBUG_TOSTRING_HELP( nreturned );
-        if ( responseLength > 0 )
+        if (responseLength > 0) {
             s << " reslen:" << responseLength;
+        }
+
+        {
+            BSONObjBuilder locks;
+            lockStats.report(&locks);
+            s << " locks:" << locks.obj().toString();
+        }
+
         s << " " << executionTime << "ms";
         
         return s.str();
@@ -563,7 +571,10 @@ namespace {
 
 #define OPDEBUG_APPEND_NUMBER(x) if( x != -1 ) b.appendNumber( #x , (x) )
 #define OPDEBUG_APPEND_BOOL(x) if( x ) b.appendBool( #x , (x) )
-    void OpDebug::append(const CurOp& curop, BSONObjBuilder& b) const {
+    void OpDebug::append(const CurOp& curop,
+                         const SingleThreadedLockStats& lockStats,
+                         BSONObjBuilder& b) const {
+
         const size_t maxElementSize = 50 * 1024;
 
         b.append( "op" , iscommand ? "command" : opToString( op ) );
@@ -602,11 +613,16 @@ namespace {
         OPDEBUG_APPEND_BOOL( upsert );
         OPDEBUG_APPEND_NUMBER( keyUpdates );
         OPDEBUG_APPEND_NUMBER( writeConflicts );
-
         b.appendNumber("numYield", curop.numYields());
 
-        if ( ! exceptionInfo.empty() )
-            exceptionInfo.append( b , "exception" , "exceptionCode" );
+        {
+            BSONObjBuilder locks(b.subobjStart("locks"));
+            lockStats.report(&locks);
+        }
+
+        if (!exceptionInfo.empty()) {
+            exceptionInfo.append(b, "exception", "exceptionCode");
+        }
 
         OPDEBUG_APPEND_NUMBER( nreturned );
         OPDEBUG_APPEND_NUMBER( responseLength );
diff --git a/src/mongo/db/commands/write_commands/batch_executor.cpp b/src/mongo/db/commands/write_commands/batch_executor.cpp
index e187b8f359a..0d2560b486e 100644
--- a/src/mongo/db/commands/write_commands/batch_executor.cpp
+++ b/src/mongo/db/commands/write_commands/batch_executor.cpp
@@ -642,7 +642,10 @@ namespace mongo {
                        > ( serverGlobalParams.slowMS + currentOp->getExpectedLatencyMs() );
 
         if ( logAll || logSlow ) {
-            LOG(0) << currentOp->debug().report( *currentOp ) << endl;
+            Locker::LockerInfo lockerInfo;
+            txn->lockState()->getLockerInfo(&lockerInfo);
+
+            LOG(0) << currentOp->debug().report(*currentOp, lockerInfo.stats);
         }
 
         if (currentOp->shouldDBProfile(executionTime)) {
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index 4f3f27d1fe0..e830f4c67ec 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -129,13 +129,17 @@ namespace mongo {
 
         void recordStats();
 
-        std::string report( const CurOp& curop ) const;
+        std::string report(const CurOp& curop, const SingleThreadedLockStats& lockStats) const;
 
         /**
-         * Appends information about the current operation to "builder".  "curop" must be a
-         * reference to the CurOp that owns this OpDebug.
+         * Appends information about the current operation to "builder"
+         *
+         * @param curop reference to the CurOp that owns this OpDebug
+         * @param lockStats lockStats object containing locking information about the operation
          */
-        void append(const CurOp& curop, BSONObjBuilder& builder) const;
+        void append(const CurOp& curop,
+                    const SingleThreadedLockStats& lockStats,
+                    BSONObjBuilder& builder) const;
 
         // -------------------
         
diff --git a/src/mongo/db/instance.cpp b/src/mongo/db/instance.cpp
index d8f8c26fba6..0b75def0e27 100644
--- a/src/mongo/db/instance.cpp
+++ b/src/mongo/db/instance.cpp
@@ -493,8 +493,10 @@ namespace mongo {
         logThreshold += currentOp.getExpectedLatencyMs();
 
         if ( shouldLog || debug.executionTime > logThreshold ) {
-            MONGO_LOG_COMPONENT(0, responseComponent)
-                    << debug.report( currentOp ) << endl;
+            Locker::LockerInfo lockerInfo;
+            txn->lockState()->getLockerInfo(&lockerInfo);
+
+            MONGO_LOG_COMPONENT(0, responseComponent) << debug.report(currentOp, lockerInfo.stats);
         }
 
         if (currentOp.shouldDBProfile(debug.executionTime)) {
diff --git a/src/mongo/db/introspect.cpp b/src/mongo/db/introspect.cpp
index a43e92edc66..797ff974c7b 100644
--- a/src/mongo/db/introspect.cpp
+++ b/src/mongo/db/introspect.cpp
@@ -86,7 +86,11 @@ namespace {
 
         BSONObjBuilder b(profileBufBuilder);
 
-        txn->getCurOp()->debug().append(*txn->getCurOp(), b);
+        {
+            Locker::LockerInfo lockerInfo;
+            txn->lockState()->getLockerInfo(&lockerInfo);
+            txn->getCurOp()->debug().append(*txn->getCurOp(), lockerInfo.stats, b);
+        }
 
         b.appendDate("ts", jsTime());
         b.append("client", txn->getClient()->clientAddress());