| Bug #47814 | Diagnostics are frequently not printed after a long lock wait in InnoDB | ||
|---|---|---|---|
| Submitted: | 4 Oct 2009 18:33 | Modified: | 19 Jun 2010 17:53 |
| Reporter: | Mark Callaghan | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S2 (Serious) |
| Version: | 5.0.44 | OS: | Linux |
| Assigned to: | Satya B | CPU Architecture: | Any |
| Tags: | innodb, lock, long, Semaphore, wait | ||
[5 Oct 2009 17:41]
Harrison Fisk
This can occur when InnoDB is hanging on the kernel_mutex. sync_array_print_long_waits() signals the background lock timeout and monitor thread to output the show innodb status info by doing: srv_print_innodb_monitor = TRUE; os_event_set(srv_lock_timeout_thread_event); However, the srv_lock_timeout_and_monitor_thread does two things: 1. Outputs show innodb status as requested (such as by sync_array_print_long_waits) 2. Checks for innodb_lock_wait_timeout While doing #2 it attempts to acquire the kernel_mutex. When the kernel_mutex is the one causing the hang, then it will never make it back to #1 and hence will not output the requested information. One way to solve this would be to split these two uses into two threads. Another way would be to allow the kernel_mutex acquisition required for #2 to timeout after some set time limit.
[14 Oct 2009 10:36]
Jimmy Yang
Here is a repro for this problem:
0) mysql> create table test (a int) engine = innodb;
Query OK, 0 rows affected (0.01 sec)
1) Start two sessions, in session one, start a transaction, and insert a row:
mysql> start transaction;
Query OK, 0 rows affected (0.01 sec)
mysql> insert into test values(9);
Query OK, 1 row affected (0.00 sec)
2) Attach debugger, put break point in srv_suspend_mysql_thread() right after mutex_enter(&kernel_mutex);
3) In session 2, call delete from table test, this will hang (lock conflict):
mysql> delete from test;
4) And after a while, it will get to the break point you set in step 2, when it handles DB_LOCK_WAIT error, stack is:
srv_suspend_mysql_thread
row_mysql_handle_errors (DB_LOCK_WAIT )
row_search_for_mysql
ha_innobase::index_read
5) Create a function of yourself, and let it keep looping in os_thread_yield() (this might need to be done first and compiled into server)
void
debug_loop()
{
int set = 1;
while (set)
{
os_thread_yield();
}
}
6) In the debugger, when you break right after the mutex_enter(), call this function:
(gdb) call debug_loop()
7) Now this thread is hold the kernel_mutex and looping(), we artificially create extended holding of mutex.
8) The srv_lock_timeout_and_monitor_thread() is invoked by the background thread, and it will find kernel_mutex is not available to it:
srv_lock_timeout_and_monitor_thread()
{
...
mutex_enter(&kernel_mutex); <===
...
}
As a result, sync_array_print_long_waits() will be called, and again, it will wait 30 seconds for srv_lock_timeout_and_monitor_thread() to print monitor information. However, nothing will get printed because srv_lock_timeout_and_monitor_thread() is stuck (by the mutex). So you will get the exact output described by this bug report:
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 1152145728 has waited at srv/srv0srv.c line 1992 for 614.00 seconds the semaphore:
Mutex at 0x2aaaaad732b8 created file srv/srv0srv.c line 875, lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
So we created a artificial situation for the case. In the real time, it would more likely be a race condition.
Solutions are being evaluated...
Thanks
Jimmy
[22 Oct 2009 10:24]
Jimmy Yang
Additional note on this bug. The monitor printing operation also requires the kernel_mutex in following call path: srv_printf_innodb_monitor() -> lock_print_info_summary() -> lock_mutex_enter_kernel() It is possible, the thread gets blocked there before the request (mutex_enter(&kernel_mutex)) in srv_lock_timeout_and_monitor_thread() We are testing approaches built on top of mutex_enter_nowait() for a limited wait and skip the operation if we cannot gain the lock for this trial. Thanks Jimmy
[17 Dec 2009 3:41]
Jimmy Yang
After the fix, the monitor information prints fine when we blocked on kernel_mutex, and displays the kernel_mutex getting blocked in srv_lock_timeout_thread(): --Thread 1148021056 has waited at srv/srv0srv.c line 2095 for 159.00 seconds the semaphore: Mutex at 0x2aaaaad732b8 created file srv/srv0srv.c line 890, lock var 1 And also it displays the info that due to unable to get kernel_mutex, lock info printing will be skipped: FAIL TO OBTAIN KERNEL MUTEX, SKIP LOCK INFO PRINTING Following is the full output with a simulated block on kernel_mutex with method described in bug description: ===================================== 091216 19:34:52 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 8 seconds ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 6, signal count 5 --Thread 1148021056 has waited at srv/srv0srv.c line 2095 for 159.00 seconds the semaphore: Mutex at 0x2aaaaad732b8 created file srv/srv0srv.c line 890, lock var 1 waiters flag 1 Mutex spin waits 0, rounds 40, OS waits 2 RW-shared spins 7, OS waits 3; RW-excl spins 1, OS waits 1 FAIL TO OBTAIN KERNEL MUTEX, SKIP LOCK INFO PRINTING -------- FILE I/O -------- I/O thread 0 state: waiting for i/o request (insert buffer thread) I/O thread 1 state: waiting for i/o request (log thread) I/O thread 2 state: waiting for i/o request (read thread) I/O thread 3 state: waiting for i/o request (write thread) Pending normal aio reads: 0, aio writes: 0, ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 42 OS file reads, 15 OS file writes, 11 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf: size 1, free list len 0, seg size 2, 0 inserts, 0 merged recs, 0 merges Hash table size 17393, node heap has 1 buffer(s) 0.00 hash searches/s, 0.00 non-hash searches/s --- LOG --- Log sequence number 0 46270 Log flushed up to 0 46270 Last checkpoint at 0 46270 0 pending log writes, 0 pending chkp writes 12 log i/o's done, 0.00 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 22452576; in additional pool allocated 687360 Dictionary memory allocated 37816 Buffer pool size 512 Free buffers 491 Database pages 20 Modified db pages 0 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages read 20, created 0, written 6 0.00 reads/s, 0.00 creates/s, 0.00 writes/s No buffer pool page gets since the last printout -------------- ROW OPERATIONS -------------- 1 queries inside InnoDB, 0 queries in queue 1 read views open inside InnoDB Main thread process no. 32549, id 1179490624, state: waiting for server activity Number of rows inserted 1, updated 0, deleted 0, read 0 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================ Thanks Jimmy
[23 Dec 2009 7:00]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/95455 3292 Satya B 2009-12-23 Applying InnoDB snapshot 5.1-ss6344, Fixes BUG#47814 and also applying 5.1-ss6355 Detailed revision comments: r6324 | jyang | 2009-12-17 06:54:24 +0200 (Thu, 17 Dec 2009) | 8 lines branches/5.1: Fix bug #47814 - Diagnostics are frequently not printed after a long lock wait in InnoDB. Separate out the lock wait timeout check thread from monitor information printing thread. rb://200 Approved by Marko. r6349 | marko | 2009-12-22 11:09:54 +0200 (Tue, 22 Dec 2009) | 3 lines branches/5.1: lock_print_info_summary(): Remove a reference to innobase_mysql_end_print_arbitrary_thd() that should have been removed in r6347 when removing the function. r6350 | marko | 2009-12-22 11:11:09 +0200 (Tue, 22 Dec 2009) | 1 line branches/5.1: Remove an obsolete declaration of LOCK_thread_count.
[23 Dec 2009 7:28]
Satya B
patch queued to mysql-5.1-bugteam and NULL MERGED to msyql-pe
[15 Jan 2010 9:02]
Bugs System
Pushed into 5.1.43 (revid:joro@sun.com-20100115085139-qkh0i0fpohd9u9p5) (version source revid:satya.bn@sun.com-20091223065934-g7833n12f5lihai0) (merge vers: 5.1.42) (pib:16)
[22 Jan 2010 1:09]
Paul DuBois
Noted in 5.1.43 changelog. The InnoDB Monitor could fail to print diagnostic information after a long lock wait. Closing. Merges to trees higher than 5.1 are null merges.
[5 Feb 2010 11:51]
Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100204063540-9czpdmpixi3iw2yb) (version source revid:alik@sun.com-20100119163614-172adculixyu26j5) (pib:16)
[5 Feb 2010 11:54]
Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100205113942-oqovjy0eoqbarn7i) (version source revid:alik@sun.com-20100204064210-ljwanqvrjs83s1gq) (merge vers: 6.0.14-alpha) (pib:16)
[5 Feb 2010 12:02]
Bugs System
Pushed into 5.5.2-m2 (revid:alik@sun.com-20100203172258-1n5dsotny40yufxw) (version source revid:alexey.kopytov@sun.com-20091225091516-mbk3c41dhl1vunpo) (merge vers: 5.5.1-m2) (pib:16)
[12 Mar 2010 14:13]
Bugs System
Pushed into 5.1.44-ndb-7.0.14 (revid:jonas@mysql.com-20100312135944-t0z8s1da2orvl66x) (version source revid:jonas@mysql.com-20100312115609-woou0te4a6s4ae9y) (merge vers: 5.1.44-ndb-7.0.14) (pib:16)
[12 Mar 2010 14:29]
Bugs System
Pushed into 5.1.44-ndb-6.2.19 (revid:jonas@mysql.com-20100312134846-tuqhd9w3tv4xgl3d) (version source revid:jonas@mysql.com-20100312060623-mx6407w2vx76h3by) (merge vers: 5.1.44-ndb-6.2.19) (pib:16)
[12 Mar 2010 14:45]
Bugs System
Pushed into 5.1.44-ndb-6.3.33 (revid:jonas@mysql.com-20100312135724-xcw8vw2lu3mijrhn) (version source revid:jonas@mysql.com-20100312103652-snkltsd197l7q2yg) (merge vers: 5.1.44-ndb-6.3.33) (pib:16)
[6 Apr 2010 7:59]
Bugs System
Pushed into 5.1.46 (revid:sergey.glukhov@sun.com-20100405111026-7kz1p8qlzglqgfmu) (version source revid:svoj@sun.com-20100401151005-c6re90vdvutln15d) (merge vers: 5.1.46) (pib:16)
[5 May 2010 15:14]
Bugs System
Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[6 May 2010 17:13]
Paul DuBois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug. Re-closing.
[28 May 2010 5:53]
Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)
[28 May 2010 6:22]
Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[28 May 2010 6:50]
Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[29 May 2010 22:41]
Paul DuBois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug. Re-closing.
[15 Jun 2010 8:14]
Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100615080459-smuswd9ooeywcxuc) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:16)
[15 Jun 2010 8:31]
Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (pib:16)
[17 Jun 2010 11:57]
Bugs System
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 12:36]
Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 13:23]
Bugs System
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
Description: Code in innobase/sync/sync0arr.c attempts to print diagnostics when a long semaphore/lock wait is detected. Frequently, nothing is printed in that case. I frequently see this: InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: InnoDB: Pending preads 0, pwrites 0 InnoDB: ###### Diagnostic info printed to the standard error stream And from the code below I expect much more to be printed between the 'InnoDB: #####' lines. The code is: if (noticed) { fprintf(stderr, "InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:\n"); old_val = srv_print_innodb_monitor; /* If some crucial semaphore is reserved, then also the InnoDB Monitor can hang, and we do not get diagnostics. Since in many cases an InnoDB hang is caused by a pwrite() or a pread() call hanging inside the operating system, let us print right now the values of pending calls of these. */ fprintf(stderr, "InnoDB: Pending preads %lu, pwrites %lu\n", (ulong)os_file_n_pending_preads, (ulong)os_file_n_pending_pwrites); srv_print_innodb_monitor = TRUE; os_event_set(srv_lock_timeout_thread_event); os_thread_sleep(30000000); srv_print_innodb_monitor = old_val; fprintf(stderr, "InnoDB: ###### Diagnostic info printed to the standard error stream\n"); How to repeat: Make a long semaphore wait occur in InnoDB Suggested fix: I don't know.