buf_validate may see an unlatched but I/O fixed for read page

[Laurynas Biveinis]

A low-probability debug build failure seen once on innodb_zip.innodb_wl6501_debug:

Thread 1 (Thread 0x7f48cebfd700 (LWP 2852)):
...
#6 0x000000000104b69b in ut_dbg_assertion_failed (expr=0x14e3be8 "rw_lock_is_locked(&block->lock, RW_LOCK_X)", file=0x14e1410 "/mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/buf/buf0buf.cc", line=5794) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/ut/ut0dbg.cc:68
#7 0x00000000010b0cdc in buf_pool_validate_instance (buf_pool=0x2b4e130) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/buf/buf0buf.cc:5793
#8 0x00000000010b14a5 in buf_validate () at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/buf/buf0buf.cc:5952
...

it asserts that a page, that is I/O-fixed for read, is X-latched. The assert failed because of

Thread 3 (Thread 0x7f48f6502700 (LWP 2860)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1 0x0000000000f187fc in os_event::wait (this=0x2b4eae0) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/os/os0event.cc:217
#2 0x0000000000f181b9 in os_event::wait_low (this=0x2b4eae0, reset_sig_count=1) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/os/os0event.cc:446
#3 0x0000000000f18608 in os_event_wait_low (event=0x2b4eae0, reset_sig_count=1) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/os/os0event.cc:700
#4 0x0000000001000fdb in sync_array_wait_event (arr=0x2ab8bf0, cell=@0x7f48f64fbb68: 0x7f48f7372020) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/sync/sync0arr.cc:453
#5 0x0000000000e9d088 in TTASEventMutex<DebugPolicy>::wait (this=0x2b4e1c0, filename=0x14e9ea0 "/mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/buf/buf0lru.cc", line=1182) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/include/ut0mutex.ic:80
#6 0x0000000000e9c4d3 in TTASEventMutex<DebugPolicy>::spin_and_wait (this=0x2b4e1c0, max_spins=30, max_delay=6, filename=0x14e9ea0 "/mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/buf/buf0lru.cc", line=1182) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/include/ib0mutex.h:896
#7 0x0000000000e9b850 in TTASEventMutex<DebugPolicy>::enter (this=0x2b4e1c0, max_spins=30, max_delay=6, filename=0x14e9ea0 "/mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/buf/buf0lru.cc", line=1182) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/include/ib0mutex.h:784
#8 0x0000000000e9ab7d in PolicyMutex<TTASEventMutex<DebugPolicy> >::enter (this=0x2b4e1b8, n_spins=30, n_delay=6, name=0x14e9ea0 "/mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/buf/buf0lru.cc", line=1182) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/include/ib0mutex.h:1038
#9 0x00000000010c966f in buf_LRU_get_free_only (buf_pool=0x2b4e130) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/buf/buf0lru.cc:1182
#10 0x00000000011997c1 in buf_buddy_alloc_low (buf_pool=0x2b4e130, i=4) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/buf/buf0buddy.cc:517
#11 0x00000000010a1bf4 in buf_buddy_alloc (buf_pool=0x2b4e130, size=16384) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/include/buf0buddy.ic:102
#12 0x00000000010af060 in buf_page_create (page_id=..., page_size=..., mtr=0x7f48f64fc5a0) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/buf/buf0buf.cc:5112

with the code fragment immediately before

  /* Prevent race conditions during buf_buddy_alloc()
  by IO-fixing and X-latching the block. */
  buf_page_set_io_fix(&block->page, BUF_IO_READ);
  rw_lock_x_lock(&block->lock);

The fix would be swapping the I/O fix set and the X latch.

[Laurynas Biveinis (laurynas-biveinis)]

http://jenkins.percona.com/job/mysql-5.7-param/4/BUILD_TYPE=debug,Host=ubuntu-precise-64bit/consoleText

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3270