Bug #74416 Don't use non-monotonic clocks for time interval measurements
Submitted: 16 Oct 2014 9:02 Modified: 19 Sep 2016 8:39
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S4 (Feature request)
Version: OS:Any
Assigned to: CPU Architecture:Any
Tags: gettimeofday

[16 Oct 2014 9:02] Laurynas Biveinis
Description:
MySQL uses gettimeofday on platforms that have it for both time reporting and taking the time points for later duration calculations. The latter use is incorrect, as getttimeofday is non-monotonic, so it's possible to end up with negative / extremely large intervals.

How to repeat:
man 2 gettimeofday
grep MySQL source for gettimeofday (my_micro_time etc...)

We have seen instances of negative time intervals, but we don't have a repeatable test case (one would be highly unlikely given the nature of the problem). Maybe adding an assert as https://bugs.launchpad.net/percona-server/+bug/1379582 describes would help to catch an occurrence.

Suggested fix:
For measuring durations, replace gettimeofday with something monotonic.
[16 Oct 2014 10:01] Roel Van de Paar
There is a testcase for Percona Server, but in it's current form it cannot be used for MySQL Server as there is no TIME_MS there. Yet, for someone from your QA or Shane it would be relatively easy to create a testcase here.
[17 Oct 2014 15:00] Davi Arnaut
At the risk of sounding obvious, one can always adjust the machine clock back and forwards to reproduce such issues.
[17 Oct 2014 20:11] Roel Van de Paar
Davi, agreed. Yet, to be clear, the issue exists even without NTPD involvement.
[27 Feb 2015 10:17] Mark Callaghan
I am curious. On which platforms does this occur?
[27 Feb 2015 10:38] Roel Van de Paar
Hi Mark! This was either Centos6 or 7 x64.
[2 Jan 2016 2:27] Roel Van de Paar
See http://bugs.mysql.com/bug.php?id=79822 for testcase. Please set this to verified also.
[10 Jan 2016 21:42] Roel Van de Paar
Please ignore [2 Jan 2:27]
[2 Mar 2016 6:41] Laurynas Biveinis
Saw the following once in testing, don't have enough for a full bug report, so piggybacking here, as it could be the same reason in theory:

PS 5.7.11 (no patches in my_rdtsc.c):

innodb_stress.innodb_bigstress_crash_nocompress w4 [ fail ]

Program terminated with signal SIGFPE, Arithmetic exception.
#0  0x0000000001280410 in my_timer_init_frequency (mti=0x1dd1760 <pfs_timer_info>) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/release/Host/ubuntu-wily-64bit/mysys/my_rdtsc.c:441
441	  return (mti->microseconds.frequency * (time4 - time1)) / (time3 - time2);
#0  0x0000000001280410 in my_timer_init_frequency (mti=0x1dd1760 <pfs_timer_info>) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/release/Host/ubuntu-wily-64bit/mysys/my_rdtsc.c:441
#1  my_timer_init (mti=mti@entry=0x1dd1760 <pfs_timer_info>) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/release/Host/ubuntu-wily-64bit/mysys/my_rdtsc.c:677
#2  0x0000000000ec12b8 in init_timers () at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/release/Host/ubuntu-wily-64bit/storage/perfschema/pfs_timer.cc:69
#3  0x0000000000ebe012 in initialize_performance_schema (param=param@entry=0x1dd1400 <pfs_param>) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/release/Host/ubuntu-wily-64bit/storage/perfschema/pfs_server.cc:104
#4  0x000000000076cd3e in mysqld_main (argc=101, argv=0x290c908) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/release/Host/ubuntu-wily-64bit/sql/mysqld.cc:4710
#5  0x00007f0d70e7ea40 in __libc_start_main (main=0x748060 <main(int, char**)>, argc=10, argv=0x7ffcd3d3d3b8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffcd3d3d3a8) at libc-start.c:289
#6  0x00000000007615c9 in _start ()

Code in question

static ulonglong my_timer_init_frequency(MY_TIMER_INFO *mti)
{
  int i;
  ulonglong time1, time2, time3, time4;
  time1= my_timer_cycles();
  time2= my_timer_microseconds();
  time3= time2; /* Avoids a Microsoft/IBM compiler warning */
  for (i= 0; i < MY_TIMER_ITERATIONS; ++i)
  {
    time3= my_timer_microseconds();
    if (time3 - time2 > 200) break;
  }
  time4= my_timer_cycles() - mti->cycles.overhead;
  time4-= mti->microseconds.overhead;
  return (mti->microseconds.frequency * (time4 - time1)) / (time3 - time2);
}

I assume it crashed because time3 == time2.
[19 Sep 2016 8:39] MySQL Verification Team
Hello Laurynas,

Thank you for the feature request!

Thanks,
Umesh