Details
-
Type:
Bug
-
Status: Confirmed
-
Priority:
Major
-
Resolution: Unresolved
-
Affects Version/s: 10.1
-
Fix Version/s: 10.1
-
Component/s: Admin statements, Data Manipulation - Insert Delayed
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
Gliffy Diagrams
Attachments
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
I could not reproduce it without ANALYZE. It does not mean it cannot happen on any other circumstances, it might be that I did not find the right mix.
If I add ALTER TABLE, I don't need ANALYZE, but then I get MDEV-8889 as mentioned in the description. If I remove ALTER TABLE and just leave REPLACE and KILL, I am not getting the deadlock.
@elenst, does the problem occur if the test runs regular INSERT/REPLACE DELAYED instead of ANALYZE ?