[SERVER-36835] High mongod CPU usage on multiple change streams Created: 24/Aug/18  Updated: 06/Dec/22

Status: Backlog
Project: Core Server
Component/s: Performance
Affects Version/s: 3.6.6
Fix Version/s: None

Type: Question Priority: Major - P3
Reporter: Dmitry Volodin Assignee: Backlog - Query Execution
Resolution: Unresolved Votes: 0
Labels: change-streams-improvements
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

MongoDB shell version v3.6.6
git version: 6405d65b1d6432e138b44c13085d0c2fe235d6bd
OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013
allocator: tcmalloc
modules: none
build environment:
distmod: rhel70
distarch: x86_64
target_arch: x86_64

Pymongo 3.7.1


Attachments: PNG File cpu.png     PNG File image.png    
Issue Links:
Related
is related to SERVER-42885 Registering multiple change stream wa... Backlog
Assigned Teams:
Query Execution
Participants:

 Description   

We've noticed increased mongod CPU usage when trying to watch change streams.

One of our microservices tracks changes on 6 specially prepared collections and notifies clients when change occures. Service implemented in python (Pymongo 3.7.1). Part of relevant code below

    def watch_waiter(self, coll, queue):
        """
        Waiter thread tracking mongo's ChangeStream
        :param coll:
        :param queue:
        :return:
        """
        while True:
            with coll.watch(pipeline=[{"$project": {"_id": 1}}]) as stream:
                try:
                    for _ in stream:
                        # Change received, call all pending callback
                        self._run_callbacks(queue)
                except pymongo.errors.PyMongoError as e:
                    self.logger.error("Unrecoverable watch error: %s", e)
                    time.sleep(1)

Each service starts separate thread per each change stream (6 in total), we have total of 3 services in our cluster.

Tracked collections are relatively rarely changed (100-1000 changes per day).

Setup works as expected on single-node replica set. When trying to deploy on 3-node replica set we observing additional significant CPU consuming by mongod service. Our service remains fully functional and works as expected.

mongod CPU usage chart is attached.

mongod also reports slow getMore operations on tracked collections

авг 24 05:25:27 ddb03fm mongod.27017[1958]: [conn87463] command sova.ds_managedobject command: getMore { getMore: 7824301615466829785, collection: "ds_managedobject", lsid: { id: UUID("0814702b-262e-48e7-9ae5-09a68a1560fd") }, $clusterTime: { clusterTime: Timestamp(1535052326, 131), signature: { keyId: 6590282739075777080, hash: BinData(0, D233053EEFA7C58E0DD1AE898977806564882F53) } }, $db: "sova", $readPreference: { mode: "primary" } } originatingCommand: { aggregate: "ds_managedobject", pipeline: [ { $changeStream: { fullDocument: "default" } }, { $project: { _id: 1 } } ], cursor: {}, lsid: { id: UUID("0814702b-262e-48e7-9ae5-09a68a1560fd") }, $clusterTime: { clusterTime: Timestamp(1535052160, 573), signature: { keyId: 6590282739075777080, hash: BinData(0, 52ED832339DA7BC72BAEA5CAB7C989E5B130A3DA) } }, $db: "sova", $readPreference: { mode: "primary" } } planSummary: COLLSCAN cursorid:7824301615466829785 keysExamined:0 docsExamined:822 numYields:2485 nreturned:0 reslen:218 locks:{ Global: { acquireCount: { r: 4974 } }, Database: { acquireCount: { r: 2487 } }, oplog: { acquireCount: { r: 2486 } } } protocol:op_msg 100ms

Altering pipeline options (including empty pipelines) leads to no visible effect.

We've replaced our waiter thread with simple poller

    def sleep_waiter(self, coll, queue):
        """
        Simple timeout waiter
        :param coll:
        :param queue:
        :return:
        """
        TIMEOUT = 60
        JITER = 0.1
        while True:
            # Sleep timeout is random of [TIMEOUT - TIMEOUT * JITTER, TIMEOUT + TIMEOUT * JITTER]
            time.sleep(TIMEOUT + (random.random() - 0.5) * TIMEOUT * 2 * JITER)
            self._run_callbacks(queue)

and observed CPU usage dropped to usual levels.

Is this expected behaviour? How can we estimate change streams watching penalty?



 Comments   
Comment by Joe Kanaan [ 09/Mar/22 ]

3.6 is EOL

Comment by Aleksey Shirokih [ 28/Aug/18 ]

collStats files on the store

Comment by Dmitry Volodin [ 28/Aug/18 ]

We have a set of collections, called DataStreams. Each DataStream contains specially prepared set of data which may be tracked by external systems. DataStream API supports long polling mode, holding incoming request until appropriative collection been changed.
So the main purpose of callbacks is to set events when collection has been changed. Incoming requests call wait() function below and puts callback to the queue. waiter_thread from above tracks change stream and calls all pending callbacks, waking up requests

    def _run_callbacks(self, queue):
        """
        Execute callbacks from queue
        :param queue:
        :return:
        """
        while True:
            try:
                cb = queue.get(block=False)
            except Queue.Empty:
                break
            cb()
 
    @tornado.gen.coroutine
    def wait(self, ds_name):
        def notify():
            ioloop.add_callback(event.set)
 
        if ds_name not in self.ds_queue:
            raise tornado.gen.Return()
        event = tornado.locks.Event()
        ioloop = tornado.ioloop.IOLoop.current()
        self.ds_queue[ds_name].put(notify)
        yield event.wait()

This scheme works as expected for single-node mongo, but implies significant penalty on 3-node cluster.

DataStream API is below https://docs.getnoc.com/microservices/en/api/datastream.html

Comment by Nick Brewer [ 27/Aug/18 ]

Volodin, freeseacher I'd like to confirm a few things:

  • What is the intended purpose of the callback in this code?
  • The collStats output on a collection that you're creating change streams for.

Thanks,
-Nick

Comment by Aleksey Shirokih [ 24/Aug/18 ]

Hi. i will assist Dmitriy with owr case. files uploaded ok

Comment by Nick Brewer [ 24/Aug/18 ]

Volodin Thanks for your report. Could you please upload:

  • mongod logs from the time this increase in CPU usage is seen
  • an archive (tar or zip) of the dbpath/diagnostic.data directory

I've created a secure portal where you can upload this information; it will only be visible to MongoDB employees, and is automatically removed after a period of time.

Thanks,
Nick

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