[SERVER-36991] mongo startup by parameter --syslog: mongod 100% cpu usage under big data insert Created: 05/Sep/18  Updated: 20/Sep/18  Resolved: 20/Sep/18

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: 3.4.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: wynn zhao Assignee: Nick Brewer
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File Screen Shot 2018-09-06 at 10.10.58 AM.png     File db.getLogComponents     File diagnostic-data.tar.gz     File diagnostic-data.tar.gz     File server1-rsyslog.conf     File server2-rsyslog.conf     File server2-rsyslog.conf    
Operating System: ALL
Steps To Reproduce:

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

Participants:

 Description   

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



 Comments   
Comment by Nick Brewer [ 20/Sep/18 ]

wynn Happy to help. As an aside, I suggest upgrading to the latest MongoDB 3.4 version - currently 3.4.17, as it contains numerous improvements and bug fixes.

-Nick

Comment by wynn zhao [ 19/Sep/18 ]

Hi Nick

You can close this issue, if we reproduce it with suitable testing environment, we can reopen it.

Thanks for your timely and seriously support. Have a nice day!

 

Best Regards!

Wynn

Comment by Nick Brewer [ 13/Sep/18 ]

wynn I've attempted to reproduce this, but I haven't been able to. Using MongoDB 3.4.2 on CentOS 7, I started mongod up first with -syslog, and then -logpath (log file) - in each case I performed an insert of 3 million documents. The CPU utilization according to top hovered around 3% for both of them:

--syslog:

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 3292 root      20   0  418964 169328  12408 S  3.0  2.3   0:01.91 mongod
 3100 root      20   0  418964 169328  12408 S  0.3  2.3   0:00.17 mongod

--logpath:

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 3465 root      20   0  413732 164344  12596 S  3.0  2.3   0:01.81 mongod
 3442 root      20   0  413732 164344  12596 S  0.3  2.3   0:00.08 mongod

Do you have any other suggestions as to how I might be able to reproduce what you're seeing? If not, I believe we can close this ticket, as it does not appear to represent an underlying bug in MongoDB.

Thanks,
-Nick

Comment by wynn zhao [ 13/Sep/18 ]

db.getLogComponents

Comment by wynn zhao [ 13/Sep/18 ]

Hi Nick

We have same configuration with MongoDB and Servers.

 

[*####@badash-linux-5 ~*]# mongo[####@badash-linux-5 ~]# mongoMongoDB shell version v3.4.2connecting to: mongodb://127.0.0.1:27017MongoDB server version: 3.4.2Server has startup warnings: 2018-09-07T10:27:28.572+0200 I CONTROL  [initandlisten] 2018-09-07T10:27:28.573+0200 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.2018-09-07T10:27:28.573+0200 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.2018-09-07T10:27:28.573+0200 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.2018-09-07T10:27:28.573+0200 I CONTROL  [initandlisten] 2018-09-07T10:27:28.573+0200 I CONTROL  [initandlisten] 2018-09-07T10:27:28.573+0200 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.2018-09-07T10:27:28.573+0200 I CONTROL  [initandlisten] **        We suggest setting it to 'never'2018-09-07T10:27:28.573+0200 I CONTROL  [initandlisten] > *db.getLogComponents()*{ "verbosity" : 0, "accessControl" : \{ "verbosity" : -1 }, "command" : \{ "verbosity" : -1 }, "control" : \{ "verbosity" : -1 }, "executor" : \{ "verbosity" : -1 }, "geo" : \{ "verbosity" : -1 }, "index" : \{ "verbosity" : -1 }, "network" : \{ "verbosity" : -1, "asio" : { "verbosity" : -1 }, "bridge" : \{ "verbosity" : -1 } }, "query" : \{ "verbosity" : -1 }, "replication" : \{ "verbosity" : -1 }, "sharding" : \{ "verbosity" : -1 }, "storage" : \{ "verbosity" : -1, "journal" : { "verbosity" : -1 } }, "write" : \{ "verbosity" : -1 }, "ftdc" : \{ "verbosity" : -1 }, "tracking" : \{ "verbosity" : -1 }}

[*####@badash-linux-6 ~*]$ mongoMongoDB shell version v3.4.2connecting to: mongodb://127.0.0.1:27017MongoDB server version: 3.4.2Server has startup warnings: 2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] 2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] 2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] 2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] **        We suggest setting it to 'never'2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] 2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] **        We suggest setting it to 'never'2018-09-12T16:38:48.314+0800 I CONTROL  [initandlisten] > *db.getLogComponents()*{ "verbosity" : 0, "accessControl" : \{ "verbosity" : -1 }, "command" : \{ "verbosity" : -1 }, "control" : \{ "verbosity" : -1 }, "executor" : \{ "verbosity" : -1 }, "geo" : \{ "verbosity" : -1 }, "index" : \{ "verbosity" : -1 }, "network" : \{ "verbosity" : -1, "asio" : { "verbosity" : -1 }, "bridge" : \{ "verbosity" : -1 } }, "query" : \{ "verbosity" : -1 }, "replication" : \{ "verbosity" : -1 }, "sharding" : \{ "verbosity" : -1 }, "storage" : \{ "verbosity" : -1, "journal" : { "verbosity" : -1 } }, "write" : \{ "verbosity" : -1 }, "ftdc" : \{ "verbosity" : -1 }, "tracking" : \{ "verbosity" : -1 }}> 

Best Regards!

Wynn

Comment by Nick Brewer [ 12/Sep/18 ]

wynn I don't see anything unusual there, but this reinforces my belief that this issue is not with the --syslog setting itself, as you should be seeing roughly the same behavior on badash-linux-5 as you are on badash-linux-6. Are there any other differences (in terms of configuration, hardware, etc) between these two machines? It would be useful to see the output of db.getLogComponents() from both machines.

Thanks,
-Nick

Comment by wynn zhao [ 12/Sep/18 ]

Hi Nick

rsyslog.conf attached. And the server version as follows:

[####@badash-linux-6 etc]$ cat /etc/os-release
NAME="CentOS Linux"
VERSION="7 (Core)"
ID="centos"
ID_LIKE="rhel fedora"
VERSION_ID="7"
PRETTY_NAME="CentOS Linux 7 (Core)"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:centos:centos:7"
HOME_URL="https://www.centos.org/"
BUG_REPORT_URL="https://bugs.centos.org/"

CENTOS_MANTISBT_PROJECT="CentOS-7"
CENTOS_MANTISBT_PROJECT_VERSION="7"
REDHAT_SUPPORT_PRODUCT="centos"
REDHAT_SUPPORT_PRODUCT_VERSION="7"

 

Best Regards!

Wynn

 

server1-rsyslog.conf

server2-rsyslog.conf

 

Comment by Nick Brewer [ 11/Sep/18 ]

wynn Have you made any modifications to your system's syslog configuration? It would be helpful to see your rsyslog.conf file for each of the machines you've provided diagnostic data for. It's worth noting that only one of the machines are seeing increased CPU utilization, despite the fact that they're both using the --syslog option with similar workloads.

-Nick

Comment by wynn zhao [ 06/Sep/18 ]

Hi Nick,

We just use one database include several collections with multi-thread writing and reading(c++ driver write or read, php driver read mostly). When this core cpu reach 100%, all other operation will be very slowly or hang. For example, read data from collections by PHP driver, some times, no data will be got or "no such server" errors reported.

 

In addition, we modify the start up parameter, remove --syslog and instead by --logpath /dev/null. Finally, after one day test, the cpu is very low and the cpu high issue not be reproduced, every operation looks good currently.

 

Best Regards!

Wynn

 

Comment by Nick Brewer [ 06/Sep/18 ]

wynn Looking at the data provided, it doesn't appear that there's substantial CPU used before or after the reboot (where the --syslog option was presumably added):

I believe the disparity here is due to the fact that, by default, top measures CPU usage percentage as 100% per core, meaning that multi-core systems can easily exceed 100% usage. So this line:

29078 root 20 0 6586752 5.919g 6920 S 99.7 38.2 0:48.07 mongod

Indicates that mongod is utilizing one core on this 8-core system.

-Nick

Comment by wynn zhao [ 06/Sep/18 ]

Hi Nick,

diagnostic.data has been attached. 

Best Regards!

Wynn

Comment by Nick Brewer [ 05/Sep/18 ]

wynn Could you please archive (tar or zip) and upload the dbpath/diagnostic.data directory to this ticket?

Thanks,
Nick

Generated at Thu Feb 08 04:44:40 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.