MySQL Bugs: #50378: Uptime_since_flush_status has an abnormally large value

Bug #50378	Uptime_since_flush_status has an abnormally large value
Submitted:	15 Jan 2010 17:34	Modified:	18 Jan 2010 14:12
Reporter:	Sheeri Cabral (Candidate Quality Contributor)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Options	Severity:	S2 (Serious)
Version:	5.0.77, 5.0, 5.1 bzr	OS:	Linux (RHEL 5.4)
Assigned to:	Geir Høydalsvik	CPU Architecture:	Any
Tags:	flush, qc, uptime, uptime_since_flush_status

Description:
As far as I understand it, "Uptime" is "Uptime since the server started" and "Uptime_since_flush_status" is the "Uptime since the last flush status OR server restart".  Thus, Uptime should always be greater than or equal to "Uptime_since_flush_status".

However, I came across a fairly interesting scenario:

mysql> select @@version;
+------------+
| @@version  |
+------------+
| 5.0.77-log | 
+------------+
1 row in set (0.00 sec)

mysql> show global status like 'Uptime%';
+---------------------------+-----------+
| Variable_name             | Value     |
+---------------------------+-----------+
| Uptime                    | 313409    | 
| Uptime_since_flush_status | 479530127 | 
+---------------------------+-----------+
2 rows in set (0.00 sec)

########## OK, let's see how long ago each of those were:

mysql> select now()-interval 479530127 second;
+---------------------------------+
| now()-interval 479530127 second |
+---------------------------------+
| 1994-11-06 01:41:43             | 
+---------------------------------+
1 row in set (0.01 sec)

mysql> select now()-interval 313409 second;
+------------------------------+
| now()-interval 313409 second |
+------------------------------+
| 2010-01-12 13:27:05          | 
+------------------------------+
1 row in set (0.00 sec)

########### OK, I highly doubt this mysqld instance has been up since 1994:

mysql> \! ps -ef | grep mysqld
root     13905     1  0  2009 ?        00:00:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --socket=/var/run/
mysql    17230 13905 88 Jan12 ?        3-05:23:29 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mys

mysql> \! uptime
 04:32:44 up 172 days, 16:32,  2 users,  load average: 9.86, 8.43, 7.08

####### And in fact the machine has not been up that long.

How to repeat:
I have been able to confirm this on 2 separate machines with different MySQL instances, both are RHEL 5.4, running Server version: 5.0.77-log Source distribution

On the 2nd server, I am getting:

mysql> show status like 'Uptime%';
+---------------------------+------------+
| Variable_name             | Value      |
+---------------------------+------------+
| Uptime                    | 2548771    | 
| Uptime_since_flush_status | 2138834350 | 
+---------------------------+------------+
2 rows in set (0.00 sec)

mysql> select now() - interval 2138834350 second;
+------------------------------------+
| now() - interval 2138834350 second |
+------------------------------------+
| 1942-04-08 03:55:47                | 
+------------------------------------+
1 row in set (0.03 sec)

So again, the value for Uptime_since_flush_status is abnormally high.

Thank you for the report.

Verified as described.

To repeat apply patch:

$bzr diff
=== modified file 'sql/sql_class.h'
--- sql/sql_class.h     2009-12-02 13:49:21 +0000
+++ sql/sql_class.h     2010-01-18 13:25:27 +0000
@@ -20,6 +20,9 @@
 #pragma interface                      /* gcc class implementation */
 #endif
 
+//#include "bug50378.h"
+extern my_bool bug50378;
+
 #include "log.h"
 #include "rpl_tblmap.h"
 
@@ -2009,6 +2012,7 @@
     }
     else
       start_utime= utime_after_lock= my_micro_time_and_time(&start_time);
+       if (bug50378) {sleep(5); bug50378=TRUE;}
   }
   inline void  set_current_time()    { start_time= my_time(MY_WME); }
   inline void  set_time(time_t t)

=== modified file 'sql/sql_parse.cc'
--- sql/sql_parse.cc    2010-01-12 14:16:26 +0000
+++ sql/sql_parse.cc    2010-01-18 13:53:24 +0000
@@ -22,6 +22,9 @@
 #include <myisam.h>
 #include <my_dir.h>
 
+//extern my_bool bug50378;
+#include "bug50378.h"
+
 #include "sp_head.h"
 #include "sp.h"
 #include "sp_cache.h"
@@ -5891,6 +5894,14 @@
 {
   DBUG_ENTER("mysql_parse");
 
+  char *t = (char*) malloc(12);
+  strncpy(t, inBuf, 11);
+  t[11] = '\0';
+  fprintf(stderr, "part: %s\n", t);
+  if (0 == strcmp(t, "flush statu")) {
+         bug50378 = TRUE;
+  }
+
   DBUG_EXECUTE_IF("parser_debug", turn_parser_debug_on(););
 
   /*

=== modified file 'sql/sql_show.cc'
--- sql/sql_show.cc     2010-01-13 10:28:42 +0000
+++ sql/sql_show.cc     2010-01-18 11:53:25 +0000
@@ -31,6 +31,8 @@
 #endif
 #include <my_dir.h>
 
+//#include "bug50378.h"
+
 #define STR_OR_NIL(S) ((S) ? (S) : "<nil>")
 
 #ifdef WITH_PARTITION_STORAGE_ENGINE

$cat include/bug50378.h 
#ifndef BUG50378
#if defined(BUG50378)
#else
#define BUG50378 1
my_bool bug50378 = FALSE;
#endif
#endif

Then run test following:

connect (addconroot, localhost, root,,);
connection addconroot;
flush status;

connection default;
--send flush status

connection addconroot;
show status like 'Uptime%';

Patch against 5.1

for the record, with version 5.1.53 for a recently started mysql i'm getting :

mysql> show status like 'Uptime%';
+---------------------------+------------+
| Variable_name             | Value      |
+---------------------------+------------+
| Uptime                    | 4294960791 |
| Uptime_since_flush_status | 4294960791 |
+---------------------------+------------+

so not just since_flush_status, but also plain uptime.

is that a known problem that is already fixed under this report, or should a new one be reported ?

https://bugs.mysql.com/bug.php?id=92021 marked as duplicate of this one.