Why does mysql_query() sometimes require 0.1 of a second on a query that executes fast

Question

I’ve noticed that sometimes mysql_query() on particular query in my script executes immediately and sometimes it takes (almost exactly) 0.1 of a second. I wrote a simple script to test it:

mysql_connect('<server>','<login>','<pass>');
mysql_select_db('<db>');

print microtime(true).'<br />';
mysql_query("select * from `messages` where `sq_id`=1");

print microtime(true).'<br />';
mysql_query("select * from `messages` where `sq_id`=1");

print microtime(true).'<br />';
mysql_query("select * from `messages` where `sq_id`=1");

print microtime(true).'<br />';
mysql_query("select * from `messages` where `sq_id`=1");

print microtime(true).'<br />';

And results are pretty unexpected:

0.02919600 1282686965
0.12934100 1282686965
0.22935700 1282686965
0.32934100 1282686965
0.32985500 1282686965

or, another time,

0.43041500 1282687515
0.52974500 1282687515
0.53034800 1282687515
0.53082400 1282687515
0.63109600 1282687515

Do you have any ideas why mysql_query() behaves like this?

Answer 1

I would guess the effect your observe is a combination of the mysql query cache and floating-point inaccuracy.

Answer 2

It could be the server load.

Answer 3

Five examples isn't enough to establish a benchmark. Run it 100k times and take the average. Then do it again and take the average. Compare those. Things like system load, query cache, etc will still affect it, but 100k times will reduce some of that variation.

Answer 4

My results are perfectly sensible...

1 second + processing time is 1.0010678768158 seconds
query in 0.00055694580078125 seconds
query in 0.00095701217651367 seconds
query in 0.0003049373626709 seconds
query in 0.0012030601501465 seconds
query in 0.0003972053527832 seconds

Between 0.00001s and 0.1s you have to account for MySQL liftoff, Apache dancing around, crontab jumping in, whatever...

Try something like this. Makes it easier to read.

$time_start = microtime(true);
sleep(1);
$time_end = microtime(true);
$time = $time_end - $time_start;
echo "1 second + processing time is actually $time seconds<br />\n";

$time_start = microtime(true);
mysql_query("select * from `messages` where `sq_id`=1");
$time_end = microtime(true);
$time = $time_end - $time_start;
echo "query in $time seconds<br />\n";

$time_start = microtime(true);
mysql_query("select * from `messages` where `sq_id`=1");
$time_end = microtime(true);
$time = $time_end - $time_start;
echo "query in $time seconds<br />\n";

$time_start = microtime(true);
mysql_query("select * from `messages` where `sq_id`=1");
$time_end = microtime(true);
$time = $time_end - $time_start;
echo "query in $time seconds<br />\n";

$time_start = microtime(true);
mysql_query("select * from `messages` where `sq_id`=1");
$time_end = microtime(true);
$time = $time_end - $time_start;
echo "query in $time seconds<br />\n";

$time_start = microtime(true);
mysql_query("select * from `messages` where `sq_id`=1");
$time_end = microtime(true);
$time = $time_end - $time_start;
echo "query in $time seconds<br />\n";