MongoDB线上案例:一个参数提升16倍写入速度
作者:快盘下载 人气:01、问题背景
今天在线上遇到了一个MongoDB的性能问题,经过排查和参数调优,最终解决,还是很有收获,这里记录下整个问题排查过程以及思路,如果你不是搞MongoDB数据库的,那看看也无妨,这个排查问题的思路,后续会对你排查其他数据库有帮助。
问题描述:接到业务反馈线上的一个MongoDB副本集环境写入很慢,存在很多超时报警。设定的报警阈值是2s,一旦查询或者写入超过2s,就会触发报警,而本次报警的内容基本上都是写入报警,查询上面的报警较少。
02、基本的分析排查思路
通常情况下,一个业务请求从客户端发出,到客户端受到请求的反馈,需要经过一下的链路:
这个链路分为客户端、网络链路、服务器三个部分,任何一个环节出了差错,都会导致访问慢的问题,例如客户端部署的服务器负载高、网络链路带宽跑满、服务器上的慢查询等等问题,都可能表现为响应超时,所以,这里想说的是,如果你是一个开发,发现数据库返回时间超时了,请同时检查客户端和网络层面的问题,而不要直接把问题都丢给DBA。
这里给出我的排查思路
1、分析响应慢的问题
那么我们目前面临的问题是写入慢,而读取速度正常,通常情况下,跟网络关系就不太明显,因为网络如果慢,那么读写都会慢,看起来,更像是数据库服务器端的问题,那么我们的重点就是关注MongoDB数据库服务层面的问题。
首先,写入比较慢,我们可以通过查看mongodb的log,来查看写入慢的那些语句的具体执行时间,通常情况下,MongoDB默认会记录所有的查询语句,如果你想要的记录的内容更加丰富,可以使用db.setLogLevel的命令来设置mongodb的log等级。我们可以看到,log中的内容如下(省略了记录):
2021-08-03T10:17:41.912+0800 I COMMAND [conn2005245099] command fs.xxx command: insert { xxx } protocol:op_query 16169ms 2021-08-03T10:17:41.913+0800 I COMMAND [conn2005245095] command fs.xxx command: insert { xxx } protocol:op_query 16165ms 2021-08-03T10:17:41.913+0800 I COMMAND [conn2005245101] command fs.xxx command: insert { xxx } protocol:op_query 16161ms 2021-08-03T10:17:41.913+0800 I COMMAND [conn2005245107] command fs.xxx command: insert { xxx } protocol:op_query 16148ms 2021-08-03T10:17:41.913+0800 I COMMAND [conn2005245106] command fs.xxx command: insert { xxx } protocol:op_query 16146ms 2021-08-03T10:17:41.915+0800 I COMMAND [conn2005245148] command fs.xxx command: insert { xxx } protocol:op_query 16078ms 2021-08-03T10:17:41.915+0800 I COMMAND [conn2005245138] command fs.xxx command: insert { xxx } protocol:op_query 16090ms
可以看到,每行的最后面,都有执行时间,日志里面大量的insert语句,执行时间都是16s左右,这代表仅仅在MongoDB层面,一个insert语句,就需要执行16s,加上网络层面的开销,业务感知到的插入语句返回时间大概在20s左右,好在这个业务主要是保存图片信息的,每次插入对于时间不是特别敏感,但是最多能容忍2s的返回时间,这20s看起来,确实有点夸张了。
2、服务器级别分析
因为插入都是在MongoDB副本集的Primary节点来进行的,那么我们只需要分析Primary节点所在Linux服务器的基本情况,就可以从全局上对这个问题有一个总体的了解,分析服务器的指标包含但不限于CPU使用率、负载、内存、磁盘容量、TCP连接数等。
能够看到,除了TCP连接数有主键增多的趋势外,其他的指标没有特别明显的异常。TCP连接数增多,主要是业务的响应迟迟得不到返回,重新发起连接导致的,TCP的报警趋势图如下:
对应的,我们使用db.serverStatus().connections采集一下当前Primary节点所在服务器的连接数,可以发现,基本一致,都在7600左右,会有小幅抖动:
+------+----------+---+-------+-----------+-----------+--------+---------+ |TYPE |STATE |LAG|VERSION|node_CONF |CONNECTIONS|MEM_USED|DISK_USED| +------+----------+---+-------+-----------+-----------+--------+---------+ |mongod| | | | | | | | | |PRIMARY |0 |3.2.8 |P:1;D:0;H:0|7691/10000 |15.6GB |1.3T | | |SECONDARY |25 |3.2.8 |P:1;D:0;H:0|4599/10000 |11.3GB |1.3T | | |SECONDARY |17 |3.2.8 |P:1;D:0;H:0|4563/10000 |27.8GB |1.3T | | |SECONDARY |17 |3.2.8 |P:1;D:0;H:0|2984/10000 |12.2GB |1.4T | | |RECOVERING| |3.2.8 |P:0;D:1;H:1|7/10000 |22.6GB |1.4T | +------+----------+---+-------+-----------+-----------+--------+---------+
3、查看当前写入的表的基本情况
通常情况下,如果我们写入某个数据库中的集合比较慢,我们可以通过查看集合的基本情况来了解一些基本信息。
例如,集合的数据量和索引情况,在数据量比较大而索引较多的时候,每一个记录的插入,都需要维护集合上面的索引信息,那么这个插入问题肯定会被放大,耗时肯定比较长。MongoDB也类似mysql一样,采用插件式存储引擎架构,底层的WiredTiger存储引擎还可以支持B-Tree和LSM两种结构组织数据,但MongoDB在使用WiredTiger作为存储引擎时,目前默认配置是使用了B-Tree结构,B-Tree结构的话,索引原理大家就比较熟悉了,插入的时候肯定要产生数据页的裂变等维护开销,自然,索引和数据量对插入性能影响就很大
这个表的基本情况是:32亿条数据,6个索引。到这里,就能够解释为什么业务的阈值设置是2s了,因为正常情况下,如果根据自己生成的_id乱序插入的话,维护索引的时间代价就很大,如此大的数据量,达到秒级别,自然不稀奇。但是,一个插入20s,似乎还是说不过去。
这肯定不是主要原因,接着看。
4、查看当前数据库上是否有慢查询
如果当前这个数据库上存在其他操作持有排它锁,或者其他一些耗费巨额资源的查询操作,那么会导致数据库整体响应变慢。
对于MongoDB的慢查询,我一般喜欢使用currentOp这个命令看,这个命令类似于MySQL服务器中的show processlist,能够看到数据库目前在干什么事情,执行了多长时间,一个常用的命令如下:
db.currentOp({"secs_running":{"$gt":3600}})
这个命令表示,查看当前数据库耗时超过3600s的操作。
执行的结果是:没有类似的操作,我把阈值设置成100s,还是没有结果。
这个结果表示,当前数据库上没有其他耗费资源的操作。
5、使用MongoDB的性能分析工具mongostat查看数据库状态
mongostat对这个副本集的Primary节点进行了分析,注意,因为插入只能在Primary节点操作,所以对Primary节点进行分析:
[11:20:18]insert query update delete getmore command % dirty % used flushes vsize res qr|qw ar|aw netIn netOut conn set repl time [11:20:18] 262 34 *0 *0 2 2462|0 6.1 96.0 0 44.8G 15.4G 0|483 1|128 987k 604k 3639 comos_temp PRI 2021-08-03T11:20:19+08:00 [11:20:19] 299 32 *0 *0 0 2668|0 6.1 96.0 0 45.3G 15.4G 0|790 15|128 990k 607k 4141 comos_temp PRI 2021-08-03T11:20:20+08:00 [11:20:20] 250 28 *0 *0 4 2271|0 6.1 96.0 0 45.6G 15.4G 0|926 13|128 945k 732k 4397 comos_temp PRI 2021-08-03T11:20:21+08:00 [11:20:21] 303 26 *0 *0 0 2706|0 6.1 96.0 0 46.0G 15.4G 0|1226 13|128 1m 600k 4841 comos_temp PRI 2021-08-03T11:20:22+08:00 [11:20:22] 297 51 *0 *0 0 2570|0 4.8 96.0 1 46.4G 15.4G 0|1548 32|128 980k 558k 5231 comos_temp PRI 2021-08-03T11:20:23+08:00 [11:20:23] 306 32 *0 *0 0 2453|0 4.3 96.0 0 46.7G 15.4G 0|1815 9|128 901k 582k 5537 comos_temp PRI 2021-08-03T11:20:24+08:00 [11:20:25] 309 34 *0 *0 0 2608|0 3.3 96.0 0 47.0G 15.4G 0|2149 14|128 982k 577k 5842 comos_temp PRI 2021-08-03T11:20:25+08:00 [11:20:26] 353 26 *0 *0 0 2959|0 1.3 96.0 0 47.5G 15.4G 0|2516 24|128 1m 657k 6339 comos_temp PRI 2021-08-03T11:20:26+08:00 [11:20:27] 325 47 *0 *0 0 2821|0 0.5 96.0 0 48.0G 15.4G 0|2884 26|128 999k 679k 6875 comos_temp PRI 2021-08-03T11:20:27+08:00 [11:20:28] 325 32 *0 *0 0 2759|0 0.2 96.0 0 48.4G 15.4G 0|3242 10|128 992k 658k 7267 comos_temp PRI 2021-08-03T11:20:28+08:00
对mongostat性能分析工具的结果进行分析:
前面4个列分别代表每秒增删改查操作的次数;getmore代表游标信息,command代表mongod副本集之间的交互命令,dirty是一个关键参数,代表的是mongodb内存中被更新的脏数据占比,它有两个临界值,5%和20%。这些脏数据需要落在磁盘上,如果占比不超过5%,那么MongoDB会每分钟刷盘,如果超过5%,MongoDB会启动主动刷盘,尽量让这个数字不超过5%,如果写入太快,导致dirty的值超过20%,MongoDB就会阻塞新请求,全力以赴的刷盘。used另一个关键参数,它代表系统分配给MongoDB的内存中,已经被占用的内存比例,MongoDB默认情况下,最大会占用系统内存的60%,例如我们在100G内存中,MongoDB默认最大可以占用60G内存,而当used值为50%的时候,代表此时分配给MongoDB的内存已经被占用了30G。它也有2个临界值80%和95%,在低于80%的时候,MongoDB会认为当前分配的内存还没有被完全使用,不会做太多干预;如果高于80%了,MongoDB会认为内存冗余量不足,就会触发内存数据清理动作,清理策略是依据LRU算法的,旧数据会被踢出内存;一旦高于95%,那么代表MongoDB数据库承受着巨大的写入压力,就会阻塞其他操作,全力以赴淘汰内存中的数据。qr和qw,代表目前正在排队(queue)的read和write请求数量。ar和aw,代表目前活跃(active)的read和write请求conn,代表连接数。其他参数不重要,这里不赘述。
有了上述参数的基础,我们可以看到,我们的检测结果中,used值已经达到了96%,而qw的值高达1k~2k,这说明当前分配给MongoDB的内存几乎耗尽,MongoDB承受巨大的写入压力,在努力淘汰内存中的数据。
到这里,整个分析过程就结束了,接下来就是对症治疗了。
03、解决方案及改善效果
分析出来问题所在之后,解决方案就很容易能够提出来了,我们查看服务器上的剩余内存,发现剩余内存比较充裕,那么给MongoDB分配更多的内存,就能够缓解这个问题。
要加内存,就得知道MongoDB中,哪个参数控制内存的分配,MongoDB 3.2 及以后,默认使用 WiredTiger 存储引擎,可通过 cacheSizeGB 选项配置 WiredTiger 引擎使用内存的上限,一般建议配置在系统可用内存的60%左右。
接下来就是扩大内存的命令了,我们把内存从15G扩容到40G:
db.adminCommand({setParameter: 1, wiredTigerEngineRuntimeConfig: "cache_size=40G"})
官方文档也给出了修改wiredTiger存储引擎其他参数的命令:
详细可以查看:https://docs.mongodb.com/v4.2/reference/parameters/index.html
接下来我们看看效果,
1、首先来看mongostat性能分析的输出变化,重点关注used列和qw列(排队等待的写入):[11:21:00]insert query update delete getmore command % dirty % used flushes vsize res qr|qw ar|aw netIn netOut conn set repl time [11:21:00] 39 7 *0 *0 0 949|0 2.6 96.0 0 51.1G 15.5G 0|5309 2|128 161k 412k 10000 comos_temp PRI 2021-08-03T11:21:00+08:00 [11:21:01] 104 14 *0 *0 0 1224|0 2.7 96.0 0 51.1G 15.5G 1|5129 0|128 337k 510k 10000 comos_temp PRI 2021-08-03T11:21:01+08:00 [11:21:02] 488 31 *0 *0 0 3544|0 3.1 96.0 0 51.1G 15.5G 0|4764 0|128 1m 1m 10000 comos_temp PRI 2021-08-03T11:21:02+08:00 [11:21:03] 527 35 *0 *0 0 4164|0 3.4 96.0 0 51.1G 15.5G 0|4403 8|128 1m 1m 9999 comos_temp PRI 2021-08-03T11:21:03+08:00 [11:21:04] 305 27 *0 *0 0 1964|0 3.4 96.0 0 51.1G 15.5G 0|4536 6|128 445k 696k 10000 comos_temp PRI 2021-08-03T11:21:04+08:00 [11:21:05] 214 20 *0 *0 0 1645|0 3.5 96.0 0 51.1G 15.5G 0|4337 8|128 566k 620k 10000 comos_temp PRI 2021-08-03T11:21:05+08:00 [11:21:06] 155 19 *0 *0 0 2312|0 3.5 96.0 0 51.1G 15.5G 0|4497 1|128 910k 552k 10000 comos_temp PRI 2021-08-03T11:21:06+08:00 [11:21:07] 137 14 *0 *0 0 2103|0 3.6 96.0 0 51.1G 15.5G 0|4463 4|128 908k 513k 10000 comos_temp PRI 2021-08-03T11:21:08+08:00 [11:21:08] 127 11 *0 *0 0 2090|0 3.6 96.0 0 51.1G 15.5G 0|4428 5|128 902k 515k 10000 comos_temp PRI 2021-08-03T11:21:09+08:00 [11:21:09] 120 17 *0 *0 0 2261|0 3.6 96.0 0 51.2G 15.5G 0|4297 4|128 976k 597k 10000 comos_temp PRI 2021-08-03T11:21:10+08:00 [11:21:10]insert query update delete getmore command % dirty % used flushes vsize res qr|qw ar|aw netIn netOut conn set repl time [11:21:10] 736 44 *0 *0 1 5314|0 1.3 32.3 1 50.2G 15.5G 0|2966 1|128 3m 2m 9109 comos_temp PRI 2021-08-03T11:21:11+08:00 [11:21:11] 587 44 *0 *0 54 4655|0 1.3 32.7 0 46.9G 15.4G 0|1 0|1 3m 11m 5652 comos_temp PRI 2021-08-03T11:21:12+08:00 [11:21:12] 433 38 *0 *0 349 3237|0 1.7 33.0 0 46.6G 15.4G 0|0 0|1 1m 3m 5402 comos_temp PRI 2021-08-03T11:21:13+08:00 [11:21:13] 324 41 *0 *0 389 3112|0 1.5 33.3 0 46.5G 15.4G 0|0 0|2 1m 3m 5354 comos_temp PRI 2021-08-03T11:21:14+08:00 [11:21:14] 328 46 *0 *0 463 3278|0 1.2 33.6 0 46.5G 15.4G 0|0 0|1 2m 11m 5268 comos_temp PRI 2021-08-03T11:21:15+08:00 [11:21:15] 331 39 *0 *0 640 3172|0 1.1 33.8 0 46.4G 15.4G 0|0 2|1 2m 4m 5222 comos_temp PRI 2021-08-03T11:21:16+08:00 [11:21:16] 343 37 *0 *0 661 3489|0 1.1 34.0 0 46.4G 15.4G 1|0 0|3 2m 4m 5206 comos_temp PRI 2021-08-03T11:21:17+08:00 [11:21:17] 359 29 *0 *0 619 3364|0 1.3 34.2 0 46.4G 15.4G 0|0 0|4 2m 3m 5177 comos_temp PRI 2021-08-03T11:21:18+08:00 [11:21:19] 332 45 2 *0 637 3771|0 1.5 34.5 0 46.4G 15.4G 0|0 0|2 2m 3m 5185 comos_temp PRI 2021-08-03T11:21:19+08:00 [11:21:20] 297 25 *0 *0 636 3849|0 1.7 34.7 0 46.4G 15.4G 0|0 0|2 2m 3m 5203 comos_temp PRI 2021-08-03T11:21:20+08:00 --------------省略若干行--------- [11:25:04]insert query update delete getmore command % dirty % used flushes vsize res qr|qw ar|aw netIn netOut conn set repl time [11:25:04] 354 24 *0 *0 631 2417|0 15.7 77.7 0 43.0G 26.6G 0|1 0|1 1m 5m 1735 comos_temp PRI 2021-08-03T11:25:05+08:00 [11:25:05] 365 40 1 *0 636 2404|0 16.1 78.0 0 43.0G 26.7G 0|0 0|3 1m 4m 1730 comos_temp PRI 2021-08-03T11:25:06+08:00 [11:25:06] 438 25 1 *0 635 2491|0 16.5 78.2 0 43.0G 26.8G 0|0 0|2 1m 4m 1675 comos_temp PRI 2021-08-03T11:25:07+08:00 [11:25:07] 346 39 *0 *0 661 2692|0 16.9 78.5 0 42.9G 26.8G 0|0 0|1 1m 4m 1689 comos_temp PRI 2021-08-03T11:25:08+08:00 [11:25:08] 359 27 *0 *0 673 2735|0 17.3 78.7 0 43.0G 26.9G 0|0 0|2 1m 4m 1697 comos_temp PRI 2021-08-03T11:25:09+08:00 [11:25:09] 375 33 *0 *0 686 2622|0 17.7 79.0 0 43.0G 27.0G 0|0 0|1 1m 4m 1678 comos_temp PRI 2021-08-03T11:25:10+08:00 [11:25:10] 264 18 *0 *0 697 2144|0 18.0 79.2 0 43.0G 27.0G 0|0 1|2 1m 4m 1706 comos_temp PRI 2021-08-03T11:25:11+08:00 [11:25:11] 356 28 *0 *0 717 2435|0 18.5 79.4 0 43.0G 27.1G 0|0 0|1 1m 4m 1670 comos_temp PRI 2021-08-03T11:25:12+08:00 [11:25:12] 286 30 *0 *0 711 2222|0 19.0 79.6 0 43.0G 27.2G 2|0 0|3 1m 4m 1687 comos_temp PRI 2021-08-03T11:25:13+08:00 [11:25:13] 267 32 *0 *0 727 2556|0 19.3 79.8 0 43.0G 27.2G 0|0 0|1 1m 4m 1703 comos_temp PRI 2021-08-03T11:25:14+08:00 [11:25:14]insert query update delete getmore command % dirty % used flushes vsize res qr|qw ar|aw netIn netOut conn set repl time [11:25:14] 300 30 *0 *0 706 2598|0 19.8 80.1 0 43.0G 27.3G 0|1 0|1 1m 5m 1682 comos_temp PRI 2021-08-03T11:25:15+08:00 [11:25:15] 400 40 *0 *0 692 2508|0 20.3 79.9 0 42.9G 27.3G 0|0 0|2 1m 6m 1658 comos_temp PRI 2021-08-03T11:25:16+08:00 [11:25:16] 289 17 *0 *0 715 1892|0 20.7 79.9 0 42.9G 27.4G 0|0 0|2 895k 5m 1671 comos_temp PRI 2021-08-03T11:25:17+08:00 [11:25:17] 272 28 *0 *0 596 1534|0 20.8 80.0 0 42.9G 27.4G 0|0 0|0 581k 2m 1636 comos_temp PRI 2021-08-03T11:25:18+08:00 [11:25:18] 272 27 *0 1 657 1521|0 21.1 80.1 0 42.9G 27.4G 0|0 1|2 597k 3m 1650 comos_temp PRI 2021-08-03T11:25:19+08:00 [11:25:19] 293 25 1 *0 719 1696|0 21.4 80.0 0 42.9G 27.5G 0|0 0|1 653k 4m 1649 comos_temp PRI 2021-08-03T11:25:20+08:00 [11:25:20] 244 36 1 *0 773 1455|0 21.8 80.1 0 42.9G 27.5G 0|0 0|1 587k 5m 1627 comos_temp PRI 2021-08-03T11:25:21+08:00 [11:25:21] 313 33 *0 *0 757 1798|0 22.1 80.2 0 42.9G 27.5G 0|0 0|1 694k 5m 1624 comos_temp PRI 2021-08-03T11:25:22+08:00 [11:25:22] 302 13 *0 *0 738 1798|0 22.5 80.2 0 42.9G 27.5G 0|1 0|1 717k 5m 1613 comos_temp PRI 2021-08-03T11:25:23+08:00 [11:25:23] 300 30 *0 *0 756 2023|0 22.5 80.2 1 42.9G 27.6G 1|0 0|1 977k 5m 1611 comos_temp PRI 2021-08-03T11:25:24+08:00 [11:25:24]insert query update delete getmore command % dirty % used flushes vsize res qr|qw ar|aw netIn netOut conn set repl time [11:25:24] 247 28 *0 *0 772 2257|0 22.1 80.1 0 42.9G 27.6G 0|0 0|1 1m 5m 1605 comos_temp PRI 2021-08-03T11:25:25+08:00 [11:25:25] 244 20 *0 *0 682 1737|0 22.0 80.1 0 42.9G 27.6G 0|1 0|1 774k 4m 1595 comos_temp PRI 2021-08-03T11:25:26+08:00 [11:25:26] 244 21 *0 *0 753 2105|0 21.9 80.0 0 42.9G 27.6G 0|0 0|1 1m 5m 1596 comos_temp PRI 2021-08-03T11:25:27+08:00 [11:25:27] 286 26 *0 *0 723 1612|0 21.8 80.1 0 42.8G 27.6G 0|0 0|1 797k 5m 1569 comos_temp PRI 2021-08-03T11:25:28+08:00 [11:25:28] 250 14 *0 *0 650 1325|0 21.5 80.0 0 42.8G 27.6G 0|0 0|1 661k 5m 1571 comos_temp PRI 2021-08-03T11:25:29+08:00 [11:25:29] 306 25 *0 *0 692 1986|0 21.3 80.0 0 42.8G 27.7G 0|0 0|1 996k 5m 1563 comos_temp PRI 2021-08-03T11:25:30+08:00 [11:25:30] 312 23 *0 *0 682 1957|0 21.0 80.0 0 42.8G 27.7G 0|1 1|1 1m 5m 1569 comos_temp PRI 2021-08-03T11:25:31+08:00 [11:25:31] 287 26 *0 *0 695 2193|0 20.6 80.0 0 42.8G 27.7G 0|0 0|2 1m 6m 1580 comos_temp PRI 2021-08-03T11:25:32+08:00 [11:25:32] 340 36 *0 *0 673 2328|0 20.2 80.0 0 42.8G 27.7G 0|0 0|1 1m 6m 1564 comos_temp PRI 2021-08-03T11:25:33+08:00 [11:25:33] 406 32 *0 *0 621 2199|0 19.8 80.1 0 42.8G 27.7G 0|0 0|1 1m 5m 1572 comos_temp PRI 2021-08-03T11:25:34+08:00
可以发现,扩容内存为40G之后,used列从96%直接降低到32%,然后逐渐上升到80%之后,稳定下来,而qw列从2000多降低到0,也就意味着没有了排队等待写入的记录了。
同时我们可以看到,dirty的值,增加到22%之后,后续开始减小,因为触发了MongoDB的全力刷盘机制,超过20%之后,就开始全力刷盘了
2、来看内存的变化(因为我们设置的缘故,有一个明显增长):3、再来看连接数的变化:使用db.serverStatus().connections来对比实际连接数:
扩容内存前: +------+----------+---+-------+-----------+-----------+--------+---------+ |TYPE |STATE |LAG|VERSION|NODE_CONF |CONNECTIONS|MEM_USED|DISK_USED| +------+----------+---+-------+-----------+-----------+--------+---------+ |mongod| | | | | | | | | |PRIMARY |0 |3.2.8 |P:1;D:0;H:0|9691/10000 |15.6GB |1.3T | | |SECONDARY |25 |3.2.8 |P:1;D:0;H:0|4599/10000 |11.3GB |1.3T | | |SECONDARY |17 |3.2.8 |P:1;D:0;H:0|4563/10000 |27.8GB |1.3T | | |SECONDARY |17 |3.2.8 |P:1;D:0;H:0|2984/10000 |12.2GB |1.4T | | |RECOVERING| |3.2.8 |P:0;D:1;H:1|7/15000 |22.6GB |1.4T | +------+----------+---+-------+-----------+-----------+--------+---------+ 扩容内存后: +------+----------+---+-------+-----------+-----------+--------+---------+ |TYPE |STATE |LAG|VERSION|NODE_CONF |CONNECTIONS|MEM_USED|DISK_USED| +------+----------+---+-------+-----------+-----------+--------+---------+ |mongod| | | | | | | | | |PRIMARY |0 |3.2.8 |P:1;D:0;H:0|2744/10000 |15.4GB |1.3T | | |SECONDARY |0 |3.2.8 |P:1;D:0;H:0|1939/10000 |11.4GB |1.3T | | |SECONDARY |10 |3.2.8 |P:1;D:0;H:0|1883/10000 |27.8GB |1.3T | | |SECONDARY |11 |3.2.8 |P:1;D:0;H:0|1882/10000 |14.6GB |1.4T | | |RECOVERING| |3.2.8 |P:0;D:1;H:1|7/15000 |22.6GB |1.4T | +------+----------+---+-------+-----------+-----------+--------+---------+4、业务侧的超时监控(可以看到,超时数量少了很多):5、查看慢日志中的insert执行时间
2021-08-03T11:35:13.500+0800 I COMMAND [conn2006075353] command fs.xxx command: insert {xxx} protocol:op_query 1092ms
2021-08-03T11:35:13.501+0800 I COMMAND [conn2006023287] command fs.xxx command: insert {xxx} protocol:op_query 1114ms
可以看到,从一开始的16s,降低到目前的1s左右,insert速度提升了将近16倍
04、拓展和总结
1、为什么有4个阈值?
上面讲述dirty和used的时候,我们说到了临界值的概念,WiredTiger 引擎通过tcmalloc分配的内存总量不会超过cacheSizeDB的大小。为了控制内存的使用,WiredTiger 在内存使用接近一定阈值就会开始做淘汰,避免内存使用满了阻塞用户请求。于是乎就有了这4个阈值。
dirty有2个临界值,分别是5和20,而used有2个临界值,分别是80和95,
2、这个值可以根据我们的实际需求更改吗?
答案是:可以,但不建议
其实这4个阈值,是由下面的4个参数控制的,
参数 默认值 含义 eviction_target 80 当 cache used 超过 eviction_target,后台evict线程开始淘汰 CLEAN PAGE eviction_trigger 95 当 cache used 超过 eviction_trigger,用户线程也开始淘汰 CLEAN PAGE eviction_dirty_target 5 当 cache dirty 超过 eviction_dirty_target,后台evict线程开始淘汰 DIRTY PAGE eviction_dirty_trigger 20 当 cache dirty 超过 eviction_dirty_trigger, 用户线程也开始淘汰 DIRTY PAGE
在这个规则下,一个正常运行的 MongoDB 实例,cache used 一般会在 0.8 * cacheSizeGB 及以下,偶尔超出问题不大;如果出现 used>=95% 或者 dirty>=20%,并一直持续,说明内存淘汰压力很大,用户的请求线程会阻塞参与page淘汰,请求延时就会增加,这时可以考虑「扩大内存」或者 「换更快的磁盘提升IO能力」。
总结:
1、排查数据库响应慢的问题,可以从客户端、网络、数据库服务三个层面考虑;
2、如果确定是数据库服务器问题,不妨从服务器开始排查,先总览全局;
3、服务器层面没问题,查看数据库的基本信息,例如数据库容量、索引、日志等问题
4、借助第三方工具来对性能瓶颈进行分析
5、根据最终的问题结论确定解决问题的方案
6、执行后的反思和拓展
加载全部内容