Major slowdown since version 1.17.0 about mongo-php-driver HOT 8 CLOSED

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' => '[email protected]',
    '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.

from mongo-php-driver.

@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!

from mongo-php-driver.

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

from mongo-php-driver.

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.

from mongo-php-driver.

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!

from mongo-php-driver.

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.

from mongo-php-driver.

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.

from mongo-php-driver.

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);

from mongo-php-driver.