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.