summaryrefslogtreecommitdiff
path: root/jstests/noPassthrough/column_scan_slow_logs.js
blob: b4fda3d42000f1575c82ee9add5f966c898d0423 (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
69
/**
 * Tests to ensure that COLUMN_SCAN plan and scanned columns appear in slow query log lines when
 * the columstore index is the winning plan.
 * @tags: [
 *   featureFlagColumnstoreIndexes,
 * ]
 */
(function() {
"use strict";

load("jstests/libs/columnstore_util.js");  // For setUpServerForColumnStoreIndexTest.

const conn = MongoRunner.runMongod({});
assert.neq(null, conn, "mongod was unable to start up");

const db = conn.getDB(jsTestName());
assert.commandWorked(db.dropDatabase());

if (!setUpServerForColumnStoreIndexTest(db)) {
    MongoRunner.stopMongod(conn);
    return;
}

const coll = db.collection;

// Set logLevel to 1 so that all queries will be logged.
assert.commandWorked(db.setLogLevel(1));

// Set profiling level to profile all queries.
// Additionally, set slow threshold to -1 to ensure that all operations are logged as SLOW.
assert.commandWorked(db.setProfilingLevel(2, {slowms: -1}));

assert.commandWorked(coll.createIndex({"$**": "columnstore"}));
const docs = [
    {_id: 0, x: 1, y: [{a: 2}, {a: 3}, {a: 4}]},
    {_id: 1, x: 1},
    {_id: 2, x: 2, y: [{b: 5}, {b: 6}, {b: 7}]},
    {_id: 3, x: 1, y: [{b: 5}, {b: [1, 2, {c: 5}]}, {c: 7}]},
    {_id: 4, x: 5, y: [{b: {c: 1}}]}
];
assert.commandWorked(coll.insertMany(docs));

const queryComment = 'findColumnScan';
coll.find({x: {$gt: 1}}, {_id: 1, x: 1}).comment(queryComment).toArray();

const relevantLog = JSON.parse(checkLog.getLogMessage(db, /\"planSummary\":\"COLUMN_SCAN/));
assert(relevantLog !== null);
assert.eq(relevantLog.id, 51803, 'Slow query log (id: 51803) not found.');
assert.eq(relevantLog.attr.command.comment,
          'findColumnScan',
          `Relevant query with comment '${queryComment}' not found.`);

// We expect a log line with a planSummary format like "COLUMN_SCAN
// {match:['x'],output:['_id','x']}". We assert only on the pieces (and frequency) here to avoid
// depending on the exact order.
const planSummary = relevantLog.attr.planSummary;
assert(planSummary.match(/COLUMN_SCAN/),
       `'COLUMN_SCAN' plan not found. Instead, got: ${planSummary}`);
assert(planSummary.match(/'match'/), `'match' not found. Instead, got: ${planSummary}`);
assert(planSummary.match(/'output'/), `'output' not found. Instead, got: ${planSummary}`);
assert.eq(planSummary.match(/'x'/g).length,
          2,
          `'x' should appear twice in planSummary. Instead, got: ${planSummary}`);
assert.eq(planSummary.match(/'_id'/g).length,
          1,
          `'_id' should appear once in planSummary. Instead, got: ${planSummary}`);

MongoRunner.stopMongod(conn);
}());