diff options
24 files changed, 761 insertions, 14 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..7b06776cf44 --- /dev/null +++ b/jstests/noPassthrough/global_operation_latency_histogram.js @@ -0,0 +1,168 @@ +// 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 + var commandResult = testDB.runCommand({compact: testColl.getName()}); + // If storage engine supports compact, it should count as a command. + if (!commandResult.ok) { + assert.commandFailedWithCode(commandResult, ErrorCodes.CommandNotSupported); + } + 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/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 247c9f0e802..c0b0e5fd833 100644 --- a/src/mongo/db/commands/pipeline_command.cpp +++ b/src/mongo/db/commands/pipeline_command.cpp @@ -201,15 +201,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/curop.cpp b/src/mongo/db/curop.cpp index 9562f3dff0e..c76ba86105a 100644 --- a/src/mongo/db/curop.cpp +++ b/src/mongo/db/curop.cpp @@ -280,6 +280,23 @@ void CurOp::raiseDbProfileLevel(int dbProfileLevel) { _dbprofile = std::max(dbProfileLevel, _dbprofile); } +Command::ReadWriteType CurOp::getReadWriteType() const { + if (_command) { + return _command->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; + } +} + namespace { /** * Appends {name: obj} to the provided builder. If obj is greater than maxSize, appends a diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h index fc8612f7acc..d362fb0345d 100644 --- a/src/mongo/db/curop.h +++ b/src/mongo/db/curop.h @@ -32,6 +32,7 @@ #pragma once #include "mongo/base/disallow_copying.h" +#include "mongo/db/commands.h" #include "mongo/db/operation_context.h" #include "mongo/db/server_options.h" #include "mongo/platform/atomic_word.h" @@ -42,7 +43,6 @@ namespace mongo { class Client; -class Command; class CurOp; class OperationContext; struct PlanSummaryStats; @@ -316,6 +316,11 @@ public: } /** + * Returns whether the current operation is a read, write, or command. + */ + Command::ReadWriteType getReadWriteType() const; + + /** * Appends information about this CurOp to "builder". * * If called from a thread other than the one executing the operation associated with this diff --git a/src/mongo/db/db_raii.cpp b/src/mongo/db/db_raii.cpp index f1bc7208092..945dee16aab 100644 --- a/src/mongo/db/db_raii.cpp +++ b/src/mongo/db/db_raii.cpp @@ -109,11 +109,13 @@ 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(), - currentOp->isCommand()); + currentOp->isCommand(), + currentOp->getReadWriteType()); } void AutoGetCollectionForRead::_ensureMajorityCommittedSnapshotIsValid(const NamespaceString& nss) { @@ -206,11 +208,13 @@ 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(), - currentOp->isCommand()); + currentOp->isCommand(), + currentOp->getReadWriteType()); } 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..43fcee9df85 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,9 @@ void assembleResponse(OperationContext* txn, debug.executionTime = currentOp.totalTimeMillis(); logThreshold += currentOp.getExpectedLatencyMs(); + Top::get(txn->getServiceContext()) + .incrementGlobalLatencyStats( + txn, currentOp.totalTimeMicros(), currentOp.getReadWriteType()); 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..6e71e278d4d 100644 --- a/src/mongo/db/ops/write_ops_exec.cpp +++ b/src/mongo/db/ops/write_ops_exec.cpp @@ -86,11 +86,13 @@ 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(), - curOp->isCommand()); + curOp->isCommand(), + curOp->getReadWriteType()); if (!curOp->debug().exceptionInfo.empty()) { LOG(3) << "Caught Assertion in " << logicalOpToString(curOp->getLogicalOp()) << ": " @@ -392,11 +394,13 @@ 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(), - curOp.isCommand()); + curOp.isCommand(), + curOp.getReadWriteType()); }); @@ -552,7 +556,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 +658,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..be3a5dfe0e0 100644 --- a/src/mongo/db/stats/SConscript +++ b/src/mongo/db/stats/SConscript @@ -28,9 +28,11 @@ 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', ], ) @@ -44,6 +46,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..6fafb8f4aac 100644 --- a/src/mongo/db/stats/top.cpp +++ b/src/mongo/db/stats/top.cpp @@ -33,6 +33,7 @@ #include "mongo/db/stats/top.h" +#include "mongo/db/commands/server_status_metric.h" #include "mongo/db/jsobj.h" #include "mongo/db/service_context.h" #include "mongo/util/log.h" @@ -72,7 +73,13 @@ 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, + Command::ReadWriteType readWriteType) { if (ns[0] == '?') return; @@ -87,10 +94,18 @@ 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, readWriteType); } -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, + Command::ReadWriteType readWriteType) { + + _incrementHistogram(txn, micros, &c.opLatencyHistogram, readWriteType); + c.total.inc(micros); if (lockType > 0) @@ -180,4 +195,48 @@ 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, + Command::ReadWriteType readWriteType) { + stdx::lock_guard<SimpleMutex> guard(_lock); + _incrementHistogram(txn, latency, &_globalHistogramStats, readWriteType); } + +void Top::appendGlobalLatencyStats(BSONObjBuilder* builder) { + stdx::lock_guard<SimpleMutex> guard(_lock); + _globalHistogramStats.append(builder); +} + +void Top::_incrementHistogram(OperationContext* txn, + long long latency, + OperationLatencyHistogram* histogram, + Command::ReadWriteType readWriteType) { + // Only update histogram if operation came from a user. + Client* client = txn->getClient(); + if (client->isFromUserConnection() && !client->isInDirectClient()) { + 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..a7d543e0ae0 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,62 @@ 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, + Command::ReadWriteType readWriteType); + 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, + Command::ReadWriteType readWriteType); + + /** + * Appends the global latency statistics. + */ + void appendGlobalLatencyStats(BSONObjBuilder* builder); + private: 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, + Command::ReadWriteType readWriteType); + + void _incrementHistogram(OperationContext* txn, + long long latency, + OperationLatencyHistogram* histogram, + Command::ReadWriteType readWriteType); mutable SimpleMutex _lock; + OperationLatencyHistogram _globalHistogramStats; UsageMap _usage; std::string _lastDropped; }; |