MySQL Bugs: #48677: PROCESSLIST can report a huge value for time

Bug #48677	PROCESSLIST can report a huge value for time
Submitted:	10 Nov 2009 22:09	Modified:	20 Nov 2009 6:24
Reporter:	Baron Schwartz (Basic Quality Contributor)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Information schema	Severity:	S3 (Non-critical)
Version:	5.1	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	qc

Description:
The following query,

select TIME, INFO from PROCESSLIST where USER NOT IN ('mmm','system user','DELAYED') AND TIME >= 300 AND COMMAND <> 'Sleep'

Can actually match itself, and return

4294967295 select TIME, INFO from PROCESSLIST where USER NOT IN ('mmm','system user','DELAYED') AND TIME >= 300 AND COMMAND <> 'Sleep'

Obviously the query hasn't been running for 4294967295 seconds.  My guess is that the system time was adjusted by NTP during query execution, so the query appears to be running -1 seconds.

How to repeat:
I bet Shane can think of a way to repro this :-)

Suggested fix:
Compute the timestamp difference something like this:

time = current_time - least(start_time, current_time);

Thank you for the report.

If negative time offset is cause similar problem is easy to repeat:

modify query to 

select TIME, INFO from PROCESSLIST where USER NOT IN ('mmm','system user','DELAYED') AND TIME >= 300 AND COMMAND <> 'Sleep' or 0 = sleep(10);

then hit "Enter", then change time 1 minute back:

mysql> select TIME, INFO from PROCESSLIST where USER NOT IN ('mmm','system user','DELAYED') AND TIME >= 300 AND COMMAND <> 'Sleep' or 0 = sleep(10);
+------+----------------------------------------------------------------------------------------------------------------------------------------------+
| TIME | INFO                                                                                                                                         |
+------+----------------------------------------------------------------------------------------------------------------------------------------------+
|    0 | select TIME, INFO from PROCESSLIST where USER NOT IN ('mmm','system user','DELAYED') AND TIME >= 300 AND COMMAND <> 'Sleep' or 0 = sleep(10) |
+------+----------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (497 days 2 hours 27 min 1.61 sec)

Although if modify finish time value in debugger such it is 1 second less than start time I get with latest bzr version:

-1      select TIME, INFO from PROCESSLIST where USER NOT IN ('mmm','system user','DELAYED') AND
....

Which exact version do you use?

It is 5.1.33, a custom build.

Thank you for the feedback.

In 5.1.33 problem is repeatable if use gdb:

1$./mtr --manual-gdb bug48677
...
2$gdb ...
(gdb)  b sql_show.cc:1875
Breakpoint 2 at 0x6efd98: file sql_show.cc, line 1875.
(gdb) c
Continuing.

Breakpoint 2, fill_schema_processlist (thd=0xd0d9a80, tables=<value optimized out>, cond=<value optimized out>) at sql_show.cc:1876
1876    sql_show.cc: No such file or directory.
        in sql_show.cc
(gdb) p now
$1 = 1258697927
(gdb) p tmp->start_time
No symbol "tmp" in current context.
(gdb) set now=1258697926
(gdb) c
Continuing.
...
1$
CURRENT_TEST: main.bug48677
--- /users/ssmirnova/blade12/mysql-5.1.33-linux-x86_64-glibc23/mysql-test/r/bug48677.result     2009-11-20 09:09:32.000000000 +0300
+++ /users/ssmirnova/blade12/mysql-5.1.33-linux-x86_64-glibc23/mysql-test/r/bug48677.reject     2009-11-20 09:19:10.000000000 +0300
@@ -3,6 +3,6 @@
 TIME >= 300 AND 
 COMMAND <> 'Sleep';
 TIME   INFO
-0      select TIME, INFO from PROCESSLIST where USER NOT IN ('mmm','system user','DELAYED') AND
+4294967295     select TIME, INFO from PROCESSLIST where USER NOT IN ('mmm','system user','DELAYED') AND

While with current sources I get negative values.

But I leave status of the bug "Verified", because we still have "1 row in set (497 days 2 hours 27 min 1.61 sec)" if time moved back. Also negative value looks strange as well.

see also bug#22047