1. MongoDB server version: 3.4.2
2. startup mongo with parameter --syslog
/usr/local/mongodb/bin/mongod --fork --dbpath=/data/db --syslog --port=27017 --bind_ip=127.0.0.1,136.227.20.70
3. top -H -p
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
29078 root 20 0 6586752 5.919g 6920 S 99.7 38.2 0:48.07 mongod
30297 root 20 0 6586752 5.919g 6920 S 0.3 38.2 0:00.82 mongod
30270 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.34 mongod
30271 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.00 mongod
30272 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:01.02 mongod
30274 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.13 mongod
30275 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.04 mongod
30276 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.33 mongod
30277 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.05 mongod
30278 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.00 mongod
30279 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:01.49 mongod
30280 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.96 mongod
30281 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.00 mongod
30282 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:02.26 mongod
30283 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.06 mongod
30284 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.00 mongod
30285 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.05 mongod
30286 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.00 mongod
30287 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.07 mongod
30291 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.20 mongod
30295 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.01 mongod
30301 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.01 mongod
30304 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.08 mongod
30461 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.02 mongod
30494 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:01.95 mongod
30879 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.23 mongod
31477 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.02 mongod
31478 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.03 mongod
31572 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.02 mongod
31917 root 20 0 6586752 5.919g 6920 S 0.0 38.2 0:00.00 mongod
4. thread of high cpu usage with common output by "pstack 29078"
Thread 1 (process 29078):
#0 0x00007f0e6bd2585d in write () from /lib64/libc.so.6
#1 0x00007f0e6bcb1fb3 in _IO_new_file_write () from /lib64/libc.so.6
#2 0x00007f0e6bcb274f in _GI_IO_file_xsputn () from /lib64/libc.so.6
#3 0x00007f0e6bc8469d in vfprintf () from /lib64/libc.so.6
#4 0x00007f0e6bcb0028 in vdprintf () from /lib64/libc.so.6
#5 0x00007f0e6bc8db17 in dprintf () from /lib64/libc.so.6
#6 0x00007f0e6bd2e47e in __vsyslog_chk () from /lib64/libc.so.6
#7 0x00007f0e6bd2e622 in __syslog_chk () from /lib64/libc.so.6
#8 0x000055bf16b15e9c in mongo::logger::SyslogAppender<mongo::logger::MessageEventEphemeral>::append(mongo::logger::MessageEventEphemeral const&) ()
#9 0x000055bf171abca4 in mongo::logger::LogDomain<mongo::logger::MessageEventEphemeral>::append(mongo::logger::MessageEventEphemeral const&) ()
#10 0x000055bf171aa849 in mongo::logger::LogstreamBuilder::~LogstreamBuilder() ()
#11 0x000055bf16b1a1a1 in mongo::assembleResponse(mongo::OperationContext*, mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&) ()
#12 0x000055bf1670a54d in mongo::ServiceEntryPointMongod::_sessionLoop(std::shared_ptr<mongo::transport::Session> const&) ()
#13 0x000055bf1670ae8d in std::_Function_handler<void (std::shared_ptr<mongo::transport::Session> const&), mongo::ServiceEntryPointMongod::startSession(std::shared_ptr<mongo::transport::Session>)::{lambda(std::shared_ptr<mongo::transport::Session> const&)#1}>::_M_invoke(std::_Any_data const&, std::shared_ptr<mongo::transport::Session> const&) ()
#14 0x000055bf17379292 in mongo::(anonymous namespace)::runFunc(void*) ()
#15 0x00007f0e6c006e25 in start_thread () from /lib64/libpthread.so.0
#16 0x00007f0e6bd3434d in clone () from /lib64/libc.so.6
5. strace -T -tt -e trace=all -s 10000 -fp 29078
[pid 29078] 13:49:53.945831 futex(0x55e854e411a8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000017>
[pid 29078] 13:49:53.945899 futex(0x55e854e411d4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 56277, {1536126593, 955806828}, ffffffff) = -1 ETIMEDOUT (Connection timed out) <0.009955>
[pid 29078] 13:49:53.955895 futex(0x55e854e411a8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000013>
[pid 29078] 13:49:53.955940 futex(0x55e854e411d4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 56279, {1536126593, 965887819}, ffffffff) = -1 ETIMEDOUT (Connection timed out) <0.009992>
[pid 29078] 13:49:53.965976 futex(0x55e854e411a8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000015>
[pid 29078] 13:49:53.966025 futex(0x55e854e411d4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 56281, {1536126593, 975969073}, ffffffff) = -1 ETIMEDOUT (Connection timed out) <0.009991>
[pid 29078] 13:49:53.976056 futex(0x55e854e411a8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000013>
[pid 29078] 13:49:53.976101 futex(0x55e854e411d4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 56283, {1536126593, 986048750}, ffffffff) = -1 ETIMEDOUT (Connection timed out) <0.009996>
[pid 29078] 13:49:53.986135 futex(0x55e854e411a8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000018>
[pid 29078] 13:49:53.986208 futex(0x55e854e411d4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 56285, {1536126593, 996128238}, ffffffff) = -1 ETIMEDOUT (Connection timed out) <0.009960>
[pid 29078] 13:49:53.996214 futex(0x55e854e411a8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000021>
[pid 29078] 13:49:53.996263 futex(0x55e854e411d4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 56287, {1536126594, 6205991}, ffffffff <unfinished ...>
[pid 29089] 13:49:54.000072 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out) <0.997855>
[pid 29089] 13:49:54.000103 futex(0x55e8587277e8, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000013>
[pid 29089] 13:49:54.000188 open("/proc/29076/stat", O_RDONLY) = 61 <0.000024>
[pid 29089] 13:49:54.000258 fstat(61, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 <0.000013>
[pid 29089] 13:49:54.000309 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f46eaba3000 <0.000020>
[pid 29089] 13:49:54.000361 read(61, "29076 (mongod) S 1 29075 29075 0 -1 1077944384 218410 0 33 0 794 25000 0 0 20 0 27 0 303434491 2047733760 423496 18446744073709551615 94456257441792 94456302719232 140724326755424 140724326748608 139942541384005 0 8405507 4097 3308 18446744073709551615 0 0 17 5 0 0 43 0 0 94456302726464 94456304527088 94456334974976 140724326758539 140724326758636 140724326758636 140724326760410 0\n", 1024) = 384 <0.000032>
[pid 29089] 13:49:54.000437 close(61) = 0 <0.000052>
[pid 29089] 13:49:54.000538 munmap(0x7f46eaba3000, 4096) = 0 <0.000027>
6. big size data insert mongodb: mongostat
insert query update delete getmore command dirty used flushes vsize res qrw arw net_in net_out conn time
2 *0 *0 *0 0 2|0 1.2% 76.7% 0 6.30G 5.96G 0|0 0|0 2.66m 54.3k 10 Sep 5 14:37:09.504
*0 *0 *0 *0 0 2|0 1.2% 76.7% 0 6.30G 5.96G 0|0 0|0 2.68m 54.2k 10 Sep 5 14:37:10.504
4 *0 *0 *0 0 3|0 1.3% 76.8% 0 6.30G 5.96G 0|0 0|0 5.33m 54.4k 10 Sep 5 14:37:11.503
1 *0 *0 *0 0 4|0 1.3% 76.8% 0 6.30G 5.96G 0|0 0|0 3.28m 54.6k 10 Sep 5 14:37:12.504
4 *0 *0 *0 0 3|0 1.4% 76.9% 0 6.30G 5.96G 0|0 0|0 5.33m 54.4k 10 Sep 5 14:37:13.504
*0 *0 *0 *0 0 2|0 1.4% 76.9% 0 6.30G 5.96G 0|0 0|0 2.63m 54.2k 10 Sep 5 14:37:14.505
3 *0 *0 *0 0 5|0 1.5% 77.0% 0 6.30G 5.96G 0|0 0|0 2.71m 54.6k 10 Sep 5 14:37:15.504
2 *0 *0 *0 0 3|0 1.5% 77.0% 0 6.30G 5.96G 0|0 0|0 5.35m 54.3k 10 Sep 5 14:37:16.503
2 *0 *0 *0 0 7|0 1.6% 77.1% 0 6.30G 5.96G 0|0 0|0 2.66m 56.9k 10 Sep 5 14:37:17.504
2 *0 *0 *0 0 3|0 1.6% 77.2% 0 6.30G 5.96G 0|0 0|0 5.35m 54.3k 10 Sep 5 14:37:18.504
insert query update delete getmore command dirty used flushes vsize res qrw arw net_in net_out conn time
3 *0 *0 *0 0 4|0 1.7% 77.2% 0 6.30G 5.96G 0|0 0|0 2.69m 54.4k 10 Sep 5 14:37:19.504
*0 *0 *0 *0 0 2|0 1.8% 77.2% 0 6.30G 5.96G 0|0 0|0 2.67m 54.2k 10 Sep 5 14:37:20.504
3 *0 *0 *0 0 3|0 1.8% 77.3% 0 6.30G 5.96G 0|0 0|0 5.35m 54.5k 10 Sep 5 14:37:21.504
2 *0 1 *0 0 5|0 1.9% 77.3% 0 6.30G 5.96G 0|0 0|0 3.26m 54.6k 10 Sep 5 14:37:22.504
3 *0 *0 *0 0 2|0 1.9% 77.4% 0 6.30G 5.96G 0|0 0|0 5.32m 54.3k 10 Sep 5 14:37:23.505
1 *0 *0 *0 0 3|0 2.0% 77.5% 0 6.30G 5.96G 0|0 0|0 2.71m 54.3k 10 Sep 5 14:37:24.503
2 *0 *0 *0 0 3|0 2.0% 77.5% 0 6.30G 5.96G 0|0 0|0 2.63m 54.5k 10 Sep 5 14:37:25.504
2 *0 *0 *0 0 4|0 2.1% 77.6% 0 6.30G 5.96G 0|0 0|0 5.33m 54.5k 10 Sep 5 14:37:26.504
2 *0 *0 *0 0 2|0 2.1% 77.6% 0 6.30G 5.96G 0|0 0|0 2.69m 54.2k 10 Sep 5 14:37:27.505
2 *0 *0 *0 0 3|0 2.2% 77.7% 0 6.30G 5.96G 0|0 0|0 5.34m 54.3k 10 Sep 5 14:37:28.504
insert query update delete getmore command dirty used flushes vsize res qrw arw net_in net_out conn time
3 *0 *0 *0 0 3|0 2.2% 77.7% 0 6.30G 5.96G 0|0 0|0 2.67m 54.3k 10 Sep 5 14:37:29.503
1 *0 *0 *0 0 3|0 2.3% 77.8% 0 6.30G 5.96G 0|0 0|0 5.35m 54.3k 10 Sep 5 14:37:30.503
2 *0 *0 *0 0 2|0 2.3% 77.8% 0 6.30G 5.96G 0|0 0|0 2.66m 53.8k 10 Sep 5 14:37:31.512
2 *0 1 *0 0 9|0 2.4% 77.9% 0 6.30G 5.96G 0|0 0|0 3.31m 57.6k 10 Sep 5 14:37:32.503
4 *0 *0 *0 0 4|0 2.4% 78.0% 0 6.30G 5.96G 0|0 0|0 5.36m 54.6k 10 Sep 5 14:37:33.503
*0 *0 *0 *0 0 3|0 2.5% 78.0% 0 6.30G 5.96G 0|0 0|0 2.64m 54.2k 10 Sep 5 14:37:34.504
3 *0 *0 *0 0 3|0 2.5% 78.1% 0 6.30G 5.96G 0|0 0|0 5.32m 54.4k 10 Sep 5 14:37:35.506
1 *0 *0 *0 0 3|0 2.6% 78.1% 0 6.30G 5.96G 0|0 0|0 2.71m 54.3k 10 Sep 5 14:37:36.504
3 *0 *0 *0 0 3|0 2.7% 78.1% 0 6.30G 5.96G 0|0 0|0 2.63m 54.3k 10 Sep 5 14:37:37.503
1 *0 *0 *0 0 2|0 2.7% 78.2% 0 6.30G 5.96G 0|0 0|0 5.33m 54.3k 10 Sep 5 14:37:38.504