MongoDB 运维优化系列(二)

一个MQ，开5个线程，平均一天消费数据如下：

总表：249733  （upsert + $inc）

子表：1732389 (insert)

在数据量插入到这个级别的时候，数据库插入就有延迟了，延迟时间在5分钟以上，逐渐增大...

jstack <pid>走一发，看MQ消息线程状况,5个线程都是如下状况：

"main" prio=10 tid=0x00007f38ac009000 nid=0x1359 runnable [0x00007f38b3723000]
   java.lang.Thread.State: RUNNABLE
	at java.net.PlainSocketImpl.socketAccept(Native Method)
	at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:398)
	at java.net.ServerSocket.implAccept(ServerSocket.java:530)
	at java.net.ServerSocket.accept(ServerSocket.java:498)
	at org.apache.catalina.core.StandardServer.await(StandardServer.java:470)
	at org.apache.catalina.startup.Catalina.await(Catalina.java:781)
	at org.apache.catalina.startup.Catalina.start(Catalina.java:727)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:294)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:428)

 注意其中一句话：java.lang.Thread.State: RUNNABLE

这表示线程正在运行，如果5个都这样，直白点就是线程繁忙。

 

此时，还不能确定问题所在，但要解决这个问题可以有三个方案，也可并行这三个方案：

1、增加MongoDB索引

2、增加消费线程数。（5->15）

3、将消息处理OnMessage内处理程序改为异步（即走线程池模式）

 

这三个方案，最快实施的则是方案1，于是方案1走一波，为了验证是否因索引导致，我们开启MongoDB慢日志，命令如下：

db.setProfilingLevel(1 ,50); 

 其中第一个参数：

0 –  不开启 

1 –  记录慢命令 (默认为>100ms)  

2 –  记录所有命令  

第二个参数：

n,慢操作执行时间，单位ms

执行成功后，系统会在DB下生成一个系统表

system.profile

这个表的结构如下：

{
    "op" : "update",
    "ns" : "chae_prod.oma_osoa_link_total",
    "query" : {
        "$and" : [ 
            {
                "nsCode" : {
                    "$eq" : "lyf"
                }
            }, 
            {
                "envCode" : {
                    "$eq" : "prod"
                }
            }, 
            {
                "minuteTime" : {
                    "$eq" : "2017-06-29 10:09"
                }
            }, 
            {
                "clientServiceName" : {
                    "$eq" : "back-order-web"
                }
            }, 
            {
                "serviceName" : {
                    "$eq" : "basics-stock-service"
                }
            }
        ]
    },
    "updateobj" : {
        "$set" : {
            "clientServiceName" : "back-order-web",
            "nsCode" : "lyf",
            "envCode" : "prod",
            "minuteTime" : "2017-06-29 10:09",
            "belongDate" : "2017-06-29",
            "serviceName" : "basics-stock-service"
        },
        "$inc" : {
            "successTotalNumber" : 1,
            "totalNumber" : 1,
            "failedTotalNumber" : 0
        }
    },
    "keysExamined" : 0,
    "docsExamined" : 213026,
    "nMatched" : 1,
    "nModified" : 1,
    "keyUpdates" : 0,
    "writeConflicts" : 0,
    "numYield" : 1669,
    "locks" : {
        "Global" : {
            "acquireCount" : {
                "r" : NumberLong(1670),
                "w" : NumberLong(1670)
            }
        },
        "Database" : {
            "acquireCount" : {
                "w" : NumberLong(1670)
            }
        },
        "Collection" : {
            "acquireCount" : {
                "w" : NumberLong(1670)
            }
        }
    },
    "millis" : 631,
    "execStats" : {},
    "ts" : ISODate("2017-06-29T10:19:58.387+08:00"),
    "client" : "10.10.254.15",
    "allUsers" : [],
    "user" : ""
}

 

 

 

其中millis字段表示执行时长，我们看到631MS，好高啊。

 

 

OK，我们迅速实施增加索引动作

我们在主表上增加upsert的query索引（也是前台查询索引）：

 

{
    "nsCode" : -1,
    "envCode" : -1,
    "minuteTime" : -1,
    "clientServiceName" : -1,
    "serviceName" : -1
}

 

 

在子表上增加前台查询索引:

 

{
    "nsCode" : -1,
    "envCode" : -1,
    "endTime" : -1,
    "clientServiceName" : -1,
    "serviceName" : -1
}

 

 

增加完后，我们再查询数据，发现order最新时间的数据，OK出来了，和现在时间对的上了。

 再来看一下内存stack:

"pool-2-thread-1" daemon prio=10 tid=0x00007f385ce3c800 nid=0x1370 waiting on condition [0x00007f38a14f7000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000c6bd5740> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:745)

 “TIMED_WAITING (parking)”中的 timed_waiting 指等待状态，但这里指定了时间，到达指定的时间后自动退出等待状态；parking指线程处于挂起中。

这就表示我们的线程消费已经处于挂起状态了，比较清闲，等着自动回收了。

观察一段时间后，发现没有什么大的问题。

于是我们便不再执行2，3方案。

为了保险期间我增加了方案4：

方案4：删除历史数据

有两种方法实现方案4，一个是用 MongoDB自带的TTL,具体语法列一下，剩下的请度娘：

db.log_events.createIndex({"createdAt": 1},{expireAfterSeconds: 180}) #5分钟后过期

后面的参数单位是秒，180秒。

由于我们默认给MongoDB分配的是1G内存，我们还对 MongoDB内存进行了加大，增加到2G。

另一种就是你自己写JOB定时删了。好了方案优化到此结束。

期待与大家分享更多的MongoDB运维优化方案