Major slowdown since version 1.17.0

[floverdevel]

Hi all :)
It's my first bug report, i hope i supplied the right amount of information.

Bug Report

For a long time we ran our website with the mongodb extension version 1.16.0, 1.16.1 and 1.16.2.
It gave an http response between 200ms~300 ms.

A couple of weeks ago we updated php mongodb extension to version 1.17.0 and since this update, our website responds time is now from 1000ms to 2000ms.

Environment

The mongodb extension is installed via a Dockerfile

RUN apt-get update && \
    apt-get install -y --no-install-recommends \
    php8.2-apcu \
    php8.2-curl \
    php8.2-mbstring \
    php8.2-memcached \
    php8.2-mongodb \
    php8.2-mysql \
    php8.2-xml \
    && rm -rf /var/lib/apt/lists/* /usr/src/* /root/packages/* \
    && apt-get purge -y --auto-remove

Alongside we have a composer.json file who looks like this :

{
    "require": {
        "php": "8.2.*",
        "ext-gettext": "*",
        "doctrine/cache": "^1.8",
        "doctrine/mongodb-odm": "^2",
        "elasticsearch/elasticsearch": "^7",
        "http-interop/http-factory-guzzle": "^1.0",
        "jsq/amazon-es-php": "^0.3",
        "kreait/firebase-php": "^6.9",
        "monolog/monolog": "^1",
        "php-di/php-di": "^6",
        "slim/slim": "^4.1",
        "symfony/console": "^5.4",
        "symfony/routing": "^2.6.3",
        "twig/twig": "^2.10",
        "zeuxisoo/slim-whoops": "^0.7.0"
    },
}

Database is hosted on MongoDB Atlas.

Connection string looks like this : mongodb://USERNAME@dbmongo-prod-shard-00-00-XXX.mongodb.net:27017,dbmongo-prod-shard-00-01-XXX.mongodb.net:27017,dbmongo-prod-shard-00-02-XXX.mongodb.net:27017/?ssl=true&replicaSet=dbmongo-prod-shard-0&authSource=admin&readPreference=secondary&compressors=snappy

When running with 1.16

• php -v

PHP 8.2.12 (cli) (built: Oct 27 2023 13:00:10) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.2.12, Copyright (c) Zend Technologies
    with Zend OPcache v8.2.12, Copyright (c), by Zend Technologies

• php -i | grep mongo -i

/etc/php/8.2/cli/conf.d/20-mongodb.ini,
mongodb
MongoDB support => enabled
MongoDB extension version => 1.16.2
MongoDB extension stability => stable
libmongoc bundled version => 1.24.3
libmongoc SSL => enabled
libmongoc SSL library => OpenSSL
libmongoc crypto => enabled
libmongoc crypto library => libcrypto
libmongoc crypto system profile => disabled
libmongoc SASL => enabled
libmongoc ICU => disabled
libmongoc compression => enabled
libmongoc compression snappy => enabled
libmongoc compression zlib => enabled
libmongoc compression zstd => enabled
libmongocrypt bundled version => 1.8.1
libmongocrypt crypto => enabled
libmongocrypt crypto library => libcrypto
mongodb.debug => no value => no value

• composer show mongodb/mongodb : composer is not install in our Docker image, but composer.lock show this

        {
            "name": "mongodb/mongodb",
            "version": "1.15.0",
            "source": {
                "type": "git",
                "url": "https://github.com/mongodb/mongo-php-library.git",
                "reference": "3a681a3b2f2c0ebac227a3b86bb9057d0e6eb8f8"
            },
            "dist": {
                "type": "zip",
                "url": "https://api.github.com/repos/mongodb/mongo-php-library/zipball/3a681a3b2f2c0ebac227a3b86bb9057d0e6eb8f8",
                "reference": "3a681a3b2f2c0ebac227a3b86bb9057d0e6eb8f8",
                "shasum": ""
            },
            "require": {
                "ext-hash": "*",
                "ext-json": "*",
                "ext-mongodb": "^1.15.0",
                "jean85/pretty-package-versions": "^1.2 || ^2.0.1",
                "php": "^7.2 || ^8.0",
                "symfony/polyfill-php80": "^1.19"
            },
            "require-dev": {
                "doctrine/coding-standard": "^9.0",
                "squizlabs/php_codesniffer": "^3.6",
                "symfony/phpunit-bridge": "^5.2",
                "vimeo/psalm": "^4.28"
            },
            "type": "library",
            "extra": {
                "branch-alias": {
                    "dev-master": "1.15.x-dev"
                }
            },
            "autoload": {
                "files": [
                    "src/functions.php"
                ],
                "psr-4": {
                    "MongoDB\\": "src/"
                }
            },
            "notification-url": "https://packagist.org/downloads/",
            "license": [
                "Apache-2.0"
            ],
            "authors": [
                {
                    "name": "Andreas Braun",
                    "email": "andreas.braun@mongodb.com"
                },
                {
                    "name": "Jeremy Mikola",
                    "email": "jmikola@gmail.com"
                }
            ],
            "description": "MongoDB driver library",
            "homepage": "https://jira.mongodb.org/browse/PHPLIB",
            "keywords": [
                "database",
                "driver",
                "mongodb",
                "persistence"
            ],
            "support": {
                "issues": "https://github.com/mongodb/mongo-php-library/issues",
                "source": "https://github.com/mongodb/mongo-php-library/tree/1.15.0"
            },
            "time": "2022-11-23T04:45:35+00:00"
        },

When running with 1.17.0

• php -v

PHP 8.2.11 (cli) (built: Oct  6 2023 10:18:26) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.2.11, Copyright (c) Zend Technologies
    with Zend OPcache v8.2.11, Copyright (c), by Zend Technologies
    with Xdebug v3.3.0, Copyright (c) 2002-2023, by Derick Rethans

• php -i | grep mongo -i

/etc/php/8.2/cli/conf.d/20-mongodb.ini,
mongodb
MongoDB support => enabled
MongoDB extension version => 1.17.0
MongoDB extension stability => stable
libmongoc bundled version => 1.25.1
libmongoc SSL => enabled
libmongoc SSL library => OpenSSL
libmongoc crypto => enabled
libmongoc crypto library => libcrypto
libmongoc crypto system profile => disabled
libmongoc SASL => enabled
libmongoc ICU => disabled
libmongoc compression => enabled
libmongoc compression snappy => enabled
libmongoc compression zlib => enabled
libmongoc compression zstd => enabled
libmongocrypt bundled version => 1.8.2
libmongocrypt crypto => enabled
libmongocrypt crypto library => libcrypto
mongodb.debug => no value => no value

• composer show mongodb/mongodb : composer is not install in our Docker image, but composer.lock show this

        {
            "name": "mongodb/mongodb",
            "version": "1.17.0",
            "source": {
                "type": "git",
                "url": "https://github.com/mongodb/mongo-php-library.git",
                "reference": "9d9c917cf7ff275ed6bd63c596efeb6e49fd0e53"
            },
            "dist": {
                "type": "zip",
                "url": "https://api.github.com/repos/mongodb/mongo-php-library/zipball/9d9c917cf7ff275ed6bd63c596efeb6e49fd0e53",
                "reference": "9d9c917cf7ff275ed6bd63c596efeb6e49fd0e53",
                "shasum": ""
            },
            "require": {
                "ext-hash": "*",
                "ext-json": "*",
                "ext-mongodb": "^1.17.0",
                "jean85/pretty-package-versions": "^2.0.1",
                "php": "^7.4 || ^8.0",
                "psr/log": "^1.1.4|^2|^3",
                "symfony/polyfill-php80": "^1.27",
                "symfony/polyfill-php81": "^1.27"
            },
            "require-dev": {
                "doctrine/coding-standard": "^12.0",
                "rector/rector": "^0.18",
                "squizlabs/php_codesniffer": "^3.7",
                "symfony/phpunit-bridge": "^5.2",
                "vimeo/psalm": "^5.13"
            },
            "type": "library",
            "extra": {
                "branch-alias": {
                    "dev-master": "1.17.x-dev"
                }
            },
            "autoload": {
                "files": [
                    "src/functions.php"
                ],
                "psr-4": {
                    "MongoDB\\": "src/"
                }
            },
            "notification-url": "https://packagist.org/downloads/",
            "license": [
                "Apache-2.0"
            ],
            "authors": [
                {
                    "name": "Andreas Braun",
                    "email": "andreas.braun@mongodb.com"
                },
                {
                    "name": "Jeremy Mikola",
                    "email": "jmikola@gmail.com"
                },
                {
                    "name": "Jérôme Tamarelle",
                    "email": "jerome.tamarelle@mongodb.com"
                }
            ],
            "description": "MongoDB driver library",
            "homepage": "https://jira.mongodb.org/browse/PHPLIB",
            "keywords": [
                "database",
                "driver",
                "mongodb",
                "persistence"
            ],
            "support": {
                "issues": "https://github.com/mongodb/mongo-php-library/issues",
                "source": "https://github.com/mongodb/mongo-php-library/tree/1.17.0"
            },
            "time": "2023-11-15T09:21:50+00:00"
        },

Expected and Actual Behavior

additional information

Lately we also tried updating to PHP 8.3 + mongodb extension 1.17.0 but the results are the same : very slow performance.
That's the part on the rightmost of my screenshot, at the right of the red line.

[alcaeus]

Hi @floverdevel,

thank you for the detailed information. We've received a different report regarding a similar issue, but have not been able to reproduce it consistently. I was however see occasional performance degradation regarding SRV lookups using the 1.17 driver, but haven't yet found the source of the variance. I've published the script I was using in a gist, and it'd be very helpful if you could run it a few times in a 1.16 environment, followed by a few runs in a 1.17 environment.
The script takes a MONGODB_URI environment variable, which you can use to pass your own connection string. It then connects to the server, runs a ping command (to establish connections), followed by dropping a test collection, inserting a document, and retrieving said document. Feel free to change the database/collection names used in the example to not interfere with your database deployment. You can then share the output of the scripts (either a representative run, or better all runs you did) in a gist. When sharing logs, please make sure to not include the full connection string. While the script does print host names, it does not include credentials. You are free to replace host names with an anonymised version (i.e. maintaining the server numbers typically found in atlas URIs).

From my tests, I observed that working with data was unchanged (and even slightly faster in 1.17), but the process of connecting to the database deployment varies more significantly. I'm looking forward to seeing your logs so I can either confirm or refute my suspicion. If we have an update in the meantime, I'll update this ticket to keep you in the loop.

[floverdevel]

it'd be very helpful if you could run it a few times in a 1.16 environment, followed by a few runs in a 1.17 environment

Hi @alcaeus
Thank you very much for your answer.
I'm going to try your script and will share the output with you.

[floverdevel]

Hi @alcaeus
We ran some tests today with your script.
We did not found any obvious differences between to two drivers.

However, we were also able to install an APM agent on our website to track every layer of execution in our web application.
We found some interesting things with that tool :)

I will upload the result from your script and also going to upload some screenshots of our APM analysis later (maybe tonight but most likely tomorrow morning) but I just wanted to post this quick message to keep you up to date until I can upload those files.

Mainly, we found via the APM that almost every mongodb requests are 20 times slower to execute.
Even a simple request on a small collection (25 documents) is 20 time slower.

[ozon1234]

We do not use APM and measure time through PHP and also received a 2-fold slowdown for all requests (including even the simplest find-by-id requests) when updating to driver 1.17.
Purple line on a graph is a find a single document by id query:

Here is the code:

$tm = new Counter(Request::getLast(), ['service' => 'mongo', 'srv' => static::getCollectionName(), 'op' => 'find']);

$keys = ['_id' => $id];
try {
	$document = $this->getCollection()->findOne($keys);
} catch (ConnectionTimeoutException $e) {
	throw new ExternalStorageTimeoutException($e->getMessage());
}

unset($tm);

[adobre]

I have managed to reproduce the slowdown issue for inserts and also found the source of the problem in that particular case.

I used the following script to do the troubleshooting.

use MongoDB\Client;

require __DIR__ . '/vendor/autoload.php';

$client = new MongoDB\Client(
    'mongodb://localhost/',
    [
        'username' => 'user',
        'password' => 'pass',
        'ssl' => false,
        'authSource' => 'admin',
    ],
);

$collection = $client->test->big;

$a=microtime(true);
print((new \DateTimeImmutable())->format('Y-m-d H:i:s.u') . " generating document \n");
$document = [
    'username' => 'admin',
    'email' => 'admin@example.com',
    'name' => 'Admin User',
    'data' => str_repeat("abcdefghijklmnopqrstuvwxyz",1000*100)
];
$b=microtime(true);
print((new \DateTimeImmutable())->format('Y-m-d H:i:s.u') . " start insert \n");
$insertOneResult = $collection->insertOne($document);
$c=microtime(true);
print((new \DateTimeImmutable())->format('Y-m-d H:i:s.u') . " stop insert " . ($c-$b) .  " \n");

printf("Inserted %d document(s)\n", $insertOneResult->getInsertedCount());

var_dump($insertOneResult->getInsertedId());

The script inserts just one BIG document in a collection.
The size of the document is relevant to reproduce the issue.

With the driver 1.16.2 I get very good numbers ( under 500ms to finish the script ) with normal CPU usage.
With the driver 1.17.0 and 1.17.1 I get very poor numbers ( more than 4 seconds ) with very high CPU usage seen in htop.

The drivers where installed using pecl ( sudo pecl install mongodb-1.17.1 ).
I executed the tests on my laptop in Ubuntu 22, with PHP 8.1 using the command time php script.php.

I traced the problem in the following call chain that is executed during each write on the connection socket: _mongoc_socket_try_sendv -> DUMP_IOVEC (sendbuf, iov, iovcnt); -> mongoc_log_trace_iovec

When using the driver version 1.17.x, the function mongoc_log_trace_iovec is executed to completion without any message being logged. The method _mongoc_log_trace_is_enabled returns true and mongoc_log does not do anything.

In case of the 1.16.2 driver, the method returns before doing any intensive processing :
if (!_mongoc_log_trace_is_enabled ()) { return; }

bool _mongoc_log_trace_is_enabled (void) { return gLogTrace && MONGOC_TRACE_ENABLED; }

After the code in https://jira.mongodb.org/browse/PHPC-2180 was merged, the trace is enabled all the time mainly because the gLogTrace variable is always true.

In version 1.16.2 the variable gLogTrace was set to false by the call chain PHP_INI_MH->phongo_log_disable->mongoc_log_trace_disable.

In version 1.17.x that variable should be configured by PHP_INI_MH->phongo_log_set_stream(NULL)->phongo_log_sync_handler()->mongoc_log_trace_disable.
Unfortunately the call to phongo_log_set_stream exists before calling the mongoc_log_trace_disable function:
if (prev_stream == stream) { return; }

The macro DUMP_IOVEC is also used in socket read operations
So this would also explain why all the operations are impacted.

Let me know if there is anything else I can help you with.

[alcaeus]

@adobre Wow, you went above and beyond with this one! I'm not sure why I wasn't able to identify this in our performance tests, but the note that this becomes noticeable with big documents was the pointer I needed. Your root cause analysis is the cherry on top and absolutely spot on.

I've created #1504 to fix this, and as you suggested it's simply disabling trace logging at initialisation time, as phongo_log_sync_handlers is never called in a scenario where the mongodb.debug setting is disabled. I've confirmed the fix works in local testing, but if you want to confirm yourself you can grab a copy of the driver from my fork and build it yourself. Instructions for doing so can be found in the PHP documentation.

Thank you for taking the time to investigate this, it helped us out a lot!

[alcaeus]

1.17.2 has been released, with a more detailed post-mortem posted in JIRA. I'm closing this issue, but please let us know if this fixes the issue for you or if you continue to see performance issues. Thank you all for your patience!

[adobre]

I tested the latest version 1.17.2 and the performance issue does not manifest anymore.
Thank you!