summaryrefslogtreecommitdiff
path: root/jstests/noPassthrough/lock_stats.js
blob: 078a22ead2dcf47b8bda11ae56998b3c36a5fa17 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
// SERVER-21305: reported lock times are way too high.
//
// This test uses the fsync command to induce locking.
// @tags: [requires_fsync]
(function() {
    'use strict';

    function testBlockTime(blockTimeMillis) {
        // Lock the database, and in parallel start an operation that needs the lock, so it blocks.
        assert.commandWorked(db.fsyncLock());
        var startStats = db.serverStatus().locks.Global;
        var startTime = new Date();
        var minBlockedMillis = blockTimeMillis;
        var s = startParallelShell('assert.commandWorked(db.adminCommand({fsync:1}));', conn.port);

        // Wait until we see somebody waiting to acquire the lock, defend against unset stats.
        assert.soon((function() {
            var stats = db.serverStatus().locks.Global;
            if (!stats.acquireWaitCount || !stats.acquireWaitCount.W)
                return false;
            if (!startStats.acquireWaitCount || !startStats.acquireWaitCount.W)
                return true;
            return stats.acquireWaitCount.W > startStats.acquireWaitCount.W;
        }));

        // Sleep for minBlockedMillis, so the acquirer would have to wait at least that long.
        sleep(minBlockedMillis);
        db.fsyncUnlock();

        // Wait for the parallel shell to finish, so its stats will have been recorded.
        s();

        // The fsync command from the shell cannot have possibly been blocked longer than this.
        var maxBlockedMillis = new Date() - startTime;
        var endStats = db.serverStatus().locks.Global;

        //  The server was just started, so initial stats may be missing.
        if (!startStats.acquireWaitCount || !startStats.acquireWaitCount.W) {
            startStats.acquireWaitCount = {
                W: 0
            };
        }
        if (!startStats.timeAcquiringMicros || !startStats.timeAcquiringMicros.W) {
            startStats.timeAcquiringMicros = {
                W: 0
            };
        }

        var acquireWaitCount = endStats.acquireWaitCount.W - startStats.acquireWaitCount.W;
        var blockedMillis =
            Math.floor((endStats.timeAcquiringMicros.W - startStats.timeAcquiringMicros.W) / 1000);

        // Require that no other commands run (and maybe acquire locks) in parallel.
        assert.eq(acquireWaitCount, 1, "other commands ran in parallel, can't check timing");
        assert.gte(blockedMillis, minBlockedMillis, "reported time acquiring lock is too low");
        assert.lte(blockedMillis, maxBlockedMillis, "reported time acquiring lock is too high");
        return ({
            blockedMillis: blockedMillis,
            minBlockedMillis: minBlockedMillis,
            maxBlockedMillis: maxBlockedMillis
        });
    }

    var conn = MongoRunner.runMongod();
    var db = conn.getDB('test');
    printjson([1, 10, 100, 500, 1000, 1500].map(testBlockTime));
    MongoRunner.stopMongod(conn);
})();