Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Won't Fix
-
10.4.20
Description
This is not a full bug report yet, though I do have a reproducible scenario on a test server. I am working on a smaller test case.
To cause the problem, we do this:
set innodb_log_file_size to 4M to quickly simulate log space shortage
use a table with 72M rows
alter it with the INSTANT algorithm adding a few columns
set innodb_buffer_pool_size to 1G
run an update modifying one of the instant-added columns (everything goes well, the query takes 3 minutes)
then set innodb_buffer_pool_size to 512M and wait for the dust to settle down so that it actually shows as 512M
then re-run the above query
This time we go into the deadlock timeout, and from the gdb trace we can see this race:
hread 23 (Thread 0x7f39f4ff5700 (LWP 38128)):
|
#0 0x00007f3a20687a35 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
|
#1 0x0000560a685f3b89 in wait (this=0x7f3a0c429bb0)
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/include/sync0types.h:463
|
#2 os_event::wait_low(long) () at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/os/os0event.cc:325
|
#3 0x0000560a685f3e65 in os_event_wait_low (event=<optimized out>, reset_sig_count=<optimized out>)
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/os/os0event.cc:502
|
#4 0x0000560a68670c21 in sync_array_wait_event(sync_array_t*, sync_cell_t*&) ()
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/include/ib0mutex.h:496
|
#5 0x0000560a6867350a in rw_lock_sx_lock_func(rw_lock_t*, unsigned long, char const*, unsigned int) ()
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/sync/sync0rw.cc:833
|
#6 0x0000560a686ea9c9 in pfs_rw_lock_sx_lock_func (pass=2,
|
file_name=0x560a68cd2a38 "/home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/buf/buf0flu.cc", line=1186,
|
lock=0x7f39d88fb248) at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/include/sync0rw.ic:674
|
#7 buf_flush_page(buf_pool_t*, buf_page_t*, buf_flush_t, bool) ()
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/buf/buf0flu.cc:1186
|
#8 0x0000560a686eb201 in buf_flush_try_neighbors (n_to_flush=<optimized out>, n_flushed=<optimized out>,
|
flush_type=BUF_FLUSH_LIST, page_id=...)
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/buf/buf0flu.cc:1431
|
#9 buf_flush_page_and_try_neighbors(buf_page_t*, buf_flush_t, unsigned long, unsigned long*) [clone .isra.0] ()
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/buf/buf0flu.cc:1505
|
#10 0x0000560a686ec109 in buf_do_flush_list_batch(buf_pool_t*, unsigned long, unsigned long) ()
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/buf/buf0flu.cc:1763
|
#11 0x0000560a686edef9 in buf_flush_batch (n=0x7f39f4ff4c50, lsn_limit=1446564044560, min_n=18446744073709551614,
|
flush_type=BUF_FLUSH_LIST, buf_pool=0x560a6b20c620)
|
/home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/buf/buf0flu.cc:1834
|
#12 buf_flush_do_batch (n=0x7f39f4ff4c50, lsn_limit=1446564044560, min_n=18446744073709551614, type=BUF_FLUSH_LIST,
|
buf_pool=0x560a6b20c620) at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/buf/buf0flu.cc:1992
|
#13 buf_flush_do_batch (type=BUF_FLUSH_LIST, n=0x7f39f4ff4c50, lsn_limit=<optimized out>, min_n=<optimized out>,
|
buf_pool=0x560a6b20c620) at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/buf/buf0flu.cc:1975
|
#14 pc_flush_slot () at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/buf/buf0flu.cc:2791
|
#15 0x0000560a680b1d54 in buf_flush_page_cleaner_coordinator ()
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/buf/buf0flu.cc:3160
|
#16 0x00007f3a20683ea5 in start_thread () from /lib64/libpthread.so.0
|
#17 0x00007f3a1f11396d in clone () from /lib64/libc.so.6
|
|
The flush thread wants a page lock that is being held by another thread.
Following the writer_thread member of rw_lock we find that it is being held by the purge thread with this trace:
Thread 16 (Thread 0x7f39ec7f8700 (LWP 38147)):
|
#0 0x00007f3a2068ae9d in nanosleep () from /lib64/libpthread.so.0
|
#1 0x0000560a685f401c in os_thread_sleep (tm=tm@entry=100000)
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/os/os0thread.cc:231
|
#2 0x0000560a685d96ca in log_margin_checkpoint_age(unsigned long) ()
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/log/log0log.cc:283
|
#3 0x0000560a685eb4f3 in prepare_write (this=0x7f39ec7f6c50)
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/mtr/mtr0mtr.cc:699
|
#4 mtr_t::commit() () at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/mtr/mtr0mtr.cc:439
|
#5 0x0000560a6869c445 in trx_undo_truncate_start(trx_rseg_t*, unsigned long, unsigned long, unsigned long) ()
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/trx/trx0undo.cc:1018
|
#6 0x0000560a6867cae4 in trx_purge_truncate_rseg_history (limit=..., rseg=...)
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/trx/trx0purge.cc:465
|
#7 trx_purge_truncate_history() () at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/trx/trx0purge.cc:564
|
#8 0x0000560a6867f9e5 in trx_purge(unsigned long, bool) ()
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/trx/trx0purge.cc:1329
|
#9 0x0000560a6866cbad in srv_do_purge (n_total_purged=<synthetic pointer>)
|
at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/srv/srv0srv.cc:2613
|
#10 srv_purge_coordinator_thread () at /home/bdempsey/samurai/var/10.4.20samurai/src/storage/innobase/srv/srv0srv.cc:2752
|
#11 0x00007f3a20683ea5 in start_thread () from /lib64/libpthread.so.0
|
#12 0x00007f3a1f11396d in clone () from /lib64/libc.so.6
|
So apparently the purge thread is waiting for the log space to become available, but it will never happen because it is doing it while holding the lock on the page that the flush thread wants to flush to make that space available.
We are working on isolating this into something manageable that we can post, but since we are aware of this bug, I figured I would open an issue and hopefully get some tips on the code in question. In particular, I would like to know how to get a call in trx_undo_truncate_start() to do something meaningful - I can get a call to happen, but it returns immediately because the limit argument is 0.
Attachments
Issue Links
- relates to
-
-
- Closed
-
-
-
- Closed
-