SERVER-15614 Lock statistics for db.currentOp

Add deadlock counter as well.

8 files changed, 47 insertions, 14 deletions

diff --git a/jstests/core/profile4.js b/jstests/core/profile4.js
index 408af65a225..aeb567f6ab0 100644
--- a/jstests/core/profile4.js
+++ b/jstests/core/profile4.js
@@ -1,4 +1,4 @@
-if (0) { // TODO SERVER-15614 reenable
+if (0) { // TODO SERVER-16799 reenable
 // Check debug information recorded for a query.
 
 // special db so that it can be run in parallel tests
diff --git a/src/mongo/db/concurrency/lock_state.cpp b/src/mongo/db/concurrency/lock_state.cpp
index 103630804cc..c28d03cb7dc 100644
--- a/src/mongo/db/concurrency/lock_state.cpp
+++ b/src/mongo/db/concurrency/lock_state.cpp
@@ -32,7 +32,6 @@
 
 #include "mongo/db/concurrency/lock_state.h"
 
-#include "mongo/db/concurrency/lock_stats.h"
 #include "mongo/db/global_environment_experiment.h"
 #include "mongo/db/namespace_string.h"
 #include "mongo/platform/compiler.h"
@@ -66,6 +65,11 @@ namespace {
             stats.recordWaitTime(resId, mode, waitMicros);
         }
 
+        void recordDeadlock(ResourceId resId, LockMode mode) {
+            LockStats& stats = _get(resId);
+            stats.recordDeadlock(resId, mode);
+        }
+
         void report(LockStats* outStats) const {
             for (int i = 0; i < NumPartitions; i++) {
                 outStats->append(_partitions[i].stats);
@@ -508,6 +512,7 @@ namespace {
         // Zero-out the contents
         lockerInfo->locks.clear();
         lockerInfo->waitingResource = ResourceId();
+        lockerInfo->stats.reset();
 
         if (!isLocked()) return;
 
@@ -526,6 +531,7 @@ namespace {
         std::sort(lockerInfo->locks.begin(), lockerInfo->locks.end(), SortByGranularity());
 
         lockerInfo->waitingResource = getWaitingResource();
+        lockerInfo->stats.append(_stats);
     }
 
     template<bool IsForMMAPV1>
@@ -624,6 +630,7 @@ namespace {
 
         // Making this call here will record lock re-acquisitions and conversions as well.
         globalStats.recordAcquisition(_id, resId, mode);
+        _stats.recordAcquisition(resId, mode);
 
         // Give priority to the full modes for global and flush lock so we don't stall global
         // operations such as shutdown or flush.
@@ -649,6 +656,7 @@ namespace {
             // Start counting the wait time so that lockComplete can update that metric
             _requestStartTime = curTimeMicros64();
             globalStats.recordWait(_id, resId, mode);
+            _stats.recordWait(resId, mode);
         }
 
         return result;
@@ -682,6 +690,7 @@ namespace {
             // Account for the time spent waiting on the notification object
             const uint64_t elapsedTimeMicros = curTimeMicros64() - _requestStartTime;
             globalStats.recordWaitTime(_id, resId, mode, elapsedTimeMicros);
+            _stats.recordWaitTime(resId, mode, elapsedTimeMicros);
 
             if (result == LOCK_OK) break;
 
@@ -690,6 +699,9 @@ namespace {
                 if (wfg.check().hasCycle()) {
                     warning() << "Deadlock found: " << wfg.toString();
 
+                    globalStats.recordDeadlock(resId, mode);
+                    _stats.recordDeadlock(resId, mode);
+
                     result = LOCK_DEADLOCK;
                     break;
                 }
diff --git a/src/mongo/db/concurrency/lock_state.h b/src/mongo/db/concurrency/lock_state.h
index b99731c94e4..2022199c6d3 100644
--- a/src/mongo/db/concurrency/lock_state.h
+++ b/src/mongo/db/concurrency/lock_state.h
@@ -207,6 +207,10 @@ namespace mongo {
         // about to wait and is sampled at grant time.
         uint64_t _requestStartTime;
 
+        // Per-locker locking statistics. Reported in the slow-query log message and through
+        // db.currentOp. Complementary to the per-instance locking statistics.
+        LockStats _stats;
+
         // Delays release of exclusive/intent-exclusive locked resources until the write unit of
         // work completes. Value of 0 means we are not inside a write unit of work.
         int _wuowNestingLevel;
diff --git a/src/mongo/db/concurrency/lock_stats.cpp b/src/mongo/db/concurrency/lock_stats.cpp
index ec6e597c608..6293d32ada8 100644
--- a/src/mongo/db/concurrency/lock_stats.cpp
+++ b/src/mongo/db/concurrency/lock_stats.cpp
@@ -52,6 +52,11 @@ namespace mongo {
         stat.stats[mode].combinedWaitTimeMicros.addAndFetch(waitMicros);
     }
 
+    void LockStats::recordDeadlock(ResourceId resId, LockMode mode) {
+        PerModeAtomicLockStats& stat = get(resId);
+        stat.stats[mode].numDeadlocks.addAndFetch(1);
+    }
+
     void LockStats::append(const LockStats& other) {
         // Append all lock stats
         for (int i = 0; i < ResourceTypesCount; i++) {
@@ -125,6 +130,16 @@ namespace mongo {
             }
             timeAcquiring.done();
         }
+
+        // Deadlocks
+        {
+            BSONObjBuilder deadlockCount(builder->subobjStart("deadlockCount"));
+            for (int mode = 1; mode < LockModesCount; mode++) {
+                deadlockCount.append(legacyModeName(static_cast<LockMode>(mode)),
+                                     stat.stats[mode].numDeadlocks.load());
+            }
+            deadlockCount.done();
+        }
     }
 
     void LockStats::reset() {
@@ -157,12 +172,14 @@ namespace mongo {
         numAcquisitions.addAndFetch(other.numAcquisitions.load());
         numWaits.addAndFetch(other.numWaits.load());
         combinedWaitTimeMicros.addAndFetch(other.combinedWaitTimeMicros.load());
+        numDeadlocks.addAndFetch(other.numDeadlocks.load());
     }
 
     void LockStats::AtomicLockStats::reset() {
         numAcquisitions.store(0);
         numWaits.store(0);
         combinedWaitTimeMicros.store(0);
+        numDeadlocks.store(0);
     }
 
 } // namespace mongo
diff --git a/src/mongo/db/concurrency/lock_stats.h b/src/mongo/db/concurrency/lock_stats.h
index ac4f53dda3d..2e58ac17e83 100644
--- a/src/mongo/db/concurrency/lock_stats.h
+++ b/src/mongo/db/concurrency/lock_stats.h
@@ -52,6 +52,7 @@ namespace mongo {
             AtomicInt64 numAcquisitions;
             AtomicInt64 numWaits;
             AtomicInt64 combinedWaitTimeMicros;
+            AtomicInt64 numDeadlocks;
         };
 
         // Keep the per-mode lock stats next to each other in case we want to do fancy operations
@@ -66,6 +67,7 @@ namespace mongo {
         void recordAcquisition(ResourceId resId, LockMode mode);
         void recordWait(ResourceId resId, LockMode mode);
         void recordWaitTime(ResourceId resId, LockMode mode, uint64_t waitMicros);
+        void recordDeadlock(ResourceId resId, LockMode mode);
 
         PerModeAtomicLockStats& get(ResourceId resId);
 
diff --git a/src/mongo/db/concurrency/lock_stats_test.cpp b/src/mongo/db/concurrency/lock_stats_test.cpp
index 7b1a2e0b384..5a38ee4455b 100644
--- a/src/mongo/db/concurrency/lock_stats_test.cpp
+++ b/src/mongo/db/concurrency/lock_stats_test.cpp
@@ -30,7 +30,6 @@
 
 #include "mongo/bson/bsonobjbuilder.h"
 #include "mongo/db/concurrency/lock_manager_test_help.h"
-#include "mongo/db/concurrency/lock_stats.h"
 #include "mongo/unittest/unittest.h"
 
 namespace mongo {
diff --git a/src/mongo/db/concurrency/locker.h b/src/mongo/db/concurrency/locker.h
index edbedfa4ddb..52740e5254a 100644
--- a/src/mongo/db/concurrency/locker.h
+++ b/src/mongo/db/concurrency/locker.h
@@ -33,6 +33,7 @@
 
 #include "mongo/base/disallow_copying.h"
 #include "mongo/db/concurrency/lock_manager.h"
+#include "mongo/db/concurrency/lock_stats.h"
 
 namespace mongo {
     
@@ -205,6 +206,9 @@ namespace mongo {
 
             // If isValid(), then what lock this particular locker is sleeping on
             ResourceId waitingResource;
+
+            // Lock timing statistics
+            LockStats stats;
         };
 
         virtual void getLockerInfo(LockerInfo* lockerInfo) const = 0;
diff --git a/src/mongo/db/currentop_command.cpp b/src/mongo/db/currentop_command.cpp
index 35cdf3e812b..0ff88ae479c 100644
--- a/src/mongo/db/currentop_command.cpp
+++ b/src/mongo/db/currentop_command.cpp
@@ -45,13 +45,6 @@
 #include "mongo/util/log.h"
 
 namespace mongo {
-namespace {
-
-    // Until we are able to resolve resource ids to db/collection names, report local db specially
-    const ResourceId resourceIdLocalDb = ResourceId(RESOURCE_DATABASE, std::string("local"));
-
-} // namespace
-
 
     void inProgCmd(OperationContext* txn, Message &message, DbResponse &dbresponse) {
         DbMessage d(message);
@@ -163,7 +156,7 @@ namespace {
         for (size_t i = 0; i < lockerInfo.locks.size(); i++) {
             const Locker::OneLock& lock = lockerInfo.locks[i];
 
-            if (resourceIdLocalDb == lock.resourceId) {
+            if (resourceIdLocalDB == lock.resourceId) {
                 locks.append("local", legacyModeName(lock.mode));
             }
             else {
@@ -177,9 +170,11 @@ namespace {
         infoBuilder.append("waitingForLock", lockerInfo.waitingResource.isValid());
 
         // "lockStats" section
-        BSONObjBuilder lockStats(infoBuilder.subobjStart("lockStats"));
-        // TODO: When we implement lock stats tracking
-        lockStats.done();
+        {
+            BSONObjBuilder lockStats(infoBuilder.subobjStart("lockStats"));
+            lockerInfo.stats.report(&lockStats);
+            lockStats.done();
+        }
     }
 
 } // namespace mongo