MySQL Bugs: #45114: long_query_time and Query

Bug #45114	long_query_time and Query_time bug in slow log
Submitted:	27 May 2009 6:48	Modified:	1 Dec 2009 8:57
Reporter:	l j	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Options	Severity:	S3 (Non-critical)
Version:	5.0.32	OS:	Linux (Debian_7etch8-log)
Assigned to:		CPU Architecture:	Any
Tags:	long_query_time, slow log

Description:
when i show variables in mysql,i can see as below:
| log_slow_queries                | ON                                    | 
| log_warnings                    | 1                                     | 
| long_query_time                 | 2
long_query_time  has really been set to 2 seconds,but in slow log,i also see somes queries which query_time is less than 2 seconds.

< # User@Host: reader[reader] @ [60.1xxx.xxx.xxx]
< # Query_time: 3 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
< SELECT serverid,areaid,game_serverid,ip,status,status_remark,signature_key,interface_status,merge_to FROM server_info WHERE 1=1 AND serverid=135;
< # Time: 090526 20:14:14
< # User@Host: reader[reader] @ [60.xxx.xx.xxx]
< # Query_time: 0 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
< SELECT area.areaid, area.area_name, server_name.server_name , server.status, server.status_remark, server.interface_status, server.game_serverid FROM server_info server,server_name server_name,area_info area WHERE server.serverid=48 AND server.areaid=area.areaid AND server.serverid = server_name.serverid;
< # Time: 090526 21:41:34
< # User@Host: reader[reader] @ [60.xxx.xx.xxx]
< # Query_time: 0 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
< SELECT COUNT(*) FROM 132_message WHERE status=1 AND 1=1 AND to_uid=482;

why?

How to repeat:
it's very usual in my system under current my.cnf
here is my.cnf:
[mysqld]
skip-slave-start
#skip-networking
skip-name-resolve
max-connections = 800
transaction-isolation=REPEATABLE-READ
datadir         = /home/database

port            = 3306
socket          = /tmp/mysql.sock
skip-locking
max_allowed_packet = 16M
table_cache = 2048
sort_buffer = 16M
record_buffer = 64M
thread_cache = 8

wait_timeout = 3600
interactive_timeout = 3600
join_buffer_size = 8M
query_cache_size = 128M
query_cache_limit = 2M
sort_buffer_size = 16M
tmp_table_size=128M

#*** MyISAM Specific options
key_buffer_size = 64M
read_buffer_size = 64M
read_rnd_buffer_size=16M
myisam_sort_buffer_size = 64M

innodb_buffer_pool_size = 2G
innodb_additional_mem_pool_size = 20M
innodb_thread_concurrency = 16
innodb_log_buffer_size = 8M
innodb_log_file_size = 64M
innodb_flush_log_at_trx_commit = 1
innodb_lock_wait_timeout = 20

# Try number of CPU's*2 for thread_concurrency
thread_concurrency = 4
log-error=err.log
log-bin=bin-log
log-slow-queries=mysqlslow.log
long_query_time = 2
server-id       = 1

# Uncomment the following if you are using InnoDB tables
innodb_data_home_dir = /home/database
innodb_data_file_path = ibdata1:1G:autoextend
innodb_log_group_home_dir = /home/database
innodb_log_arch_dir = /home/database
innodb_log_files_in_group = 3
innodb_file_per_table

# Point the following paths to different dedicated disks
tmpdir          = /tmp
#log-update     = /path-to-dedicated-directory/hostname

[mysqldump]
quick
set-variable    = max_allowed_packet=16M

[mysql]
no-auto-rehash
# Remove the next comment character if you are not familiar with SQL
#safe-updates

[isamchk]
set-variable    = key_buffer=128M
set-variable    = sort_buffer=128M
set-variable    = read_buffer=2M
set-variable    = write_buffer=2M

[myisamchk]
set-variable    = key_buffer=128M
set-variable    = sort_buffer=128M
set-variable    = read_buffer=2M
set-variable    = write_buffer=2M

[mysqlhotcopy]
interactive-timeout

Thank you for the report.

But version 5.0.32 is old and many bug fixed since. Please try with current version 5.0.81 and inform us if problem still exists.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

same version installed in another machine with the same my.cnf,there is no such problem at that machine

after google,i still can't find the problem,thanks for reply~

Thank you for the feedback.

Probably some timing issue on the box problem is repeatable on. Please check new version 5.0.88 on problem box to be sure if problem solved for you.

execute me,what does problem box mean?
can you give me some urls or some detail explains?

in my last replay,i mean that it seems no matter with versions, because on another machine,5.0.32 works well.
so,”check new version 5.0.88 on problem box “ means what?

much thanks.

Thank you for the feedback.

"problem box" means "machine where you can repeat the problem". So ”check new version 5.0.88 on problem box “ means ”check new version 5.0.88 on the machine where you can repeat this timing problem“.

i am sorry to trouble you so much, but i still can't understand why you want me to check version 5.0.88 on the problem box and how to check? with the same my.cnf?
i don't think version is the key to this problem,because with the same version(5.0.32) on another machine,it works well.
i wonder whether you just want me to check new version(5.0.88) first on the problem box to see if this problem still exists,is that right?do you have any next step to check deeply?due to some reasons,it's not convenient to install another new version on that problem box.

thanks very much.

Thank you for the feedback.

> i wonder whether you just want me to check new version(5.0.88) first on the problem box
to see if this problem still exists,is that right?

Yes, because we had similar bugs which were repeatable on particular machines with timing issues which were fixed after 5.0.32. For example, bug #35396 This is why I want you to check if you still have problems with new version.

> do you have any next step to check deeply?due to some reasons,it's not convenient to install another new version on that problem box.

Nothing special: just same configuration and set of queries.

i have installed new version 5.0.88 on the problem box,ran with the same my.cnf(just different port,sock file and datadir).after some simple test(not full test),i didn't find this problem under this new version.as you say,maybe the bug is fixed in the lastest version.

in this case,what do you think about this bug?can you give me some suggestions to find modification in lastest versions for fixing this bug?because same version(5.0.32) installed on another machine works well(these two machines are very similar),in another word,can i configure this problem box to suit version 5.0.32 to resolve this problem instead of installing version 5.0.88?

thanks very much~

Thank you for the feedback.

Closed as "Can't repeat" for now.

I think this was happening, because you have some unusual setup of ntp in the problem machine. Also I think cause could be same as in bug #35396 which was fixed after 5.0.32. See comments to this bug to find what and when was fixed.

Also I think there is a little chance you could see this problem again. If this happen please reopen this report.