Bug #72520 os_event_wait_time_low(): wait time calculation is messed up
Submitted: 3 May 2014 4:53 Modified: 5 May 2014 5:08
Reporter: Inaam Rana (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.5, 5.6, 5.7 OS:Any
Assigned to: CPU Architecture:Any

[3 May 2014 4:53] Inaam Rana
Description:
os_event_wait_time_low() is used for timed wait. The calculation of absolute time for timeout is broken.

514                 tv.tv_usec += time_in_usec;
515 
516                 if ((ulint) tv.tv_usec >= MICROSECS_IN_A_SECOND) {
517                         tv.tv_sec += time_in_usec / MICROSECS_IN_A_SECOND;
518                         tv.tv_usec %= MICROSECS_IN_A_SECOND;
519                 }

time_in_usec is time in microsecond that caller wants to set the timeout value to. Line 517 should not use time_in_usec, instead it should use tv.tv_usec. This has been present since 5.5 atleast but it didn't cause any grief because all caller pass multiples of seconds as wait time. In 5.7, however, we have page_cleaner thread which passes sub-second timeout values. When time_in_usec is less than MICROSECS_IN_A_SECOND, we'll never add to tv_tv_sec and we'll likely return much before than actual intended timeout.

This can cause seriously erratic behavior of page_cleaner.

How to repeat:
see code.

Suggested fix:
=== modified file 'storage/innobase/os/os0event.cc'
--- storage/innobase/os/os0event.cc	2013-12-12 16:28:03 +0000
+++ storage/innobase/os/os0event.cc	2014-05-03 04:51:44 +0000
@@ -514,7 +514,7 @@
 		tv.tv_usec += time_in_usec;
 
 		if ((ulint) tv.tv_usec >= MICROSECS_IN_A_SECOND) {
-			tv.tv_sec += time_in_usec / MICROSECS_IN_A_SECOND;
+			tv.tv_sec += tv.tv_usec / MICROSECS_IN_A_SECOND;
 			tv.tv_usec %= MICROSECS_IN_A_SECOND;
 		}
[5 May 2014 5:08] Umesh Shastry
Hello Inaam,

Thank you for the bug report and contribution.

Thanks,
Umesh
[5 May 2014 5:41] Sunny Bains
This was IIRC found and fixed by Yasufumi recently. I will check the latest 5.5 and 5.6 code too:

------------------------------------------------------------
revno: 7694
revision-id: yasufumi.kinoshita@oracle.com-20140313074852-0u31sml409l9llbg
parent: tatjana.nuernberg@oracle.com-20140313062138-e4hnkrn6dziemou2
committer: Yasufumi Kinoshita <yasufumi.kinoshita@oracle.com>
branch nick: mysql-trunk
timestamp: Thu 2014-03-13 08:48:52 +0100
message:
  Bug #18386498	OS_EVENT_WAIT_TIME_LOW() RETURNS OS_SYNC_TIME_EXCEEDED BEFORE THE TIME ELAPSED
  
  approved by Sunny over IM.
sunny@linux innobase> bzr diffp -c 7694
=== modified file 'storage/innobase/os/os0event.cc'
--- storage/innobase/os/os0event.cc	revid:tatjana.nuernberg@oracle.com-20140313062138-e4hnkrn6dziemou2
+++ storage/innobase/os/os0event.cc	revid:yasufumi.kinoshita@oracle.com-20140313074852-0u31sml409l9llbg
@@ -514,7 +514,7 @@ os_event::wait_time_low(
 		tv.tv_usec += time_in_usec;
 
 		if ((ulint) tv.tv_usec >= MICROSECS_IN_A_SECOND) {
-			tv.tv_sec += time_in_usec / MICROSECS_IN_A_SECOND;
+			tv.tv_sec += tv.tv_usec / MICROSECS_IN_A_SECOND;
 			tv.tv_usec %= MICROSECS_IN_A_SECOND;
 		}
[8 Apr 2016 9:05] zhai weixiang
This bug has been fixed, so it should be closed ? 

$git show 5529e0f96d82419def08da8a37ed1cee04ca1114
commit 5529e0f96d82419def08da8a37ed1cee04ca1114
Author: Yasufumi Kinoshita <yasufumi.kinoshita@oracle.com>
Date:   Thu Mar 13 08:48:52 2014 +0100

    Bug #18386498       OS_EVENT_WAIT_TIME_LOW() RETURNS OS_SYNC_TIME_EXCEEDED BEFORE THE TIME ELAPSED

    approved by Sunny over IM.