Analysis of the causes of Serverstatus was very slow in MongoDb

In the same cluster, two 1 times from Node db117,db118 "Serverstatus was very slow"

Db117 appears very slow:

2017-09-14t18:55:49.599+0800 [conn13113916] serverstatus was very slow: {after basic:0, after asserts:0 After the ndflushing:0, after the connections:0, after the cursors:0, after the dur:0, after the extra_info:0, after the globallock:0, after the index counters:0, after the locks:0, after the network:0, after the opcounters:0, after the opcountersrepl:0, after recordstats:1214, afte R repl:1214, at end:1214}

No large query (>10 seconds or more) was found before and after. Other performance indicators are also normal.

Just see the space in front of 30 additional connections.

2017-09-14t18:55:48.157+0800 [Initandlisten] connection accepted from 10.116.207.64:57026 #13113915 (264 connections Now OPEN)

...................

2017-09-14t18:55:49.551+0800 [Initandlisten] connection accepted from 10.174.177.10:64840 #13113946 (295 connections Now OPEN)

2017-09-14t18:55:49.599+0800 [conn13113916] serverstatus was very slow:

Should be a sudden number of inquiries, although the time of each query is not long, but IO,CPU has a reason for fluctuations.

(But there is no spike in the surveillance data)

This phenomenon also appeared once yesterday in DB118, but not at the same time.

2017-09-14t14:12:16.102+0800 [Initandlisten] connection accepted from 10.116.207.112:10800 #13301443 (286 connections Now OPEN)

..............................................................

2017-09-14t14:12:19.780+0800 [Initandlisten] connection accepted from 10.168.168.212:51264 #13301552 (395 connections Now OPEN)

2017-09-14t14:12:19.819+0800 [conn13300638] Query Mallcoo.mallcard query: {uid:17433632, status:1, mallid:273} plansu Mmary:ixscan {uid:1.0, mallid:1.0} ntoreturn:1 ntoskip:0 nscanned:1 nscannedobjects:1 keyUpdates:0 numYields:0 Locks ( Micros) r:4079097 nreturned:1 reslen:99 4079ms

2017-09-14t14:12:19.844+0800 [conn13301520] serverstatus was very slow: {After the basic:0, after the asserts:0, after the backgroundflushing:0, after the connections:0, after the cursors:0, after dur:0, aft Er extra_info:0, after the globallock:0, after the indexcounters:0, after the locks:0, after the network:0, after opcounters:0, afte R opcountersrepl:0, after recordstats:1516, after repl:1516, at end:1526}

2017-09-14t14:12:19.844+0800 [conn13301520] command admin. $cmd command:serverstatus {serverstatus:1.0} keyupdates:0 N umyields:0 locks (micros) r:83 reslen:7456 1557ms

DB118 14:12 time, Io has a peak point, from 2%-->12%. But db117 is not, the cause of the problem is more difficult to find.

From the two slow log, 2017-09-14t14:12:19.844+0800 [conn13301520] serverstatus was very slow: {after basic:0, afte R asserts:0, after the backgroundflushing:0, after the connections:0, after the cursors:0, after the dur:0, after extra_info:0, afte R globallock:0, after the indexcounters:0, after the locks:0, after the network:0, after the opcounters:0, after opcountersrepl:0, C2>after recordstats:1516, after repl:1516, at end:1526}

The slow reasons are: after recordstats:1516,

In other words, there are queries, and there is no data in memory, there are a lot of page faults.

Then Io, the CPU has a temporary busy state.

These two from node memory are now 64G, although not very high. But temporarily because the business relative growth is slow, does not increase the memory.

If a large number of such early warning logs appear, the field can be mongostat to view the status of faults, if it has been above 5. It can be considered that there is not enough memory.