SERVER-5905 Add operation latency histogram

Signed-off-by: Kyle Suarez <kyle.suarez@mongodb.com>

6 files changed, 471 insertions, 5 deletions

diff --git a/src/mongo/db/stats/SConscript b/src/mongo/db/stats/SConscript
index 0dea68e45da..d2cd6f697e8 100644
--- a/src/mongo/db/stats/SConscript
+++ b/src/mongo/db/stats/SConscript
@@ -28,9 +28,12 @@ env.Library(
     target='top',
     source=[
         'top.cpp',
+        'operation_latency_histogram.cpp'
     ],
     LIBDEPS=[
         '$BUILD_DIR/mongo/db/service_context',
+        '$BUILD_DIR/mongo/db/commands/server_status_core',
+        '$BUILD_DIR/mongo/db/curop',
     ],
 )
 
@@ -44,6 +47,16 @@ env.CppUnitTest(
     ],
 )
 
+env.CppUnitTest(
+    target='operation_latency_histogram_test',
+    source=[
+        'operation_latency_histogram_test.cpp'
+        ],
+    LIBDEPS=[
+        '$BUILD_DIR/mongo/base',
+        '$BUILD_DIR/mongo/db/stats/top',
+        ])
+
 env.Library(
     target='counters',
     source=[
diff --git a/src/mongo/db/stats/operation_latency_histogram.cpp b/src/mongo/db/stats/operation_latency_histogram.cpp
new file mode 100644
index 00000000000..3b55b18af5a
--- /dev/null
+++ b/src/mongo/db/stats/operation_latency_histogram.cpp
@@ -0,0 +1,171 @@
+/**
+ * Copyright (C) 2016 MongoDB Inc.
+ *
+ * This program is free software: you can redistribute it and/or  modify
+ * it under the terms of the GNU Affero General Public License, version 3,
+ * as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * As a special exception, the copyright holders give permission to link the
+ * code of portions of this program with the OpenSSL library under certain
+ * conditions as described in each individual source file and distribute
+ * linked combinations including the program with the OpenSSL library. You
+ * must comply with the GNU Affero General Public License in all respects
+ * for all of the code used other than as permitted herein. If you modify
+ * file(s) with this exception, you may extend this exception to your
+ * version of the file(s), but you are not obligated to do so. If you do not
+ * wish to do so, delete this exception statement from your version. If you
+ * delete this exception statement from all source files in the program,
+ * then also delete it in the license file.
+ */
+
+#include "mongo/platform/basic.h"
+
+#include "mongo/db/stats/operation_latency_histogram.h"
+
+#include <algorithm>
+
+#include "mongo/bson/bsonobjbuilder.h"
+#include "mongo/db/namespace_string.h"
+#include "mongo/platform/bits.h"
+
+namespace mongo {
+
+const std::array<uint64_t, OperationLatencyHistogram::kMaxBuckets>
+    OperationLatencyHistogram::kLowerBounds = {0,
+                                               2,
+                                               4,
+                                               8,
+                                               16,
+                                               32,
+                                               64,
+                                               128,
+                                               256,
+                                               512,
+                                               1024,
+                                               2048,
+                                               3072,
+                                               4096,
+                                               6144,
+                                               8192,
+                                               12288,
+                                               16384,
+                                               24576,
+                                               32768,
+                                               49152,
+                                               65536,
+                                               98304,
+                                               131072,
+                                               196608,
+                                               262144,
+                                               393216,
+                                               524288,
+                                               786432,
+                                               1048576,
+                                               1572864,
+                                               2097152,
+                                               4194304,
+                                               8388608,
+                                               16777216,
+                                               33554432,
+                                               67108864,
+                                               134217728,
+                                               268435456,
+                                               536870912,
+                                               1073741824,
+                                               2147483648,
+                                               4294967296,
+                                               8589934592,
+                                               17179869184,
+                                               34359738368,
+                                               68719476736,
+                                               137438953472,
+                                               274877906944,
+                                               549755813888,
+                                               1099511627776};
+
+void OperationLatencyHistogram::_append(const HistogramData& data,
+                                        const char* key,
+                                        BSONObjBuilder* builder) const {
+
+    BSONObjBuilder histogramBuilder(builder->subobjStart(key));
+    BSONArrayBuilder arrayBuilder(histogramBuilder.subarrayStart("histogram"));
+    for (int i = 0; i < kMaxBuckets; i++) {
+        if (data.buckets[i] == 0)
+            continue;
+        BSONObjBuilder entryBuilder(arrayBuilder.subobjStart());
+        entryBuilder.append("micros", static_cast<long long>(kLowerBounds[i]));
+        entryBuilder.append("count", static_cast<long long>(data.buckets[i]));
+        entryBuilder.doneFast();
+    }
+
+    arrayBuilder.doneFast();
+    histogramBuilder.append("latency", static_cast<long long>(data.sum));
+    histogramBuilder.append("ops", static_cast<long long>(data.entryCount));
+    histogramBuilder.doneFast();
+}
+
+void OperationLatencyHistogram::append(BSONObjBuilder* builder) const {
+    _append(_reads, "reads", builder);
+    _append(_writes, "writes", builder);
+    _append(_commands, "commands", builder);
+}
+
+// Computes the log base 2 of value, and checks for cases of split buckets.
+int OperationLatencyHistogram::_getBucket(uint64_t value) {
+    // Zero is a special case since log(0) is undefined.
+    if (value == 0) {
+        return 0;
+    }
+
+    int log2 = 63 - countLeadingZeros64(value);
+    // Half splits occur in range [2^11, 2^21) giving 10 extra buckets.
+    if (log2 < 11) {
+        return log2;
+    } else if (log2 < 21) {
+        int extra = log2 - 11;
+        // Split value boundary is at (2^n + 2^(n+1))/2 = 2^n + 2^(n-1).
+        // Which corresponds to (1ULL << log2) | (1ULL << (log2 - 1))
+        // Which is equivalent to the following:
+        uint64_t splitBoundary = 3ULL << (log2 - 1);
+        if (value >= splitBoundary) {
+            extra++;
+        }
+        return log2 + extra;
+    } else {
+        // Add all of the extra 10 buckets.
+        return std::min(log2 + 10, kMaxBuckets - 1);
+    }
+}
+
+void OperationLatencyHistogram::_incrementData(uint64_t latency, int bucket, HistogramData* data) {
+    data->buckets[bucket]++;
+    data->entryCount++;
+    data->sum += latency;
+}
+
+void OperationLatencyHistogram::increment(uint64_t latency, Command::ReadWriteType type) {
+    int bucket = _getBucket(latency);
+    switch (type) {
+        case Command::ReadWriteType::kRead:
+            _incrementData(latency, bucket, &_reads);
+            break;
+        case Command::ReadWriteType::kWrite:
+            _incrementData(latency, bucket, &_writes);
+            break;
+        case Command::ReadWriteType::kCommand:
+            _incrementData(latency, bucket, &_commands);
+            break;
+        default:
+            MONGO_UNREACHABLE;
+    }
+}
+
+}  // namespace mongo
diff --git a/src/mongo/db/stats/operation_latency_histogram.h b/src/mongo/db/stats/operation_latency_histogram.h
new file mode 100644
index 00000000000..ca4ced82e02
--- /dev/null
+++ b/src/mongo/db/stats/operation_latency_histogram.h
@@ -0,0 +1,77 @@
+/**
+ * Copyright (C) 2016 MongoDB Inc.
+ *
+ * This program is free software: you can redistribute it and/or  modify
+ * it under the terms of the GNU Affero General Public License, version 3,
+ * as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * As a special exception, the copyright holders give permission to link the
+ * code of portions of this program with the OpenSSL library under certain
+ * conditions as described in each individual source file and distribute
+ * linked combinations including the program with the OpenSSL library. You
+ * must comply with the GNU Affero General Public License in all respects
+ * for all of the code used other than as permitted herein. If you modify
+ * file(s) with this exception, you may extend this exception to your
+ * version of the file(s), but you are not obligated to do so. If you do not
+ * wish to do so, delete this exception statement from your version. If you
+ * delete this exception statement from all source files in the program,
+ * then also delete it in the license file.
+ */
+#pragma once
+
+#include <array>
+
+#include "mongo/db/commands.h"
+
+namespace mongo {
+
+class BSONObjBuilder;
+
+/**
+ * Stores statistics for latencies of read, write, and command operations.
+ *
+ * Note: This class is not thread-safe.
+ */
+class OperationLatencyHistogram {
+public:
+    static const int kMaxBuckets = 51;
+
+    // Inclusive lower bounds of the histogram buckets.
+    static const std::array<uint64_t, kMaxBuckets> kLowerBounds;
+
+    /**
+     * Increments the bucket of the histogram based on the operation type.
+     */
+    void increment(uint64_t latency, Command::ReadWriteType type);
+
+    /**
+     * Appends the three histograms with latency totals and operation counts.
+     */
+    void append(BSONObjBuilder* builder) const;
+
+private:
+    struct HistogramData {
+        std::array<uint64_t, kMaxBuckets> buckets{};
+        uint64_t entryCount = 0;
+        uint64_t sum = 0;
+    };
+
+    static int _getBucket(uint64_t latency);
+
+    static uint64_t _getBucketMicros(int bucket);
+
+    void _append(const HistogramData& data, const char* key, BSONObjBuilder* builder) const;
+
+    void _incrementData(uint64_t latency, int bucket, HistogramData* data);
+
+    HistogramData _reads, _writes, _commands;
+};
+}  // namespace mongo
diff --git a/src/mongo/db/stats/operation_latency_histogram_test.cpp b/src/mongo/db/stats/operation_latency_histogram_test.cpp
new file mode 100644
index 00000000000..de14d809365
--- /dev/null
+++ b/src/mongo/db/stats/operation_latency_histogram_test.cpp
@@ -0,0 +1,92 @@
+/**
+ * Copyright (C) 2016 MongoDB Inc.
+ *
+ * This program is free software: you can redistribute it and/or  modify
+ * it under the terms of the GNU Affero General Public License, version 3,
+ * as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * As a special exception, the copyright holders give permission to link the
+ * code of portions of this program with the OpenSSL library under certain
+ * conditions as described in each individual source file and distribute
+ * linked combinations including the program with the OpenSSL library. You
+ * must comply with the GNU Affero General Public License in all respects
+ * for all of the code used other than as permitted herein. If you modify
+ * file(s) with this exception, you may extend this exception to your
+ * version of the file(s), but you are not obligated to do so. If you do not
+ * wish to do so, delete this exception statement from your version. If you
+ * delete this exception statement from all source files in the program,
+ * then also delete it in the license file.
+ */
+
+#include "mongo/platform/basic.h"
+
+#include "mongo/db/stats/operation_latency_histogram.h"
+
+#include <array>
+#include <iostream>
+#include <numeric>
+#include <vector>
+
+#include "mongo/db/commands.h"
+#include "mongo/db/jsobj.h"
+#include "mongo/unittest/unittest.h"
+
+namespace mongo {
+
+namespace {
+const int kMaxBuckets = OperationLatencyHistogram::kMaxBuckets;
+const std::array<uint64_t, kMaxBuckets>& kLowerBounds = OperationLatencyHistogram::kLowerBounds;
+}  // namespace
+
+TEST(OperationLatencyHistogram, EnsureIncrementsStored) {
+    OperationLatencyHistogram hist;
+    for (int i = 0; i < kMaxBuckets; i++) {
+        hist.increment(i, Command::ReadWriteType::kRead);
+        hist.increment(i, Command::ReadWriteType::kWrite);
+        hist.increment(i, Command::ReadWriteType::kCommand);
+    }
+    BSONObjBuilder outBuilder;
+    hist.append(&outBuilder);
+    BSONObj out = outBuilder.done();
+    ASSERT_EQUALS(out["reads"]["ops"].Long(), kMaxBuckets);
+    ASSERT_EQUALS(out["writes"]["ops"].Long(), kMaxBuckets);
+    ASSERT_EQUALS(out["commands"]["ops"].Long(), kMaxBuckets);
+}
+
+TEST(OperationLatencyHistogram, CheckBucketCountsAndTotalLatency) {
+    OperationLatencyHistogram hist;
+    // Increment at the boundary, boundary+1, and boundary-1.
+    for (int i = 0; i < kMaxBuckets; i++) {
+        hist.increment(kLowerBounds[i], Command::ReadWriteType::kRead);
+        hist.increment(kLowerBounds[i] + 1, Command::ReadWriteType::kRead);
+        if (i > 0) {
+            hist.increment(kLowerBounds[i] - 1, Command::ReadWriteType::kRead);
+        }
+    }
+
+    // The additional +1 because of the first boundary.
+    uint64_t expectedSum = 3 * std::accumulate(kLowerBounds.begin(), kLowerBounds.end(), 0ULL) + 1;
+    BSONObjBuilder outBuilder;
+    hist.append(&outBuilder);
+    BSONObj out = outBuilder.done();
+    ASSERT_EQUALS(static_cast<uint64_t>(out["reads"]["latency"].Long()), expectedSum);
+
+    // Each bucket has three counts with the exception of the last bucket, which has two.
+    ASSERT_EQUALS(out["reads"]["ops"].Long(), 3 * kMaxBuckets - 1);
+    std::vector<BSONElement> readBuckets = out["reads"]["histogram"].Array();
+    ASSERT_EQUALS(readBuckets.size(), static_cast<unsigned int>(kMaxBuckets));
+    for (int i = 0; i < kMaxBuckets; i++) {
+        BSONObj bucket = readBuckets[i].Obj();
+        ASSERT_EQUALS(static_cast<uint64_t>(bucket["micros"].Long()), kLowerBounds[i]);
+        ASSERT_EQUALS(bucket["count"].Long(), (i < kMaxBuckets - 1) ? 3 : 2);
+    }
+}
+}  // namespace mongo
diff --git a/src/mongo/db/stats/top.cpp b/src/mongo/db/stats/top.cpp
index be251870d94..3cfb01fd386 100644
--- a/src/mongo/db/stats/top.cpp
+++ b/src/mongo/db/stats/top.cpp
@@ -33,6 +33,8 @@
 
 #include "mongo/db/stats/top.h"
 
+#include "mongo/db/commands/server_status_metric.h"
+#include "mongo/db/curop.h"
 #include "mongo/db/jsobj.h"
 #include "mongo/db/service_context.h"
 #include "mongo/util/log.h"
@@ -72,7 +74,12 @@ Top& Top::get(ServiceContext* service) {
     return getTop(service);
 }
 
-void Top::record(StringData ns, LogicalOp logicalOp, int lockType, long long micros, bool command) {
+void Top::record(OperationContext* txn,
+                 StringData ns,
+                 LogicalOp logicalOp,
+                 int lockType,
+                 long long micros,
+                 bool command) {
     if (ns[0] == '?')
         return;
 
@@ -87,10 +94,14 @@ void Top::record(StringData ns, LogicalOp logicalOp, int lockType, long long mic
     }
 
     CollectionData& coll = _usage[hashedNs];
-    _record(coll, logicalOp, lockType, micros);
+    _record(txn, coll, logicalOp, lockType, micros);
 }
 
-void Top::_record(CollectionData& c, LogicalOp logicalOp, int lockType, long long micros) {
+void Top::_record(
+    OperationContext* txn, CollectionData& c, LogicalOp logicalOp, int lockType, long long micros) {
+
+    _incrementHistogram(txn, micros, &c.opLatencyHistogram);
+
     c.total.inc(micros);
 
     if (lockType > 0)
@@ -180,4 +191,66 @@ void Top::_appendStatsEntry(BSONObjBuilder& b, const char* statsName, const Usag
     bb.appendNumber("count", map.count);
     bb.done();
 }
+
+void Top::appendLatencyStats(StringData ns, BSONObjBuilder* builder) {
+    auto hashedNs = UsageMap::HashedKey(ns);
+    stdx::lock_guard<SimpleMutex> lk(_lock);
+    BSONObjBuilder latencyStatsBuilder;
+    _usage[hashedNs].opLatencyHistogram.append(&latencyStatsBuilder);
+    builder->append("latencyStats", latencyStatsBuilder.obj());
+}
+
+void Top::incrementGlobalLatencyStats(OperationContext* txn, uint64_t latency) {
+    stdx::lock_guard<SimpleMutex> guard(_lock);
+    _incrementHistogram(txn, latency, &_globalHistogramStats);
+}
+
+void Top::appendGlobalLatencyStats(BSONObjBuilder* builder) {
+    stdx::lock_guard<SimpleMutex> guard(_lock);
+    _globalHistogramStats.append(builder);
+}
+
+Command::ReadWriteType Top::_getReadWriteType(Command* cmd, LogicalOp logicalOp) {
+    // For legacy operations, cmd may be a nullptr.
+    if (cmd) {
+        return cmd->getReadWriteType();
+    }
+    switch (logicalOp) {
+        case LogicalOp::opGetMore:
+        case LogicalOp::opQuery:
+            return Command::ReadWriteType::kRead;
+        case LogicalOp::opUpdate:
+        case LogicalOp::opInsert:
+        case LogicalOp::opDelete:
+            return Command::ReadWriteType::kWrite;
+        default:
+            return Command::ReadWriteType::kCommand;
+    }
+}
+
+void Top::_incrementHistogram(OperationContext* txn,
+                              long long latency,
+                              OperationLatencyHistogram* histogram) {
+    // Only update histogram if operation came from a user.
+    Client* client = txn->getClient();
+    if (client->isFromUserConnection() && !client->isInDirectClient()) {
+        CurOp* curOp = CurOp::get(txn);
+        Command* cmd = curOp->getCommand();
+        Command::ReadWriteType readWriteType = _getReadWriteType(cmd, curOp->getLogicalOp());
+        histogram->increment(latency, readWriteType);
+    }
 }
+
+/**
+ * Appends the global histogram to the server status.
+ */
+class GlobalHistogramServerStatusMetric : public ServerStatusMetric {
+public:
+    GlobalHistogramServerStatusMetric() : ServerStatusMetric(".metrics.latency") {}
+    virtual void appendAtLeaf(BSONObjBuilder& builder) const {
+        BSONObjBuilder latencyBuilder;
+        Top::get(getGlobalServiceContext()).appendGlobalLatencyStats(&latencyBuilder);
+        builder.append("latency", latencyBuilder.obj());
+    }
+} globalHistogramServerStatusMetric;
+}  // namespace mongo
diff --git a/src/mongo/db/stats/top.h b/src/mongo/db/stats/top.h
index eb7f6ab9872..6a58f7d6f7f 100644
--- a/src/mongo/db/stats/top.h
+++ b/src/mongo/db/stats/top.h
@@ -31,6 +31,9 @@
 
 #include <boost/date_time/posix_time/posix_time.hpp>
 
+#include "mongo/db/commands.h"
+#include "mongo/db/operation_context.h"
+#include "mongo/db/stats/operation_latency_histogram.h"
 #include "mongo/util/concurrency/mutex.h"
 #include "mongo/util/net/message.h"
 #include "mongo/util/string_map.h"
@@ -78,22 +81,59 @@ public:
         UsageData update;
         UsageData remove;
         UsageData commands;
+        OperationLatencyHistogram opLatencyHistogram;
     };
 
     typedef StringMap<CollectionData> UsageMap;
 
 public:
-    void record(StringData ns, LogicalOp logicalOp, int lockType, long long micros, bool command);
+    void record(OperationContext* txn,
+                StringData ns,
+                LogicalOp logicalOp,
+                int lockType,
+                long long micros,
+                bool command);
+
     void append(BSONObjBuilder& b);
+
     void cloneMap(UsageMap& out) const;
+
     void collectionDropped(StringData ns);
 
+    /**
+     * Appends the collection-level latency statistics
+     */
+    void appendLatencyStats(StringData ns, BSONObjBuilder* builder);
+
+    /**
+     * Increments the global histogram.
+     */
+    void incrementGlobalLatencyStats(OperationContext* txn, uint64_t latency);
+
+    /**
+     * Appends the global latency statistics.
+     */
+    void appendGlobalLatencyStats(BSONObjBuilder* builder);
+
 private:
+    static Command::ReadWriteType _getReadWriteType(Command* cmd, LogicalOp logicalOp);
+
     void _appendToUsageMap(BSONObjBuilder& b, const UsageMap& map) const;
+
     void _appendStatsEntry(BSONObjBuilder& b, const char* statsName, const UsageData& map) const;
-    void _record(CollectionData& c, LogicalOp logicalOp, int lockType, long long micros);
+
+    void _record(OperationContext* txn,
+                 CollectionData& c,
+                 LogicalOp logicalOp,
+                 int lockType,
+                 long long micros);
+
+    void _incrementHistogram(OperationContext* txn,
+                             long long latency,
+                             OperationLatencyHistogram* histogram);
 
     mutable SimpleMutex _lock;
+    OperationLatencyHistogram _globalHistogramStats;
     UsageMap _usage;
     std::string _lastDropped;
 };