0

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?

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.

  • 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 at 8: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 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 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 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 at 19:38
0

One of the things that can give an inconsistent result are all these sed commands - Each one is a separate fork and can add some time.

Generally, removing leading zeros is not necessary when you're using the arithmetic expansion. If you Have to, however, it's much better to use parameter expansion instead, like this:

start=${start##0}

Additional recommendation: avoid using [ in logical expressions, unless there is a chance the script will run under a legacy interpreter. Always use [[ instead. For purely arithmetic logic, (( is far superior.

I'd rework the script in the following way, also accounting for longer queries:

start=`date +%s.%N`
startN=${start##*.}
startN=${startN##0}
start=${start%%.*}
start=${start##0}

/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=`date +%s.%N`
endN=${end##*.}
endN=${endN##0}
end=${end%%.*}
end=${end##0}


((elapsed = ((end - start)*1000000000 + endN - startN)/1000000))

echo $elapsed

  • Thanks for the suggestions, no doubt there is some good stuff there, I'm no bash expert. But the reason for removing leading zeros was that the script failed otherwise. The revisions suggested also fail sometimes: response.value ./mysql_response: line 23: elapsed: elapsed = ((1553425250 - 1553425250)*1000000000 + 321534352 - 079214847: value too great for base (error token is "079214847"). With leading zero, number is treated as octal. – mbrampton Mar 24 at 11:04
  • It's also unclear that sed is the problem (although removing it would be good), given that replacing the SQL by sleep gives entirely consistent results. The variability does seem related to the SQL. – mbrampton Mar 24 at 11:06
  • @mbrampton - Since %N is only the nanoseconds, removing the leading zeros will be incorrect. – Rick James Mar 31 at 15:02
  • I updated my answer to remove the leading zeros, which is indeed necessary to avoid them being treated as octal. – ExtraT Apr 1 at 17:32

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.