mongodb - MongoDB 日志中的时间戳 - 执行时间的开始或结束？

Question

此 MongoDB 实例的典型负载是每秒 300 个命令，通常每个命令都在 50 毫秒内完成，即使在使用所有可能查询的负载测试下也是如此。有时会出现一个问题，即命令 block 花费的时间超过几秒钟。

mongod 日志中完整的有问题命令 block 的时间戳具有相同的值。除了下面包含的示例日志行外，日志中还有 20 条其他命令(插入和更新的混合)具有完全相同的时间戳 10:32:30.456，但记录的执行时间非常不同，从 2 秒到 6 秒不等秒。

我在 mongod 日志中看到的时间戳是命令开始的时间，还是命令结束的时间？

示例 mongod 日志条目:

2016-03-10T10:32:30.456+0000 I COMMAND [conn94] command sampleDb.sampleEvents command: insert { ... } ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 4555ms

Answer 1

为了解决同样的问题，我找到了一套对分析 mongod 日志文件有很大帮助的工具:mtools . 其中一个名为 mplotqueries 的工具有一个选项 --operation-start-time described如下:

Events are written to the log file when they finish, and by default, mplotqueries plots the operation on the x-axis at that point in time. Sometimes, it can be useful to see when operations started instead. For operations that have a duration (queries, updates, etc.) mplotqueries can subtract the duration and plot the operation when it started instead. Turn this feature on with the --optime-start flag.

这是我在该主题上找到的唯一提示。

PS:另一个名为 mlogvis 的可视化日志条目的工具没有此选项，但这里有一个代码片段可以做同样的事情:

//This goes to adopt all datetime fields in the datastructure
if(!d.hasOwnProperty('logtime') && d[this.yaxis_field] && d.datetime){
    d.logtime = d.datetime;
    if(d.duration > 0){
        var logtime = new Date(d.datetime);
        var starttime = new Date(logtime.valueOf()- d.duration - (logtime.getTimezoneOffset() * 60000));
        d.datetime = starttime.toISOString();
        d.line_str = d.datetime + ' - ' + d.line_str;
    }
}

为此，您需要修改生成的 html 文件并将代码片段添加到 MLogVis.prototype._recalc_data_extents 内的 this.data.filter 函数中。