mongodb/jstests/noPassthrough/global_transaction_latency_histogram.js

// Checks that the global histogram counter for transactions are updated as we expect.
// @tags: [requires_replication, uses_transactions]
(function() {
"use strict";

// Set up the replica set.
const rst = new ReplSetTest({nodes: 1});
rst.startSet();
rst.initiate();
const primary = rst.getPrimary();

// Set up the test database.
const dbName = "test";
const collName = "global_transaction_latency_histogram";

const testDB = primary.getDB(dbName);
testDB.runCommand({drop: collName, writeConcern: {w: "majority"}});
assert.commandWorked(testDB.runCommand({create: collName, writeConcern: {w: "majority"}}));

// Start the session.
const sessionOptions = {
    causalConsistency: false
};
const session = testDB.getMongo().startSession(sessionOptions);
const sessionDb = session.getDatabase(dbName);
const sessionColl = sessionDb[collName];

function getHistogramStats() {
    return testDB.serverStatus({opLatencies: {histograms: 1}}).opLatencies;
}

// Checks that the actual value is within a minimum on the bound of the expected value. All
// arguments must be in the same units.
function assertLowerBound(expected, actual, bound) {
    assert.gte(actual, expected - bound);
}

// This function checks the diff between the last histogram and the current histogram, not the
// absolute values.
function checkHistogramDiff(lastHistogram, thisHistogram, fields) {
    for (let key in fields) {
        if (fields.hasOwnProperty(key)) {
            assert.eq(thisHistogram[key].ops - lastHistogram[key].ops, fields[key]);
        }
    }
    return thisHistogram;
}

// This function checks the diff between the last histogram's accumulated transactions latency
// and this histogram's accumulated transactions latency is within a reasonable bound of what
// we expect.
function checkHistogramLatencyDiff(lastHistogram, thisHistogram, sleepTime) {
    let latencyDiff = thisHistogram.transactions.latency - lastHistogram.transactions.latency;
    // Check the bound in microseconds, which is the unit the latency is in. We do not check
    // upper bound because of unknown extra server latency.
    assertLowerBound(sleepTime * 1000, latencyDiff, 50000);
    return thisHistogram;
}

let lastHistogram = getHistogramStats();

// Verify the base stats are correct.
lastHistogram = checkHistogramDiff(lastHistogram,
                                   getHistogramStats(),
                                   {"reads": 0, "writes": 0, "commands": 1, "transactions": 0});

// Test histogram increments on a successful transaction. "commitTransaction" and "serverStatus"
// commands are counted towards the "commands" counter.
session.startTransaction();
assert.commandWorked(sessionColl.insert({_id: "insert-1"}));
assert.commandWorked(session.commitTransaction_forTesting());
lastHistogram = checkHistogramDiff(lastHistogram,
                                   getHistogramStats(),
                                   {"reads": 0, "writes": 1, "commands": 2, "transactions": 1});

// Test histogram increments on aborted transaction due to error (duplicate insert).
session.startTransaction();
assert.commandFailedWithCode(sessionColl.insert({_id: "insert-1"}), ErrorCodes.DuplicateKey);
lastHistogram = checkHistogramDiff(lastHistogram,
                                   getHistogramStats(),
                                   {"reads": 0, "writes": 1, "commands": 1, "transactions": 1});

// Ensure that the transaction was aborted on failure.
assert.commandFailedWithCode(session.commitTransaction_forTesting(), ErrorCodes.NoSuchTransaction);
lastHistogram = checkHistogramDiff(lastHistogram,
                                   getHistogramStats(),
                                   {"reads": 0, "writes": 0, "commands": 2, "transactions": 0});

// Test histogram increments on an aborted transaction. "abortTransaction" command is counted
// towards the "commands" counter.
session.startTransaction();
assert.commandWorked(sessionColl.insert({_id: "insert-2"}));
assert.commandWorked(session.abortTransaction_forTesting());
lastHistogram = checkHistogramDiff(lastHistogram,
                                   getHistogramStats(),
                                   {"reads": 0, "writes": 1, "commands": 2, "transactions": 1});

// Test histogram increments on a multi-statement committed transaction.
session.startTransaction();
assert.commandWorked(sessionColl.insert({_id: "insert-3"}));
assert.commandWorked(sessionColl.insert({_id: "insert-4"}));
assert.eq(sessionColl.find({_id: "insert-1"}).itcount(), 1);
assert.commandWorked(session.commitTransaction_forTesting());
lastHistogram = checkHistogramDiff(lastHistogram,
                                   getHistogramStats(),
                                   {"reads": 1, "writes": 2, "commands": 2, "transactions": 1});

// Test that the cumulative transaction latency counter is updated appropriately after a
// sequence of back-to-back 200 ms transactions.
const sleepTime = 200;
for (let i = 0; i < 3; i++) {
    session.startTransaction();
    assert.eq(sessionColl.find({_id: "insert-1"}).itcount(), 1);
    sleep(sleepTime);
    assert.commandWorked(session.commitTransaction_forTesting());
    lastHistogram = checkHistogramLatencyDiff(lastHistogram, getHistogramStats(), sleepTime);
}

session.endSession();
rst.stopSet();
}());