Description:
is call thd->end_time() in log_slow_statement needed if slow logs are disabled ?
it seems calls to time() or gtime() on solaris are made many times.
since i don't log slow statements, this leads to alot of extra calls.
gtime() was one of the highest system calls made in some simple tests
<cut>
lwp_sigmask 931463
pwrite64 980081
gtime 1912818
llseek 16034893
read 33489876
mysql> show global variables like 'log_slow_queries';
+------------------+-------+
| Variable_name | Value |
+------------------+-------+
| log_slow_queries | OFF |
+------------------+-------+
1 row in set (0.00 sec)
this seems fixed in 5.1-bzr due to the microseconds logging.
http://developers.sun.com/solaris/articles/mysql_perf_tune.html#2
How to repeat:
read the source code of log_slow_statement() in sql_parse.cc
dstrace can show the number of these calls on solaris - just run few thousand queries against mysqld and monitor mysqld like this:
dtrace -n 'syscall::gtime:entry /execname == "mysqld"/ { @[ustack()] = count();}'
Suggested fix:
in function void log_slow_statement(THD *thd)
put these two lines :
start_of_query= thd->start_time;
thd->end_time(); // Set start time
inside the block:
if (thd->enable_slow_log && !thd->user_time)
{
}
