[SERVER-74526] Change stream opened against a secondary node uses a lot of CPU even when there is no write load Created: 01/Mar/23  Updated: 29/Oct/23  Resolved: 03/Mar/23

Status: Closed
Project: Core Server
Component/s: Change streams, Query Execution
Affects Version/s: 6.3.0-rc0
Fix Version/s: 7.0.0-rc0, 6.3.0-rc1

Type: Bug Priority: Critical - P2
Reporter: David Storch Assignee: David Storch
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Problem/Incident
Related
related to SERVER-74555 Re-introduce majority commit point ad... Closed
is related to SERVER-69959 Introduce majority committed point ad... Closed
Assigned Teams:
Query Execution
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v6.3
Steps To Reproduce:

Start a 2-node replica set. I'm doing it like so:

$ ./mongo --nodb
> var rst = new ReplSetTest({nodes: 2}); rst.startSet(); rst.initiate();

Then connect to the secondary node and start watching a change stream on an arbitrary non-existent collection:

$ mongosh --port 20001
> db.getMongo().setReadPref("secondary");
> var cursor = db.foo.watch();
> while (cursor.hasNext()) { printjson(cursor.next()); }

You should be able to see the secondary node's CPU utilization spike. The CPU will become idle again if you stop iterating the change stream cursor.

Sprint: QE 2023-03-06
Participants:
Linked BF Score: 20

 Description   

The changes from SERVER-69959 introduced a performance regression starting in 6.3 for change streams opened against a replica set secondary node. Let's assume that the system is completely idle, with no reads or writes being issued by clients. The client opens a $changeStream against the idle system. The client's driver will issue getMore operations against this cursor in a loop in order to watch for changes. The expected behavior is that the thread executing the $changeStream will block on the server side waiting for inserts to the oplog. This thread should use very little CPU, since it waits on a condition variable rather than busy waiting.

The changes from SERVER-69959 appear to have caused the change stream thread to wake up far more often than it should. I added experimental logging to the server which showed that in 6.2, a change stream thread watching a secondary node of an idle system would wake up less than 10 times per second. For the same scenario in 6.3, however, the thread wakes up at least a few orders of magnitude more often. The consequence is that the change stream thread behaves effectively like it is busy waiting rather than blocking and has unreasonably high CPU utilization.

Again, this happens only for change streams opened against secondary nodes, not for change streams opened against primary nodes. I speculate it has something to do with differing behavior between primary and secondary nodes for how we choose which timestamp to read from?



 Comments   
Comment by Githook User [ 03/Mar/23 ]

Author:

{'name': 'David Storch', 'email': 'david.storch@mongodb.com', 'username': 'dstorch'}

Message: SERVER-74526 Fix high CPU utilization for a change streams opened against secondary nodes

This reverts commit 34ac49477b87e183637f68cda828ecff8b393c64. Future
work is needed to reintroduce the changes from SERVER-69959 without
causing the problematic "busy wait" behavior on secondary nodes.
Branch: master
https://github.com/mongodb/mongo/commit/67773ced2cb8c57935b9ea08331fe69bbc608d57

Comment by Githook User [ 02/Mar/23 ]

Author:

{'name': 'David Storch', 'email': 'david.storch@mongodb.com', 'username': 'dstorch'}

Message: SERVER-74526 Fix high CPU utilization for a change streams opened against secondary nodes

This reverts commit 34ac49477b87e183637f68cda828ecff8b393c64. Future
work is needed to reintroduce the changes from SERVER-69959 without
causing the problematic "busy wait" behavior on secondary nodes.
Branch: v6.3
https://github.com/mongodb/mongo/commit/96763fa1fef7faa2513afd2618d4d039ee70a6fe

Comment by David Storch [ 02/Mar/23 ]

The proposed fix is to revert the changes from SERVER-69959. I filed SERVER-74555 for the work of reintroducing the original change in such a way that is not subject to the high CPU utilization on secondaries problem.

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