MongoDB中创建与删除索引对业务的影响案例

首先祝大家节日快乐, 利用放假时间把之前的案例整理下,希望对大家有帮助,如有疑问可以留言区或者私信沟通。

跟传统数据库相同,为了提升查询效率,需要对集合增加适合的索引，同样需要移除冗余、没有被使用的索引,在MongoDB数据库日常运维过程如何规避创建与删除索引对系统的影响？本次总结三个案例关于创建与删除索引造成对业务影响的案例，希望对大家有所帮助。

• 4.2之前版本中后台创建索引变成前台
• 4.2版本创建索引造成DB几分钟不能写
• 3.6版本创建索引后删除索引造成备库无法登录

【4.2之前版本后台创建索引变成前台】

MongoDB 4.2之前版本分为前台与后台,默认是前台创建索引，这个速度最快，但是整个DB都不能读写，如果在副本集主库或者分片集群mongos执行且此时是大表，那么影响比较大。通常安全方式是指定background:1参数来创建或者进入维护模式滚动创建索引,4.2版本采用全新方式创建索引,类似online方式,只是在开始与结束阶段需要对集合持有短暂排他锁(再也不用担心前台创建索引)，包括我自己以及周围的朋友都遇到明明指定background:1,最终变成前台创建--主要原因是语法写错导致忽略第三个括号导致.options只能在第一个大括号里面.

【错误语法】

db.POCCOLL.createIndex({ "auditStatus": 1 , "dTime": 1 },{"name":"auditStatus_dTime"},{"background":true})

【正确语法】

db.POCCOLL.createIndex({ "auditStatus": 1 , "dTime": 1 },{"name":"auditStatus_dTime","background":true})

【错误语法】

db.eventlog.createIndex( { "lastModifiedDate": 1 }, { expireAfterSeconds: 3600},background：true })

【正确语法】

db.eventlog.createIndex( { "lastModifiedDate": 1 }, { expireAfterSeconds: 3600,background：true })

【解决方案】

1、通过currentOp找到对应opid来查杀线程,及时释放锁.例如通过mes信息来匹配,然后通过db.killOp(881798),如果是备库的,只能等待.主库线程被kill后,使用正确语法来创建索引.

db.currentOp({active:true,"msg":/^Index Build/})
备注:只是列出部分信息,可以根据自己来格式化输出
"msg" : "Index Build Index Build: 4531761/15690752 28%",
"progress" : {
"done" : 4531761,
"total" : 15690752
"locks" : {
"Global" : "w",
"Database" : "W",--DB级别排他锁
"Collection" : "w"
}

2、如果是多副本集或者分片集群下多副本集，如果业务很繁忙且避免对业务对影响,可以进入维护模式来创建索引,需要进行主备切换.如果实例特别多，没有自动化脚本，这个工作也是很繁重的.否则还是建议在低峰期时采用后台创建.

【4.2版本创建索引造成DB几分钟不能写】

【现象描述】

线上4.2集群版本运行超过半年,经常对大表在线增加索引,业务都无感知，直到有一天根据研发提交需求来增加索引,整个过程都已经跑快2小时,业务都异常，午休过程中，接到研发说业务全部无法消费,数据积压.心想不会是创建索引搞出事情？大约5分钟后,研发说可以消费了。接下来就要找问题了。

【日志分析】

查看副本集主库都日志:index Build: scanning collection阶段集群读写无任何异常,但Index Build: inserting keys from external sorter into index这个阶段导致整个DB 5分钟不能写,与业务TPS为0时间重叠,等待inserting keys完成后，业务恢复写。难道不是如文档说的那样吗？但查看slowlog里面锁信息来看，DB整个过程并没有持有排他锁Database: { acquireCount: { r: 1, w: 3447959 },Collection: { acquireCount: { r: 3447959, w: 1, R: 1, W: 2 } }.

根据官方说明,从MongoDB 4.2开始创建索引只是在开始与结束时持有短暂排他锁来保护元数据，其他时间段类似后台创建索引方式,允许正常读写操作.根据slow log里面信息确实集合持有2个排他锁.说明能够匹配上.

【关键信息】

只有5分钟MongoDB 整个DB不能写,能读,但索引inserting keys没有停止写入,是不是特定线程或者命令需要持有DB级别共享锁R(而不是意向锁),如果这个R锁被阻塞，那么后续集合写入操作需要申请DB级别的意向写锁才会被阻塞，因为DB意向读锁与共享读锁不是排斥，此时只有意向写锁与共享读锁是排斥,由于没有对锁实时监控导致没有发现异常到处理异常时,异常已经恢复,但能够从slow log里面发现一些蛛丝马迹(由于权限管控排除人为执行命令导致)

根据时间点去查找日志,发现有执行命令{profile:-1},这个命令对应DB级别锁是R.由此可以判断是这个命令导致创建索引所在的DB下所有写入都被阻塞的,锁队列类似-->IX-->R-->IX.并不是创建索引本身导致业务不可用,这个符合4.2 create index的锁特征以及最小化对业务影响。

--4.2版本创建索引大概步骤
1、持有集合排他X锁后创建INDEX元数据信息以及2个临时表(side writes table
&constraint violation table)后降级为意向锁(IX )
2、扫描集合所有记录到内存中external sorter(如果内存放不下写入磁盘上)
--这一步应该意向读锁
3、插入external sorter到index中---这一步是长事务持有IX锁导致profile:
-1获取R锁拿不到。
4、处理增量数据--2个临时表数据--虽然也持有IX，但不同于external sorter。
5、把IX升级S锁到X锁，根据需要应用临时表数据后并删除临时表
6、标识索引为可用状态，释放X锁。---索引状态通过getIndexes并没有发现索引
状态字段。

【MongoDB日志中关键信息】

2020-11-22T12:22:48  Index Build: scanning collection: 100%
2020-11-22T12:22:50  index build: collection scan done. 
2020-11-22T12:22:57  Index Build: inserting keys from external 
sorter into index: 
2020-11-22T12:28:09  index build: inserted xx keys from external 
sorter into  index in 319 seconds
2020-11-22T12:28:10  command: profile { profile: -1} Database: 
{ acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, 
timeAcquiringMicros: { R: 291292837 } } Mprotocol:op_msg 291293ms
2020-11-22T12:28:13 Index Build: draining writes received during 
build:  1%
2020-11-22T12:28:51 index build: done building index

【profile:-1作用以及来源】

1、通过官方文档得知,profile:-1是来当前DB的profile当前配置情况.

MongoDB server version: 4.2.8
{
  "was" : 1,
  "slowms" : 500,
  "sampleRate" : 1,
  "ok" : 1,
  "$gleStats" : {
    "lastOpTime" : Timestamp(0, 0),
    "electionId" : ObjectId("7fffffff0000000000000005")
  },
  "lastCommittedOpTime" : Timestamp(1619762205, 5),
  "$configServerState" : {
    "opTime" : {
      "ts" : Timestamp(1619762205, 4),
      "t" : NumberLong(5)
    }
  },
  "$clusterTime" : {
    "clusterTime" : Timestamp(1619762205, 5),
    "signature" : {
      "hash" : BinData(0,"mkJ5kn+sRme7vfW4/Hrpj3CbB5M="),
      "keyId" : NumberLong("6901213022409195552")
    }
  },
  "operationTime" : Timestamp(1619762205, 5)
}

2、谁执行这个命令

经过分析发现,是监控工作定期会检查profile设置情况，如果开启的话，会拉取性能数据进行暂时.至此阻塞对源头已经找到.接下来就要如何处理这个潜在的问题.

[如何解决]

1、通过监控数据库锁的情况,及时发现阻塞源头并kill线程

db.currentOp({waitingForLock:true})

2、关闭监控工具获取profile配置信息或者修改监控工作的逻辑

3、副本集或者集群采用滚动模式创建索引--如果系统不是特别繁忙,不用采用此方案.

4、profile:-1降低锁级别。IS而不是R锁.(直到4.4版本都没有解决，只能等下一个大版本,来自jira)

Some services poll the profiling state once per minute. We should investigate how to stop taking such strong locks for this command.

【3.6版本创建索引后删除索引造成备库无法登录以及消费积压】

【现象描述】

MongoDB 3.6.14版本集群,由于业务规则发生变化,需要创建索引，主要为了新老业务并存,提升查询以及聚合性能,在mongos中使用后台创建组合索引,大约2小时创建完成后立即发现索引字段写错(大小写问题),随后立即删除索引进行重建,不久后业务反馈报表无法打开(读写分离)以及后续业务数据消费积压.

主要表现特征:

• MongoDB Secondary节点阻塞读2个小时,也无法登陆且同步延迟时间持续增长(大约阻塞2小时)-<主要分析这个影响>
• MongoDB 应用TPS基本上接近为平时10%,正常TPS在2000左右,数据库后台慢日志op时间从几百毫秒上升到几秒到几十秒

【故障过程】

✅MongoDB Secondary节点阻塞读写以及登录2个小时,也无法登陆且同步延迟时间持续增长,直到错误索引被删除后.

1、【触发过程】

对大的集合使用后台创建索引后,然后又删除这个相同索引,然后触发触发Secondary阻塞所有读的情况,读写分离业务受到影响,不管是客户端还是shell命令行，以下shell命令行登录，输入密码之后,窗口一直hang无返回,通常情况下，输入密码之后立即登录.

1.1、【查看MongoDB Secondary日志】

1.1.1 [通过shell本地登录Seconary日志]

备注:备库认证卡在Global locks上意向读锁时间5858531ms.肯定存在其他线程对global lock持有互斥锁.

2020-09-28T19:15:33.311+0800 I COMMAND  [conn3067320] 
 command admin.system.users appName: "MongoDB Shell" 
 command: saslStart { saslStart: 1, mechanism: "SCRAM-SHA-1",
  payload: "xxx", $db: "admin" } 
locks:{ Global: { acquireCount: { r: 2 }, 
acquireWaitCount: { r: 1 }, 
timeAcquiringMicros: { r: 5858495396 } }, 
Database: { acquireCount: { r: 1 } }, Collection: 
{ acquireCount: { r: 1 } } } protocol:op_msg 5858531ms

1.1.2 [MongoDB创建索引以及删除索引日志]

【16:48开始创建索引,创建到13%时遇到dropindex,其中是background创建,创建索引时间为9534s,删除索引时间为7390s,备库读业务基本上被阻塞7390s】

2020-09-28T16:48:55.905+0800 I INDEX    
[repl index builder 94] build index on: 
xx.xx properties: { name: "xxx_1", background: true}
2020-09-28T17:24:37.003+0800 I -        
[Index Build (background): 30102400/215111973 13%
2020-09-28T17:24:38.931+0800 I COMMAND  
[repl writer worker 12] CMD: dropIndexes xx.xx
2020-09-28T19:27:50.052+0800 I INDEX    
[repl index builder 94] build index done. 9534 secs
2020-09-28T19:27:50.074+0800 I COMMAND  
[repl writer worker 12] 
CMD: dropIndexes xx.xx
2020-09-28T19:27:50.700+0800 I REPL

2、[故障原因]

1、通过以上日志来看确实就是对一个大的集合『后台建立索引 + 删除索引』2个相对连续动作导致，触发条件是此时备库创建还是进行中+删除动作，如果备库完成创建索引，那么删除不影响。

2、4.2版本之前dropIndex是database exclusive lock),既然db锁，为什么会阻塞admin登录admin，因为Secondary mongod instances block on Global lock and effectively all operations except building index are waiting for Global lock,主要是这个锁导致的.4.2版本开始dropIndex是collection exclusive lock,那么此时数据库肯定是登录，只是这个集合操作.建议使用4.2版本.4.4版本解决这个问题,4.4版本主备库会触发同时创建索引动作.

3、[如何解决问题]

1、【等待备库创建完成索引后在主库删除索引】

4.2版本之前使用后台完成创建索引后，等待所有从库创建后，再执行删除索引.

2、【升级版本到4.2版本】

4.2版本加锁是集合级别，如果此时删除索引，只是会阻塞这个集合而已,不会影响其他集合，如果是大集合，同样存在影响，如果使用4.4版本，此时就不存在这个问题.