MongoDB日志浅析-阿里云开发者社区

一、系统日志

系统日志在MongoDB中十分重要，它记录MongoDB启动和停止的操作，以及服务器在运行过程中发生的任何异常信息；配置系统日志非常简单，在运行mongod时候增加额外参数或者写入配置文件即可:

#在启动mongoDB时使用-logpath指定日志的路径，-logappend表示使用追加的方式写日志
mongod -logpath='/usr/local/mongodb/log/rs1.log' -logappend
#也可以在配置文件中指定参数进行配置：
logpath=/usr/local/mongodb/log/rs1.log #日志文件路径
logappend=true #表示使用追加的方式写日志
verbose=true #表示会打印debug信息
vv=true #表示debug级别，有vv-vvvvv，v越多则记录的日志信息越详细。
#quiet=true #quiet=true，表示安静地输出，不会再有debug信息，日志中只会打印一些关键的信息，比如自动故障切换，系统错误等信息，相当于error log。这时需要注释掉verbose参数。

二、Journal日志

不开启journal日志，写入wiredtiger的数据，并不会立即持久化存储；而是每分钟会做一次全量的checkpoint，将所有的数据持久化。
开启journal日志后，数据的更新就先写入Journal日志（其中包含了此次写入操作具体更改的磁盘地址和字节），定期集中提交，然后在正式数据执行更改。这样即使出现宕机，启动时Wiredtiger会先将数据恢复到最近的一次checkpoint的点，然后重放后续的journal操作日志来恢复数据。
由于MongoDB使用的journal文件大小限制为100MB,因此WiredTiger大约每100MB数据创建一个新的日志文件。
向MongoDB中写入数据是先写入内存，然后每隔60s在刷盘，同样写入journal,也是先写入对应的buffer，然后每隔50ms在刷盘到磁盘的journal文件。
需要注意的是如果客户端的写入速度超过了日志的刷新速度，mongod则会限制写入操作，直到日志完成磁盘的写入。这是mongod会限制写入的唯一情况。
Jouranl日志就是预写入的redo日志，是用于数据故障恢复和持久化数据的，为mongodb增加了额外的可靠性保障。journal除了故障恢复的作用之外，还可以提高写入的性能，批量提交。在这个过程中，所有的写入都可以一次提交，是单事务的，全部成功或者全部失败。启动数据库的Journal功能非常简单，只需写入配置文件即可：

#在启动时指定--journal代表启动journal日志。
mongod --journal
journal=true #启用journal日志
journalCommitInterval=100 #刷写提交机制。可修改范围是2~300，值越低，刷新输出频率越高，数据安全度也就越高，但磁盘性能上的开销也更高。

三、oplog主从日志与慢查询日志

3.1 固定集合

在讲下面两种日志之前先来认识下固定集合。MongoDB中的普通集合是动态创建的，而且可以自动增长以容纳更多的数据。MongoDB中还有另一种不同类型的集合，叫做固定集合。固定集合需要先创建好，而且它的大小是固定的。固定集合的行为类型与循环队列一样。如果没有空间了，最老的文档会被删除以释放空间，新插入的文档会占据这块空间。
固定集合创建之后就不能改变,无法将固定集合转换为非固定集合,但是可以将常规集合转换为固定集合。
固定集合可以进行一种特殊的排序，称为自然排序,自然排序返回结果集中文档的顺序就是文档在磁盘的顺序。自然顺序就是文档的插入顺序，因此自然排序得到的文档是从旧到新排列的。

3.2 oplog主从日志

MongoDB的高可用复制策略有一个叫做副本集。副本集的复制过程中有一个服务器充当主服务器，而一个或多个充当从服务器，主服务器将更新写入oplog，oplog记录着发生在主服务器的更新操作，oplog是主节点的local数据库中的固定集合(oplog.rs)中，并将这些操作分发到从服务器上。
每个备份节点都维护着自己的oplog,记录着每一次从主节点复制数据的操作。这样，每个成员都可以作为同步源给其他成员使用。
备份节点从当前使用的同步源中获取需要执行的操作，然后在自己的数据集上执行这些操作，最后再将这些操作写入自己的oplog,如果遇到某个操作失败的情况(只有当同步源的数据损坏或者数据与主节点不一致时才可能发生),那么备份节点就会停止从当前的同步源复制数据。
oplog中按顺序保存着所有执行过的写操作，副本集中每个成员都维护着一份自己的oplog，每个成员的oplog都应该跟主节点的oplog完全一致。
如果某个备份节点由于某些原因挂了，但它重新启动后，就会自动从oplog中最后一个操作开始进行同步。由于复制操作的过程是复制数据再写入oplog,所以备份节点可能会在已经同步过的数据上再次执行复制操作。MongoDB在设计之初就考虑到了这种情况:将oplog中的同一个操作执行多次，与只执行一次的效果是一样的。
oplog是固定集合，MongoDB默认将其大小设置为可用disk空间的5%（默认最小为1G，最大为50G），也可以在MongoDB复制集实例初始化之前将mongo.conf中oplogSize设置为我们需要的值。它只能保持特定数量的操作日志，并且如果执行大量的批量操作，oplog很快就会被填满。

#oplog各字段详解
ts: 8字节的时间戳，由4字节unix timestamp + 4字节自增计数表示。这个值很重要，在选举(如master宕机时)新primary时，会选择ts最大的那个secondary作为新primary
op：1字节的操作类型
"i"： insert
"u"： update
"d"： delete
"c"： db cmd
"db"：声明当前数据库 (其中ns 被设置成为=>数据库名称+ '.')
"n": no op,即空操作，其会定期执行以确保时效性
ns：操作所在的namespace
o：操作所对应的document，即当前操作的内容（比如更新操作时要更新的的字段和值）
o2: 在执行更新操作时的where条件，仅限于update时才有该属性

通过"db.printReplicationInfo()"命令可以查看oplog的信息：

通过"db.printSlaveReplicationInfo()"可以查看slave的同步状态：

3.3 慢查询日志

说到MongoDB的慢查询日志，就不得不提到profile分析器，profile分析器将记录的慢日志写到当前库下的system.profile集合下，这个集合是一个固定集合，使用db.system.profile.find()进行查询,慢日志可以在启动时或者在配置文件中进行指定。

#在启动mongoDB时使用--profile=1启动慢日志，--slowms表示慢日志阈值时间
mongod --profile=1 --slowms=5 
#也可以在配置文件中指定参数
slowms=100 #单位是毫秒
profile = 1#0：关闭，不收集任何数据。1：收集慢查询数据，默认是100毫秒。2：收集所有数据

#慢日志内容格式详解
    "op" : "query",  #操作类型，有insert、query、update、remove、getmore、command   
    "ns" : "test.test", #操作的集合
    "query" : {
        "$query" : {
            "user_id" : 314436841,
            "data_time" : {
                "$gte" : 1436198400
        "$orderby" : {
            "data_time" : 1
    "ntoskip" : 0, #指定跳过skip()方法的文档的数量。
    "nscanned" : 2, #为了执行该操作，MongoDB在index中浏览的文档数。一般来说，如果nscanned值高于nreturned 的值，说明数据库为了找到目标文档扫描了很多文档。这时可以考虑创建索引来提高效率。
    "nscannedObjects" : 1, #为了执行该操作，MongoDB在collection中浏览的文档数。
    "keyUpdates" : 0, #索引更新的数量，改变一个索引键带有一个小的性能开销，因为数据库必须删除旧的key，并插入一个新的key到B-树索引
    "numYield" : 1,  #该操作为了使其他操作完成而放弃的次数。通常来说，当他们需要访问还没有完全读入内存中的数据时，操作将放弃。这使得在MongoDB为了放弃操作进行数据读取的同时，还有数据在内存中的其他操作可以完成
    "lockStats" : {#锁信息，R：全局读锁；W：全局写锁；r：特定数据库的读锁；w：特定数据库的写锁
        "timeLockedMicros" : {  #该操作获取一个级锁花费的时间。对于请求多个锁的操作，比如对local数据库锁来更新oplog，该值比该操作的总长要长（即millis ）
            "r" : NumberLong(1089485),
            "w" : NumberLong(0)
        "timeAcquiringMicros" : {  #该操作等待获取一个级锁花费的时间。
            "r" : NumberLong(102),
            "w" : NumberLong(2)
    "nreturned" : 1,  // 返回的文档数量
    "responseLength" : 1669, // 返回字节长度，如果这个数字很大，考虑值返回所需字段
    "millis" : 544, #消耗的时间（毫秒）
    "execStats" : {  #一个文档,其中包含执行 查询 的操作，对于其他操作,这个值是一个空文件， system.profile.execStats 显示了就像树一样的统计结构，每个节点提供了在执行阶段的查询操作情况。
        "type" : "LIMIT", ##使用limit限制返回数  
        "works" : 2,
        "yields" : 1,
        "unyields" : 1,
        "invalidates" : 0,
        "advanced" : 1,
        "needTime" : 0,
        "needFetch" : 0,
        "isEOF" : 1,  #是否为文件结束符
        "children" : [
                "type" : "FETCH",  #根据索引去检索指定document
                "works" : 1,
                "yields" : 1,
                "unyields" : 1,
                "invalidates" : 0,
                "advanced" : 1,
                "needTime" : 0,
                "needFetch" : 0,
                "isEOF" : 0,
                "alreadyHasObj" : 0,
                "forcedFetches" : 0,
                "matchTested" : 0,
                "children" : [
                        "type" : "IXSCAN", #扫描索引键
                        "works" : 1,
                        "yields" : 1,
                        "unyields" : 1,
                        "invalidates" : 0,
                        "advanced" : 1,
                        "needTime" : 0,
                        "needFetch" : 0,
                        "isEOF" : 0,
                        "keyPattern" : "{ user_id: 1.0, data_time: -1.0 }",
                        "boundsVerbose" : "field #0['user_id']: [314436841, 314436841], field #1['data_time']: [1436198400, inf.0]",
                        "isMultiKey" : 0,
                        "yieldMovedCursor" : 0,
                        "dupsTested" : 0,
                        "dupsDropped" : 0,
                        "seenInvalidated" : 0,
                        "matchTested" : 0,
                        "keysExamined" : 2,
                        "children" : [ ]
    "ts": ISODate("2019-08-31T10:05:21.401Z"), #登陆时间
    "client": "127.0.0.1", #登陆IP或地址
    "appName": "MongoDB Shell",
    "allUsers": [],
    "user": ""
  总体来说，MongoDB有以上四种日志，其中系统日志和journal日志是物理文件日志，而oplog主从日志和慢查询日志其实是MongoDB中的固定集合。oplog主从日志被放在local库下的oplog.rs集合中；慢查询日志被放在当前库下system.profile集合中。
  因为MongoDB中的journal日志类似于MySQL的redo日志，oplog日志类似于MySQL的binlog；所以可能有人会问journal日志和oplog主从日志的顺序。其实我们仔细思考可以明白：oplog是MongoDB的一个固定集合，与其他的集合没有其他区别；所以是先写入journal日志的。
                使用 MongoDB 存储日志数据
            线上运行的服务会产生大量的运行及访问日志，日志里会包含一些错误、警告及用户行为等信息。通常服务会以文本的形式记录日志信息，这样可读性强，方便于日常定位问题。但当产生大量的日志之后，要想从大量日志里挖掘出有价值的内容，则需要对数据进行进一步的存储和分析。本文以存储 web 服务的访问日志为例，介绍如何使用 MongoDB 来存储、分析日志数据，让日志数据发挥最大的价值。本文的内容同样适用于其他的日志存储型应用。
突发MongoDB集群中的某个分片节点CPU飙高，初步判断是慢查询，现在需要拉取CPU飙高时间段的慢查询。拉取慢查询应该很快，不就是个系统日志吗？而且还做了日志切割一天一个，按道理很快搞定的，谁知当天晚上搞了接近三个小时也没搞定。
                使用MongoDB存储Docker日志（续）
            在上一篇文章《使用MongoDB存储Docker日志》中完成了Docker + Fluentd + MongoDB的基本配置。但是在实际的使用过程中，却发现Docker生成的日志并不会立即写入到MongoDB中，有大概1分钟左右的延迟。
                使用MongoDB存储Docker日志
            日志是系统很重要的一个组成部分，通过日志可以及时发现系统中存在的问题，也可以为修复问题提供线索。Docker提供了多种插件方式管理日志，本文就对使用MongoDB存储Docker日志的过程做个记录。
            版权声明：本文为博主武伟峰原创文章，转载请注明地址http://blog.csdn.net/tianyaleixiaowu。
前面提到过logback输出日志的多种方式，这一篇看一下自定义Appender，将logback输出的日志保存到mongo中。
                   关于ELK5.0.1的安装部署，请参考博文（ ELK 5.0.1+Filebeat5.0.1 for LINUX RHEL6.6 监控MongoDB日志），
本文重点说明如何适用filebeat实时监控mongodb数据库日志及在logstash正则解析mongodb日志。
                   ELK5.0.1搭建用到的工具有：
filebeat-5.0.1-linux-x86_64.tar.gzlogstash-5.0.1.tar.gzelasticsearch-5.0.1.tar.gz
kibana-5.0.1-linux-x86_64.tar.gz
以上4个工具可以https://www.elastic.co/downloads网址下的历史版本中找到。