Perf issues with prepared statements ?

[yched]

I'm seeing a large perf impact on prepared queries vs regular queries :

\Amp\Promise\wait(
    \Amp\call(function() {
        $db = yield \Amp\Mysql\connect('host=127.0.0.1;user=root;pass=foobar;db=my_db');
        for ($i = 0; $i < 10; $i++) {
            $time = microtime(true);
            $results = yield $db->execute("SELECT :rand", [ 'rand' => rand() ]);
            yield $results->advance();
            echo round((microtime(true) - $time) * 1000, 2) . " ms" . PHP_EOL;
        }
    })
);

outputs : 2.73 ms 40.8 ms 39.99 ms 40.22 ms 40.02 ms 39.91 ms 40 ms 39.98 ms 40 ms 39.57 ms

Same code using a regular query :

\Amp\Promise\wait(
    \Amp\call(function() {
        $db = yield \Amp\Mysql\connect('host=127.0.0.1;user=root;pass=foobar;db=my_db');
        for ($i = 0; $i < 10; $i++) {
            $time = microtime(true);
            $results = yield $db->query(sprintf("SELECT %d", rand()));
            yield $results->advance();
            echo round((microtime(true) - $time) * 1000, 2) . " ms" . PHP_EOL;
        }
    })
);

outputs : 1.89 ms 0.37 ms 0.37 ms 0.36 ms 0.36 ms 0.36 ms 0.36 ms 0.36 ms 0.41 ms 0.32 ms

40ms overhead per query seems fairly taxing for the confort of prepared queries ?

[trowski]

I tried your examples and see approximately 2x difference for execute vs. query, which is in line with my expectations.

Locally I get something around 1.3 ms for execute and 0.8 ms for query.

Could you take another look? Maybe there's something on your system specifically that's slowing down prepares. Where is the most time being spent in the prepared requests?

[staabm]

Maybe xdebug or blackfire or simlar extension loaded which can have such impact?

[yched]

Thanks for the feedback.

Double-checked : xdebug and blackfire are off

Will try to run it through blackfire to see where the time is spent.

[yched]

So I ran both scripts above in blackfire, here are the corresponding profiles:

• query() : 19ms for 10 queries
• execute() : 385ms for 10 queries
• comparison +1910%, +366ms

Most of the extra time seems to be spent in stream_select() (+339ms) - not sure what it's waiting for. There's also 10 more calls to stream_select() in the "execute()" script, that is 1 extra call per query.

Could it be something with my mysql setup ? (5.7.20-0ubuntu0.16.04.1)

[kelunik]

@yched Do you use TLS?

[yched]

@kelunik You mean between php and mysql ? Not that I know of (and I could not find any sign of that in my /etc/mysql/my.conf, but maybe I'm not seeing it right ?)

Basically, this is just a CLI script on my local dev machine, with my local php and mysql both pretty much off-the-shelf from the ubuntu packages.

[trowski]

execute() makes another round-trip to the MySQL server, so everything you said makes sense. With all the time spent in stream_select() it seems the server is just taking it's sweet time to respond.

This thread in the MySQL bug tracker may be relevant. Logging may be slowing the prepare. It appears the speed may be improved in 5.8.

[yched]

@trowski Thanks for the heads-up, this sounds related indeed.

PDO prepared queries don't seem to be affected, though ? Using DBAL, $db->fetchAssoc("SELECT :rand", [ 'rand' => rand() ]) completes in < 1ms, roughly like the non-prepared amp/mysql queries.

[trowski]

Ensure that PDO::ATTR_EMULATE_PREPARES has not been set to true somewhere, as this causes PDO to use client-side escaping and string concatenation instead of server-side prepares. If that's not the case then double check the connection settings for any differences… beyond that I'm running out of ideas.

[yched]

Right, PDO::ATTR_EMULATE_PREPARES is true on my setup (not sure where this default is set though).

OK, so in summary, this is caused by my mysql setup, this might get better in 5.8, and for some reason your setup doesn't show this perf impact :-)

[yched]

Regarding the mysql issue you mentioned, and that is apparently fixed in 5.8 - it is supposedly only triggered "if the binlog, general log, or slow log is enabled", which AFAICT is not the case on my setup :

$ mysqladmin variables | grep log
...
| general_log                                              | OFF
...
| log_bin                                                  | OFF
...
| slow_query_log                                           | OFF

[kelunik]

@yched Could you try to run these tests against a Docker image and if it doesn't show the slow behavior, change the Docker image so it's reproducible?

[yched]

Done, the behavior can be seen with this repro repo: https://github.com/yched/amphp_mysql_prepare_55 (mysql 5.7.20 / php 7.2.1)

[kelunik]

Thanks, I can reproduce those numbers on my system.

GitHub/yched/amphp_mysql_prepare_55 on  master on 🐳 v17.09.0-ce took 4s 
➜ docker-compose run php php amphp_sql_prepare.php
3.68 ms
46.92 ms
43.37 ms
43.88 ms
44.63 ms
43.52 ms
44.57 ms
43.83 ms
50.3 ms
41.22 ms

GitHub/yched/amphp_mysql_prepare_55 on  master on 🐳 v17.09.0-ce took 3s 
➜ docker-compose run php php amphp_sql_query.php  
2.18 ms
0.49 ms
0.39 ms
0.34 ms
0.34 ms
0.35 ms
0.38 ms
0.34 ms
0.32 ms
0.36 ms

[yched]

FWIW, I get the same results if I replace mysql with mariadb.

[trowski]

@yched So when you disabled PDO::ATTR_EMULATE_PREPARES or used mysqli, you saw the same latency in prepares as you do with this lib?

[yched]

Nope, I do see extra latency, but from 0.1ms (pdo, emulate on) to 0.2ms (pdo, emulate off), rather than the 40ms I get with amp/mysql.

Updated my repo with scripts for PDO

[yched]

oops, I committed the change from mysql to mariadb along with the PDO scripts :-/ Same results either way...

[jonhoo]

FWIW, I'm seeing this in a completely unrelated Rust library for MySQL, so this seems to be a MySQL/MariaDB bug, not one in this particular library. Specifically, preparing statements seems to take on the order of 40ms, almost regardless of the query in question. The CPU load of the server also seems to be near 0% that entire time. The only thing I can imagine is that there's some kind of protocol mismatch where the server expects a flush or a terminating byte or something, which the client does not provide, which forces the server to time out before deciding to execute the prepare..

[staabm]

see the bug referenced above https://bugs.mysql.com/bug.php?id=73056

[yched]

@staabm : this mysql bug has been mentioned above in https://github.com/amphp/mysql/issues/55#issuecomment-356380455, but does not seem to be actually related - see https://github.com/amphp/mysql/issues/55#issuecomment-357448477 :

it is supposedly only triggered "if the binlog, general log, or slow log is enabled", which AFAICT is not the case on my setup [edit : nor in the docker image used in the repro repository at https://github.com/yched/amphp_mysql_prepare_55 ]

[kelunik]

@jonhoo Could you link an issue report for the unrelated Rust library, so we can keep track of it in case the root cause is found?

[jonhoo]

I don't think that bug is related, as I see 0% CPU usage on both server and client. The linked bug says:

CPU profiling of the server shows that 98% of the time is spent in String::replace().

@kelunik I haven't filed a bug for the Rust library yet, but will link it once I do.

[jonhoo]

Filed as https://github.com/blackbeam/rust-mysql-simple/issues/132

[kelunik]

According to @trowski this issue seems to be related to Nagle's Algorithm and can be solved by setting tcp_nodelay.

[jonhoo]

Oh, sorry, I forgot to follow up here. Yes, that is indeed the case. See https://github.com/blackbeam/rust-mysql-simple/issues/132#issuecomment-368090555

[kelunik]

Thanks, everyone!