[MDEV-21826] Recovery failure : loop of Read redo log up to LSN Created: 2020-02-27  Updated: 2020-08-25  Resolved: 2020-03-18

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.31, 10.3.22, 10.4.12
Fix Version/s: 10.2.32, 10.3.23, 10.4.13

Type: Bug Priority: Major
Reporter: Damien BRS Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: None
Environment:

debian 10


Issue Links:
Problem/Incident
is caused by MDEV-19176 Do not run out of InnoDB buffer pool ... Closed
Relates
relates to MDEV-22512 innodb_zip.recover, innodb_gis.types ... Closed

 Description   

Hello,

I think I've just encountered a bug with the latest version of mariadb-server-10.3.

After a power failure mariadb start a crash recovery but it seems to loop on the same LSN for ever.

To fix it I uninstall everythning and install v10.3.21.
The crash recovery just run fine.

Version: '10.3.22-MariaDB-0+deb10u1-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Debian 10
2020-02-25 23:46:30 0 [Note] InnoDB: Buffer pool(s) load completed at 200225 23:46:30
2020-02-26 20:31:14 0 [Note] InnoDB: Using Linux native AIO
2020-02-26 20:31:14 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-02-26 20:31:14 0 [Note] InnoDB: Uses event mutexes
2020-02-26 20:31:14 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-02-26 20:31:14 0 [Note] InnoDB: Number of pools: 1
2020-02-26 20:31:14 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-02-26 20:31:14 0 [Note] InnoDB: Initializing buffer pool, total size = 3G, instances = 3, chunk size = 128M
2020-02-26 20:31:15 0 [Note] InnoDB: Completed initialization of buffer pool
2020-02-26 20:31:15 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-02-26 20:31:15 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=3388965427
2020-02-26 20:31:30 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:31:45 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:32:00 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:32:15 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:32:30 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:32:45 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:33:00 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:33:15 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:33:30 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:33:45 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:34:00 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:34:15 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:34:30 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:34:45 0 [Note] InnoDB: Read redo log up to LSN=3388965888
2020-02-26 20:35:00 0 [Note] InnoDB: Read redo log up to LSN=3388965888

mariad configuration:

[mysqld]
 
skip-name-resolve
 
query_cache_type        	= 0
query_cache_size		= 0
 
innodb_io_capacity		= 3000
innodb_buffer_pool_size		= 3G
innodb_buffer_pool_instances	= 3
innodb_flush_method		= O_DIRECT
 
# Logs
log-error			= /var/log/mysql/error.log
slow_query_log			= 1
slow_query_log_file		= /var/log/mysql/mysql-slow.log
long_query_time			= 5



 Comments   
Comment by Marko Mäkelä [ 2020-02-27 ]

The only change that might be related to this is MDEV-19176, which should avoid a hang of the crash recovery when the previously inaccurate prediction of memory usage fails and the redo log records occupy the entire buffer pool.

We have not observed anything like this in our internal testing. We would need more information to proceed. Can you repeat this easily? For starters, I would like to see some stack traces during the hang. Something like:

gdb -ex "set pagination 0" -ex "thread apply all backtrace" --batch -p $(pgrep -x mysqld)

Also, if this is not easy to repeat, it would be very useful if you could make a copy of the ib_logfile* files for future reference.

Comment by Damien BRS [ 2020-02-27 ]

I don't know how to repeat the bug.

I was on the stock version of debian : 10.3.18-MariaDB-0+deb10u1-log
I made an upgrade to 10.3.22-MariaDB-0+deb10u1-log two day ago (2020-02-25 23:44)
Then crash it with a power failure
restart it normaly without checking if everythning was OK (the loop occur for more than 14hours)
notice this morning an 500 error on my website.
try several kill / start with the same loop everytime
change to mariadb official version with the same result
downgrade to 10.3.21-MariaDB-1:10.3.21+maria~buster-log and it start normally

I made a copy of my ib_logfile but i can't attach then here (48M)
and made a new upgrade to 10.3.22-MariaDB-1:10.3.22+maria~buster-log
I will try this evening to reproduce it

Comment by Damien BRS [ 2020-02-27 ]

Ok i manage to reproduce the bug

apt upgrade to 10.3.22 at 12:18:54
first start : OK
kill -9 mysql
restart auto by systemd
and then read redo log loop

2020-02-27 12:41:24 0 [Note] InnoDB: Using Linux native AIO
2020-02-27 12:41:24 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-02-27 12:41:24 0 [Note] InnoDB: Uses event mutexes
2020-02-27 12:41:24 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-02-27 12:41:24 0 [Note] InnoDB: Number of pools: 1
2020-02-27 12:41:24 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-02-27 12:41:24 0 [Note] InnoDB: Initializing buffer pool, total size = 3G, instances = 3, chunk size = 128M
2020-02-27 12:41:24 0 [Note] InnoDB: Completed initialization of buffer pool
2020-02-27 12:41:24 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-02-27 12:41:24 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-02-27 12:41:24 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-02-27 12:41:24 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-02-27 12:41:24 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-02-27 12:41:24 0 [Note] InnoDB: 10.3.22 started; log sequence number 3388967464; transaction id 2537445
2020-02-27 12:41:24 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2020-02-27 12:41:24 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-02-27 12:41:28 0 [Note] InnoDB: Using Linux native AIO
2020-02-27 12:41:28 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-02-27 12:41:28 0 [Note] InnoDB: Uses event mutexes
2020-02-27 12:41:28 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-02-27 12:41:28 0 [Note] InnoDB: Number of pools: 1
2020-02-27 12:41:28 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-02-27 12:41:28 0 [Note] InnoDB: Initializing buffer pool, total size = 3G, instances = 3, chunk size = 128M
2020-02-27 12:41:28 0 [Note] InnoDB: Completed initialization of buffer pool
2020-02-27 12:41:28 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-02-27 12:41:28 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-02-27 12:41:28 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-02-27 12:41:28 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-02-27 12:41:28 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-02-27 12:41:28 0 [Note] InnoDB: 10.3.22 started; log sequence number 3388967473; transaction id 2537445
2020-02-27 12:41:28 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2020-02-27 12:41:28 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-02-27 12:41:28 0 [Note] Server socket created on IP: '::'.
2020-02-27 12:41:28 0 [Note] Reading of all Master_info entries succeeded
2020-02-27 12:41:28 0 [Note] Added new Master_info '' to hash table
2020-02-27 12:41:28 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.3.22-MariaDB-1:10.3.22+maria~buster-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
2020-02-27 12:41:29 0 [Note] InnoDB: Buffer pool(s) load completed at 200227 12:41:29
2020-02-27 12:42:32 0 [Note] InnoDB: Using Linux native AIO
2020-02-27 12:42:32 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-02-27 12:42:32 0 [Note] InnoDB: Uses event mutexes
2020-02-27 12:42:32 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-02-27 12:42:32 0 [Note] InnoDB: Number of pools: 1
2020-02-27 12:42:32 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-02-27 12:42:32 0 [Note] InnoDB: Initializing buffer pool, total size = 3G, instances = 3, chunk size = 128M
2020-02-27 12:42:32 0 [Note] InnoDB: Completed initialization of buffer pool
2020-02-27 12:42:32 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-02-27 12:42:32 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=3388967473
2020-02-27 12:42:47 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:43:02 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:43:17 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:43:32 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:43:47 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:44:02 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:44:17 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:44:32 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:44:47 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:45:02 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:45:17 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:45:32 0 [Note] InnoDB: Read redo log up to LSN=3388967936
2020-02-27 12:45:47 0 [Note] InnoDB: Read redo log up to LSN=3388967936

gdb -ex "set pagination 0" -ex "thread apply all backtrace" --batch -p $(pgrep -x mysqld)
[New LWP 14570]
[New LWP 14571]
[New LWP 14572]
[New LWP 14573]
[New LWP 14574]
[New LWP 14575]
[New LWP 14576]
[New LWP 14577]
[New LWP 14578]
[New LWP 14579]
[New LWP 14580]
[New LWP 14581]
[New LWP 14582]
[New LWP 14583]
[New LWP 14584]
[New LWP 14586]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x000055e34482f385 in ?? ()
 
Thread 17 (Thread 0x7f7305140700 (LWP 14586)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x7f730513fe10, expected=0, futex_word=0x55e3477ee8c0) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  __pthread_cond_wait_common (abstime=0x7f730513fe10, mutex=0x55e3477ee870, cond=0x55e3477ee898) at pthread_cond_wait.c:539
#2  __pthread_cond_timedwait (cond=0x55e3477ee898, mutex=0x55e3477ee870, abstime=0x7f730513fe10) at pthread_cond_wait.c:667
#3  0x000055e344841fc2 in ?? ()
#4  0x000055e344842111 in ?? ()
#5  0x000055e34482bcd2 in ?? ()
#6  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#7  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 16 (Thread 0x7f7306142700 (LWP 14584)):
#0  futex_wait_cancelable (private=0, expected=0, futex_word=0x55e34bef9870) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x55e34bef9820, cond=0x55e34bef9848) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=0x55e34bef9848, mutex=0x55e34bef9820) at pthread_cond_wait.c:655
#3  0x000055e344842071 in ?? ()
#4  0x000055e344947353 in ?? ()
#5  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#6  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 15 (Thread 0x7f7306943700 (LWP 14583)):
#0  futex_wait_cancelable (private=0, expected=0, futex_word=0x55e34bef9870) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x55e34bef9820, cond=0x55e34bef9848) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=0x55e34bef9848, mutex=0x55e34bef9820) at pthread_cond_wait.c:655
#3  0x000055e344842071 in ?? ()
#4  0x000055e344947353 in ?? ()
#5  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#6  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 14 (Thread 0x7f7307144700 (LWP 14582)):
#0  futex_wait_cancelable (private=0, expected=0, futex_word=0x55e34bedb544) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x55e34bedb4f0, cond=0x55e34bedb518) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=0x55e34bedb518, mutex=0x55e34bedb4f0) at pthread_cond_wait.c:655
#3  0x000055e344842071 in ?? ()
#4  0x000055e34439a353 in ?? ()
#5  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#6  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 13 (Thread 0x7f7307945700 (LWP 14581)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f73f4a9c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x000055e34483d1b1 in ?? ()
#3  0x000055e34483d5e5 in ?? ()
#4  0x000055e344840e90 in ?? ()
#5  0x000055e34498fbb8 in ?? ()
#6  0x000055e3448c4220 in ?? ()
#7  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 12 (Thread 0x7f7308146700 (LWP 14580)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f73f4a9c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x000055e34483d1b1 in ?? ()
#3  0x000055e34483d5e5 in ?? ()
#4  0x000055e344840e90 in ?? ()
#5  0x000055e34498fbb8 in ?? ()
#6  0x000055e3448c4220 in ?? ()
#7  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 11 (Thread 0x7f7308947700 (LWP 14579)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f73f4a9c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x000055e34483d1b1 in ?? ()
#3  0x000055e34483d5e5 in ?? ()
#4  0x000055e344840e90 in ?? ()
#5  0x000055e34498fbb8 in ?? ()
#6  0x000055e3448c4220 in ?? ()
#7  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 10 (Thread 0x7f7309148700 (LWP 14578)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f73f4a9c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x000055e34483d1b1 in ?? ()
#3  0x000055e34483d5e5 in ?? ()
#4  0x000055e344840e90 in ?? ()
#5  0x000055e34498fbb8 in ?? ()
#6  0x000055e3448c4220 in ?? ()
#7  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 9 (Thread 0x7f7309949700 (LWP 14577)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f73f4a9c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x000055e34483d1b1 in ?? ()
#3  0x000055e34483d5e5 in ?? ()
#4  0x000055e344840e90 in ?? ()
#5  0x000055e34498fbb8 in ?? ()
#6  0x000055e3448c4220 in ?? ()
#7  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 8 (Thread 0x7f730a14a700 (LWP 14576)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f73f4a9c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x000055e34483d1b1 in ?? ()
#3  0x000055e34483d5e5 in ?? ()
#4  0x000055e344840e90 in ?? ()
#5  0x000055e34498fbb8 in ?? ()
#6  0x000055e3448c4220 in ?? ()
#7  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 7 (Thread 0x7f730a94b700 (LWP 14575)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f73f4a9c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x000055e34483d1b1 in ?? ()
#3  0x000055e34483d5e5 in ?? ()
#4  0x000055e344840e90 in ?? ()
#5  0x000055e34498fbb8 in ?? ()
#6  0x000055e3448c4220 in ?? ()
#7  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 6 (Thread 0x7f730b14c700 (LWP 14574)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f73f4a9c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x000055e34483d1b1 in ?? ()
#3  0x000055e34483d5e5 in ?? ()
#4  0x000055e344840e90 in ?? ()
#5  0x000055e34498fbb8 in ?? ()
#6  0x000055e3448c4220 in ?? ()
#7  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 5 (Thread 0x7f730b94d700 (LWP 14573)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f73f4a9c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x000055e34483d1b1 in ?? ()
#3  0x000055e34483d5e5 in ?? ()
#4  0x000055e344840e90 in ?? ()
#5  0x000055e34498fbb8 in ?? ()
#6  0x000055e3448c4220 in ?? ()
#7  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 4 (Thread 0x7f730c14e700 (LWP 14572)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f73f4a9c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x000055e34483d1b1 in ?? ()
#3  0x000055e34483d5e5 in ?? ()
#4  0x000055e344840e90 in ?? ()
#5  0x000055e34498fbb8 in ?? ()
#6  0x000055e3448c4220 in ?? ()
#7  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 3 (Thread 0x7f73f1601700 (LWP 14571)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x7f73f1600d60, expected=0, futex_word=0x55e345b06388) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  __pthread_cond_wait_common (abstime=0x7f73f1600d60, mutex=0x55e345b063a0, cond=0x55e345b06360) at pthread_cond_wait.c:539
#2  __pthread_cond_timedwait (cond=0x55e345b06360, mutex=0x55e345b063a0, abstime=0x7f73f1600d60) at pthread_cond_wait.c:667
#3  0x000055e344a26b99 in ?? ()
#4  0x000055e344a1f359 in ?? ()
#5  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#6  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 2 (Thread 0x7f73f3d12700 (LWP 14570)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x7f73f3d11df0, expected=0, futex_word=0x55e345b15da8) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  __pthread_cond_wait_common (abstime=0x7f73f3d11df0, mutex=0x55e345b15dc0, cond=0x55e345b15d80) at pthread_cond_wait.c:539
#2  __pthread_cond_timedwait (cond=0x55e345b15d80, mutex=0x55e345b15dc0, abstime=0x7f73f3d11df0) at pthread_cond_wait.c:667
#3  0x000055e344b42b83 in ?? ()
#4  0x00007f73f4acafa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#5  0x00007f73f3fac4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 1 (Thread 0x7f73f4ae67c0 (LWP 14569)):
#0  0x000055e34482f385 in ?? ()
#1  0x000055e3448320cc in ?? ()
#2  0x000055e344832fcc in ?? ()
#3  0x000055e34438a3d2 in ?? ()
#4  0x000055e3447d24da in ?? ()
#5  0x000055e344659748 in ha_initialize_handlerton(st_plugin_int*) ()
#6  0x000055e34448d6c9 in ?? ()
#7  0x000055e34448e8d2 in plugin_init(int*, char**, int) ()
#8  0x000055e3443ca2db in ?? ()
#9  0x000055e3443d022e in mysqld_main(int, char**) ()
#10 0x00007f73f3ed709b in __libc_start_main (main=0x55e3443af620 <main>, argc=1, argv=0x7ffcf850da68, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffcf850da58) at ../csu/libc-start.c:308
#11 0x000055e3443c302a in _start ()
[Inferior 1 (process 14569) detached]

mysql    14569 99.5  2.9 4360936 226596 ?      Rsl  12:42   6:19 /usr/sbin/mysqld
:~#strace -p 14569
strace: Process 14569 attached
strace: [ Process PID=14569 runs in x32 mode. ]
strace: [ Process PID=14569 runs in 64 bit mode. ]
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb5b4, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0x55e34bedb560, FUTEX_WAKE_PRIVATE, 1) = 0
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb5b0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0x55e34bedb560, FUTEX_WAKE_PRIVATE, 1) = 0
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb5b4, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0x55e34bedb560, FUTEX_WAKE_PRIVATE, 1) = 0
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x55e34bedb560, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x55e34bedb560, FUTEX_WAKE_PRIVATE, 1) = 0
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb544, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x55e34bedb5b4, FUTEX_WAIT_PRIVATE, 0, NULL) = -1 EAGAIN (Ressource temporairement non disponible)
futex(0x55e34bedb560, FUTEX_WAKE_PRIVATE, 1) = 0
munmap(0x7f730d81d000, 51003392)        = 0
mmap(NULL, 51003392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f730d81d000
pread64(11, "\200d\377\306\0:\0\26\0\2F\206\378\0\0\0\0\311\377\211\2678\0\0\0\0\311\377\212\268"..., 65536, 16877568) = 65536
futex(0x55e34bedb540, FUTEX_WAKE_PRIVATE, 2147483647) = 1
futex(0x55e34bedb4f0, FUTEX_WAKE_PRIVATE, 1) = 1
munmap(0x7f730d81d000, 51003392)        = 0

Comment by Marko Mäkelä [ 2020-02-27 ]

Thanks! Can you try to install debug symbols, so that we can get something more useful than ?? for function names?
Also, can you reproduce this with a small installation that does not contain confidential data? Or could you upload the contents of the data directory (at least the ib_logfile*) to our private server?

Comment by Damien BRS [ 2020-02-28 ]

I can upload the ib_logfile to your server.
This is my personnal server there is only my small personal data.

/dev/mapper/vg0-mysql   4,6G    270M  4,1G   7% /var/lib/mysql 

:~#gdb -ex "set pagination 0" -ex "thread apply all backtrace" --batch -p $(pgrep -x mysqld)
[New LWP 11200]
[New LWP 11201]
[New LWP 11202]
[New LWP 11203]
[New LWP 11204]
[New LWP 11205]
[New LWP 11206]
[New LWP 11207]
[New LWP 11208]
[New LWP 11209]
[New LWP 11210]
[New LWP 11211]
[New LWP 11212]
[New LWP 11213]
[New LWP 11214]
[New LWP 11216]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00005566f47f9390 in recv_apply_hashed_log_recs (last_batch=<optimized out>) at ./storage/innobase/include/hash0hash.ic:42
42	./storage/innobase/include/hash0hash.ic: Aucun fichier ou dossier de ce type.
 
Thread 17 (Thread 0x7f7d22b80700 (LWP 11216)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x7f7d22b7fe10, expected=0, futex_word=0x5566f61818c0) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  __pthread_cond_wait_common (abstime=0x7f7d22b7fe10, mutex=0x5566f6181870, cond=0x5566f6181898) at pthread_cond_wait.c:539
#2  __pthread_cond_timedwait (cond=0x5566f6181898, mutex=0x5566f6181870, abstime=abstime@entry=0x7f7d22b7fe10) at pthread_cond_wait.c:667
#3  0x00005566f480bfc2 in os_event::timed_wait (this=<optimized out>, abstime=0x7f7d22b7fe10) at ./storage/innobase/include/sync0types.h:476
#4  0x00005566f480c111 in os_event::wait_time_low (this=0x5566f6181860, time_in_usec=<optimized out>, reset_sig_count=1) at ./storage/innobase/os/os0event.cc:385
#5  0x00005566f47f5cd2 in recv_writer_thread (arg=<optimized out>) at ./storage/innobase/log/log0recv.cc:798
#6  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#7  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 16 (Thread 0x7f7d1bfff700 (LWP 11214)):
#0  futex_wait_cancelable (private=0, expected=0, futex_word=0x5566fa88c874) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x5566fa88c820, cond=0x5566fa88c848) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=cond@entry=0x5566fa88c848, mutex=mutex@entry=0x5566fa88c820) at pthread_cond_wait.c:655
#3  0x00005566f480c071 in os_event::wait (this=0x5566fa88c810) at ./storage/innobase/include/sync0types.h:476
#4  os_event::wait_low (this=0x5566fa88c810, reset_sig_count=11131) at ./storage/innobase/os/os0event.cc:325
#5  0x00005566f4911353 in buf_flush_page_cleaner_worker (arg=<optimized out>) at ./storage/innobase/buf/buf0flu.cc:3499
#6  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#7  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 15 (Thread 0x7f7d23b82700 (LWP 11213)):
#0  futex_wait_cancelable (private=0, expected=0, futex_word=0x5566fa88c874) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x5566fa88c820, cond=0x5566fa88c848) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=cond@entry=0x5566fa88c848, mutex=mutex@entry=0x5566fa88c820) at pthread_cond_wait.c:655
#3  0x00005566f480c071 in os_event::wait (this=0x5566fa88c810) at ./storage/innobase/include/sync0types.h:476
#4  os_event::wait_low (this=0x5566fa88c810, reset_sig_count=11131) at ./storage/innobase/os/os0event.cc:325
#5  0x00005566f4911353 in buf_flush_page_cleaner_worker (arg=<optimized out>) at ./storage/innobase/buf/buf0flu.cc:3499
#6  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#7  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 14 (Thread 0x7f7d24383700 (LWP 11212)):
#0  futex_wait_cancelable (private=0, expected=0, futex_word=0x5566fa86e544) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x5566fa86e4f0, cond=0x5566fa86e518) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=cond@entry=0x5566fa86e518, mutex=mutex@entry=0x5566fa86e4f0) at pthread_cond_wait.c:655
#3  0x00005566f480c071 in os_event::wait (this=0x5566fa86e4e0) at ./storage/innobase/include/sync0types.h:476
#4  os_event::wait_low (this=0x5566fa86e4e0, reset_sig_count=11130) at ./storage/innobase/os/os0event.cc:325
#5  0x00005566f4364353 in buf_flush_page_cleaner_coordinator () at ./storage/innobase/buf/buf0flu.cc:3093
#6  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#7  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 13 (Thread 0x7f7d24b84700 (LWP 11211)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7e11b6c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x00005566f48071b1 in LinuxAIOHandler::collect (this=0x7f7d24b83be0) at ./storage/innobase/os/os0file.cc:1932
#3  0x00005566f48075e5 in LinuxAIOHandler::poll (this=0x7f7d24b83be0, m1=0x7f7d24b83c80, m2=0x7f7d24b83c88, request=0x7f7d24b83c90) at ./storage/innobase/os/os0file.cc:2093
#4  0x00005566f480ae90 in os_aio_linux_handler (request=0x7f7d24b83c90, m2=0x7f7d24b83c88, m1=0x7f7d24b83c80, global_segment=<optimized out>) at /usr/include/c++/8/bits/stl_vector.h:805
#5  os_aio_handler (segment=segment@entry=9, m1=m1@entry=0x7f7d24b83c80, m2=m2@entry=0x7f7d24b83c88, request=request@entry=0x7f7d24b83c90) at ./storage/innobase/os/os0file.cc:5725
#6  0x00005566f4959bb8 in fil_aio_wait (segment=segment@entry=9) at ./storage/innobase/fil/fil0fil.cc:4435
#7  0x00005566f488e220 in io_handler_thread (arg=<optimized out>) at ./storage/innobase/srv/srv0start.cc:326
#8  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 12 (Thread 0x7f7d25385700 (LWP 11210)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7e11b6c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x00005566f48071b1 in LinuxAIOHandler::collect (this=0x7f7d25384be0) at ./storage/innobase/os/os0file.cc:1932
#3  0x00005566f48075e5 in LinuxAIOHandler::poll (this=0x7f7d25384be0, m1=0x7f7d25384c80, m2=0x7f7d25384c88, request=0x7f7d25384c90) at ./storage/innobase/os/os0file.cc:2093
#4  0x00005566f480ae90 in os_aio_linux_handler (request=0x7f7d25384c90, m2=0x7f7d25384c88, m1=0x7f7d25384c80, global_segment=<optimized out>) at /usr/include/c++/8/bits/stl_vector.h:805
#5  os_aio_handler (segment=segment@entry=8, m1=m1@entry=0x7f7d25384c80, m2=m2@entry=0x7f7d25384c88, request=request@entry=0x7f7d25384c90) at ./storage/innobase/os/os0file.cc:5725
#6  0x00005566f4959bb8 in fil_aio_wait (segment=segment@entry=8) at ./storage/innobase/fil/fil0fil.cc:4435
#7  0x00005566f488e220 in io_handler_thread (arg=<optimized out>) at ./storage/innobase/srv/srv0start.cc:326
#8  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 11 (Thread 0x7f7d25b86700 (LWP 11209)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7e11b6c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x00005566f48071b1 in LinuxAIOHandler::collect (this=0x7f7d25b85be0) at ./storage/innobase/os/os0file.cc:1932
#3  0x00005566f48075e5 in LinuxAIOHandler::poll (this=0x7f7d25b85be0, m1=0x7f7d25b85c80, m2=0x7f7d25b85c88, request=0x7f7d25b85c90) at ./storage/innobase/os/os0file.cc:2093
#4  0x00005566f480ae90 in os_aio_linux_handler (request=0x7f7d25b85c90, m2=0x7f7d25b85c88, m1=0x7f7d25b85c80, global_segment=<optimized out>) at /usr/include/c++/8/bits/stl_vector.h:805
#5  os_aio_handler (segment=segment@entry=7, m1=m1@entry=0x7f7d25b85c80, m2=m2@entry=0x7f7d25b85c88, request=request@entry=0x7f7d25b85c90) at ./storage/innobase/os/os0file.cc:5725
#6  0x00005566f4959bb8 in fil_aio_wait (segment=segment@entry=7) at ./storage/innobase/fil/fil0fil.cc:4435
#7  0x00005566f488e220 in io_handler_thread (arg=<optimized out>) at ./storage/innobase/srv/srv0start.cc:326
#8  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 10 (Thread 0x7f7d26387700 (LWP 11208)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7e11b6c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x00005566f48071b1 in LinuxAIOHandler::collect (this=0x7f7d26386be0) at ./storage/innobase/os/os0file.cc:1932
#3  0x00005566f48075e5 in LinuxAIOHandler::poll (this=0x7f7d26386be0, m1=0x7f7d26386c80, m2=0x7f7d26386c88, request=0x7f7d26386c90) at ./storage/innobase/os/os0file.cc:2093
#4  0x00005566f480ae90 in os_aio_linux_handler (request=0x7f7d26386c90, m2=0x7f7d26386c88, m1=0x7f7d26386c80, global_segment=<optimized out>) at /usr/include/c++/8/bits/stl_vector.h:805
#5  os_aio_handler (segment=segment@entry=6, m1=m1@entry=0x7f7d26386c80, m2=m2@entry=0x7f7d26386c88, request=request@entry=0x7f7d26386c90) at ./storage/innobase/os/os0file.cc:5725
#6  0x00005566f4959bb8 in fil_aio_wait (segment=segment@entry=6) at ./storage/innobase/fil/fil0fil.cc:4435
#7  0x00005566f488e220 in io_handler_thread (arg=<optimized out>) at ./storage/innobase/srv/srv0start.cc:326
#8  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 9 (Thread 0x7f7d26b88700 (LWP 11207)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7e11b6c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x00005566f48071b1 in LinuxAIOHandler::collect (this=0x7f7d26b87be0) at ./storage/innobase/os/os0file.cc:1932
#3  0x00005566f48075e5 in LinuxAIOHandler::poll (this=0x7f7d26b87be0, m1=0x7f7d26b87c80, m2=0x7f7d26b87c88, request=0x7f7d26b87c90) at ./storage/innobase/os/os0file.cc:2093
#4  0x00005566f480ae90 in os_aio_linux_handler (request=0x7f7d26b87c90, m2=0x7f7d26b87c88, m1=0x7f7d26b87c80, global_segment=<optimized out>) at /usr/include/c++/8/bits/stl_vector.h:805
#5  os_aio_handler (segment=segment@entry=5, m1=m1@entry=0x7f7d26b87c80, m2=m2@entry=0x7f7d26b87c88, request=request@entry=0x7f7d26b87c90) at ./storage/innobase/os/os0file.cc:5725
#6  0x00005566f4959bb8 in fil_aio_wait (segment=segment@entry=5) at ./storage/innobase/fil/fil0fil.cc:4435
#7  0x00005566f488e220 in io_handler_thread (arg=<optimized out>) at ./storage/innobase/srv/srv0start.cc:326
#8  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 8 (Thread 0x7f7d27389700 (LWP 11206)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7e11b6c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x00005566f48071b1 in LinuxAIOHandler::collect (this=0x7f7d27388be0) at ./storage/innobase/os/os0file.cc:1932
#3  0x00005566f48075e5 in LinuxAIOHandler::poll (this=0x7f7d27388be0, m1=0x7f7d27388c80, m2=0x7f7d27388c88, request=0x7f7d27388c90) at ./storage/innobase/os/os0file.cc:2093
#4  0x00005566f480ae90 in os_aio_linux_handler (request=0x7f7d27388c90, m2=0x7f7d27388c88, m1=0x7f7d27388c80, global_segment=<optimized out>) at /usr/include/c++/8/bits/stl_vector.h:805
#5  os_aio_handler (segment=segment@entry=4, m1=m1@entry=0x7f7d27388c80, m2=m2@entry=0x7f7d27388c88, request=request@entry=0x7f7d27388c90) at ./storage/innobase/os/os0file.cc:5725
#6  0x00005566f4959bb8 in fil_aio_wait (segment=segment@entry=4) at ./storage/innobase/fil/fil0fil.cc:4435
#7  0x00005566f488e220 in io_handler_thread (arg=<optimized out>) at ./storage/innobase/srv/srv0start.cc:326
#8  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 7 (Thread 0x7f7d27b8a700 (LWP 11205)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7e11b6c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x00005566f48071b1 in LinuxAIOHandler::collect (this=0x7f7d27b89be0) at ./storage/innobase/os/os0file.cc:1932
#3  0x00005566f48075e5 in LinuxAIOHandler::poll (this=0x7f7d27b89be0, m1=0x7f7d27b89c80, m2=0x7f7d27b89c88, request=0x7f7d27b89c90) at ./storage/innobase/os/os0file.cc:2093
#4  0x00005566f480ae90 in os_aio_linux_handler (request=0x7f7d27b89c90, m2=0x7f7d27b89c88, m1=0x7f7d27b89c80, global_segment=<optimized out>) at /usr/include/c++/8/bits/stl_vector.h:805
#5  os_aio_handler (segment=segment@entry=3, m1=m1@entry=0x7f7d27b89c80, m2=m2@entry=0x7f7d27b89c88, request=request@entry=0x7f7d27b89c90) at ./storage/innobase/os/os0file.cc:5725
#6  0x00005566f4959bb8 in fil_aio_wait (segment=segment@entry=3) at ./storage/innobase/fil/fil0fil.cc:4435
#7  0x00005566f488e220 in io_handler_thread (arg=<optimized out>) at ./storage/innobase/srv/srv0start.cc:326
#8  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 6 (Thread 0x7f7d2838b700 (LWP 11204)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7e11b6c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x00005566f48071b1 in LinuxAIOHandler::collect (this=0x7f7d2838abe0) at ./storage/innobase/os/os0file.cc:1932
#3  0x00005566f48075e5 in LinuxAIOHandler::poll (this=0x7f7d2838abe0, m1=0x7f7d2838ac80, m2=0x7f7d2838ac88, request=0x7f7d2838ac90) at ./storage/innobase/os/os0file.cc:2093
#4  0x00005566f480ae90 in os_aio_linux_handler (request=0x7f7d2838ac90, m2=0x7f7d2838ac88, m1=0x7f7d2838ac80, global_segment=<optimized out>) at /usr/include/c++/8/bits/stl_vector.h:805
#5  os_aio_handler (segment=segment@entry=2, m1=m1@entry=0x7f7d2838ac80, m2=m2@entry=0x7f7d2838ac88, request=request@entry=0x7f7d2838ac90) at ./storage/innobase/os/os0file.cc:5725
#6  0x00005566f4959bb8 in fil_aio_wait (segment=segment@entry=2) at ./storage/innobase/fil/fil0fil.cc:4435
#7  0x00005566f488e220 in io_handler_thread (arg=<optimized out>) at ./storage/innobase/srv/srv0start.cc:326
#8  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 5 (Thread 0x7f7d28b8c700 (LWP 11203)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7e11b6c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x00005566f48071b1 in LinuxAIOHandler::collect (this=0x7f7d28b8bbe0) at ./storage/innobase/os/os0file.cc:1932
#3  0x00005566f48075e5 in LinuxAIOHandler::poll (this=0x7f7d28b8bbe0, m1=0x7f7d28b8bc80, m2=0x7f7d28b8bc88, request=0x7f7d28b8bc90) at ./storage/innobase/os/os0file.cc:2093
#4  0x00005566f480ae90 in os_aio_linux_handler (request=0x7f7d28b8bc90, m2=0x7f7d28b8bc88, m1=0x7f7d28b8bc80, global_segment=<optimized out>) at /usr/include/c++/8/bits/stl_vector.h:805
#5  os_aio_handler (segment=segment@entry=1, m1=m1@entry=0x7f7d28b8bc80, m2=m2@entry=0x7f7d28b8bc88, request=request@entry=0x7f7d28b8bc90) at ./storage/innobase/os/os0file.cc:5725
#6  0x00005566f4959bb8 in fil_aio_wait (segment=segment@entry=1) at ./storage/innobase/fil/fil0fil.cc:4435
#7  0x00005566f488e220 in io_handler_thread (arg=<optimized out>) at ./storage/innobase/srv/srv0start.cc:326
#8  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 4 (Thread 0x7f7d2938d700 (LWP 11202)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7e11b6c27a in ?? () from target:/lib/x86_64-linux-gnu/libaio.so.1
#2  0x00005566f48071b1 in LinuxAIOHandler::collect (this=0x7f7d2938cbe0) at ./storage/innobase/os/os0file.cc:1932
#3  0x00005566f48075e5 in LinuxAIOHandler::poll (this=0x7f7d2938cbe0, m1=0x7f7d2938cc80, m2=0x7f7d2938cc88, request=0x7f7d2938cc90) at ./storage/innobase/os/os0file.cc:2093
#4  0x00005566f480ae90 in os_aio_linux_handler (request=0x7f7d2938cc90, m2=0x7f7d2938cc88, m1=0x7f7d2938cc80, global_segment=<optimized out>) at /usr/include/c++/8/bits/stl_vector.h:805
#5  os_aio_handler (segment=segment@entry=0, m1=m1@entry=0x7f7d2938cc80, m2=m2@entry=0x7f7d2938cc88, request=request@entry=0x7f7d2938cc90) at ./storage/innobase/os/os0file.cc:5725
#6  0x00005566f4959bb8 in fil_aio_wait (segment=segment@entry=0) at ./storage/innobase/fil/fil0fil.cc:4435
#7  0x00005566f488e220 in io_handler_thread (arg=<optimized out>) at ./storage/innobase/srv/srv0start.cc:326
#8  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 3 (Thread 0x7f7dfc360700 (LWP 11201)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x7f7dfc35fd60, expected=0, futex_word=0x5566f5ad0388 <COND_checkpoint+40>) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  __pthread_cond_wait_common (abstime=0x7f7dfc35fd60, mutex=0x5566f5ad03a0 <LOCK_checkpoint>, cond=0x5566f5ad0360 <COND_checkpoint>) at pthread_cond_wait.c:539
#2  __pthread_cond_timedwait (cond=cond@entry=0x5566f5ad0360 <COND_checkpoint>, mutex=mutex@entry=0x5566f5ad03a0 <LOCK_checkpoint>, abstime=abstime@entry=0x7f7dfc35fd60) at pthread_cond_wait.c:667
#3  0x00005566f49f0b99 in inline_mysql_cond_timedwait (src_file=0x5566f4cd5d60 "/home/buildbot/buildbot/build/mariadb-10.3.22/storage/maria/ma_servicethread.c", src_line=116, abstime=0x7f7dfc35fd60, mutex=0x5566f5ad03a0 <LOCK_checkpoint>, that=0x5566f5ad0360 <COND_checkpoint>) at ./include/mysql/psi/mysql_thread.h:1222
#4  my_service_thread_sleep (control=control@entry=0x5566f51ceda0 <checkpoint_control>, sleep_time=<optimized out>) at ./storage/maria/ma_servicethread.c:115
#5  0x00005566f49e9359 in ma_checkpoint_background (arg=0x1e) at ./storage/maria/ma_checkpoint.c:707
#6  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#7  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 2 (Thread 0x7f7e10de2700 (LWP 11200)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x7f7e10de1df0, expected=0, futex_word=0x5566f5adfda8 <COND_timer+40>) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  __pthread_cond_wait_common (abstime=0x7f7e10de1df0, mutex=0x5566f5adfdc0 <LOCK_timer>, cond=0x5566f5adfd80 <COND_timer>) at pthread_cond_wait.c:539
#2  __pthread_cond_timedwait (cond=cond@entry=0x5566f5adfd80 <COND_timer>, mutex=mutex@entry=0x5566f5adfdc0 <LOCK_timer>, abstime=abstime@entry=0x7f7e10de1df0) at pthread_cond_wait.c:667
#3  0x00005566f4b0cb83 in inline_mysql_cond_timedwait (that=0x5566f5adfd80 <COND_timer>, mutex=0x5566f5adfdc0 <LOCK_timer>, src_file=0x5566f4cead48 "/home/buildbot/buildbot/build/mariadb-10.3.22/mysys/thr_timer.c", src_line=292, abstime=0x7f7e10de1df0) at ./include/mysql/psi/mysql_thread.h:1222
#4  timer_handler (arg=<optimized out>) at ./mysys/thr_timer.c:292
#5  0x00007f7e11b9afa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#6  0x00007f7e1107c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 1 (Thread 0x7f7e11bb67c0 (LWP 11199)):
#0  0x00005566f47f9390 in recv_apply_hashed_log_recs (last_batch=<optimized out>) at ./storage/innobase/include/hash0hash.ic:42
#1  0x00005566f47fc0cc in recv_group_scan_log_recs (checkpoint_lsn=checkpoint_lsn@entry=3929631106, contiguous_lsn=contiguous_lsn@entry=0x7ffcabf71658, last_phase=last_phase@entry=true) at ./storage/innobase/log/log0recv.cc:3430
#2  0x00005566f47fcfcc in recv_recovery_from_checkpoint_start (flush_lsn=<optimized out>) at ./storage/innobase/log/log0recv.cc:3849
#3  0x00005566f43543d2 in srv_start (create_new_db=<optimized out>) at ./storage/innobase/srv/srv0start.cc:1973
#4  0x00005566f479c4da in innodb_init (p=<optimized out>) at ./storage/innobase/handler/ha_innodb.cc:4250
#5  0x00005566f4623748 in ha_initialize_handlerton (plugin=0x5566f6084e48) at ./sql/handler.cc:549
#6  0x00005566f44576c9 in plugin_initialize (tmp_root=tmp_root@entry=0x7ffcabf78e50, plugin=plugin@entry=0x5566f6084e48, argc=argc@entry=0x5566f5250888 <remaining_argc>, argv=argv@entry=0x5566f6046440, options_only=options_only@entry=false) at ./sql/sql_plugin.cc:1433
#7  0x00005566f44588d2 in plugin_init (argc=argc@entry=0x5566f5250888 <remaining_argc>, argv=0x5566f6046440, flags=2) at ./sql/sql_plugin.cc:1715
#8  0x00005566f43942db in init_server_components () at ./sql/mysqld.cc:5416
#9  0x00005566f439a22e in mysqld_main (argc=<optimized out>, argv=<optimized out>) at ./sql/mysqld.cc:6023
#10 0x00007f7e10fa709b in __libc_start_main (main=0x5566f4379620 <main(int, char**)>, argc=1, argv=0x7ffcabf796e8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffcabf796d8) at ../csu/libc-start.c:308
#11 0x00005566f438d02a in _start () at ./sql/sql_list.h:158
[Inferior 1 (process 11199) detached]

Comment by Marko Mäkelä [ 2020-02-28 ]

neimad, thank you. It looks like there is an infinite loop in recv_apply_hashed_log_recs().
Could you please upload an archive created by

tar cjf MDEV-21826.tar.bz2 ib_logfile*

or similar command to our server https://mariadb.com/kb/en/meta/mariadb-ftp-server/ and let me know the file name?

Comment by Damien BRS [ 2020-02-28 ]

I uploaded the file with name MDEV-21826-OK.tar.bz2
Can you delete MDEV-21826.tar.bz2, I made a mistake and upload the wrong ib_logfile of an other server...

I checked on several other instance (deb10 + 10.3.22) and I can't reproduce de bug.
The bug seems to be very specific.

Comment by Thirunarayanan Balathandayuthapani [ 2020-02-28 ]

Thanks neimad. Uploaded ib_logfile* files (MDEV-21826-OK.tar.bz2) doesn't have any redo log to replay. It looks like the data was taken after normal shutdown.
Please upload the file which were taken after killing the server and before recovery has been attempted.

Comment by Marko Mäkelä [ 2020-02-28 ]

neimad, we ran a debug version of the server with --debug=d,ib_log (which would display information about the records as they are parsed). That output indicated that the log was logically empty (there were no records to apply after the last checkpoint). A shutdown will create a log checkpoint, and checkpoints will also be created periodically. If the server was killed while it was idle, recovery would have nothing to do.

We need log files with which the reported problem is repeatable. I’d suggest the following:

  1. Ensure that the server is busy writing something, not idle.
  2. Kill the server.
  3. Archive the redo log files while the server is offline.
  4. Try to start up the 10.3.22 server.
  5. If the server startup hangs, and 10.3.21 will not hang, then upload the archive.

You might also help us by installing a debug version of the 10.3.22 server and adding the parameter debug=d,ib_log so that additional information would be written to the server error log during the seemingly hung recovery. But I think that it is easier for us to work on the ‘bad’ log files directly.

Comment by Damien BRS [ 2020-02-29 ]

sorry for the wrong file...
I made a new upload after a kill -9 of mysql ( MDEV-21826.tar.bz2 )

how do you install the debug version of mysql?

Comment by Marko Mäkelä [ 2020-03-02 ]

neimad, also that new file seems to be logically clean. Here is the --debug=d,ib_log output:

mariadb-10.3.22

innodb_init: ib_log: checkpoint 0 at 2795063308 found
innodb_init: ib_log: checkpoint 1 at 2795063317 found
recv_group_scan_log_recs: ib_log: scan 2795063317 completed
innodb_init: ib_log: checkpoint 2 at 2795063317 written
innodb_init: ib_log: MLOG_CHECKPOINT(2795063317) written at 2795063326
innodb_init: ib_log: apply completed

The 9-byte LSN difference corresponds to the size of the MLOG_CHECKPOINT record.

Did you really follow all my suggested steps? Did the recovery really hang for you, for the file that you uploaded? If yes, what was the output of step 4 in my earlier comment? (Note: Replacing part of the data directory with older files can easily corrupt the database.)

It appears that we do not provide precompiled debug packages. You can compile it yourself.

Comment by Damien BRS [ 2020-03-04 ]

Hello,

Sorry for the late reply.
Yes I follow exactly the step you mentioned except that systemd try to restart mysql after the kill.

A new try to bypass systemd:
apt upgrade from 10.3.21 to 10.3.22
clean stop with systemctl stop mysql
sudo -u mysql /usr/sbin/mysqld &
kill -9 mysqld
tar cjf MDEV-21826.tar.bz2 ib_logfile*
systemctl start mysql : hang

Log in mariadb :
2020-03-04 11:03:20 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4174599553
2020-03-04 11:03:35 0 [Note] InnoDB: Read redo log up to LSN=4174599680
2020-03-04 11:03:50 0 [Note] InnoDB: Read redo log up to LSN=4174599680

kill -9 mysql
rollback to 10.3.21
systemctl start mysql : OK

the log

2020-03-04 11:06:07 0 [Note] InnoDB: Using Linux native AIO
2020-03-04 11:06:07 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-03-04 11:06:07 0 [Note] InnoDB: Uses event mutexes
2020-03-04 11:06:07 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-03-04 11:06:07 0 [Note] InnoDB: Number of pools: 1
2020-03-04 11:06:07 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-03-04 11:06:07 0 [Note] InnoDB: Initializing buffer pool, total size = 3G, instances = 3, chunk size = 128M
2020-03-04 11:06:08 0 [Note] InnoDB: Completed initialization of buffer pool
2020-03-04 11:06:08 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-03-04 11:06:08 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-03-04 11:06:08 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-03-04 11:06:08 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-03-04 11:06:08 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-03-04 11:06:08 0 [Note] InnoDB: 10.3.21 started; log sequence number 4174599571; transaction id 2953141
2020-03-04 11:06:08 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2020-03-04 11:06:08 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-03-04 11:06:12 0 [Note] InnoDB: Using Linux native AIO
2020-03-04 11:06:12 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-03-04 11:06:12 0 [Note] InnoDB: Uses event mutexes
2020-03-04 11:06:12 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-03-04 11:06:12 0 [Note] InnoDB: Number of pools: 1
2020-03-04 11:06:12 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-03-04 11:06:12 0 [Note] InnoDB: Initializing buffer pool, total size = 3G, instances = 3, chunk size = 128M
2020-03-04 11:06:12 0 [Note] InnoDB: Completed initialization of buffer pool
2020-03-04 11:06:12 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-03-04 11:06:12 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-03-04 11:06:12 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-03-04 11:06:12 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-03-04 11:06:12 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-03-04 11:06:12 0 [Note] InnoDB: 10.3.21 started; log sequence number 4174599580; transaction id 2953141
2020-03-04 11:06:12 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2020-03-04 11:06:12 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-03-04 11:06:12 0 [Note] Server socket created on IP: '::'.
2020-03-04 11:06:12 0 [Note] Reading of all Master_info entries succeeded
2020-03-04 11:06:12 0 [Note] Added new Master_info '' to hash table
2020-03-04 11:06:12 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.3.21-MariaDB-1:10.3.21+maria~buster-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
2020-03-04 11:06:13 0 [Note] InnoDB: Buffer pool(s) load completed at 200304 11:06:13

I uploaded the file to your FTP (MDEV-21826.tar.bz2)

Regards,

Comment by Marko Mäkelä [ 2020-03-12 ]

neimad, if the server is restarted (by whatever mechanism) before the files from the killed server are being copied, that will ruin the log file for us. Also, (after you copied the files) the server will not crash on startup, then those files are useless for us, and you need to try to kill the server again, while it is executing some writes.

Note that it is generally not safe to copy files while the server is running. The mariabackup command does that with special means. To repeat this particular issue, we would need a copy of the redo log file, in such a state that the next startup will crash. A copy of the server error log before the kill and after the failed startup attempt would also be helpful when analyzing that log file.

Comment by Marko Mäkelä [ 2020-03-12 ]

We were very busy with 10.5 development, but thiru will take a look at the new upload soon.

Comment by Thirunarayanan Balathandayuthapani [ 2020-03-13 ]

I used the latest uploaded ib_logfile* to start the server for the following builds:

mariadb-10.3.22 debug built from source

2020-03-13 15:48:48 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
innodb_init: ib_log: checkpoint 155950 at 4174599553 found
innodb_init: ib_log: checkpoint 155949 at 4174599424 found
2020-03-13 15:48:48 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4174599553
recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(4174599553) read at 4174599562
recv_group_scan_log_recs: ib_log: scan 4174599562 completed
recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(4174599553) reread at 4174599562
recv_group_scan_log_recs: ib_log: scan 4174599562 completed
innodb_init: ib_log: checkpoint 155951 at 4174599553 written
innodb_init: ib_log: MLOG_CHECKPOINT(4174599553) written at 4174599571
innodb_init: ib_log: apply completed

mariadb-10.3.22 release built from source

2020-03-13 18:05:49 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-03-13 18:05:49 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2020-03-13 18:05:49 0 [Note] InnoDB: Completed initialization of buffer pool
2020-03-13 18:05:49 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-03-13 18:05:49 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4174599553
2020-03-13 18:05:49 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-03-13 18:05:49 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-03-13 18:05:49 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-03-13 18:05:49 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-03-13 18:05:49 0 [Note] InnoDB: Waiting for purge to start
2020-03-13 18:05:49 0 [Note] InnoDB: 10.3.22 started; log sequence number 4174599562; transaction id 21
2020-03-13 18:05:49 0 [Note] InnoDB: Loading buffer pool(s) from /home/thiru/mariarepo/10.3/MDEV-21826/bld_MDEV-21826-rel/data/ib_buffer_pool
2020-03-13 18:05:49 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-03-13 18:05:49 0 [Note] InnoDB: Buffer pool(s) load completed at 200313 18:05:49

mariadb-10.3.22-buster_all.deb

- Unit mariadb.service has begun starting up.
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] /usr/sbin/mysqld (mysqld 10.3.22-MariaDB-1:10.3.22+maria~bionic) starting as p
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Using Linux native AIO
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Uses event mutexes
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Number of pools: 1
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Using SSE2 crc32 instructions
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Completed initialization of buffer pool
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priori
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4174599553
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file ful
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: 10.3.22 started; log sequence number 4174599562; transaction id 21
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] Plugin 'FEEDBACK' is disabled.
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Buffer pool(s) load completed at 2003

Recovery didn't show up any issue for the given ib_logfile* files.
Can you provide ssh access to the environment where the issue can be repeated ? Thanks neimad

Comment by Thirunarayanan Balathandayuthapani [ 2020-03-17 ]

Thanks neimad. I can repeat the issue now.

Comment by Marko Mäkelä [ 2020-03-18 ]

neimad, the bug can be worked around by setting innodb_buffer_pool_instances=1. The MDEV-19176 fix included a bogus condition that we missed not only in code review but also in our internal testing, because we usually run tests with random input using rather small buffer pool sizes. For the record, MariaDB 10.5 would not be affected by this, because MDEV-15058 removed multiple buffer pool instances.

Comment by Matthias Leich [ 2020-03-18 ]

I was able to replay the problem on origin/10.2 ab0034a78966f3e9f76cf332744fdc54ef10f8c1 2020-03-17T16:28:16+02:00 with RQG

  • innodb_buffer_pool_instances=3 replay
    innodb_buffer_pool_instances=1 never a replay
  • running DDL within the RQG grammar is not required.

No replay + no unknown bad effect on origin/10.2 09e8707d90a8a73887fd4f22b64df43ff4669556 2020-03-18T15:25:28+05:30

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