Bug #65778 User has reported large and continued spike in CPU after leap second
Submitted: 1 Jul 2012 3:51 Modified: 4 Jun 2013 10:38
Reporter: Nicholas Bamber (OCA) Email Updates:
Status: Won't fix Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S5 (Performance)
Version:5.5.24 OS:Linux
Assigned to:
Tags: leap second
Triage: Needs Triage: D3 (Medium)

[1 Jul 2012 3:51] Nicholas Bamber
Description:
My mysqld recently started using loads of CPU, on two different
computers.  There was no obvious reason, and restarting the daemon did
not appear to help.  Finding a thread about mythtv suggested a
possible reason: the leap second which occurred at 23:59:60 GMT on 30
June 2012 (about 3 hours ago now).  Rebooting the computer seems to
have sorted the problem.

I'm running kernel 3.2.0-2-amd64 (linux-image 3.2.20-1) and running
ntpd.

It seems to be reproduced on my linux machine:

Actually on my Linux system it the mysqld process has the hghest CPU:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

 2560 mysql     20   0  408m 2372  692 S   53  0.1 155:39.60 mysqld

Also Mozilla IT have a web page reporting the same:
http://blog.mozilla.org/it/2012/06/30/mysql-and-the-leap-second-high-cpu-and-the-fix/

How to repeat:
I have not tried but I imagine that it may be possible to reproduce this with ome aggressive playing with a system's clock.

Suggested fix:
The Mozilla IT article suggests rebooting or setting the time. Of course that is a work around at best.
[1 Jul 2012 9:33] Peter Laursen
The questions are

1) Is this is bug in MySQL or in Linux/specific Linux kernels?
2) Was there a real CPU spike or was it a false reporting by Linux system tools (a 'hoax' so to say)?

Peter
(not a MySQL person)
[1 Jul 2012 10:00] Sadao Hiratsuka
There are 2 threads consume CPU.

- thread/innodb/srv_lock_timeout_thread
- thread/innodb/srv_error_monitor_thread

Here is a sample patch which changes os_event_wait_time_low() to os_thread_sleep()
(it is MySQL 5.1's behavior), and this patch fixes CPU consumption.

I think it is not a MySQL's bug.
Perhaps Linux kernel, libc, libpthread, and so on.

Affected systems are ...
- RHEL 6 + MySQL 5.5

Not affected systems are ...
- RHEL 6 + MySQL 5.1
- RHEL 5 + MySQL 5.5
- RHEL 5 + MySQL 5.1

Thanks.

# uname -a
Linux sbridge 2.6.32-220.23.1.el6.x86_64 #1 SMP Mon Jun 18 09:58:09 CDT 2012 x86_64 x86_64 x86_64 GNU/Linux

# rpm -q MySQL-server
MySQL-server-5.5.24-1.el6.x86_64

# ps -efL
UID        PID  PPID   LWP  C NLWP STIME TTY          TIME CMD
root      8814     1  8814  0    1 18:38 pts/4    00:00:00 /bin/sh /usr/bin/mysqld_safe --datad
mysql     9108  8814  9108  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9110  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9111  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9112  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9113  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9114  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9115  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9116  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9117  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9118  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9119  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9121 71   16 18:38 pts/4    00:00:19 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9122 83   16 18:38 pts/4    00:00:23 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9123  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9124  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da
mysql     9108  8814  9130  0   16 18:38 pts/4    00:00:00 /usr/sbin/mysqld --basedir=/usr --da

(gdb) info thread
  16 Thread 0x7face23a7700 (LWP 9110)  0x00000031f2800614 in ?? () from /lib64/libaio.so.1
  15 Thread 0x7fac5663a700 (LWP 9111)  0x00000031f2800614 in ?? () from /lib64/libaio.so.1
  14 Thread 0x7fac55c39700 (LWP 9112)  0x00000031f2800614 in ?? () from /lib64/libaio.so.1
  13 Thread 0x7fac55238700 (LWP 9113)  0x00000031f2800614 in ?? () from /lib64/libaio.so.1
  12 Thread 0x7fac54837700 (LWP 9114)  0x00000031f2800614 in ?? () from /lib64/libaio.so.1
  11 Thread 0x7fac53e36700 (LWP 9115)  0x00000031f2800614 in ?? () from /lib64/libaio.so.1
  10 Thread 0x7fac53435700 (LWP 9116)  0x00000031f2800614 in ?? () from /lib64/libaio.so.1
  9 Thread 0x7fac52a34700 (LWP 9117)  0x00000031f2800614 in ?? () from /lib64/libaio.so.1
  8 Thread 0x7fac52033700 (LWP 9118)  0x00000031f2800614 in ?? () from /lib64/libaio.so.1
  7 Thread 0x7fac51632700 (LWP 9119)  0x00000031f2800614 in ?? () from /lib64/libaio.so.1
  6 Thread 0x7fac50230700 (LWP 9121)  0x0000003bc3c0b75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  5 Thread 0x7fac4f82f700 (LWP 9122)  sync_array_print_long_waits (waiter=0x7fac4f82ee78,
    sema=0x7fac4f82ee70)
    at /pb2/build/sb_0-5519472-1334833515.86/rpm/BUILD/mysql-5.5.24/mysql-5.5.24/storage/innobase/sync/sync0arr.c:952
  4 Thread 0x7fac4ddf4700 (LWP 9123)  0x0000003bc3c0b75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  3 Thread 0x7fac50c31700 (LWP 9124)  0x0000003bc3c0b3dc in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
  2 Thread 0x7fac4d3f3700 (LWP 9130)  0x0000003bc3c0f245 in sigwait ()
   from /lib64/libpthread.so.0
* 1 Thread 0x7face23a9700 (LWP 9108)  0x0000003bc38dc613 in poll () from /lib64/libc.so.6

(gdb) thread 6
(gdb) where
#0  0x0000003bc3c0b75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000008b2d53 in os_cond_wait_timed (event=0x35e7090,
    time_in_usec=<value optimized out>, reset_sig_count=1)
    at /pb2/build/sb_0-5519472-1334833515.86/rpm/BUILD/mysql-5.5.24/mysql-5.5.24/storage/innobase/os/os0sync.c:171
#2  os_event_wait_time_low (event=0x35e7090, time_in_usec=<value optimized out>,
    reset_sig_count=1)
    at /pb2/build/sb_0-5519472-1334833515.86/rpm/BUILD/mysql-5.5.24/mysql-5.5.24/storage/innobase/os/os0sync.c:716
#3  0x00000000007f73c8 in srv_lock_timeout_thread (arg=<value optimized out>)
    at /pb2/build/sb_0-5519472-1334833515.86/rpm/BUILD/mysql-5.5.24/mysql-5.5.24/storage/innobase/srv/srv0srv.c:2287
#4  0x0000003bc3c077f1 in start_thread () from /lib64/libpthread.so.0
#5  0x0000003bc38e5ccd in clone () from /lib64/libc.so.6

(gdb) thread 5
(gdb) where
#0  sync_array_print_long_waits (waiter=0x7fac4f82ee78, sema=0x7fac4f82ee70)
    at /pb2/build/sb_0-5519472-1334833515.86/rpm/BUILD/mysql-5.5.24/mysql-5.5.24/storage/innobase/sync/sync0arr.c:952
#1  0x00000000007f70cc in srv_error_monitor_thread (arg=<value optimized out>)
    at /pb2/build/sb_0-5519472-1334833515.86/rpm/BUILD/mysql-5.5.24/mysql-5.5.24/storage/innobase/srv/srv0srv.c:2444
#2  0x0000003bc3c077f1 in start_thread () from /lib64/libpthread.so.0
#3  0x0000003bc38e5ccd in clone () from /lib64/libc.so.6

diff -cr mysql-5.5.24_orig/storage/innobase/srv/srv0srv.c mysql-5.5.24/storage/innobase/srv/srv0srv.c
*** mysql-5.5.24_orig/storage/innobase/srv/srv0srv.c    2012-04-19 20:01:23.000000000 +0900
--- mysql-5.5.24/storage/innobase/srv/srv0srv.c 2012-07-01 18:45:06.247890142 +0900
***************
*** 2284,2290 ****

        sig_count = os_event_reset(srv_timeout_event);

!       os_event_wait_time_low(srv_timeout_event, 1000000, sig_count);

        srv_lock_timeout_active = TRUE;

--- 2284,2290 ----

        sig_count = os_event_reset(srv_timeout_event);

!       os_thread_sleep(1000000);

        srv_lock_timeout_active = TRUE;

***************
*** 2467,2473 ****

        sig_count = os_event_reset(srv_error_event);

!       os_event_wait_time_low(srv_error_event, 1000000, sig_count);

        if (srv_shutdown_state < SRV_SHUTDOWN_CLEANUP) {

--- 2467,2473 ----

        sig_count = os_event_reset(srv_error_event);

!         os_thread_sleep(1000000);

        if (srv_shutdown_state < SRV_SHUTDOWN_CLEANUP) {
[1 Jul 2012 14:56] Davi Arnaut
It's a kernel issue http://marc.info/?l=linux-kernel&m=134113577921904
[2 Jul 2012 10:01] Valerii Kravchuk
It would be still nice for InnoDB team to review the patch suggested.
[2 Jul 2012 15:27] Davi Arnaut
The patch happens to "work" because os_thread_sleep() uses select(), which in the kernel uses a monotonic clock to sleep until the timeout. The kernel bug seems to only have affected the realtime clock. Anyway, this did not affect only InnoDB, any timed wait on a lock within MySQL was affected.
[4 Jun 2013 10:38] Erlend Dahl
[4 Jun 2013 1:17] Georgi Kodinov

This behavior is (as explained in earlier comments) a result of a OS bug in
how waits are handled.

I don't think we should (or even can reliably) try to fix it. Rebooting is IMHO a good enough workaround.