summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorKevin Albertson <kevin.albertson@10gen.com>2016-06-23 11:49:38 -0400
committerKyle Suarez <kyle.suarez@mongodb.com>2016-06-23 17:47:06 -0400
commitc7794350b056cdea85e1c6185a7dda4579936179 (patch)
treee310fe6e872390cdfe18ab756c51aab1e34a064c
parentacb5215fd12e5d018bfec9207d9a18dd35df65a6 (diff)
downloadmongo-c7794350b056cdea85e1c6185a7dda4579936179.tar.gz
SERVER-5905 Add operation latency histogram
Signed-off-by: Kyle Suarez <kyle.suarez@mongodb.com>
-rw-r--r--jstests/noPassthrough/global_operation_latency_histogram.js164
-rw-r--r--src/mongo/db/SConscript1
-rw-r--r--src/mongo/db/commands.h12
-rw-r--r--src/mongo/db/commands/count_cmd.cpp12
-rw-r--r--src/mongo/db/commands/distinct.cpp7
-rw-r--r--src/mongo/db/commands/find_and_modify.cpp7
-rw-r--r--src/mongo/db/commands/find_cmd.cpp4
-rw-r--r--src/mongo/db/commands/geo_near_cmd.cpp4
-rw-r--r--src/mongo/db/commands/getmore_cmd.cpp4
-rw-r--r--src/mongo/db/commands/group_cmd.cpp4
-rw-r--r--src/mongo/db/commands/parallel_collection_scan.cpp4
-rw-r--r--src/mongo/db/commands/pipeline_command.cpp8
-rw-r--r--src/mongo/db/commands/write_commands/write_commands.cpp4
-rw-r--r--src/mongo/db/db_raii.cpp6
-rw-r--r--src/mongo/db/geo/haystack.cpp7
-rw-r--r--src/mongo/db/instance.cpp3
-rw-r--r--src/mongo/db/ops/write_ops_exec.cpp20
-rw-r--r--src/mongo/db/stats/SConscript13
-rw-r--r--src/mongo/db/stats/operation_latency_histogram.cpp171
-rw-r--r--src/mongo/db/stats/operation_latency_histogram.h77
-rw-r--r--src/mongo/db/stats/operation_latency_histogram_test.cpp92
-rw-r--r--src/mongo/db/stats/top.cpp79
-rw-r--r--src/mongo/db/stats/top.h44
23 files changed, 737 insertions, 10 deletions
diff --git a/jstests/noPassthrough/global_operation_latency_histogram.js b/jstests/noPassthrough/global_operation_latency_histogram.js
new file mode 100644
index 00000000000..cc4333eb22c
--- /dev/null
+++ b/jstests/noPassthrough/global_operation_latency_histogram.js
@@ -0,0 +1,164 @@
+// Checks that global histogram counters for collections are updated as we expect.
+
+(function() {
+ "use strict";
+ var name = "operationalLatencyHistogramTest";
+
+ var mongo = MongoRunner.runMongod({master: ""});
+ var testDB = mongo.getDB("test");
+ var testColl = testDB[name + "coll"];
+
+ testColl.drop();
+
+ function getHistogramStats() {
+ return testDB.serverStatus().metrics.latency;
+ }
+
+ var lastHistogram = getHistogramStats();
+
+ // Checks that the difference in the histogram is what we expect, and also
+ // accounts for the serverStatus command itself.
+ function checkHistogramDiff(reads, writes, commands) {
+ var thisHistogram = getHistogramStats();
+ assert.eq(thisHistogram.reads.ops - lastHistogram.reads.ops, reads);
+ assert.eq(thisHistogram.writes.ops - lastHistogram.writes.ops, writes);
+ // Running the server status itself will increment command stats by one.
+ assert.eq(thisHistogram.commands.ops - lastHistogram.commands.ops, commands + 1);
+ return thisHistogram;
+ }
+
+ // Insert
+ var numRecords = 100;
+ for (var i = 0; i < numRecords; i++) {
+ assert.writeOK(testColl.insert({_id: i}));
+ }
+ lastHistogram = checkHistogramDiff(0, numRecords, 0);
+
+ // Update
+ for (var i = 0; i < numRecords; i++) {
+ assert.writeOK(testColl.update({_id: i}, {x: i}));
+ }
+ lastHistogram = checkHistogramDiff(0, numRecords, 0);
+
+ // Find
+ var cursors = [];
+ for (var i = 0; i < numRecords; i++) {
+ cursors[i] = testColl.find({x: {$gte: i}}).batchSize(2);
+ assert.eq(cursors[i].next()._id, i);
+ }
+ lastHistogram = checkHistogramDiff(numRecords, 0, 0);
+
+ // GetMore
+ for (var i = 0; i < numRecords / 2; i++) {
+ // Trigger two getmore commands.
+ assert.eq(cursors[i].next()._id, i + 1);
+ assert.eq(cursors[i].next()._id, i + 2);
+ assert.eq(cursors[i].next()._id, i + 3);
+ assert.eq(cursors[i].next()._id, i + 4);
+ }
+ lastHistogram = checkHistogramDiff(numRecords, 0, 0);
+
+ // KillCursors
+ // The last cursor has no additional results, hence does not need to be closed.
+ for (var i = 0; i < numRecords - 1; i++) {
+ cursors[i].close();
+ }
+ lastHistogram = checkHistogramDiff(0, 0, numRecords - 1);
+
+ // Remove
+ for (var i = 0; i < numRecords; i++) {
+ assert.writeOK(testColl.remove({_id: i}));
+ }
+ lastHistogram = checkHistogramDiff(0, numRecords, 0);
+
+ // Upsert
+ for (var i = 0; i < numRecords; i++) {
+ assert.writeOK(testColl.update({_id: i}, {x: i}, {upsert: 1}));
+ }
+ lastHistogram = checkHistogramDiff(0, numRecords, 0);
+
+ // Aggregate
+ for (var i = 0; i < numRecords; i++) {
+ testColl.aggregate([{$match: {x: i}}, {$group: {_id: "$x"}}]);
+ }
+ lastHistogram = checkHistogramDiff(numRecords, 0, 0);
+
+ // Count
+ for (var i = 0; i < numRecords; i++) {
+ testColl.count({x: i});
+ }
+ lastHistogram = checkHistogramDiff(numRecords, 0, 0);
+
+ // Group
+ testColl.group({initial: {}, reduce: function() {}, key: {a: 1}});
+ lastHistogram = checkHistogramDiff(1, 0, 0);
+
+ // ParallelCollectionScan
+ testDB.runCommand({parallelCollectionScan: testColl.getName(), numCursors: 5});
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // FindAndModify
+ testColl.findAndModify({query: {}, update: {pt: {type: "Point", coordinates: [0, 0]}}});
+ lastHistogram = checkHistogramDiff(0, 1, 0);
+
+ // CreateIndex
+ assert.commandWorked(testColl.createIndex({pt: "2dsphere"}));
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // GeoNear
+ assert.commandWorked(testDB.runCommand({
+ geoNear: testColl.getName(),
+ near: {type: "Point", coordinates: [0, 0]},
+ spherical: true
+ }));
+ lastHistogram = checkHistogramDiff(1, 0, 0);
+
+ // GetIndexes
+ testColl.getIndexes();
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // Reindex
+ assert.commandWorked(testColl.reIndex());
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // DropIndex
+ assert.commandWorked(testColl.dropIndex({pt: "2dsphere"}));
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // Explain
+ testColl.explain().find().next();
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // CollStats
+ assert.commandWorked(testDB.runCommand({collStats: testColl.getName()}));
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // CollMod
+ assert.commandWorked(
+ testDB.runCommand({collStats: testColl.getName(), validationLevel: "off"}));
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // Compact
+ assert.commandWorked(testDB.runCommand({compact: testColl.getName()}));
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // DataSize
+ testColl.dataSize();
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // PlanCache
+ testColl.getPlanCache().listQueryShapes();
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // ServerStatus
+ assert.commandWorked(testDB.serverStatus());
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // WhatsMyURI
+ assert.commandWorked(testColl.runCommand("whatsmyuri"));
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+
+ // Test non-command.
+ assert.commandFailed(testColl.runCommand("IHopeNobodyEverMakesThisACommand"));
+ lastHistogram = checkHistogramDiff(0, 0, 1);
+}()); \ No newline at end of file
diff --git a/src/mongo/db/SConscript b/src/mongo/db/SConscript
index 925885ee3fe..83ca9eb0139 100644
--- a/src/mongo/db/SConscript
+++ b/src/mongo/db/SConscript
@@ -153,7 +153,6 @@ env.Library(
],
LIBDEPS=[
'$BUILD_DIR/mongo/bson/mutable/mutable_bson',
- '$BUILD_DIR/mongo/db/commands',
'$BUILD_DIR/mongo/db/concurrency/lock_manager',
'$BUILD_DIR/mongo/db/service_context',
'$BUILD_DIR/mongo/db/query/command_request_response',
diff --git a/src/mongo/db/commands.h b/src/mongo/db/commands.h
index 874f728ae21..139f344089e 100644
--- a/src/mongo/db/commands.h
+++ b/src/mongo/db/commands.h
@@ -78,6 +78,8 @@ protected:
public:
typedef StringMap<Command*> CommandMap;
+ enum class ReadWriteType { kCommand, kRead, kWrite };
+
/**
* Constructs a new command and causes it to be registered with the global commands list. It is
* not safe to construct commands other than when the server is starting up.
@@ -268,6 +270,16 @@ public:
return LogicalOp::opCommand;
}
+ /**
+ * Returns whether this operation is a read, write, or command.
+ *
+ * Commands which implement database read or write logic should override this to return kRead
+ * or kWrite as appropriate.
+ */
+ virtual ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kCommand;
+ }
+
protected:
/**
* Appends to "*out" the privileges required to run this command on database "dbname" with
diff --git a/src/mongo/db/commands/count_cmd.cpp b/src/mongo/db/commands/count_cmd.cpp
index d74af1b9a95..b406e861b22 100644
--- a/src/mongo/db/commands/count_cmd.cpp
+++ b/src/mongo/db/commands/count_cmd.cpp
@@ -56,28 +56,40 @@ using std::stringstream;
class CmdCount : public Command {
public:
CmdCount() : Command("count") {}
+
virtual bool supportsWriteConcern(const BSONObj& cmd) const override {
return false;
}
+
virtual bool slaveOk() const {
// ok on --slave setups
return repl::getGlobalReplicationCoordinator()->getSettings().isSlave();
}
+
virtual bool slaveOverrideOk() const {
return true;
}
+
virtual bool maintenanceOk() const {
return false;
}
+
virtual bool adminOnly() const {
return false;
}
+
bool supportsReadConcern() const final {
return true;
}
+
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kRead;
+ }
+
virtual void help(stringstream& help) const {
help << "count objects in collection";
}
+
virtual void addRequiredPrivileges(const std::string& dbname,
const BSONObj& cmdObj,
std::vector<Privilege>* out) {
diff --git a/src/mongo/db/commands/distinct.cpp b/src/mongo/db/commands/distinct.cpp
index 42993e0b99d..66e9b924670 100644
--- a/src/mongo/db/commands/distinct.cpp
+++ b/src/mongo/db/commands/distinct.cpp
@@ -81,16 +81,23 @@ public:
virtual bool slaveOk() const {
return false;
}
+
virtual bool slaveOverrideOk() const {
return true;
}
+
virtual bool supportsWriteConcern(const BSONObj& cmd) const override {
return false;
}
+
bool supportsReadConcern() const final {
return true;
}
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kRead;
+ }
+
std::size_t reserveBytesForReply() const override {
return FindCommon::kInitReplyBufferSize;
}
diff --git a/src/mongo/db/commands/find_and_modify.cpp b/src/mongo/db/commands/find_and_modify.cpp
index a31e16e8c32..6d28c2eabe9 100644
--- a/src/mongo/db/commands/find_and_modify.cpp
+++ b/src/mongo/db/commands/find_and_modify.cpp
@@ -215,18 +215,25 @@ public:
}
CmdFindAndModify() : Command("findAndModify", false, "findandmodify") {}
+
bool slaveOk() const override {
return false;
}
+
virtual bool supportsWriteConcern(const BSONObj& cmd) const override {
return true;
}
+
void addRequiredPrivileges(const std::string& dbname,
const BSONObj& cmdObj,
std::vector<Privilege>* out) override {
find_and_modify::addPrivilegesRequiredForFindAndModify(this, dbname, cmdObj, out);
}
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kWrite;
+ }
+
Status explain(OperationContext* txn,
const std::string& dbName,
const BSONObj& cmdObj,
diff --git a/src/mongo/db/commands/find_cmd.cpp b/src/mongo/db/commands/find_cmd.cpp
index 83844e619a3..7f10d506c23 100644
--- a/src/mongo/db/commands/find_cmd.cpp
+++ b/src/mongo/db/commands/find_cmd.cpp
@@ -104,6 +104,10 @@ public:
return LogicalOp::opQuery;
}
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kRead;
+ }
+
std::size_t reserveBytesForReply() const override {
return FindCommon::kInitReplyBufferSize;
}
diff --git a/src/mongo/db/commands/geo_near_cmd.cpp b/src/mongo/db/commands/geo_near_cmd.cpp
index 1fb9cd3cdeb..5f0433576bb 100644
--- a/src/mongo/db/commands/geo_near_cmd.cpp
+++ b/src/mongo/db/commands/geo_near_cmd.cpp
@@ -78,6 +78,10 @@ public:
return true;
}
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kRead;
+ }
+
std::size_t reserveBytesForReply() const override {
return FindCommon::kInitReplyBufferSize;
}
diff --git a/src/mongo/db/commands/getmore_cmd.cpp b/src/mongo/db/commands/getmore_cmd.cpp
index 9ae0a69460c..ac11e131c77 100644
--- a/src/mongo/db/commands/getmore_cmd.cpp
+++ b/src/mongo/db/commands/getmore_cmd.cpp
@@ -102,6 +102,10 @@ public:
return false;
}
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kRead;
+ }
+
void help(std::stringstream& help) const override {
help << "retrieve more results from an existing cursor";
}
diff --git a/src/mongo/db/commands/group_cmd.cpp b/src/mongo/db/commands/group_cmd.cpp
index d2c9cefa154..c721a2d0266 100644
--- a/src/mongo/db/commands/group_cmd.cpp
+++ b/src/mongo/db/commands/group_cmd.cpp
@@ -82,6 +82,10 @@ private:
return true;
}
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kRead;
+ }
+
std::size_t reserveBytesForReply() const override {
return FindCommon::kInitReplyBufferSize;
}
diff --git a/src/mongo/db/commands/parallel_collection_scan.cpp b/src/mongo/db/commands/parallel_collection_scan.cpp
index 2dfe8fdf614..97463f6cef5 100644
--- a/src/mongo/db/commands/parallel_collection_scan.cpp
+++ b/src/mongo/db/commands/parallel_collection_scan.cpp
@@ -69,6 +69,10 @@ public:
return true;
}
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kCommand;
+ }
+
virtual Status checkAuthForCommand(ClientBasic* client,
const std::string& dbname,
const BSONObj& cmdObj) {
diff --git a/src/mongo/db/commands/pipeline_command.cpp b/src/mongo/db/commands/pipeline_command.cpp
index 47d116e343a..b5c49095b9f 100644
--- a/src/mongo/db/commands/pipeline_command.cpp
+++ b/src/mongo/db/commands/pipeline_command.cpp
@@ -165,15 +165,23 @@ public:
virtual bool supportsWriteConcern(const BSONObj& cmd) const override {
return Pipeline::aggSupportsWriteConcern(cmd);
}
+
virtual bool slaveOk() const {
return false;
}
+
virtual bool slaveOverrideOk() const {
return true;
}
+
bool supportsReadConcern() const final {
return true;
}
+
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kRead;
+ }
+
virtual void help(stringstream& help) const {
help << "{ pipeline: [ { $operator: {...}}, ... ]"
<< ", explain: <bool>"
diff --git a/src/mongo/db/commands/write_commands/write_commands.cpp b/src/mongo/db/commands/write_commands/write_commands.cpp
index 653d8552a6b..97f2996baad 100644
--- a/src/mongo/db/commands/write_commands/write_commands.cpp
+++ b/src/mongo/db/commands/write_commands/write_commands.cpp
@@ -203,6 +203,10 @@ public:
return true;
}
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kWrite;
+ }
+
bool run(OperationContext* txn,
const std::string& dbname,
BSONObj& cmdObj,
diff --git a/src/mongo/db/db_raii.cpp b/src/mongo/db/db_raii.cpp
index f1bc7208092..c945912363f 100644
--- a/src/mongo/db/db_raii.cpp
+++ b/src/mongo/db/db_raii.cpp
@@ -109,7 +109,8 @@ AutoGetCollectionForRead::~AutoGetCollectionForRead() {
// Report time spent in read lock
auto currentOp = CurOp::get(_txn);
Top::get(_txn->getClient()->getServiceContext())
- .record(currentOp->getNS(),
+ .record(_txn,
+ currentOp->getNS(),
currentOp->getLogicalOp(),
-1, // "read locked"
_timer.micros(),
@@ -206,7 +207,8 @@ OldClientContext::~OldClientContext() {
auto currentOp = CurOp::get(_txn);
Top::get(_txn->getClient()->getServiceContext())
- .record(currentOp->getNS(),
+ .record(_txn,
+ currentOp->getNS(),
currentOp->getLogicalOp(),
_txn->lockState()->isWriteLocked() ? 1 : -1,
_timer.micros(),
diff --git a/src/mongo/db/geo/haystack.cpp b/src/mongo/db/geo/haystack.cpp
index 6e736ca91ea..e4010b2ff1d 100644
--- a/src/mongo/db/geo/haystack.cpp
+++ b/src/mongo/db/geo/haystack.cpp
@@ -65,16 +65,23 @@ public:
virtual bool supportsWriteConcern(const BSONObj& cmd) const override {
return false;
}
+
bool slaveOk() const {
return true;
}
+
bool slaveOverrideOk() const {
return true;
}
+
bool supportsReadConcern() const final {
return true;
}
+ ReadWriteType getReadWriteType() const {
+ return ReadWriteType::kRead;
+ }
+
std::size_t reserveBytesForReply() const override {
return FindCommon::kInitReplyBufferSize;
}
diff --git a/src/mongo/db/instance.cpp b/src/mongo/db/instance.cpp
index d3d1a1c34de..4858d50b4ce 100644
--- a/src/mongo/db/instance.cpp
+++ b/src/mongo/db/instance.cpp
@@ -71,6 +71,7 @@
#include "mongo/db/s/sharding_state.h"
#include "mongo/db/service_context.h"
#include "mongo/db/stats/counters.h"
+#include "mongo/db/stats/top.h"
#include "mongo/db/storage/storage_engine.h"
#include "mongo/db/storage/storage_options.h"
#include "mongo/platform/atomic_word.h"
@@ -686,6 +687,8 @@ void assembleResponse(OperationContext* txn,
debug.executionTime = currentOp.totalTimeMillis();
logThreshold += currentOp.getExpectedLatencyMs();
+ Top::get(txn->getServiceContext())
+ .incrementGlobalLatencyStats(txn, currentOp.totalTimeMicros());
if (shouldLogOpDebug || debug.executionTime > logThreshold) {
Locker::LockerInfo lockerInfo;
diff --git a/src/mongo/db/ops/write_ops_exec.cpp b/src/mongo/db/ops/write_ops_exec.cpp
index 5371736b7bd..06dd98eb274 100644
--- a/src/mongo/db/ops/write_ops_exec.cpp
+++ b/src/mongo/db/ops/write_ops_exec.cpp
@@ -86,7 +86,8 @@ void finishCurOp(OperationContext* txn, CurOp* curOp) {
recordCurOpMetrics(txn);
Top::get(txn->getServiceContext())
- .record(curOp->getNS(),
+ .record(txn,
+ curOp->getNS(),
curOp->getLogicalOp(),
1, // "write locked"
curOp->totalTimeMicros(),
@@ -392,7 +393,8 @@ WriteResult performInserts(OperationContext* txn, const InsertOp& wholeOp) {
// top-level curOp. The rest is handled by the top-level entrypoint.
curOp.done();
Top::get(txn->getServiceContext())
- .record(wholeOp.ns.ns(),
+ .record(txn,
+ wholeOp.ns.ns(),
LogicalOp::opInsert,
1 /* write locked*/,
curOp.totalTimeMicros(),
@@ -552,7 +554,14 @@ WriteResult performUpdates(OperationContext* txn, const UpdateOp& wholeOp) {
out.results.reserve(wholeOp.updates.size());
for (auto&& singleOp : wholeOp.updates) {
// TODO: don't create nested CurOp for legacy writes.
+ // Add Command pointer to the nested CurOp.
+ auto& parentCurOp = *CurOp::get(txn);
+ Command* cmd = parentCurOp.getCommand();
CurOp curOp(txn);
+ {
+ stdx::lock_guard<Client>(*txn->getClient());
+ curOp.setCommand_inlock(cmd);
+ }
ON_BLOCK_EXIT([&] { finishCurOp(txn, &curOp); });
try {
lastOpFixer.startingOp();
@@ -647,7 +656,14 @@ WriteResult performDeletes(OperationContext* txn, const DeleteOp& wholeOp) {
out.results.reserve(wholeOp.deletes.size());
for (auto&& singleOp : wholeOp.deletes) {
// TODO: don't create nested CurOp for legacy writes.
+ // Add Command pointer to the nested CurOp.
+ auto& parentCurOp = *CurOp::get(txn);
+ Command* cmd = parentCurOp.getCommand();
CurOp curOp(txn);
+ {
+ stdx::lock_guard<Client>(*txn->getClient());
+ curOp.setCommand_inlock(cmd);
+ }
ON_BLOCK_EXIT([&] { finishCurOp(txn, &curOp); });
try {
lastOpFixer.startingOp();
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;
};