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: | |
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 | CPU Architecture: | Any |
Tags: | exec_time, qc |
[8 Apr 2010 21:55]
Sheeri Cabral
[9 Apr 2010 5:01]
Valeriy 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]
MySQL Verification Team
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