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

【问题标题】：Timestamps in MongoDB logs - start or end of execution time?MongoDB日志中的时间戳 - 执行时间的开始或结束？
【发布时间】：2016-06-06 22:01:53
【问题描述】：

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

mongod 日志中完整的问题命令块的时间戳具有相同的值。除了下面的示例日志行之外，日志中还有 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}}，数据库：{acquireCount：{w：1}}，集合：{acquireCount：{w：1}}}协议：op_query 4555ms

【问题讨论】：

逻辑会说“之后”，因此会说“完成”，尽管它确实没有在任何地方记录，因此您需要查看代码以确定。由于当然存在执行时间，因此必须在收集和写入此类数据之前完成命令。然后使用“开始”时间戳进行操作也是没有意义的，因为如果一个操作一个接一个地开始但首先完成，那么记录的时间戳将不按顺序排列。无论如何，日志文件的典型约定是时间戳是指写入日志条目的时间。

标签： mongodb

【解决方案1】：

在处理同样的问题时，我发现了一套对分析 mongod 日志文件有很大帮助的工具：mtools。它的一个名为mplotqueries 的工具有一个选项--operation-start-time described，如下所示：

事件完成后会写入日志文件，默认情况下，mplotqueries 在 x 轴上绘制该时间点的操作。有时，查看操作何时开始会很有用。对于具有持续时间的操作（查询、更新等）mplotqueries 可以减去持续时间并在操作开始时绘制操作。使用--optime-start 标志打开此功能。

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

PS：另一个可视化日志条目的工具mlogvis没有这个选项，但是这里有一个代码sn-p可以做同样的事情：

//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文件并将sn-p添加到MLogVis.prototype._recalc_data_extents内的this.data.filter函数中。

【讨论】：