Inconsistent elapsed time for mysql/mariadb query

Question

Checking the elapsed time for a database query for munin monitoring,I have created a script, the time measurement part being:

start=$(sed 's/^0*//'<<< `date +%N`)
/usr/bin/mysql -u 3da_d9 -p****** --host="127.0.0.1" --port=4002 -e "SELECT f.*, AVG(l.value) AS vote_value, COUNT(l.value) AS vote_count, 0 AS active_feature, c.name from 3dallusions_joomla_d9.jom3_downloads_files AS f INNER JOIN 3dallusions_joomla_d9.jom3_downloads_containers AS c ON f.containerid = c.id LEFT JOIN 3dallusions_joomla_d9.jom3_downloads_log AS l ON l.type = 3 AND l.fileid = f.id AND l.value != 0" > /dev/null
end=$(sed 's/^0*//'<<< `date +%N`)
if [ "$end" -lt "$start" ]; then
    end=$(($end+1000000000))
fi
elapsed=$(($end - $start))
elapsed=$(($elapsed/1000000))
echo $elapsed

I've checked the logic of the time measurement by replacing the SQL call with a simple sleep. That gives a consistent result every time.

The database and client are MariaDB 10.1 from the Debian Stretch repository.

The thing that is puzzling me is that the first time I run the script, the answer is around 10 milliseconds. Subsequent runs give about 50 milliseconds. After not running the script for a while, a result of around 10 is obtained again.

Why would a query be five times quicker the first time than when repeated? One might expect caching to cause the opposite effect. What is happening?

score 0 · Answer 1 · answered Mar 29 '19 at 03:51

0

Look at how much overhead you are executing -- date, sed, mysql, mysql login, etc.

Instead, do the date check as close as possible to the action:

SELECT @start := SYSDATE(6), log(10), @end := SYSDATE(6);
SELECT UNIX_TIMESTAMP(@end) - UNIX_TIMESTAMP(@start) AS 'seconds';

+----------+
| seconds  |
+----------+
| 0.000037 |
+----------+

That says 37 microseconds, but still has a bunch of overhead.

Also consider the BENCHMARK function:

mysql> SELECT BENCHMARK(1000000, log(10));
+-----------------------------+
| BENCHMARK(1000000, log(10)) |
+-----------------------------+
|                           0 |
+-----------------------------+
1 row in set (0.03 sec)

That says 0.03 microseconds; I trust it. BENCHMARK is the way to time functions or expressions.

If you can use PHP, then simply do

$start = microtime(true);
... perform the query ...
$end = microtime(true);
echo $end - $start, ' seconds';

It will be 'good enough' for full statements.

answered Mar 29 '19 at 03:51

Rick James

2,463
1
6
13

Thanks. Unfortunately, the proposed SQL solution doesn't tell me what I want to know. The client is on a different server from the SQL database, and what I am trying to plot is the end to end time for a request on the client. Hence much of the time cost is essential to the question. Is invoking sed and date really more costly than starting up PHP and its runtime? I don't seem to be any nearer to understanding the big variation in elapsed time. – mbrampton Mar 30 '19 at 08:23
@mbrampton - I find the microtime approach to be consistent, and to include end-to-end (latency, etc) times. And it focuses more on the query, without the non-trivial overhead of launching `sed` and `date` and `mysql`. If you want to include the connect & login time for mysql, then include those in between the microtime calls. The startup of PHP is not included in the microtime approach. – Rick James Mar 31 '19 at 14:57
@mbrampton - And... Please better define "end-to-end". When looking at a whole program, the startup of PHP (or whatever) could be part of it. If it is the roundtrip for one `SELECT`, then it is best go get everything else out of the picture. My `microtime` eliminates all but one call to microtime, but that is only a few _microseconds_. – Rick James Mar 31 '19 at 15:00
Thanks. I monitor my servers using munin. This gives me some idea of how the database server and the web server are running. The missing information is whether there is a holdup between the web server and the database server. Running an arbitrary SQL query seems the simplest way to get a handle on this. Your PHP script works well (although it needs a bit of tweaking to give a result in milliseconds with no text. It gives pretty much the same results as the original bash script. Running out of space - see next comment also. – mbrampton Mar 31 '19 at 19:37
However, it also gives the same strange variability - usually the result is around 50 milliseconds, but occasionally it is around 8 milliseconds. Never anything in between. This continues to puzzle me. It is why I raised the question. – mbrampton Mar 31 '19 at 19:38
50ms sounds like a distance of tens of miles (or km)?? Are you using MyISAM or InnoDB? What was the query? If it is that JOIN, something could be interfering (locking/blocking) that query. For just network latency, you could do something like `SELECT 1;`. Please provide `EXPLAIN SELECT ...`. – Rick James Mar 31 '19 at 19:51
Good point. It looks as if what was being measured was the (surprisingly large) time to run the MySQL client. Fully implementing the PHP script idea, with the connection setup outside the timer, the answer is in the region of 1 msec. – mbrampton Apr 02 '19 at 13:56
@mbrampton - 1ms sounds like a 'simple' query against well-cached data with the client either on the same machine or very close physically. – Rick James Apr 03 '19 at 21:00

Inconsistent elapsed time for mysql/mariadb query

1 Answers1