[SERVER-75514] baseline CPU usage and disk reads increased significantly with >6.0.3 Created: 30/Mar/23  Updated: 07/Jul/23  Resolved: 07/Jul/23

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

Type: Bug Priority: Major - P3
Reporter: Jordan Baczuk Assignee: Chris Kelly
Resolution: Done Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

MongoDB v6.0.3 on a t3.micro (x86_64) running Ubuntu 18.04.2 LTS with a gp3 volume for data storage and an ext4 filesystem


Attachments: Text File 6.0.3-right-after-query.log     Text File 6.0.4-right-after-query.log     PNG File Screenshot 2023-03-30 at 12.41.54 PM.png     JPEG File benchmark-run_1.jpg     PNG File image-2023-04-05-12-53-43-841.png     PNG File image-2023-05-04-15-32-47-938.png     PNG File image-2023-05-08-14-49-54-836.png     PNG File image-2023-05-08-15-19-52-496.png     PNG File image-2023-05-08-15-40-30-396.png     PNG File image-2023-05-08-15-47-22-326.png     PNG File image-2023-05-09-09-48-07-236.png     PNG File image-2023-05-09-09-49-58-689.png     PNG File image-2023-05-09-09-52-02-605.png     PNG File image-2023-05-09-09-52-24-063.png     PNG File image-2023-05-09-09-54-15-302.png     PNG File image-2023-05-09-10-08-24-250.png     PNG File image-2023-05-10-14-22-20-430.png     PNG File image-2023-05-10-14-23-37-933.png     PNG File image-2023-05-17-20-16-34-127.png     PNG File image-2023-05-17-20-16-42-067.png     PNG File image-2023-06-06-14-15-39-342.png     File updateOnetest.js    
Assigned Teams:
Product Performance
Operating System: ALL
Participants:

 Description   

baseline CPU usage and disk reads increased significantly with >6.0.3

Hi! We are running MongoDB v6.0.3, when the database was upgraded to v6.0.5, the following changes were noted on the server and disk volume (without changes to the application using the database):

  • the average CPU usage went up from about 4.5% to 30%
  • average read bandwidth increased from about 100kiB/s to 4MiB/s
  • read throughput increased from 2 ops/s to 700 ops/s
  • average read size decreased from 40kiB/s to 5kiB/s

The same changes were observed in v6.0.4 and downgrading to v6.0.3 resolved the issue.

Was something changed in v6.0.4 that may have cause this? I'm trying to figure out what I need to change in order to support the newer versions without the huge performance hit.



 Comments   
Comment by Jordan Baczuk [ 07/Jul/23 ]

Thanks for your help, what info I can provide is that we have a collection with 300GB of data with a structure similar to this:

 
{
  "_id": ObjectId,
  "name": String,
  "ts": Date,
  "version": String,
  "count": number,
  "data_valid": boolean[60],
  "row":

{     "someValue": number[60],     ...+24similarfields   }

,
  "avgSum":

{     "someValue": 1078.2,     ...+24similarfields   }

}
The next step is probably to try to create a similar dataset and reproduce the issue. Our current resolution is to remain on MongoDB v6.0.3 until there is a need to upgrade. We can revisit this at that time, and if we're lucky it will be resolved by others by then.

Comment by Chris Kelly [ 07/Jul/23 ]

We haven’t heard back from you for some time, so I’m going to close this ticket. If this is still an issue for you, please provide additional information and we will reopen the ticket.

Comment by Chris Kelly [ 06/Jun/23 ]

Hi ben.figlin@qnergy.com,

Thanks for your patience, and supplying additional information.

However, given what's provided, it still lends itself to being something workload-specific that we may need your specific case to understand fully. If you have a test driver that is reproducing the issue, we would definitely like to see it.

I attempted to verify these claims independently and did not observe your issue, using updateOne and updateMany with a node driver against MongoDB 6.0.3 and 6.0.4, with 100,000 pre-inserted documents. I did not observe the cache behavior you appear to be observing. 

 

 

Where A->B is attempting to concurrently update around 100,000 documents in a single collection in a 3 node replica set, as a string of updateOne commands. I attempted the same with updateMany with similar results.

Comment by Ben Figlin [ 18/May/23 ]

I also collected the stack trace for 6.0.4 when the CPU was in the iowait state versus when it was idle, the stack trace looks quite identical except for ONE thread which is different, and as I expected, it is the checkpointer:

6.0.4 right after running the query, while in high CPU iowait state:

{"t":{"$date":"2023-05-18T14:45:55.128+00:00"},"s":"I",  "c":"COMMAND",  "id":31425,   "ctx":"SignalHandler","msg":"Stacktrace Record","attr":{"record":{"name":"Checkpointer","tid":31021,"backtrace":[{"b":"000","o":"4DD7C39","s":"_ZN5mongo12rawBacktraceEPPvm","s+":"9"},{"b":"000","o":"4DDF923","s":"stateSingletonAction","s+":"123"},{"b":"001","o":"12890"},{"b":"001","o":"11F9F","s":"pread64","s+":"4F"},{"b":"000","o":"2A2D4B6"},{"b":"000","o":"2B9A6E2","s":"__wt_block_read_off","s+":"192"},{"b":"000","o":"2B9AC31","s":"__wt_bm_read","s+":"A1"},{"b":"000","o":"2A975A6","s":"__wt_blkcache_read","s+":"3B6"},{"b":"000","o":"2ACD62C"},{"b":"000","o":"2ACE96E","s":"__wt_page_in_func","s+":"41E"},{"b":"000","o":"2B027EA"},{"b":"000","o":"2AF34C8","s":"__wt_sync_file","s+":"4A8"},{"b":"000","o":"2A7E1FB"},{"b":"000","o":"2A7F2D3"},{"b":"000","o":"2A80C46","s":"__wt_txn_checkpoint","s+":"246"},{"b":"000","o":"1AC2CF0"},{"b":"000","o":"2988D32","s":"_ZN5mongo18WiredTigerKVEngine11_checkpointEP12__wt_session","s+":"1B2"},{"b":"000","o":"298B1B0","s":"_ZN5mongo18WiredTigerKVEngine10checkpointEv","s+":"40"},{"b":"000","o":"31BF0F4","s":"_ZN5mongo12Checkpointer3runEv","s+":"DD4"},{"b":"000","o":"4BBB386","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"E6"},{"b":"000","o":"4BBB9EC"},{"b":"000","o":"4F7BC4F"},{"b":"001","o":"76DB"},{"b":"002","o":"12188F","s":"clone","s+":"3F"}]}}}
 

 

6.0.4 right after running the query, after high CPU iowait state ends and CPU back to idle:

{"t":{"$date":"2023-05-18T14:48:24.597+00:00"},"s":"I",  "c":"COMMAND",  "id":31425,   "ctx":"SignalHandler","msg":"Stacktrace Record","attr":{"record":{"name":"Checkpointer","tid":31021,"backtrace":[{"b":"000","o":"4DD7C39","s":"_ZN5mongo12rawBacktraceEPPvm","s+":"9"},{"b":"000","o":"4DDF923","s":"stateSingletonAction","s+":"123"},{"b":"001","o":"12890"},{"b":"001","o":"DF85","s":"pthread_cond_timedwait","s+":"335"},{"b":"000","o":"31BEA2A","s":"_ZN5mongo12Checkpointer3runEv","s+":"70A"},{"b":"000","o":"4BBB386","s":"_ZN5mongo13BackgroundJob7jobBodyEv","s+":"E6"},{"b":"000","o":"4BBB9EC"},{"b":"000","o":"4F7BC4F"},{"b":"001","o":"76DB"},{"b":"002","o":"12188F","s":"clone","s+":"3F"}]}}}
 

Comment by Ben Figlin [ 18/May/23 ]

Hi,

 

I moved the DB data to an XFS filesystem, just in case. exact same behavior as before. 

I tried comparing 6.0.3 to 6.0.4 so that there is the smallest possible amount of changes between the two version. 6.0.3 has no issues, 6.0.4 has issues.

 

I enabled log verbosity as mentioned above, the difference in the log files between the two versions is this line that shows up on 6.0.4:

"ctx":"Checkpointer","msg":"Checkpoint was slow to complete","attr":{"secondsElapsed":32}} 

it happens twice, and is consistent with two ~30 second periods of high CPU in iowait. during those iowait periods the RAM usage increases and there are a lot of disk reads.

 

two logs (filtered by "Checkpointer")

6.0.3:

{"t":{"$date":"2023-05-18T01:55:34.638+00:00"},"s":"D1", "c":"WTCHKPT",  "id":22430,   "ctx":"Checkpointer","msg":"WiredTiger message","attr":{"message":{"ts_sec":1684374934,"ts_usec":638434,"thread":"4739:0x7ff88d7eb700","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":6,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"saving checkpoint snapshot min: 100006, snapshot max: 100006 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 9681703"}}}
{"t":{"$date":"2023-05-18T01:55:34.659+00:00"},"s":"D2", "c":"RECOVERY", "id":5576602, "ctx":"Checkpointer","msg":"Completed unstable checkpoint.","attr":{"initialDataTimestamp":"Timestamp(0, 0)"}}
{"t":{"$date":"2023-05-18T01:56:34.664+00:00"},"s":"D1", "c":"WTCHKPT",  "id":22430,   "ctx":"Checkpointer","msg":"WiredTiger message","attr":{"message":{"ts_sec":1684374994,"ts_usec":664147,"thread":"4739:0x7ff88d7eb700","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":6,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"saving checkpoint snapshot min: 102027, snapshot max: 102027 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 9681703"}}}
{"t":{"$date":"2023-05-18T01:56:34.672+00:00"},"s":"D2", "c":"RECOVERY", "id":5576602, "ctx":"Checkpointer","msg":"Completed unstable checkpoint.","attr":{"initialDataTimestamp":"Timestamp(0, 0)"}}
{"t":{"$date":"2023-05-18T01:57:34.698+00:00"},"s":"D1", "c":"WTCHKPT",  "id":22430,   "ctx":"Checkpointer","msg":"WiredTiger message","attr":{"message":{"ts_sec":1684375054,"ts_usec":698705,"thread":"4739:0x7ff88d7eb700","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":6,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"saving checkpoint snapshot min: 200010, snapshot max: 200010 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 9681703"}}}
{"t":{"$date":"2023-05-18T01:57:34.714+00:00"},"s":"D2", "c":"RECOVERY", "id":5576602, "ctx":"Checkpointer","msg":"Completed unstable checkpoint.","attr":{"initialDataTimestamp":"Timestamp(0, 0)"}} 

6.0.4

{"t":{"$date":"2023-05-18T02:01:51.596+00:00"},"s":"D1", "c":"WTCHKPT",  "id":22430,   "ctx":"Checkpointer","msg":"WiredTiger message","attr":{"message":{"ts_sec":1684375311,"ts_usec":596572,"thread":"6627:0x7fd673bb7700","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":6,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"saving checkpoint snapshot min: 64327, snapshot max: 64327 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 9682020"}}}
{"t":{"$date":"2023-05-18T02:01:51.615+00:00"},"s":"D2", "c":"RECOVERY", "id":5576602, "ctx":"Checkpointer","msg":"Completed unstable checkpoint.","attr":{"initialDataTimestamp":"Timestamp(0, 0)"}}
{"t":{"$date":"2023-05-18T02:01:51.616+00:00"},"s":"D1", "c":"STORAGE",  "id":22308,   "ctx":"Checkpointer","msg":"Checkpoint was slow to complete","attr":{"secondsElapsed":30}}
{"t":{"$date":"2023-05-18T02:03:24.468+00:00"},"s":"D1", "c":"WTCHKPT",  "id":22430,   "ctx":"Checkpointer","msg":"WiredTiger message","attr":{"message":{"ts_sec":1684375404,"ts_usec":468211,"thread":"6627:0x7fd673bb7700","session_name":"WT_SESSION.checkpoint","category":"WT_VERB_CHECKPOINT_PROGRESS","category_id":6,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"saving checkpoint snapshot min: 100006, snapshot max: 100006 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 9682020"}}}
{"t":{"$date":"2023-05-18T02:03:24.480+00:00"},"s":"D2", "c":"RECOVERY", "id":5576602, "ctx":"Checkpointer","msg":"Completed unstable checkpoint.","attr":{"initialDataTimestamp":"Timestamp(0, 0)"}}
{"t":{"$date":"2023-05-18T02:03:24.481+00:00"},"s":"D1", "c":"STORAGE",  "id":22308,   "ctx":"Checkpointer","msg":"Checkpoint was slow to complete","attr":{"secondsElapsed":32}}
 

CPU usage (notice the iowait, in purple, which aligns with the checkpoint saving) - same operation, which ran and completed in 45 seconds in both cases

6.0.3:

 

6.0.4:

 

 

With another run, I attached full log right after the query itself finishes (where this high CPU iowait happens on 6.0.4), heap profiling enabled as well. see the two log files in the ticket.

These lines seem to show up on 6.0.4 but not on 6.0.3:

{"t":{"$date":"2023-05-18T02:31:58.048+00:00"},"s":"I",  "c":"-",        "id":23158,   "ctx":"ftdc","msg":"heapProfile stack","attr":{"stackNum":646,"stackObj":{"0":"MallocHook::InvokeNewHookSlow","1":"tc_realloc","2":"0x556b12cbee26","3":"__wt_buf_grow_worker","4":"__wt_blkcache_read","5":"0x556b12d6362c","6":"__wt_page_in_func","7":"0x556b12d987ea","8":"__wt_sync_file","9":"0x556b12d141fb","10":"0x556b12d152d3","11":"__wt_txn_checkpoint","12":"0x556b11d58cf0","13":"mongo::WiredTigerKVEngine::_checkpoint","14":"mongo::WiredTigerKVEngine::checkpoint","15":"mongo::Checkpointer::run","16":"mongo::BackgroundJob::jobBody","17":"0x556b14e519ec","18":"0x556b15211c4f","19":"0x7fddcdaca6db","20":"clone"}}}
{"t":{"$date":"2023-05-18T02:31:58.070+00:00"},"s":"I",  "c":"-",        "id":23158,   "ctx":"ftdc","msg":"heapProfile stack","attr":{"stackNum":649,"stackObj":{"0":"MallocHook::InvokeNewHookSlow","1":"tc_calloc","2":"__wt_calloc","3":"__wt_page_alloc","4":"__wt_page_inmem","5":"0x556b12d6367a","6":"__wt_page_in_func","7":"0x556b12d987ea","8":"__wt_sync_file","9":"0x556b12d141fb","10":"0x556b12d152d3","11":"__wt_txn_checkpoint","12":"0x556b11d58cf0","13":"mongo::WiredTigerKVEngine::_checkpoint","14":"mongo::WiredTigerKVEngine::checkpoint","15":"mongo::Checkpointer::run","16":"mongo::BackgroundJob::jobBody","17":"0x556b14e519ec","18":"0x556b15211c4f","19":"0x7fddcdaca6db","20":"clone"}}} 

6.0.3-right-after-query.log

6.0.4-right-after-query.log

 

I think these graphs (that were uploaded here by the MongoDB team) show a very clear difference with caching or something else to do with memory usage that is very different between <=6.0.3 and 6.0.4:

Comment by Chris Kelly [ 10/May/23 ]

Thanks for clarifying! This is definitely interesting; some additional data may help us uncover what's going on.

Some comments:

  • Getting more information about the queries actually being ran, and what the process is doing may be helpful in figuring out what's going on between the two cases. There's a few suggestions I have for getting more info:
    • Enable the heap profiler on startup with 

      -setParameter heapProfilingEnabled=true 

    • Please collect a stack trace with SIGUSR2 during the test for 6.0.3 and 6.0.5

      # collect backtrace with SIGUSR2
      # Stack traces collected this way are dumped to the mongod.log  
      # file. hint: look for the word 'stacktrace'
      kill -s USR2 $pid
      

    • Increase log verbosity with:

      db.adminCommand( {
         setParameter: 1,
         logComponentVerbosity: {
            verbosity: 1,
            query: { verbosity: 2 },
            storage: {
               verbosity: 2,
               journal: {
                  verbosity: 1
               }
            }
         }
      } )

  • We noticed you're using the ext4 filesystem, and we recommend XFS to avoid performance issues with the WiredTiger storage engine. Do you observe the same issues with that file system?
    • This would be a bit odd since you are observing a noticeable difference between minor patch versions, but may be an interesting data point.
Comment by Ben Figlin [ 10/May/23 ]

chris.kelly@mongodb.com

 

The credits are not fully utilized during the tests. 

Also, we can go back and forth between 6.0.3 and 6.0.5, multiple times, and clearly see the performance hit on 6.0.5. We tried it multiple times, sometimes with 6.0.5 first, sometimes with 6.0.3 first.

 

The performance analysis screen shots that ahmad.shah@mongodb.com uploaded show a clear and large difference between the two versions, specifically on the read ops and the io wait CPU state. I understand that this is likely due to a bottleneck on the storage, but this bottleneck does not exist on <6.0.3, so I guess something in the way 6.0.5 handles storage access is different.

Just a reminder per the original ticket description, the issue started with 6.0.4, and continued to happen with 6.0.5.

 

Thanks,

Ben

 

Comment by Chris Kelly [ 10/May/23 ]

Hi jordan.baczuk@qnergy.com,

After reviewing your most recent data, we are suspecting this issue is possibly related to the use of the T3 micro instance for this test. Specifically, if you are running the test on 6.0.3 first, we are initially suspecting you may be utilizing your burst credits prior to the 6.0.5 run. Before going further, can you please clarify:

  • Are you properly cleaning the instance between test runs?
  • Are you always running the 6.0.3 test immediately before the 6.0.5 test?
    • If so, running the 6.0.5 one first and confirming if the same behavior occurs would be interesting.

Chris

Comment by Ben Figlin [ 10/Apr/23 ]

Hi chris.kelly@mongodb.com , I'm jordan.baczuk@qnergy.com's teammate. 

I created a test nodejs script that updates 100k documents in a collection, always the same documents for consistency. The script runs on a different server from the mongod instance itself to isolate resources used by nodejs from resources used by mongod. nothing else is using the DB at the time of the tests.
I ran it in an identical environment with the only difference being mongodb v6.0.3 vs v6.0.5.

 

Please see the attached image (those charts were taken from netdata).

It is clear that with 6.0.5 there is a strange huge spike in IOPS on the db data storage disk which lasts a relatively long time after the script has ended and exited, plus, there is another strange spike that comes later, and only happens on 6.0.5. The CPU usage in all charts comes from the mongod service.

With 6.0.3, the CPU usage and disk usage look normal, and the CPU goes down to ~0% immediately after the script ends.

 

I also sent the diagnostic and log files to the secure upload link you shared above (file name 6.0.3-vs-6.0.5_same-operation.zip).

 

 

 

Comment by Jordan Baczuk [ 10/Apr/23 ]

chris.kelly@mongodb.com Ok, I wasn't sure how to interpret the charts you posted. I assume that both versions of the database are charted together with the older version first. I can try to set that test environment up again when I have time. It is quite strange that the CPU usage is lower for the last version, while on the EC2 instance, you can see it is quite higher. AFAIK, there were no other applications running on that instance, only MongoDB (except for the stuff that comes installed by default), so I'm not sure where to look next. In the meantime, is there a tool that I can use to view the diagnostic data on my end?

Comment by Chris Kelly [ 07/Apr/23 ]

No problem, jordan.baczuk@qnergy.com! To address your concerns:

  • The "opcounters" metric is independent of the slow query threshold. Here, it's derived from the serverStatus command. So, I would expect it to be accurate here.
  • Regarding CPU increase; I don't actually observe the CPU usage you're mentioning. In fact, the max CPU usage on your 6.0.3 run appeared to be noticeably worse at its worst (~52% usage) whereas 6.0.5 maxed out at 19.4% with no noticeable spike.

I would confirm that:

  • Your test is producing the exact same workload on both instances
  • The diagnostic data is reflecting the time of the correct time period
  • There is a specific code example that produces this workload if possible

Christopher

 

Comment by Jordan Baczuk [ 06/Apr/23 ]

chris.kelly@mongodb.com Thanks for taking a look. The workload should have been identical between the 2 tests. Just some thoughts... It's possible a mistake was made when running the 6.0.5 test, but perhaps the 6.0.5 logs aren't showing the inserts because none of them broke the slow query threshold of 100ms? Also, if there were no inserts, shouldn't that be an even bigger red flag if the CPU usage increased that much?

Comment by Chris Kelly [ 06/Apr/23 ]

Hey jordan.baczuk@qnergy.com,

After review of your diagnostic data it appears the workloads between your two runs are not identical. Please supply a test driver that reproduces your observations clearly and identically between the two instances if possible.

For example: your 6.0.5 instance didn't perform any inserts, whereas 6.0.3 did. This implies some significant differences in the workload that makes it difficult to draw conclusions.

Comment by Jordan Baczuk [ 30/Mar/23 ]

That info has been uploaded, thanks.

Comment by Yuan Fang [ 30/Mar/23 ]

Hi jordan.baczuk@qnergy.com,

Thank you for your report. I understand that you have observed an increase in CPU usage and disk reads after upgrading to version >=v6.0.4. I will bring this to the attention of our team. In the meantime, could you please provide diagnostic data that covers the event of downgrading to v6.0.3, or, upgrading to v6.0.4/v6.0.5 so that we can compare the two versions (i.e. v6.0.3 and >=v6.0.4)?

I've created a secure upload portal for you. Files uploaded to this portal are hosted on Box, are visible only to MongoDB employees, and are routinely deleted after some time.

For each node in the replica set spanning a time period that includes the incident, would you please archive (tar or zip) and upload to that link:

  • the mongod logs
  • the $dbpath/diagnostic.data directory (the contents are described here)

Regards,
Yuan
 

Comment by Jordan Baczuk [ 30/Mar/23 ]

For more info, a couple of applications use the database from a node.js application. Their driver versions are 4.13.0 and 4.9.1. I tested both individually, and they each had the same effect on the performance as running both at the same time. In other words, only running one of the applications did not solve the issue.

Generated at Thu Feb 08 06:30:22 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.