Details
-
Bug
-
Status: Confirmed (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.1(EOL)
Description
Note: see also MDEV-8889, they might be somehow related.
The test runs ANALYZE REPLACE DELAYED and kills some of these queries in a rapid fashion. Soon after the start the flow gets stuck, and the processlist looks like this:
+----+---------+-----------------+-------+----------------+------+------------------------------+-------------------------------------------------------------------------+----------+
|
| Id | User | Host | db | Command | Time | State | Info | Progress |
|
+----+---------+-----------------+-------+----------------+------+------------------------------+-------------------------------------------------------------------------+----------+
|
| 2 | rqg | localhost:33215 | mysql | Sleep | 53 | | NULL | 0.000 |
|
| 8 | rqg | localhost:33221 | test | Sleep | 0 | | NULL | 0.000 |
|
| 9 | rqg | localhost:33222 | test | Killed | 32 | waiting for handler insert | ANALYZE REPLACE DELAYED INTO `BB` ( `col_varchar_key` ) VALUES ( NULL ) | 0.000 |
|
| 10 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 11 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 12 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 13 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 14 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 15 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 16 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for table level lock | | 0.000 |
|
| 17 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 18 | rqg | localhost:33223 | test | Killed | 31 | waiting for handler insert | ANALYZE REPLACE DELAYED INTO `BB` ( `col_time_nokey` ) VALUES ( NULL ) | 0.000 |
|
| 19 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 20 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 21 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 22 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 23 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for table level lock | | 0.000 |
|
| 24 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 25 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for table level lock | | 0.000 |
|
| 26 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for table level lock | | 0.000 |
|
| 27 | root | localhost:38193 | test | Query | 0 | init | show processlist | 0.000 |
|
+----+---------+-----------------+-------+----------------+------+------------------------------+-------------------------------------------------------------------------+----------+
|
If lock_wait_timeout is set to a reasonable value, eventually the timeout is reached, and the hanging ANALYZE queries die, along with some of DELAYED connections; but some DELAYED stay:
MariaDB [test]> show processlist;
|
+----+---------+-----------------+------+----------------+------+--------------------+------------------+----------+
|
| Id | User | Host | db | Command | Time | State | Info | Progress |
|
+----+---------+-----------------+------+----------------+------+--------------------+------------------+----------+
|
| 10 | DELAYED | localhost | test | Killed | NULL | Waiting for INSERT | | 0.000 |
|
| 11 | DELAYED | localhost | test | Killed | NULL | Waiting for INSERT | | 0.000 |
|
| 13 | DELAYED | localhost | test | Killed | NULL | Waiting for INSERT | | 0.000 |
|
| 14 | DELAYED | localhost | test | Killed | NULL | Waiting for INSERT | | 0.000 |
|
| 16 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 17 | DELAYED | localhost | test | Killed | NULL | Waiting for INSERT | | 0.000 |
|
| 23 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 25 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 26 | DELAYED | localhost | test | Delayed insert | NULL | Waiting for INSERT | | 0.000 |
|
| 27 | root | localhost:38193 | test | Query | 0 | init | show processlist | 0.000 |
|
+----+---------+-----------------+------+----------------+------+--------------------+------------------+----------+
|
And further the server hangs on shutdown. Two thread stacks taken with a few seconds interval are attached, here is the diff:
|
Stack traces from 10.1 commit a84fae27d9badef8cc89b1369a90cfef1dc3c715 |
< #2 0x00007f85a72d50ed in page_cleaner_sleep_if_needed (next_loop_time=1443813478905) at 10.1/storage/xtradb/buf/buf0flu.cc:2644
|
---
|
> #2 0x00007f85a72d50ed in page_cleaner_sleep_if_needed (next_loop_time=1443813522777) at 10.1/storage/xtradb/buf/buf0flu.cc:2644
|
216c216
|
< #2 0x00007f85a72d50ed in page_cleaner_sleep_if_needed (next_loop_time=1443813478918) at 10.1/storage/xtradb/buf/buf0flu.cc:2644
|
---
|
> #2 0x00007f85a72d50ed in page_cleaner_sleep_if_needed (next_loop_time=1443813522792) at 10.1/storage/xtradb/buf/buf0flu.cc:2644
|
278,285d277
|
< #0 safe_mutex_unlock (mp=0x7f85a8010da0, file=0x7f85a7633ce0 "10.1/sql/sql_insert.cc", line=2886) at 10.1/mysys/thr_mutex.c:452
|
< #1 0x00007f85a6cb30d9 in inline_mysql_mutex_unlock (that=0x7f85a8010da0, src_file=0x7f85a7633ce0 "10.1/sql/sql_insert.cc", src_line=2886) at 10.1/include/mysql/psi/mysql_thread.h:761
|
< #2 0x00007f85a6cb9c19 in handle_delayed_insert (arg=0x7f857fca2070) at 10.1/sql/sql_insert.cc:2886
|
< #3 0x00007f85a63a9b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
|
< #4 0x00007f85a423595d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
|
< #5 0x0000000000000000 in ?? ()
|
<
|
< Thread 9 (Thread 0x7f85a4110700 (LWP 5137)):
|
291c283
|
< #5 0x00007f85a6cb9be3 in handle_delayed_insert (arg=0x7f857fcae070) at 10.1/sql/sql_insert.cc:2883
|
---
|
> #5 0x00007f85a6cb9be3 in handle_delayed_insert (arg=0x7f857fca2070) at 10.1/sql/sql_insert.cc:2883
|
294a287,296
|
>
|
> Thread 9 (Thread 0x7f85a4110700 (LWP 5137)):
|
> #0 0x00007f85a63ad69e in __pthread_mutex_unlock_usercnt (mutex=0x7f85a8885100, decr=<optimized out>) at pthread_mutex_unlock.c:52
|
> #1 0x00007f85a7588f63 in _db_doprnt_ (format=0x7f85a78acb60 "%s (0x%lx) unlocking") at 10.1/dbug/dbug.c:1284
|
> #2 0x00007f85a756e5ec in safe_mutex_unlock (mp=0x7f857fcb3478, file=0x7f85a7633ce0 "10.1/sql/sql_insert.cc", line=2882) at 10.1/mysys/thr_mutex.c:409
|
> #3 0x00007f85a6cb30d9 in inline_mysql_mutex_unlock (that=0x7f857fcb3478, src_file=0x7f85a7633ce0 "10.1/sql/sql_insert.cc", src_line=2882) at 10.1/include/mysql/psi/mysql_thread.h:761
|
> #4 0x00007f85a6cb9bc8 in handle_delayed_insert (arg=0x7f857fcae070) at 10.1/sql/sql_insert.cc:2882
|
> #5 0x00007f85a63a9b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
|
> #6 0x00007f85a423595d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
|
> #7 0x0000000000000000 in ?? ()
|
|
RQG grammar test.yy |
thread1:
|
SELECT Id INTO @kill_id FROM INFORMATION_SCHEMA.PROCESSLIST WHERE Info LIKE 'ANALYZE REPLACE DELAYED%' LIMIT 1; KILL QUERY @kill_id ;
|
 |
query:
|
ANALYZE REPLACE DELAYED INTO _table ( _field ) VALUES ( NULL ) ;
|
|
RQG command line |
perl ./runall-new.pl --threads=3 --duration=300 --queries=100M --grammar=test.yy --engine=MyISAM --basedir1=<your basedir> --vardir1=<your vardir>
|
For RQG, I recommend using lp:~elenst/randgen/mariadb-patches