| 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: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S5 (Performance) |
| Version: | 5.5.24 | OS: | Linux |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | leap second | ||
[1 Jul 2012 3:51]
Nicholas Bamber
[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]
Valeriy 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.
