[MDEV-12624] encryption.innodb_encryption_tables fails in buildbot with timeout Created: 2017-04-28  Updated: 2017-05-02  Resolved: 2017-05-02

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB, Tests
Affects Version/s: 10.1
Fix Version/s: 10.1.23

Type: Bug Priority: Blocker
Reporter: Elena Stepanova Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: regression


 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/7915/steps/test_3/logs/stdio

encryption.innodb_encryption_tables 'innodb_plugin' w1 [ fail ]  timeout after 900 seconds
        Test ended at 2017-04-28 22:34:51
 
Test case timeout after 900 seconds

Apparently, normally the test takes ~30 seconds there, so it shouldn't be failing just because it's too long.

It happened on my local machine too, here is the stack trace (no ps-protocol):

[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f150c9f7aed in poll () at ../sysdeps/unix/syscall-template.S:81
 
Thread 26 (Thread 0x7f15073ff700 (LWP 31709)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f150f9ec0ef in safe_cond_timedwait (cond=0x7f1510c5c000 <COND_timer>, mp=0x7f1510c5bf40 <LOCK_timer>, abstime=0x7f15073fee70, file=0x7f150fc53cf0 "/data/src/10.1/include/mysql/psi/mysql_thread.h", line=1191) at /data/src/10.1/mysys/thr_mutex.c:547
#2  0x00007f150f9ed03d in inline_mysql_cond_timedwait (that=0x7f1510c5c000 <COND_timer>, mutex=0x7f1510c5bf40 <LOCK_timer>, abstime=0x7f15073fee70, src_file=0x7f150fc53d20 "/data/src/10.1/mysys/thr_timer.c", src_line=292) at /data/src/10.1/include/mysql/psi/mysql_thread.h:1191
#3  0x00007f150f9edb33 in timer_handler (arg=0x0) at /data/src/10.1/mysys/thr_timer.c:292
#4  0x00007f150f56615a in pfs_spawn_thread (arg=0x7f150c022c70) at /data/src/10.1/storage/perfschema/pfs.cc:1860
#5  0x00007f150e848064 in start_thread (arg=0x7f15073ff700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 25 (Thread 0x7f1504fff700 (LWP 31710)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f150f9ec0ef in safe_cond_timedwait (cond=0x7f1510c52940 <COND_checkpoint>, mp=0x7f1510c52880 <LOCK_checkpoint>, abstime=0x7f1504ffedc0, file=0x7f150fc32830 "/data/src/10.1/include/mysql/psi/mysql_thread.h", line=1191) at /data/src/10.1/mysys/thr_mutex.c:547
#2  0x00007f150f8af444 in inline_mysql_cond_timedwait (that=0x7f1510c52940 <COND_checkpoint>, mutex=0x7f1510c52880 <LOCK_checkpoint>, abstime=0x7f1504ffedc0, src_file=0x7f150fc32860 "/data/src/10.1/storage/maria/ma_servicethread.c", src_line=116) at /data/src/10.1/include/mysql/psi/mysql_thread.h:1191
#3  0x00007f150f8af929 in my_service_thread_sleep (control=0x7f15102266c0 <checkpoint_control>, sleep_time=30000000000) at /data/src/10.1/storage/maria/ma_servicethread.c:115
#4  0x00007f150f8a4459 in ma_checkpoint_background (arg=0x1e) at /data/src/10.1/storage/maria/ma_checkpoint.c:708
#5  0x00007f150f56615a in pfs_spawn_thread (arg=0x7f150c0251f0) at /data/src/10.1/storage/perfschema/pfs.cc:1860
#6  0x00007f150e848064 in start_thread (arg=0x7f1504fff700) at pthread_create.c:309
#7  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 24 (Thread 0x7f1502fff700 (LWP 31711)):
#0  0x00007f150e63e6ea in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007f1505f8a8dc in os_aio_linux_collect (array=0x7f15083ea100, segment=0, seg_size=256) at /data/src/10.1/storage/innobase/os/os0file.cc:5215
#2  0x00007f1505f8acac in os_aio_linux_handle (global_seg=0, message1=0x7f1502ffee68, message2=0x7f1502ffee70, type=0x7f1502ffee78) at /data/src/10.1/storage/innobase/os/os0file.cc:5367
#3  0x00007f1505ea475c in fil_aio_wait (segment=0) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:6210
#4  0x00007f150605dd4a in io_handler_thread (arg=0x7f15063ef840 <n>) at /data/src/10.1/storage/innobase/srv/srv0start.cc:516
#5  0x00007f150e848064 in start_thread (arg=0x7f1502fff700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 23 (Thread 0x7f15027fe700 (LWP 31712)):
#0  0x00007f150e63e6ea in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007f1505f8a8dc in os_aio_linux_collect (array=0x7f15083ea0b0, segment=0, seg_size=256) at /data/src/10.1/storage/innobase/os/os0file.cc:5215
#2  0x00007f1505f8acac in os_aio_linux_handle (global_seg=1, message1=0x7f15027fde68, message2=0x7f15027fde70, type=0x7f15027fde78) at /data/src/10.1/storage/innobase/os/os0file.cc:5367
#3  0x00007f1505ea475c in fil_aio_wait (segment=1) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:6210
#4  0x00007f150605dd4a in io_handler_thread (arg=0x7f15063ef848 <n+8>) at /data/src/10.1/storage/innobase/srv/srv0start.cc:516
#5  0x00007f150e848064 in start_thread (arg=0x7f15027fe700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 22 (Thread 0x7f1501ffd700 (LWP 31713)):
#0  0x00007f150e63e6ea in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007f1505f8a8dc in os_aio_linux_collect (array=0x7f15083ea060, segment=0, seg_size=256) at /data/src/10.1/storage/innobase/os/os0file.cc:5215
#2  0x00007f1505f8acac in os_aio_linux_handle (global_seg=2, message1=0x7f1501ffce68, message2=0x7f1501ffce70, type=0x7f1501ffce78) at /data/src/10.1/storage/innobase/os/os0file.cc:5367
#3  0x00007f1505ea475c in fil_aio_wait (segment=2) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:6210
#4  0x00007f150605dd4a in io_handler_thread (arg=0x7f15063ef850 <n+16>) at /data/src/10.1/storage/innobase/srv/srv0start.cc:516
#5  0x00007f150e848064 in start_thread (arg=0x7f1501ffd700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 21 (Thread 0x7f15017fc700 (LWP 31714)):
#0  0x00007f150e63e6ea in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007f1505f8a8dc in os_aio_linux_collect (array=0x7f15083ea060, segment=1, seg_size=256) at /data/src/10.1/storage/innobase/os/os0file.cc:5215
#2  0x00007f1505f8acac in os_aio_linux_handle (global_seg=3, message1=0x7f15017fbe68, message2=0x7f15017fbe70, type=0x7f15017fbe78) at /data/src/10.1/storage/innobase/os/os0file.cc:5367
#3  0x00007f1505ea475c in fil_aio_wait (segment=3) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:6210
#4  0x00007f150605dd4a in io_handler_thread (arg=0x7f15063ef858 <n+24>) at /data/src/10.1/storage/innobase/srv/srv0start.cc:516
#5  0x00007f150e848064 in start_thread (arg=0x7f15017fc700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 20 (Thread 0x7f1500ffb700 (LWP 31715)):
#0  0x00007f150e63e6ea in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007f1505f8a8dc in os_aio_linux_collect (array=0x7f15083ea150, segment=0, seg_size=256) at /data/src/10.1/storage/innobase/os/os0file.cc:5215
#2  0x00007f1505f8acac in os_aio_linux_handle (global_seg=4, message1=0x7f1500ffae68, message2=0x7f1500ffae70, type=0x7f1500ffae78) at /data/src/10.1/storage/innobase/os/os0file.cc:5367
#3  0x00007f1505ea475c in fil_aio_wait (segment=4) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:6210
#4  0x00007f150605dd4a in io_handler_thread (arg=0x7f15063ef860 <n+32>) at /data/src/10.1/storage/innobase/srv/srv0start.cc:516
#5  0x00007f150e848064 in start_thread (arg=0x7f1500ffb700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 19 (Thread 0x7f15007fa700 (LWP 31716)):
#0  0x00007f150e63e6ea in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007f1505f8a8dc in os_aio_linux_collect (array=0x7f15083ea150, segment=1, seg_size=256) at /data/src/10.1/storage/innobase/os/os0file.cc:5215
#2  0x00007f1505f8acac in os_aio_linux_handle (global_seg=5, message1=0x7f15007f9e68, message2=0x7f15007f9e70, type=0x7f15007f9e78) at /data/src/10.1/storage/innobase/os/os0file.cc:5367
#3  0x00007f1505ea475c in fil_aio_wait (segment=5) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:6210
#4  0x00007f150605dd4a in io_handler_thread (arg=0x7f15063ef868 <n+40>) at /data/src/10.1/storage/innobase/srv/srv0start.cc:516
#5  0x00007f150e848064 in start_thread (arg=0x7f15007fa700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 18 (Thread 0x7f14ff7ff700 (LWP 31718)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f1505f8d21c in os_cond_wait_timed (cond=0x7f15051f1240, fast_mutex=0x7f15051f1200, abstime=0x7f14ff7fee70) at /data/src/10.1/storage/innobase/os/os0sync.cc:177
#2  0x00007f1505f8d9d4 in os_event_wait_time_low (event=0x7f15051f1200, time_in_usec=1000000, reset_sig_count=1) at /data/src/10.1/storage/innobase/os/os0sync.cc:705
#3  0x00007f1505f675d2 in lock_wait_timeout_thread () at /data/src/10.1/storage/innobase/lock/lock0wait.cc:531
#4  0x00007f150e848064 in start_thread (arg=0x7f14ff7ff700) at pthread_create.c:309
#5  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 17 (Thread 0x7f14fe7ff700 (LWP 31719)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f1505f8d21c in os_cond_wait_timed (cond=0x7f1509bfedc0, fast_mutex=0x7f1509bfed80, abstime=0x7f14fe7fee30) at /data/src/10.1/storage/innobase/os/os0sync.cc:177
#2  0x00007f1505f8d9d4 in os_event_wait_time_low (event=0x7f1509bfed80, time_in_usec=1000000, reset_sig_count=1) at /data/src/10.1/storage/innobase/os/os0sync.cc:705
#3  0x00007f1506059945 in srv_error_monitor_thread () at /data/src/10.1/storage/innobase/srv/srv0srv.cc:1991
#4  0x00007f150e848064 in start_thread (arg=0x7f14fe7ff700) at pthread_create.c:309
#5  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 16 (Thread 0x7f14fdffe700 (LWP 31720)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f1505f8d21c in os_cond_wait_timed (cond=0x7f1509bfee40, fast_mutex=0x7f1509bfee00, abstime=0x7f14fdffde40) at /data/src/10.1/storage/innobase/os/os0sync.cc:177
#2  0x00007f1505f8d9d4 in os_event_wait_time_low (event=0x7f1509bfee00, time_in_usec=5000000, reset_sig_count=1) at /data/src/10.1/storage/innobase/os/os0sync.cc:705
#3  0x00007f1506059314 in srv_monitor_thread () at /data/src/10.1/storage/innobase/srv/srv0srv.cc:1750
#4  0x00007f150e848064 in start_thread (arg=0x7f14fdffe700) at pthread_create.c:309
#5  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 15 (Thread 0x7f14fd7fd700 (LWP 31721)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007f1505f8d304 in os_cond_wait (cond=0x7f15051f1c40, fast_mutex=0x7f15051f1c00) at /data/src/10.1/storage/innobase/os/os0sync.cc:214
#2  0x00007f1505f8d82c in os_event_wait_low (event=0x7f15051f1c00, reset_sig_count=1) at /data/src/10.1/storage/innobase/os/os0sync.cc:592
#3  0x00007f1506063297 in sync_array_wait_event (arr=0x7f15097f0840, index=0) at /data/src/10.1/storage/innobase/sync/sync0arr.cc:465
#4  0x00007f1506066ca5 in rw_lock_x_lock_func (lock=0x7f15063c6a80 <dict_operation_lock>, pass=0, file_name=0x7f1506129db0 "/data/src/10.1/storage/innobase/srv/srv0srv.cc", line=2184) at /data/src/10.1/storage/innobase/sync/sync0rw.cc:705
#5  0x00007f15060566d4 in pfs_rw_lock_x_lock_func (lock=0x7f15063c6a80 <dict_operation_lock>, pass=0, file_name=0x7f1506129db0 "/data/src/10.1/storage/innobase/srv/srv0srv.cc", line=2184) at /data/src/10.1/storage/innobase/include/sync0rw.ic:610
#6  0x00007f1506059da2 in srv_master_evict_from_table_cache (pct_check=100) at /data/src/10.1/storage/innobase/srv/srv0srv.cc:2184
#7  0x00007f150605a697 in srv_master_do_idle_tasks () at /data/src/10.1/storage/innobase/srv/srv0srv.cc:2388
#8  0x00007f150605ac59 in srv_master_thread (arg=0x0) at /data/src/10.1/storage/innobase/srv/srv0srv.cc:2538
#9  0x00007f150e848064 in start_thread (arg=0x7f14fd7fd700) at pthread_create.c:309
#10 0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 14 (Thread 0x7f14fcffc700 (LWP 31722)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007f1505f8d304 in os_cond_wait (cond=0x7f1509bfed40, fast_mutex=0x7f1509bfed00) at /data/src/10.1/storage/innobase/os/os0sync.cc:214
#2  0x00007f1505f8d82c in os_event_wait_low (event=0x7f1509bfed00, reset_sig_count=7) at /data/src/10.1/storage/innobase/os/os0sync.cc:592
#3  0x00007f1506057603 in srv_resume_thread (slot=0x7f1507bf6b80, sig_count=7, wait=true, timeout_usec=0) at /data/src/10.1/storage/innobase/srv/srv0srv.cc:926
#4  0x00007f150605b476 in srv_purge_coordinator_suspend (slot=0x7f1507bf6b80, rseg_history_len=6) at /data/src/10.1/storage/innobase/srv/srv0srv.cc:2819
#5  0x00007f150605b7da in srv_purge_coordinator_thread (arg=0x0) at /data/src/10.1/storage/innobase/srv/srv0srv.cc:2904
#6  0x00007f150e848064 in start_thread (arg=0x7f14fcffc700) at pthread_create.c:309
#7  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 13 (Thread 0x7f14fbbff700 (LWP 31723)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f1505f8d21c in os_cond_wait_timed (cond=0x7f15051f0dc0, fast_mutex=0x7f15051f0d80, abstime=0x7f14fbbfee10) at /data/src/10.1/storage/innobase/os/os0sync.cc:177
#2  0x00007f1505f8d9d4 in os_event_wait_time_low (event=0x7f15051f0d80, time_in_usec=1000000, reset_sig_count=1) at /data/src/10.1/storage/innobase/os/os0sync.cc:705
#3  0x00007f1505e4216d in page_cleaner_sleep_if_needed (next_loop_time=1493415634014) at /data/src/10.1/storage/innobase/buf/buf0flu.cc:2287
#4  0x00007f1505e42225 in buf_flush_page_cleaner_thread (arg=0x0) at /data/src/10.1/storage/innobase/buf/buf0flu.cc:2323
#5  0x00007f150e848064 in start_thread (arg=0x7f14fbbff700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 12 (Thread 0x7f14fa7ff700 (LWP 31724)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007f1505f8d304 in os_cond_wait (cond=0x7f1509bfeec0, fast_mutex=0x7f1509bfee80) at /data/src/10.1/storage/innobase/os/os0sync.cc:214
#2  0x00007f1505f8d82c in os_event_wait_low (event=0x7f1509bfee80, reset_sig_count=1) at /data/src/10.1/storage/innobase/os/os0sync.cc:592
#3  0x00007f1505e3abfb in buf_dump_thread () at /data/src/10.1/storage/innobase/buf/buf0dump.cc:699
#4  0x00007f150e848064 in start_thread (arg=0x7f14fa7ff700) at pthread_create.c:309
#5  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 11 (Thread 0x7f14f9ffe700 (LWP 31725)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f1505f8d21c in os_cond_wait_timed (cond=0x7f15051f1940, fast_mutex=0x7f15051f1900, abstime=0x7f14f9ffde90) at /data/src/10.1/storage/innobase/os/os0sync.cc:177
#2  0x00007f1505f8d9d4 in os_event_wait_time_low (event=0x7f15051f1900, time_in_usec=10000000, reset_sig_count=1) at /data/src/10.1/storage/innobase/os/os0sync.cc:705
#3  0x00007f1505e90766 in dict_stats_thread () at /data/src/10.1/storage/innobase/dict/dict0stats_bg.cc:542
#4  0x00007f150e848064 in start_thread (arg=0x7f14f9ffe700) at pthread_create.c:309
#5  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 10 (Thread 0x7f14f97fd700 (LWP 31726)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f1505f8d21c in os_cond_wait_timed (cond=0x7f15052c80c0, fast_mutex=0x7f15052c8080, abstime=0x7f14f97fcde0) at /data/src/10.1/storage/innobase/os/os0sync.cc:177
#2  0x00007f1505f8d9d4 in os_event_wait_time_low (event=0x7f15052c8080, time_in_usec=5000000, reset_sig_count=1) at /data/src/10.1/storage/innobase/os/os0sync.cc:705
#3  0x00007f150609dd9f in ib_wqueue_timedwait (wq=0x7f1507ff34b8, wait_in_usecs=5000000) at /data/src/10.1/storage/innobase/ut/ut0wqueue.cc:154
#4  0x00007f1505edea7e in fts_optimize_thread (arg=0x7f1507ff34b8) at /data/src/10.1/storage/innobase/fts/fts0opt.cc:3060
#5  0x00007f150e848064 in start_thread (arg=0x7f14f97fd700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 9 (Thread 0x7f14f8ffc700 (LWP 31727)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f1505f8d21c in os_cond_wait_timed (cond=0x7f15052c8340, fast_mutex=0x7f15052c8300, abstime=0x7f14f8ffbd70) at /data/src/10.1/storage/innobase/os/os0sync.cc:177
#2  0x00007f1505f8d9d4 in os_event_wait_time_low (event=0x7f15052c8300, time_in_usec=1000000, reset_sig_count=7421723) at /data/src/10.1/storage/innobase/os/os0sync.cc:705
#3  0x00007f1505ead172 in fil_crypt_find_space_to_rotate (key_state=0x7f14f8ffbe00, state=0x7f14f8ffbe10, recheck=0x7f14f8ffbdeb) at /data/src/10.1/storage/innobase/fil/fil0crypt.cc:1620
#4  0x00007f1505eaea12 in fil_crypt_thread (arg=0x0) at /data/src/10.1/storage/innobase/fil/fil0crypt.cc:2337
#5  0x00007f150e848064 in start_thread (arg=0x7f14f8ffc700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 8 (Thread 0x7f14f7fff700 (LWP 31728)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f1505f8d21c in os_cond_wait_timed (cond=0x7f15052c8340, fast_mutex=0x7f15052c8300, abstime=0x7f14f7ffeda0) at /data/src/10.1/storage/innobase/os/os0sync.cc:177
#2  0x00007f1505f8d9d4 in os_event_wait_time_low (event=0x7f15052c8300, time_in_usec=1000000, reset_sig_count=7421723) at /data/src/10.1/storage/innobase/os/os0sync.cc:705
#3  0x00007f1505eae831 in fil_crypt_thread (arg=0x0) at /data/src/10.1/storage/innobase/fil/fil0crypt.cc:2309
#4  0x00007f150e848064 in start_thread (arg=0x7f14f7fff700) at pthread_create.c:309
#5  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 7 (Thread 0x7f14f77fe700 (LWP 31729)):
#0  sync_thread_level_arrays_find_slot () at /data/src/10.1/storage/innobase/sync/sync0sync.cc:769
#1  0x00007f150606a121 in sync_thread_reset_level (latch=0x7f15083a53f8) at /data/src/10.1/storage/innobase/sync/sync0sync.cc:1366
#2  0x00007f1505e9700f in mutex_exit_func (mutex=0x7f15083a53f8) at /data/src/10.1/storage/innobase/include/sync0sync.ic:165
#3  0x00007f1505e971fa in pfs_mutex_exit_func (mutex=0x7f15083a53f8) at /data/src/10.1/storage/innobase/include/sync0sync.ic:319
#4  0x00007f1505e9cc6a in fil_space_get_flags (id=1) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:1955
#5  0x00007f1505e9cc88 in fil_space_get_zip_size (id=1) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:1972
#6  0x00007f1505e0efe3 in btr_scrub_start_space (space=1, scrub_data=0x7f14f77fde78) at /data/src/10.1/storage/innobase/btr/btr0scrub.cc:859
#7  0x00007f1505eacb00 in fil_crypt_space_needs_rotation (state=0x7f14f77fde10, key_state=0x7f14f77fde00, recheck=0x7f14f77fddeb) at /data/src/10.1/storage/innobase/fil/fil0crypt.cc:1390
#8  0x00007f1505ead286 in fil_crypt_find_space_to_rotate (key_state=0x7f14f77fde00, state=0x7f14f77fde10, recheck=0x7f14f77fddeb) at /data/src/10.1/storage/innobase/fil/fil0crypt.cc:1649
#9  0x00007f1505eaea12 in fil_crypt_thread (arg=0x0) at /data/src/10.1/storage/innobase/fil/fil0crypt.cc:2337
#10 0x00007f150e848064 in start_thread (arg=0x7f14f77fe700) at pthread_create.c:309
#11 0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 6 (Thread 0x7f14f67ff700 (LWP 31730)):
#3  0x00007f1505ead172 in fil_crypt_find_space_to_rotate (key_state=0x7f14f67fee00, state=0x7f14f67fee10, recheck=0x7f14f67fedeb) at /data/src/10.1/storage/innobase/fil/fil0crypt.cc:1620
#4  0x00007f1505eaea12 in fil_crypt_thread (arg=0x0) at /data/src/10.1/storage/innobase/fil/fil0crypt.cc:2337
#5  0x00007f150e848064 in start_thread (arg=0x7f14f67ff700) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 5 (Thread 0x7f14f4bff700 (LWP 31731)):
#0  0x00007f150c9f9893 in select () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f1505f8e572 in os_thread_sleep (tm=1000000) at /data/src/10.1/storage/innobase/os/os0thread.cc:283
#2  0x00007f1505e1e59a in btr_defragment_thread (arg=0x0) at /data/src/10.1/storage/innobase/btr/btr0defragment.cc:758
#3  0x00007f150e848064 in start_thread (arg=0x7f14f4bff700) at pthread_create.c:309
#4  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 4 (Thread 0x7f15100ecb00 (LWP 31732)):
#0  do_sigwait (set=<optimized out>, sig=0x7f15100ec1d0) at ../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:63
#1  0x00007f150e84f653 in __sigwait (set=0x7f15100ec200, sig=0x0) at ../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:97
#2  0x00007f150f0843a4 in signal_hand (arg=0x0) at /data/src/10.1/sql/mysqld.cc:3399
#3  0x00007f150f56615a in pfs_spawn_thread (arg=0x7f15052b8df0) at /data/src/10.1/storage/perfschema/pfs.cc:1860
#4  0x00007f150e848064 in start_thread (arg=0x7f15100ecb00) at pthread_create.c:309
#5  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 3 (Thread 0x7f15100a2b00 (LWP 31733)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007f150f9ebde5 in safe_cond_wait (cond=0x7f15103dd520 <COND_slave_background>, mp=0x7f15103e0680 <LOCK_slave_background>, file=0x7f150fa51f80 "/data/src/10.1/include/mysql/psi/mysql_thread.h", line=1154) at /data/src/10.1/mysys/thr_mutex.c:493
#2  0x00007f150f0a676a in inline_mysql_cond_wait (that=0x7f15103dd520 <COND_slave_background>, mutex=0x7f15103e0680 <LOCK_slave_background>, src_file=0x7f150fa526dd "/data/src/10.1/sql/slave.cc", src_line=336) at /data/src/10.1/include/mysql/psi/mysql_thread.h:1154
#3  0x00007f150f0a749c in handle_slave_background (arg=0x0) at /data/src/10.1/sql/slave.cc:336
#4  0x00007f150f56615a in pfs_spawn_thread (arg=0x7f15052b9cf0) at /data/src/10.1/storage/perfschema/pfs.cc:1860
#5  0x00007f150e848064 in start_thread (arg=0x7f15100a2b00) at pthread_create.c:309
#6  0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 2 (Thread 0x7f1510058b00 (LWP 31734)):
#0  0x00007f150c9f9893 in select () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f1505f8e572 in os_thread_sleep (tm=20000) at /data/src/10.1/storage/innobase/os/os0thread.cc:283
#2  0x00007f1505eaee80 in fil_space_crypt_close_tablespace (space=0x7f15052b79f8) at /data/src/10.1/storage/innobase/fil/fil0crypt.cc:2544
#3  0x00007f1505e9e1dc in fil_check_pending_operations (id=10, space=0x7f1510054188, path=0x7f1510054180) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:2885
#4  0x00007f1505e9e577 in fil_delete_tablespace (id=10, buf_remove=BUF_REMOVE_FLUSH_NO_WRITE) at /data/src/10.1/storage/innobase/fil/fil0fil.cc:3024
#5  0x00007f150600b4e4 in row_drop_table_for_mysql (name=0x7f1510054c30 "test/innodb_compact", trx=0x7f14f3489c78, drop_db=false, create_failed=0, nonatomic=true) at /data/src/10.1/storage/innobase/row/row0mysql.cc:4481
#6  0x00007f1505f05d62 in ha_innodb::delete_table (this=0x7f14f3443998, name=0x7f1510056780 "./test/innodb_compact") at /data/src/10.1/storage/innobase/handler/ha_innodb.cc:12559
#7  0x00007f150f392f64 in handler::ha_delete_table (this=0x7f14f3443998, name=0x7f1510056780 "./test/innodb_compact") at /data/src/10.1/sql/handler.cc:4296
#8  0x00007f150f38e079 in ha_delete_table (thd=0x7f15033b0070, table_type=0x7f150c025470, path=0x7f1510056780 "./test/innodb_compact", db=0x7f14f3443768 "test", alias=0x7f14f3443130 "innodb_compact", generate_warning=true) at /data/src/10.1/sql/handler.cc:2352
#9  0x00007f150f206ab2 in mysql_rm_table_no_locks (thd=0x7f15033b0070, tables=0x7f14f3443178, if_exists=false, drop_temporary=false, drop_view=false, dont_log_query=false, dont_free_locks=false) at /data/src/10.1/sql/sql_table.cc:2469
#10 0x00007f150f205cdc in mysql_rm_table (thd=0x7f15033b0070, tables=0x7f14f3443178, if_exists=0 '\000', drop_temporary=0 '\000') at /data/src/10.1/sql/sql_table.cc:2084
#11 0x00007f150f1546de in mysql_execute_command (thd=0x7f15033b0070) at /data/src/10.1/sql/sql_parse.cc:4243
#12 0x00007f150f15ddf7 in mysql_parse (thd=0x7f15033b0070, rawbuf=0x7f14f3443088 "drop table innodb_compact", length=25, parser_state=0x7f15100575e0) at /data/src/10.1/sql/sql_parse.cc:7343
#13 0x00007f150f14cde4 in dispatch_command (command=COM_QUERY, thd=0x7f15033b0070, packet=0x7f150529f071 "drop table innodb_compact", packet_length=25) at /data/src/10.1/sql/sql_parse.cc:1490
#14 0x00007f150f14bb43 in do_command (thd=0x7f15033b0070) at /data/src/10.1/sql/sql_parse.cc:1109
#15 0x00007f150f282cd6 in do_handle_one_connection (thd_arg=0x7f15033b0070) at /data/src/10.1/sql/sql_connect.cc:1349
#16 0x00007f150f282a3a in handle_one_connection (arg=0x7f15033b0070) at /data/src/10.1/sql/sql_connect.cc:1261
#17 0x00007f150f56615a in pfs_spawn_thread (arg=0x7f15052bb0f0) at /data/src/10.1/storage/perfschema/pfs.cc:1860
#18 0x00007f150e848064 in start_thread (arg=0x7f1510058b00) at pthread_create.c:309
#19 0x00007f150ca0062d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
 
Thread 1 (Thread 0x7f15100ff780 (LWP 31708)):
#0  0x00007f150c9f7aed in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f150f089f36 in handle_connections_sockets () at /data/src/10.1/sql/mysqld.cc:6484
#2  0x00007f150f088f02 in mysqld_main (argc=153, argv=0x7f150c06aac0) at /data/src/10.1/sql/mysqld.cc:5909
#3  0x00007f150f07e1f0 in main (argc=29, argv=0x7ffd66b9b568) at /data/src/10.1/sql/main.cc:25

The failure started appearing in 10.1 regularly since this commit:
https://github.com/MariaDB/server/commit/765a43605a42c069ede604826ede2d93d72c4fdd

MDEV-12253: Buffer pool blocks are accessed after they have been freed
Problem was that bpage was referenced after it was already freed
from LRU. Fixed by adding a new variable encrypted that is
passed down to buf_page_check_corrupt() and used in
buf_page_get_gen() to stop processing page read.

Before that, it was happening in the corresponding development tree.



 Comments   
Comment by Elena Stepanova [ 2017-04-28 ]

ATTN marko

Comment by Jan Lindström (Inactive) [ 2017-05-01 ]

It seems to be some kind of timing issue i.e. does not repeat always:

jan@jan-laptop-asus:~/mysql/10.1/mysql-test$ ./mtr --vardir=/dev/shm encryption.innodb_encryption_tables,xtradb --repeat=10
Logging: ./mtr  --vardir=/dev/shm encryption.innodb_encryption_tables,xtradb --repeat=10
vardir: /dev/shm
Checking leftover processes...
Removing old var directory...
couldn't chmod(0777, /dev/shm): Operation not permitted at /usr/share/perl/5.24/File/Find.pm line 511.
Couldn't remove directory '/dev/shm': Permission denied at /usr/share/perl/5.24/File/Find.pm line 511.
Creating var directory '/dev/shm'...
Checking supported features...
MariaDB Version 10.1.23-MariaDB-debug
 - SSL connections supported
 - binaries are debug compiled
Sphinx 'indexer' binary not found, sphinx suite will be skipped
Collecting tests...
Installing system database...
 
==============================================================================
 
TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
encryption.innodb_encryption_tables 'xtradb' [ pass ]  26646
encryption.innodb_encryption_tables 'xtradb' [ pass ]  29219
encryption.innodb_encryption_tables 'xtradb' [ pass ]  27345

Comment by Jan Lindström (Inactive) [ 2017-05-01 ]

Suspect fix on bb-10.1.12624:

commit 716b49d2a7e0bea65656582e69d12199509c7193
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Mon May 1 09:03:07 2017 +0300

MDEV-12624: encryption.innodb_encryption_tables fails in buildbot with

timeout

This regression was caused by MDEV-12467 encryption.create_or_replace
hangs during DROP TABLE, where if table->is_stopping() (i.e. when
tablespace is dropped) background key rotation thread calls
fil_crypt_complete_rotate_space to release space and stop rotation.
However, that function does not decrease number of rotating
threads if table->is_stopping() is true.

Comment by Jan Lindström (Inactive) [ 2017-05-02 ]

commit acce1f37c2518278a31606c7f1b460ad0ac7347c
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Tue May 2 08:09:16 2017 +0300

MDEV-12624: encryption.innodb_encryption_tables fails in buildbot with timeout

This regression was caused by MDEV-12467 encryption.create_or_replace
hangs during DROP TABLE, where if table->is_stopping() (i.e. when
tablespace is dropped) background key rotation thread calls
fil_crypt_complete_rotate_space to release space and stop rotation.
However, that function does not decrease number of rotating
threads if table->is_stopping() is true.

Generated at Thu Feb 08 07:59:10 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.