[MDEV-9962] encryption.innodb_encryption_filekeys stalled waiting for key encryption threads to decrypt all required spaces Created: 2016-04-21  Updated: 2018-02-16  Resolved: 2018-02-16

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Tests
Affects Version/s: 10.2.0, 10.1
Fix Version/s: 10.1.32, 10.2.14, 10.3.5

Type: Bug Priority: Major
Reporter: Daniel Black Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Environment:

Power8 ppc64le
Linux p84 4.2.0-27-generic #32-Ubuntu SMP Fri Jan 22 04:48:03 UTC 2016 ppc64le ppc64le ppc64le GNU/Linux


Attachments: File encryption.innodb_encryption_filekeys.tar.gz    
Issue Links:
Relates
relates to MDEV-12253 Buffer pool blocks are accessed after... Closed
Sprint: 10.1.14, 10.2.1-5

 Description   

encryption.innodb_encryption_filekeys 'ctr,xtradb' w13 [ fail ]
        Test ended at 2016-04-21 15:36:41
 
CURRENT_TEST: encryption.innodb_encryption_filekeys
mysqltest: At line 95: Timeout waiting for encryption threads

(gdb) thread apply all bt 
 
Thread 26 (Thread 0x3fff903ff140 (LWP 36734)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x27db9bf8 <COND_timer>, mutex=0x27db9b90 <LOCK_timer>, abstime=0x3fff903fe5f8) at pthread_cond_timedwait.c:198
#1  0x0000000027018b98 in inline_mysql_cond_timedwait (that=0x27db9bf8 <COND_timer>, mutex=0x27db9b90 <LOCK_timer>, src_file=0x2715d158 "/home/danielgb/mariadb-10.2/mysys/thr_timer.c", 
    src_line=292, abstime=0x3fff903fe5f8) at /home/danielgb/mariadb-10.2/include/mysql/psi/mysql_thread.h:1175
#2  timer_handler (arg=<optimized out>) at /home/danielgb/mariadb-10.2/mysys/thr_timer.c:292
#3  0x0000000026c45a90 in pfs_spawn_thread (arg=0x3fff966f0c08) at /home/danielgb/mariadb-10.2/storage/perfschema/pfs.cc:1862
#4  0x00003fff977382cc in start_thread (arg=0x3fff903ff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 25 (Thread 0x3fff8ebff140 (LWP 36735)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x27d541f0 <COND_checkpoint>, mutex=0x27d541b8 <LOCK_checkpoint>, abstime=0x3fff8ebfe4e8) at pthread_cond_timedwait.c:198
#1  0x0000000026ca3e0c in inline_mysql_cond_timedwait (src_file=0x2710e400 "/home/danielgb/mariadb-10.2/storage/maria/ma_servicethread.c", src_line=119, abstime=<optimized out>, 
    mutex=0x27d541b8 <LOCK_checkpoint>, that=0x27d541f0 <COND_checkpoint>) at /home/danielgb/mariadb-10.2/include/mysql/psi/mysql_thread.h:1175
#2  my_service_thread_sleep (control=0x274ac800 <checkpoint_control>, sleep_time=<optimized out>) at /home/danielgb/mariadb-10.2/storage/maria/ma_servicethread.c:118
#3  0x0000000026c984f4 in ma_checkpoint_background (arg=0x1e) at /home/danielgb/mariadb-10.2/storage/maria/ma_checkpoint.c:711
#4  0x0000000026c45a90 in pfs_spawn_thread (arg=0x3fff966f0e08) at /home/danielgb/mariadb-10.2/storage/perfschema/pfs.cc:1862
#5  0x00003fff977382cc in start_thread (arg=0x3fff8ebff140) at pthread_create.c:336
#6  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 24 (Thread 0x3fff8d7bf140 (LWP 36767)):
#0  0x00003fff976f0738 in ?? () from /lib/powerpc64le-linux-gnu/libaio.so.1
#1  0x00003fff976f07a0 in io_getevents () from /lib/powerpc64le-linux-gnu/libaio.so.1
#2  0x0000000026da4308 in os_aio_linux_collect (seg_size=<optimized out>, segment=<optimized out>, array=0x3fff96730330) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5377
#3  os_aio_linux_handle (global_seg=0, message1=0x3fff8d7be680, message2=0x3fff8d7be688, type=0x3fff8d7be690, space_id=0x3fff8d7be698)
    at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5530
#4  0x0000000026f0c800 in fil_aio_wait (segment=0) at /home/danielgb/mariadb-10.2/storage/xtradb/fil/fil0fil.cc:6043
#5  0x0000000026e26ee0 in io_handler_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0start.cc:545
#6  0x00003fff977382cc in start_thread (arg=0x3fff8d7bf140) at pthread_create.c:336
#7  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 23 (Thread 0x3fff8cfbf140 (LWP 36768)):
#0  0x00003fff976f0738 in ?? () from /lib/powerpc64le-linux-gnu/libaio.so.1
#1  0x00003fff976f07a0 in io_getevents () from /lib/powerpc64le-linux-gnu/libaio.so.1
#2  0x0000000026da4308 in os_aio_linux_collect (seg_size=<optimized out>, segment=<optimized out>, array=0x3fff96730150) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5377
#3  os_aio_linux_handle (global_seg=1, message1=0x3fff8cfbe680, message2=0x3fff8cfbe688, type=0x3fff8cfbe690, space_id=0x3fff8cfbe698)
    at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5530
---Type <return> to continue, or q <return> to quit---
#4  0x0000000026f0c800 in fil_aio_wait (segment=1) at /home/danielgb/mariadb-10.2/storage/xtradb/fil/fil0fil.cc:6043
#5  0x0000000026e26ee0 in io_handler_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0start.cc:545
#6  0x00003fff977382cc in start_thread (arg=0x3fff8cfbf140) at pthread_create.c:336
#7  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 22 (Thread 0x3fff8c7bf140 (LWP 36769)):
#0  0x00003fff976f0738 in ?? () from /lib/powerpc64le-linux-gnu/libaio.so.1
#1  0x00003fff976f07a0 in io_getevents () from /lib/powerpc64le-linux-gnu/libaio.so.1
#2  0x0000000026da4308 in os_aio_linux_collect (seg_size=<optimized out>, segment=<optimized out>, array=0x3fff967301a0) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5377
#3  os_aio_linux_handle (global_seg=2, message1=0x3fff8c7be680, message2=0x3fff8c7be688, type=0x3fff8c7be690, space_id=0x3fff8c7be698)
    at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5530
#4  0x0000000026f0c800 in fil_aio_wait (segment=2) at /home/danielgb/mariadb-10.2/storage/xtradb/fil/fil0fil.cc:6043
#5  0x0000000026e26ee0 in io_handler_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0start.cc:545
#6  0x00003fff977382cc in start_thread (arg=0x3fff8c7bf140) at pthread_create.c:336
#7  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 21 (Thread 0x3fff8bfbf140 (LWP 36770)):
#0  0x00003fff976f0738 in ?? () from /lib/powerpc64le-linux-gnu/libaio.so.1
#1  0x00003fff976f07a0 in io_getevents () from /lib/powerpc64le-linux-gnu/libaio.so.1
#2  0x0000000026da4308 in os_aio_linux_collect (seg_size=<optimized out>, segment=<optimized out>, array=0x3fff967301a0) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5377
#3  os_aio_linux_handle (global_seg=3, message1=0x3fff8bfbe680, message2=0x3fff8bfbe688, type=0x3fff8bfbe690, space_id=0x3fff8bfbe698)
    at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5530
#4  0x0000000026f0c800 in fil_aio_wait (segment=3) at /home/danielgb/mariadb-10.2/storage/xtradb/fil/fil0fil.cc:6043
#5  0x0000000026e26ee0 in io_handler_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0start.cc:545
#6  0x00003fff977382cc in start_thread (arg=0x3fff8bfbf140) at pthread_create.c:336
#7  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 20 (Thread 0x3fff8b7bf140 (LWP 36771)):
#0  0x00003fff976f0738 in ?? () from /lib/powerpc64le-linux-gnu/libaio.so.1
#1  0x00003fff976f07a0 in io_getevents () from /lib/powerpc64le-linux-gnu/libaio.so.1
#2  0x0000000026da4308 in os_aio_linux_collect (seg_size=<optimized out>, segment=<optimized out>, array=0x3fff96730380) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5377
#3  os_aio_linux_handle (global_seg=4, message1=0x3fff8b7be680, message2=0x3fff8b7be688, type=0x3fff8b7be690, space_id=0x3fff8b7be698)
    at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5530
#4  0x0000000026f0c800 in fil_aio_wait (segment=4) at /home/danielgb/mariadb-10.2/storage/xtradb/fil/fil0fil.cc:6043
#5  0x0000000026e26ee0 in io_handler_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0start.cc:545
#6  0x00003fff977382cc in start_thread (arg=0x3fff8b7bf140) at pthread_create.c:336
#7  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
---Type <return> to continue, or q <return> to quit---
 
Thread 19 (Thread 0x3fff8afbf140 (LWP 36772)):
#0  0x00003fff976f0738 in ?? () from /lib/powerpc64le-linux-gnu/libaio.so.1
#1  0x00003fff976f07a0 in io_getevents () from /lib/powerpc64le-linux-gnu/libaio.so.1
#2  0x0000000026da4308 in os_aio_linux_collect (seg_size=<optimized out>, segment=<optimized out>, array=0x3fff96730380) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5377
#3  os_aio_linux_handle (global_seg=5, message1=0x3fff8afbe680, message2=0x3fff8afbe688, type=0x3fff8afbe690, space_id=0x3fff8afbe698)
    at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0file.cc:5530
#4  0x0000000026f0c800 in fil_aio_wait (segment=5) at /home/danielgb/mariadb-10.2/storage/xtradb/fil/fil0fil.cc:6043
#5  0x0000000026e26ee0 in io_handler_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0start.cc:545
#6  0x00003fff977382cc in start_thread (arg=0x3fff8afbf140) at pthread_create.c:336
#7  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 18 (Thread 0x3fff893ff140 (LWP 36775)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x3fff8efd5040, mutex=0x3fff8efd5000, abstime=0x3fff893fe580) at pthread_cond_timedwait.c:198
#1  0x0000000026da6108 in os_cond_wait_timed (abstime=0x3fff893fe580, fast_mutex=0x3fff8efd5000, cond=0x3fff8efd5040) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:177
#2  os_event_wait_time_low (event=0x3fff8efd5000, time_in_usec=<optimized out>, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:705
#3  0x0000000026d6d664 in lock_wait_timeout_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/lock/lock0wait.cc:536
#4  0x00003fff977382cc in start_thread (arg=0x3fff893ff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 17 (Thread 0x3fff88bff140 (LWP 36776)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x3fff90f40740, mutex=0x3fff90f40700, abstime=0x3fff88bfe4e0) at pthread_cond_timedwait.c:198
#1  0x0000000026da6108 in os_cond_wait_timed (abstime=0x3fff88bfe4e0, fast_mutex=0x3fff90f40700, cond=0x3fff90f40740) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:177
#2  os_event_wait_time_low (event=0x3fff90f40700, time_in_usec=<optimized out>, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:705
#3  0x0000000026e22010 in srv_error_monitor_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0srv.cc:2390
#4  0x00003fff977382cc in start_thread (arg=0x3fff88bff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 16 (Thread 0x3fff883ff140 (LWP 36777)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x3fff90f407c0, mutex=0x3fff90f40780, abstime=0x3fff883fe560) at pthread_cond_timedwait.c:198
#1  0x0000000026da6108 in os_cond_wait_timed (abstime=0x3fff883fe560, fast_mutex=0x3fff90f40780, cond=0x3fff90f407c0) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:177
#2  os_event_wait_time_low (event=0x3fff90f40780, time_in_usec=<optimized out>, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:705
#3  0x0000000026e2184c in srv_monitor_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0srv.cc:2114
#4  0x00003fff977382cc in start_thread (arg=0x3fff883ff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 15 (Thread 0x3fff87bff140 (LWP 36778)):
 
#0  0x00003fff96ea56a8 in select () at ../sysdeps/unix/syscall-template.S:84
#1  0x0000000026da7cb0 in os_thread_sleep (tm=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0thread.cc:285
#2  0x0000000026e240e8 in srv_master_sleep () at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0srv.cc:3128
#3  srv_master_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0srv.cc:3176
#4  0x00003fff977382cc in start_thread (arg=0x3fff87bff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 14 (Thread 0x3fff873ff140 (LWP 36779)):
#0  0x00003fff977412fc in __pthread_cond_wait (cond=0x3fff90f406c0, mutex=0x3fff90f40680) at pthread_cond_wait.c:186
#1  0x0000000026da5f08 in os_cond_wait (fast_mutex=0x3fff90f40680, cond=0x3fff90f406c0) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:214
#2  os_event_wait_low (event=0x3fff90f40680, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:592
#3  0x0000000026e263b8 in srv_purge_coordinator_suspend (rseg_history_len=<optimized out>, slot=0x3fff967606c0) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0srv.cc:3482
#4  srv_purge_coordinator_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/srv/srv0srv.cc:3604
#5  0x00003fff977382cc in start_thread (arg=0x3fff873ff140) at pthread_create.c:336
#6  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 13 (Thread 0x3fff89bff140 (LWP 36831)):
#0  0x00003fff96ea56a8 in select () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x0000000026da7cb0 in os_thread_sleep (tm=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0thread.cc:285
#2  0x0000000026ebbc44 in page_cleaner_sleep_if_needed (next_loop_time=1461216828159) at /home/danielgb/mariadb-10.2/storage/xtradb/buf/buf0flu.cc:2644
#3  buf_flush_page_cleaner_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/buf/buf0flu.cc:2768
#4  0x00003fff977382cc in start_thread (arg=0x3fff89bff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 12 (Thread 0x3fff85fff140 (LWP 36832)):
#0  0x00003fff96ea56a8 in select () at ../sysdeps/unix/syscall-template.S:84
#1  0x0000000026da7cb0 in os_thread_sleep (tm=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0thread.cc:285
#2  0x0000000026ebca84 in page_cleaner_sleep_if_needed (next_loop_time=1461216828660) at /home/danielgb/mariadb-10.2/storage/xtradb/buf/buf0flu.cc:2644
#3  buf_flush_lru_manager_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/buf/buf0flu.cc:2918
#4  0x00003fff977382cc in start_thread (arg=0x3fff85fff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 11 (Thread 0x3fff857ff140 (LWP 36833)):
#0  0x00003fff977412fc in __pthread_cond_wait (cond=0x3fff90f40840, mutex=0x3fff90f40800) at pthread_cond_wait.c:186
#1  0x0000000026da5f08 in os_cond_wait (fast_mutex=0x3fff90f40800, cond=0x3fff90f40840) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:214
#2  os_event_wait_low (event=0x3fff90f40800, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:592
 
#3  0x0000000026eb1250 in buf_dump_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/buf/buf0dump.cc:684
---Type <return> to continue, or q <return> to quit---
#4  0x00003fff977382cc in start_thread (arg=0x3fff857ff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 10 (Thread 0x3fff84fff140 (LWP 36834)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x3fff8efd6040, mutex=0x3fff8efd6000, abstime=0x3fff84ffe580) at pthread_cond_timedwait.c:198
#1  0x0000000026da6108 in os_cond_wait_timed (abstime=0x3fff84ffe580, fast_mutex=0x3fff8efd6000, cond=0x3fff8efd6040) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:177
 
#2  os_event_wait_time_low (event=0x3fff8efd6000, time_in_usec=<optimized out>, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:705
#3  0x0000000026f02e74 in dict_stats_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/dict/dict0stats_bg.cc:546
#4  0x00003fff977382cc in start_thread (arg=0x3fff84fff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 9 (Thread 0x3fff847ff140 (LWP 36835)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x3fff8ee60ac0, mutex=0x3fff8ee60a80, abstime=0x3fff847fe4d0) at pthread_cond_timedwait.c:198
#1  0x0000000026da6108 in os_cond_wait_timed (abstime=0x3fff847fe4d0, fast_mutex=0x3fff8ee60a80, cond=0x3fff8ee60ac0) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:177
#2  os_event_wait_time_low (event=0x3fff8ee60a80, time_in_usec=<optimized out>, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:705
#3  0x0000000026e6056c in ib_wqueue_timedwait (wq=0x3fff96701b28, wait_in_usecs=5000000) at /home/danielgb/mariadb-10.2/storage/xtradb/ut/ut0wqueue.cc:154
 
#4  0x0000000026f503a8 in fts_optimize_thread (arg=0x3fff96701b28) at /home/danielgb/mariadb-10.2/storage/xtradb/fts/fts0opt.cc:3000
#5  0x00003fff977382cc in start_thread (arg=0x3fff847ff140) at pthread_create.c:336
#6  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 8 (Thread 0x3fff83bff140 (LWP 36836)):
#0  0x00003fff96ea56a8 in select () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x0000000026da7cb0 in os_thread_sleep (tm=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0thread.cc:285
#2  0x0000000026e995ac in btr_defragment_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/btr/btr0defragment.cc:758
#3  0x00003fff977382cc in start_thread (arg=0x3fff83bff140) at pthread_create.c:336
#4  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 7 (Thread 0x3fff8a7b7940 (LWP 36839)):
#0  0x00003fff97748324 in do_sigwait (sig=0x3fff8a7b6d70, set=<optimized out>) at ../sysdeps/unix/sysv/linux/sigwait.c:61
#1  __sigwait (set=<optimized out>, sig=0x3fff8a7b6d70) at ../sysdeps/unix/sysv/linux/sigwait.c:96
#2  0x00000000267b1e2c in signal_hand (arg=<optimized out>) at /home/danielgb/mariadb-10.2/sql/mysqld.cc:3561
#3  0x0000000026c45a90 in pfs_spawn_thread (arg=0x3fff966f1e08) at /home/danielgb/mariadb-10.2/storage/perfschema/pfs.cc:1862
#4  0x00003fff977382cc in start_thread (arg=0x3fff8a7b7940) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 6 (Thread 0x3fff8a757940 (LWP 36900)):
#0  0x00003fff96ea2a58 in poll () at ../sysdeps/unix/syscall-template.S:84
---Type <return> to continue, or q <return> to quit---
#1  0x000000002706cde0 in poll (__timeout=28800000, __nfds=1, __fds=<optimized out>) at /opt/at9.0/include/bits/poll2.h:46
#2  vio_io_wait (vio=0x3fff966f2408, event=<optimized out>, timeout=<optimized out>) at /home/danielgb/mariadb-10.2/vio/viosocket.c:972
#3  0x000000002706cee4 in vio_socket_io_wait (vio=<optimized out>, event=<optimized out>) at /home/danielgb/mariadb-10.2/vio/viosocket.c:108
#4  0x000000002706d070 in vio_read (vio=<optimized out>, buf=0x3fff82486008 "\001", size=4) at /home/danielgb/mariadb-10.2/vio/viosocket.c:184
#5  0x00000000267c0690 in my_real_read (net=0x3fff82244240, complen=0x3fff8a756898, header=1 '\001') at /home/danielgb/mariadb-10.2/sql/net_serv.cc:885
 
#6  0x00000000267c1db0 in my_net_read_packet (net=0x3fff82244240, read_from_server=<optimized out>) at /home/danielgb/mariadb-10.2/sql/net_serv.cc:1111
 
#7  0x0000000026878e7c in do_command (thd=0x3fff82244008) at /home/danielgb/mariadb-10.2/sql/sql_parse.cc:1236
 
#8  0x00000000269629b4 in do_handle_one_connection (connect=<optimized out>) at /home/danielgb/mariadb-10.2/sql/sql_connect.cc:1358
#9  0x0000000026962c0c in handle_one_connection (arg=0x3fff967906a8) at /home/danielgb/mariadb-10.2/sql/sql_connect.cc:1264
#10 0x0000000026c45a90 in pfs_spawn_thread (arg=0x3fff966f2208) at /home/danielgb/mariadb-10.2/storage/perfschema/pfs.cc:1862
#11 0x00003fff977382cc in start_thread (arg=0x3fff8a757940) at pthread_create.c:336
#12 0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 5 (Thread 0x3fff813ff140 (LWP 36911)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x3fff8ee60b40, mutex=0x3fff8ee60b00, abstime=0x3fff813fda70) at pthread_cond_timedwait.c:198
#1  0x0000000026da6108 in os_cond_wait_timed (abstime=0x3fff813fda70, fast_mutex=0x3fff8ee60b00, cond=0x3fff8ee60b40) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:177
 
#2  os_event_wait_time_low (event=0x3fff8ee60b00, time_in_usec=<optimized out>, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:705
#3  0x0000000026f1d29c in fil_crypt_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/fil/fil0crypt.cc:2237
#4  0x00003fff977382cc in start_thread (arg=0x3fff813ff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 4 (Thread 0x3fff80bff140 (LWP 36912)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x3fff8ee60b40, mutex=0x3fff8ee60b00, abstime=0x3fff80bfda70) at pthread_cond_timedwait.c:198
#1  0x0000000026da6108 in os_cond_wait_timed (abstime=0x3fff80bfda70, fast_mutex=0x3fff8ee60b00, cond=0x3fff8ee60b40) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:177
#2  os_event_wait_time_low (event=0x3fff8ee60b00, time_in_usec=<optimized out>, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:705
#3  0x0000000026f1d29c in fil_crypt_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/fil/fil0crypt.cc:2237
#4  0x00003fff977382cc in start_thread (arg=0x3fff80bff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 3 (Thread 0x3fff803ff140 (LWP 36913)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x3fff8ee60b40, mutex=0x3fff8ee60b00, abstime=0x3fff803fda70) at pthread_cond_timedwait.c:198
#1  0x0000000026da6108 in os_cond_wait_timed (abstime=0x3fff803fda70, fast_mutex=0x3fff8ee60b00, cond=0x3fff8ee60b40) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:177
#2  os_event_wait_time_low (event=0x3fff8ee60b00, time_in_usec=<optimized out>, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:705
#3  0x0000000026f1d29c in fil_crypt_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/fil/fil0crypt.cc:2237
#4  0x00003fff977382cc in start_thread (arg=0x3fff803ff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 2 (Thread 0x3fff7fbff140 (LWP 36914)):
#0  0x00003fff97741860 in __pthread_cond_timedwait (cond=0x3fff8ee60b40, mutex=0x3fff8ee60b00, abstime=0x3fff7fbfda70) at pthread_cond_timedwait.c:198
#1  0x0000000026da6108 in os_cond_wait_timed (abstime=0x3fff7fbfda70, fast_mutex=0x3fff8ee60b00, cond=0x3fff8ee60b40) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:177
#2  os_event_wait_time_low (event=0x3fff8ee60b00, time_in_usec=<optimized out>, reset_sig_count=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/os/os0sync.cc:705
#3  0x0000000026f1d29c in fil_crypt_thread (arg=<optimized out>) at /home/danielgb/mariadb-10.2/storage/xtradb/fil/fil0crypt.cc:2237
#4  0x00003fff977382cc in start_thread (arg=0x3fff7fbff140) at pthread_create.c:336
#5  0x00003fff96eb3f24 in clone () at ../sysdeps/unix/sysv/linux/powerpc/powerpc64/clone.S:96
 
Thread 1 (Thread 0x3fff977e82f0 (LWP 36611)):
#0  0x00003fff96ea2a58 in poll () at ../sysdeps/unix/syscall-template.S:84
#1  0x00003fff96ecea34 in __poll_chk (fds=<optimized out>, nfds=<optimized out>, timeout=<optimized out>, fdslen=<optimized out>) at poll_chk.c:27
#2  0x00000000267b4fb0 in poll (__timeout=-1, __nfds=2, __fds=<optimized out>) at /opt/at9.0/include/bits/poll2.h:41
#3  handle_connections_sockets () at /home/danielgb/mariadb-10.2/sql/mysqld.cc:6582
#4  0x00000000267bf3c4 in mysqld_main (argc=146, argv=0x3fff96770a58) at /home/danielgb/mariadb-10.2/sql/mysqld.cc:6038
#5  0x0000000026799f08 in main (argc=<optimized out>, argv=<optimized out>) at /home/danielgb/mariadb-10.2/sql/main.cc:25
(gdb) 
(gdb) c
Continuing.
[Thread 0x3fff7fbff140 (LWP 36914) exited]
[Thread 0x3fff803ff140 (LWP 36913) exited]
[Thread 0x3fff80bff140 (LWP 36912) exited]
[Thread 0x3fff813ff140 (LWP 36911) exited]
[Thread 0x3fff8a757940 (LWP 36900) exited]
[Thread 0x3fff8a7b7940 (LWP 36839) exited]
[Thread 0x3fff83bff140 (LWP 36836) exited]
[Thread 0x3fff847ff140 (LWP 36835) exited]
[Thread 0x3fff84fff140 (LWP 36834) exited]
[Thread 0x3fff857ff140 (LWP 36833) exited]
[Thread 0x3fff85fff140 (LWP 36832) exited]
[Thread 0x3fff89bff140 (LWP 36831) exited]
[Thread 0x3fff873ff140 (LWP 36779) exited]
[Thread 0x3fff87bff140 (LWP 36778) exited]
[Thread 0x3fff883ff140 (LWP 36777) exited]
[Thread 0x3fff88bff140 (LWP 36776) exited]
[Thread 0x3fff893ff140 (LWP 36775) exited]
[Thread 0x3fff8b7bf140 (LWP 36771) exited]
[Thread 0x3fff8bfbf140 (LWP 36770) exited]
[Thread 0x3fff8c7bf140 (LWP 36769) exited]
[Thread 0x3fff8cfbf140 (LWP 36768) exited]
[Thread 0x3fff8d7bf140 (LWP 36767) exited]
[Thread 0x3fff8ebff140 (LWP 36735) exited]
[Thread 0x3fff903ff140 (LWP 36734) exited]
[Thread 0x3fff977e82f0 (LWP 36611) exited]
 
Program terminated with signal SIGKILL, Killed.
The program no longer exists.

build at commit bddd63cfbaa5dba96e934166a2a234e13e20db4b

I might have a chance to look at this later.



 Comments   
Comment by Elena Stepanova [ 2016-04-22 ]

Confirmed via buildbot - we get this problem sporadically on 10.1 and 10.2 trees, on all kinds of builders - deb, bintar, fulltest; 32 and 64 bit. So far 17 occurrences.

Here is the cross-reference search URL (it can take quite long time): http://tinyurl.com/zds5ryy

The test sets innodb_encrypt_tables to off and then waits for up to 10 minutes checking on I_S for this to happen:

SELECT COUNT(*) = 2 FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION <> 0

If it didn't happen, it reports the current status and dies with the complaint about the timeout.

Here is the status it reported on the last occurrence of the problem in buildbot (on 10.1):

SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION;
SPACE	NAME	ENCRYPTION_SCHEME	KEYSERVER_REQUESTS	MIN_KEY_VERSION	CURRENT_KEY_VERSION	KEY_ROTATION_PAGE_NUMBER	KEY_ROTATION_MAX_PAGE_NUMBER	CURRENT_KEY_ID
1	mysql/innodb_table_stats	1	1	1	1	NULL	NULL	1
2	mysql/innodb_index_stats	1	1	1	1	NULL	NULL	1
4	test/t1	1	1	1	1	NULL	NULL	1
5	test/t2	1	1	1	1	NULL	NULL	1
6	test/t3	0	0	0	0	NULL	NULL	1
7	test/t4	1	1	1	1	NULL	NULL	4
0	NULL	1	1	1	1	NULL	NULL	1
SHOW STATUS LIKE 'innodb_encryption%';
Variable_name	Value
Innodb_encryption_rotation_pages_read_from_cache	168
Innodb_encryption_rotation_pages_read_from_disk	485
Innodb_encryption_rotation_pages_modified	202
Innodb_encryption_rotation_pages_flushed	9
Innodb_encryption_rotation_estimated_iops	16058

Comment by Marko Mäkelä [ 2017-04-19 ]

There were race conditions and possible deadlocks in the MariaDB encryption code. I believe that most of the remaining issues will be fixed in MDEV-12253.

Comment by Elena Stepanova [ 2017-05-09 ]

Now we wait and see if it occurs again in buildbot (or, in Daniel's tests) after MDEV-12253.

Comment by Elena Stepanova [ 2017-06-05 ]

It still happens – not frequently, but it wasn't frequent before, either.
Here is an occasion on 10.1 of May 20 (while MDEV-12253 was closed on May 5):
http://buildbot.askmonty.org/buildbot/builders/kvm-deb-jessie-ppc64le/builds/939

encryption.innodb_encryption_filekeys 'cbc,innodb_plugin' w2 [ fail ]
        Test ended at 2017-05-20 12:43:51
 
CURRENT_TEST: encryption.innodb_encryption_filekeys
mysqltest: At line 95: Timeout waiting for encryption threads
 
The result from queries just before the failure was:
< snip >
SET GLOBAL innodb_encrypt_tables = off;
# Wait max 10 min for key encryption threads to decrypt all required spaces
SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION;
SPACE	NAME	ENCRYPTION_SCHEME	KEYSERVER_REQUESTS	MIN_KEY_VERSION	CURRENT_KEY_VERSION	KEY_ROTATION_PAGE_NUMBER	KEY_ROTATION_MAX_PAGE_NUMBER	CURRENT_KEY_ID	ROTATING_OR_FLUSHING
1	mysql/innodb_table_stats	1	1	1	1	NULL	NULL	1	0
2	mysql/innodb_index_stats	1	1	1	1	NULL	NULL	1	0
4	test/t1	1	1	1	1	NULL	NULL	1	0
5	test/t2	1	1	1	1	NULL	NULL	1	0
6	test/t3	0	0	0	0	NULL	NULL	1	0
7	test/t4	1	1	1	1	NULL	NULL	4	0
0	./ibdata1	1	1	1	1	NULL	NULL	1	0
SHOW STATUS LIKE 'innodb_encryption%';
Variable_name	Value
Innodb_encryption_rotation_pages_read_from_cache	164
Innodb_encryption_rotation_pages_read_from_disk	489
Innodb_encryption_rotation_pages_modified	205
Innodb_encryption_rotation_pages_flushed	9
Innodb_encryption_rotation_estimated_iops	113114
Innodb_encryption_key_rotation_list_length	0
Innodb_encryption_num_key_requests	683738
 
More results from queries before failure can be found in /dev/shm/var/2/log/innodb_encryption_filekeys.log

Comment by Alice Sherepa [ 2017-12-06 ]

latest occurrence on 10.1 http://buildbot.askmonty.org/buildbot/builders/kvm-deb-jessie-x86/builds/3355/steps/mtr/logs/stdio

Comment by Jan Lindström (Inactive) [ 2018-02-16 ]

commit 21e5335154e4eb689df90c52a6b55263cd2067fb
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Fri Feb 16 10:19:57 2018 +0200

MDEV-9962: encryption.innodb_encryption_filekeys stalled waiting for key encryption threads to decrypt all required spaces

Test changes.

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