Bug #52704 exec_time=4294967295
Submitted: 8 Apr 2010 21:55 Modified: 8 Oct 2010 5:23
Reporter: Sheeri Cabral (Candidate Quality Contributor) Email Updates:
Status: Patch pending Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:5.1.41 (Ubuntu), 4.1, 5.0, 5.1, 5.6.99 bzr OS:Linux
Assigned to: Assigned Account
Tags: exec_time, qc
Triage: Triaged: D3 (Medium)

[8 Apr 2010 21:55] Sheeri Cabral
Description:
While investigating an application outage for a client I am coming across some odd values for exec_time in the binary logs:

#100408 16:31:12 server id 136  end_log_pos 456727413   Query   thread_id=745731        exec_time=4294967295    error_code=0
SET TIMESTAMP=1270758672/*!*/;
UPDATE `packages` SET `notified_at` = '2010-04-08 16:31:11', `updated_at` = '2010-04-08 16:31:11' WHERE `id` = 3881265

#100408 16:42:48 server id 136  end_log_pos 462814373   Query   thread_id=757702        exec_time=4294967295    error_code=0
SET TIMESTAMP=1270759368/*!*/;
update offers set publishable_flag = true where id = 208944
/*!*/;

Different queries, different threads, different times.......

How to repeat:
no clue.  long_query_time is set to 1 and these queries did not show up in the slow query log (others did, though, so the log is working.
[9 Apr 2010 5:01] Valerii Kravchuk
I have two ideas about possible reasons. Do you run ntp client on this box? Maybe time was adjusted while statement was executed. Is this server a slave for some other machine?
[9 Apr 2010 13:03] Sheeri Cabral
Valerie -- there were many of these statements, interleaved with statements that had exec_time values of 0 or 1 (or in some cases, 215 or 62 or other values, I was diagnosing an issue with slowness at the time).  So I don't think it's an NTP issue because then it would be consistent with the queries directly before and after them.

Also this machine is indeed a slave (master/master setup), but the server-id is 136 for all the queries (as it should be, it's a primary write server, nothing should be writing to the other master, and indeed nothing is, according to the server ids).
[9 Apr 2010 16:33] Sveta Smirnova
Thank you for the feedback.

There is code in sql/log_event.cc:

2391 {
2392   time_t end_time;
2393 
2394   error_code= errcode;
2395 
2396   time(&end_time);
2397   exec_time = (ulong) (end_time  - thd_arg->start_time);

If start time is greater than end_time (due to NTP adjustment or some other issue with time function) it is possible exec_time be converted to ulong from negative value.

This situation can be tested before assigning value to exec_time. So set to "Verified".
[1 May 2010 9:13] Zhenxing He
The following test case can reproduce the problem:

create table t1 (TIMESTAMP time);
SET @@TIMESTAMP=@@TIMESTAMP + 1;
insert into t1 values (now());
[1 May 2010 12:04] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/107138

3453 He Zhenxing	2010-05-01
      Bug#52704 exec_time=4294967295
      
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      Fixed by adding a new varialbe thd->real_start_time, which will
      not be affected by TIMESTAMP, and use this to calculate the
      execution time of the query.
     @ sql/log_event.cc
        use real_start_time to calculate the execution time of the query, which is not affected by the TIMESTAMP session variable
     @ sql/sql_class.h
        add real_start_time to record the real system start time of the query, which is not affected by the TIMESTAMP session variable
[12 May 2010 6:20] Zhenxing He
See also Bug#52308, I think P1 is a dup of this bug.
[7 Jun 2010 0:21] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/110306

3453 He Zhenxing	2010-06-07
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_start_user() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
[10 Jun 2010 7:44] Zhenxing He
The above patch should also fix P1 of bug#52308
[10 Jun 2010 7:52] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/110689

3453 He Zhenxing	2010-06-10
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_start_user() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
      
      This patch also removed the unused query_start_used variable
      and made start_time, user_time private of THD.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
[10 Jun 2010 10:26] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/110701

3453 He Zhenxing	2010-06-10
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_start_user() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
      
      This patch also removed the unused query_start_used variable
      and made start_time, user_time private of THD.
      ******
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_start_user() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
      
      This patch also removed the unused query_start_used variable
      and made start_time, user_time private of THD.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
        ******
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
        ******
        Use query_user_start() instead of query_start() for time functions
[13 Jun 2010 3:59] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/110936

3453 He Zhenxing	2010-06-13
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_start_user() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
      
      This patch also removed the unused query_start_used variable
      and made start_time, user_time private of THD.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/sql_class.cc
        remove unused member query_start_used from THD
     @ sql/sql_class.h
        remove unused member query_start_used from THD
        make start_time, user_time private
[11 Jul 2010 12:03] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/113296

3453 He Zhenxing	2010-07-11
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_user_start() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
      
      This patch also removed the unused query_start_used variable
      and made start_time, user_time private of THD.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/sql_class.cc
        remove unused member query_start_used from THD
     @ sql/sql_class.h
        remove unused member query_start_used from THD
        make start_time, user_time private
[16 Jul 2010 9:03] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/113738

3470 He Zhenxing	2010-07-16
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_user_start() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
      
      This patch also removed the unused query_start_used variable
      and made start_time, user_time private of THD.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/sql_class.cc
        remove unused member query_start_used from THD
     @ sql/sql_class.h
        remove unused member query_start_used from THD
        make start_time, user_time private
[5 Aug 2010 8:26] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/115061

3470 He Zhenxing	2010-08-05
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_user_start() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
      
      This patch also removed the unused query_start_used variable
      and made start_time, user_time private of THD.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/sql_class.cc
        remove unused member query_start_used from THD
     @ sql/sql_class.h
        remove unused member query_start_used from THD
        make start_time, user_time private
[9 Aug 2010 6:37] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/115271

3470 He Zhenxing	2010-08-09
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_user_start() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
      
      This patch also removed the unused query_start_used variable
      and made start_time, user_time private of THD.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/sql_class.cc
        remove unused member query_start_used from THD
     @ sql/sql_class.h
        remove unused member query_start_used from THD
        make start_time, user_time private
[9 Aug 2010 7:05] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/115272

3470 He Zhenxing	2010-08-09
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      
      Fixed by make thd->start_time not to be affected by TIMESTAMP, and
      added a thd->query_user_start() to use the thd->user_time, which 
      is used for places where it should consult the value of TIMESTAMP.
      execution time of the query.
      
      Another reason that can cause the exec_time to be negative is
      that user or NTP service modified the time. This is fixed by
      treating netagive exec_time as 0.
      
      This patch also removed the unused query_start_used variable
      and made start_time, user_time private of THD.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/sql_class.cc
        remove unused member query_start_used from THD
     @ sql/sql_class.h
        remove unused member query_start_used from THD
        make start_time, user_time private
[8 Oct 2010 5:23] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/120338

3470 He Zhenxing	2010-10-08
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      There are two roles mixed with thd->start_time, one is to track
      the timestamp value of the query, another is to measuring time
      intervals of query execution.
      
      This patch fixed the problem by introducing stopwatch for measuring
      time intervals of query, exec_time(for binlog), lock and after_lock.
      And thd->start_time will only be used to record the start timestamp
      of the query.
      
      The current implementation of Stopwatch is still using my_micro_time(),
      which is subject to time adjustment by user or NTP service, and
      can result in negative time interval. This is currently worked around
      by treating netagive value as 0. It should be fixed later.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/sql_class.cc
        remove unused member query_start_used from THD
     @ sql/sql_class.h
        remove unused member query_start_used from THD
        make start_time, user_time private
[15 Oct 2010 11:04] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/120827

3470 He Zhenxing	2010-10-15
      Bug#52704 exec_time=4294967295
            
      thd->start_time was used to calculate the exec_time of the query,
      since thd->start_time can be affected by TIMESTAMP session variable,
      this would result in a very big value when TIMESTAMP is set to a
      future time before execution a query.
      
      In fact, only time function like NOW() or similar need to use
      the value of TIMESTAMP session variable if it present. All other
      usages of thd->start_time should not be affected by TIMESTAMP.
      There are two roles mixed with thd->start_time, one is to track
      the timestamp value of the query, another is to measuring time
      intervals of query execution.
      
      This patch fixed the problem by introducing stopwatch for measuring
      time intervals of query, exec_time(for binlog), lock and after_lock.
      And thd->start_time will only be used to record the start timestamp
      of the query.
      
      The current implementation of Stopwatch is still using my_micro_time(),
      which is subject to time adjustment by user or NTP service, and
      can result in negative time interval. This is currently worked around
      by treating netagive value as 0. It should be fixed later.
     @ sql/field.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/item_timefunc.cc
        Use query_user_start() instead of query_start() for time functions
     @ sql/sql_class.cc
        remove unused member query_start_used from THD
     @ sql/sql_class.h
        remove unused member query_start_used from THD
        make start_time, user_time private
[17 Nov 2011 14:03] Hartmut Holzgraefe
This can and does happen even without explicitly setting the TIMESTAMP variable. When running the following test on a 5.1 server using default settings and only 

  [mysqld]
  log-bin

in the my.cnf configuration file:

  <?php
  mysql_connect("127.0.0.1","root","") or die("connect");
  mysql_select_db("test");

  mysql_query("drop table if exists t1");
  mysql_query("create table t1(id int primary key, msg varchar(100)) engine=innodb");

  for ($i=1; $i< 100000; $i++) {
    if ($i % 100 == 0) echo "$i\r";
    mysql_query("begin");
    mysql_query("insert into t1 set id = $i, msg = md5(rand())");
    mysql_query("commit");
  }

i'm getting a binlog entry with exec_time=4294967295 about once per 200 INSERT iterations.

This probably happens whenever the wall clock second changes right between setting the query start time and recording the current TIMESTAMP value?

With the last attached patch applied i can't reproduce any unusual exec_time entries any more though.

So about time for finally getting the patch into a release?
[3 Jul 2013 7:40] Shane Bester
Still repeatable on 5.6.12 and 5.5.32. If I set PC clock backwards a minute, I get:

D:\mysql-5.6.12-win32\bin>mysqlbinlog --read-from-remote-server -h127.0.0.1 --stop-never test-bin.000001|grep "exec_time=42"
#130703  9:37:36 server id 4  end_log_pos 16871646 CRC32 0xe2979aae     Query   thread_id=12    exec_time=4294967236    error_code=0