Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-10269

Killed queries from I_S stay in 'Killed' state for long time and don't let server shut down

    Details

    • Sprint:
      10.1.32

      Description

      When certain queries from INFORMATION_SCHEMA get killed, they stay in the processlist for long time (10-20 min depending on the version), even if the server is already idle, like this:

      	User	Host	db	Command	Time	State	Info	Progress
      43	rqg	localhost:58730	test	Killed	636	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      44	rqg	localhost:58731	test	Killed	636	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      45	rqg	localhost:58732	test	Killed	636	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      46	rqg	localhost:58733	test	Killed	636	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      48	rqg	localhost:58735	test	Killed	636	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      50	rqg	localhost:58737	test	Killed	636	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      62	rqg	localhost:58749	test	Killed	525	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      63	rqg	localhost:58750	test	Killed	525	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      64	rqg	localhost:58751	test	Killed	525	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      65	rqg	localhost:58752	test	Killed	525	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      66	rqg	localhost:58753	test	Killed	525	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      67	rqg	localhost:58754	test	Killed	525	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      68	rqg	localhost:58755	test	Killed	525	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      69	rqg	localhost:58756	test	Killed	525	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      71	rqg	localhost:58758	test	Killed	515	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      72	rqg	localhost:58759	test	Killed	515	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      73	rqg	localhost:58760	test	Killed	515	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      74	rqg	localhost:58761	test	Killed	515	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      75	rqg	localhost:58762	test	Killed	515	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      76	rqg	localhost:58763	test	Killed	515	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      77	rqg	localhost:58764	test	Killed	515	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      78	rqg	localhost:58765	test	Killed	515	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      91	rqg	localhost:58779	test	Killed	395	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      92	rqg	localhost:58780	test	Killed	395	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      93	rqg	localhost:58781	test	Killed	395	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      94	rqg	localhost:58782	test	Killed	395	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      95	rqg	localhost:58783	test	Killed	395	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      96	rqg	localhost:58784	test	Killed	395	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      97	rqg	localhost:58785	test	Killed	395	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      98	rqg	localhost:58786	test	Killed	395	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      100	rqg	localhost:58788	test	Killed	384	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      101	rqg	localhost:58789	test	Killed	384	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      102	rqg	localhost:58790	test	Killed	384	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      103	rqg	localhost:58791	test	Killed	384	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      104	rqg	localhost:58792	test	Killed	384	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      105	rqg	localhost:58793	test	Killed	384	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      106	rqg	localhost:58794	test	Killed	384	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      107	rqg	localhost:58795	test	Killed	384	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      119	rqg	localhost:58807	test	Killed	274	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      120	rqg	localhost:58808	test	Killed	274	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      121	rqg	localhost:58809	test	Killed	274	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      122	rqg	localhost:58810	test	Killed	274	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      123	rqg	localhost:58811	test	Killed	274	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      124	rqg	localhost:58812	test	Killed	274	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      125	rqg	localhost:58813	test	Killed	274	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      126	rqg	localhost:58814	test	Killed	274	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      129	rqg	localhost:58817	test	Killed	254	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      130	rqg	localhost:58818	test	Killed	254	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      131	rqg	localhost:58819	test	Killed	254	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      132	rqg	localhost:58820	test	Killed	254	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      133	rqg	localhost:58821	test	Killed	254	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      134	rqg	localhost:58822	test	Killed	254	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      135	rqg	localhost:58823	test	Killed	254	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      136	rqg	localhost:58824	test	Killed	254	Filling schema table	SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`	0.000
      186	root	localhost:58875	NULL	Query	0	init	show processlist	0.000
      

      Eventually these sessions disappear from the list.

      It seems to be impossible to shut down the server during this time. If shutdown is issued, the server throws a lot of errors into the error log, but even after that the shutdown is delayed (note timestamps in the log below):

      Version: '10.0.26-MariaDB-debug'  socket: '/home/elenst/test_results/analyze_deadlock_10.0/mysql.sock'  port: 10720  Source distribution
      160621 23:00:22 [Note] /home/elenst/git/10.0/sql/mysqld: Normal shutdown
       
      160621 23:00:22 [Note] Event Scheduler: Purging the queue. 0 events
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 136  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 135  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 134  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 133  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 132  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 131  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 130  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 129  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 126  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 125  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 124  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 123  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 122  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 121  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 120  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 119  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 107  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 106  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 105  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 104  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 103  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 102  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 101  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 100  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 98  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 97  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 96  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 95  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 94  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 93  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 92  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 91  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 78  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 77  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 76  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 75  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 74  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 73  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 72  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 71  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 69  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 68  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 67  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 66  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 65  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 64  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 63  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:00:46 [Warning] /home/elenst/git/10.0/sql/mysqld: Forcing close of thread 62  user: 'rqg'
       
      160621 23:00:46 [ERROR] mysqld: Got an error writing communication packets
      160621 23:07:12 [Note] InnoDB: FTS optimize thread exiting.
      160621 23:07:12 [Note] InnoDB: Starting shutdown...
      160621 23:07:15 [Note] InnoDB: Shutdown completed; log sequence number 1652401
      160621 23:07:15 [Note] /home/elenst/git/10.0/sql/mysqld: Shutdown complete
      

      Killed threads look like this:

      #0  0x00007f1d500d889c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
      #1  0x00007f1d500d409b in _L_lock_1006 () from /lib/x86_64-linux-gnu/libpthread.so.0
      #2  0x00007f1d500d401c in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
      #3  0x0000000000e7956b in safe_mutex_lock (mp=0x208afa8 <maria_pagecache_var+200>, my_flags=0, file=0x101bed8 "/home/elenst/git/10.0/storage/maria/ma_pagecache.c", line=3027) at /home/elenst/git/10.0/mysys/thr_mutex.c:294
      #4  0x0000000000a49fb7 in inline_mysql_mutex_lock (that=0x208afa8 <maria_pagecache_var+200>, src_file=0x101bed8 "/home/elenst/git/10.0/storage/maria/ma_pagecache.c", src_line=3027) at /home/elenst/git/10.0/include/mysql/psi/mysql_thread.h:689
      #5  0x0000000000a50bd9 in pagecache_unlock_by_link (pagecache=0x208aee0 <maria_pagecache_var>, block=0x7f1d3dc55a70, lock=PAGECACHE_LOCK_WRITE_TO_READ, pin=PAGECACHE_PIN_LEFT_PINNED, first_REDO_LSN_for_page=0, lsn=0, was_changed=1 '\001', any=0 '\000') at /home/elenst/git/10.0/storage/maria/ma_pagecache.c:3027
      #6  0x0000000000a8997a in write_block_record (info=0x7f1c02bf0070, old_record=0x0, record=0x7f1c17788088 "\031\001", row=0x7f1c02bf00c8, bitmap_blocks=0x7f1c02bf00c8, head_block_is_read=1 '\001', row_pos=0x7f1bfc9fdb00, undo_lsn=1, old_record_checksum=0) at /home/elenst/git/10.0/storage/maria/ma_blockrec.c:3144
      #7  0x0000000000a8a9aa in allocate_and_write_block_record (info=0x7f1c02bf0070, record=0x7f1c17788088 "\031\001", row=0x7f1c02bf00c8, undo_lsn=1) at /home/elenst/git/10.0/storage/maria/ma_blockrec.c:3528
      #8  0x0000000000a8aab9 in _ma_write_init_block_record (info=0x7f1c02bf0070, record=0x7f1c17788088 "\031\001") at /home/elenst/git/10.0/storage/maria/ma_blockrec.c:3568
      #9  0x0000000000a9bc43 in maria_write (info=0x7f1c02bf0070, record=0x7f1c17788088 "\031\001") at /home/elenst/git/10.0/storage/maria/ma_write.c:156
      #10 0x0000000000a273a1 in ha_maria::write_row (this=0x7f1c174b8c88, buf=0x7f1c17788088 "\031\001") at /home/elenst/git/10.0/storage/maria/ha_maria.cc:1280
      #11 0x00000000006d9606 in handler::ha_write_tmp_row (this=0x7f1c174b8c88, buf=0x7f1c17788088 "\031\001") at /home/elenst/git/10.0/sql/sql_class.h:4993
      #12 0x00000000006e80e7 in schema_table_store_record (thd=0x7f1c19b39070, table=0x7f1c174a9088) at /home/elenst/git/10.0/sql/sql_show.cc:3542
      #13 0x0000000000b85846 in i_s_innodb_buffer_page_fill (thd=0x7f1c19b39070, tables=0x7f1c1749d418, info_array=0x7f1bff006078, num_page=10000) at /home/elenst/git/10.0/storage/xtradb/handler/i_s.cc:4992
      #14 0x0000000000b85f9e in i_s_innodb_fill_buffer_pool (thd=0x7f1c19b39070, tables=0x7f1c1749d418, buf_pool=0x7f1d4e49d738, pool_id=1) at /home/elenst/git/10.0/storage/xtradb/handler/i_s.cc:5209
      #15 0x0000000000b860bf in i_s_innodb_buffer_page_fill_table (thd=0x7f1c19b39070, tables=0x7f1c1749d418) at /home/elenst/git/10.0/storage/xtradb/handler/i_s.cc:5256
      #16 0x00000000006f9b19 in get_schema_tables_result (join=0x7f1c1749e970, executed_place=PROCESSED_BY_JOIN_EXEC) at /home/elenst/git/10.0/sql/sql_show.cc:8168
      #17 0x000000000069c30a in JOIN::exec_inner (this=0x7f1c1749e970) at /home/elenst/git/10.0/sql/sql_select.cc:2538
      #18 0x000000000069b8fe in JOIN::exec (this=0x7f1c1749e970) at /home/elenst/git/10.0/sql/sql_select.cc:2373
      #19 0x000000000069ef3b in mysql_select (thd=0x7f1c19b39070, rref_pointer_array=0x7f1c19b3d348, tables=0x7f1c1749d418, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, result=0x7f1c1749e950, unit=0x7f1c19b3c9e0, select_lex=0x7f1c19b3d0d0) at /home/elenst/git/10.0/sql/sql_select.cc:3308
      #20 0x0000000000694f03 in handle_select (thd=0x7f1c19b39070, lex=0x7f1c19b3c918, result=0x7f1c1749e950, setup_tables_done_option=0) at /home/elenst/git/10.0/sql/sql_select.cc:373
      #21 0x0000000000667b05 in execute_sqlcom_select (thd=0x7f1c19b39070, all_tables=0x7f1c1749d418) at /home/elenst/git/10.0/sql/sql_parse.cc:5293
      #22 0x000000000065fcf9 in mysql_execute_command (thd=0x7f1c19b39070) at /home/elenst/git/10.0/sql/sql_parse.cc:2562
      #23 0x000000000066a90d in mysql_parse (thd=0x7f1c19b39070, rawbuf=0x7f1c1749d088 "SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`", length=60, parser_state=0x7f1bfc9ff5f0) at /home/elenst/git/10.0/sql/sql_parse.cc:6574
      #24 0x000000000065ce95 in dispatch_command (command=COM_QUERY, thd=0x7f1c19b39070, packet=0x7f1c19b3f071 "SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`", packet_length=60) at /home/elenst/git/10.0/sql/sql_parse.cc:1308
      #25 0x000000000065c114 in do_command (thd=0x7f1c19b39070) at /home/elenst/git/10.0/sql/sql_parse.cc:998
      #26 0x0000000000786f7b in do_handle_one_connection (thd_arg=0x7f1c19b39070) at /home/elenst/git/10.0/sql/sql_connect.cc:1378
      #27 0x0000000000786ced in handle_one_connection (arg=0x7f1c19b39070) at /home/elenst/git/10.0/sql/sql_connect.cc:1293
      #28 0x00007f1d500d1e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
      #29 0x00007f1d4efc1cbd in clone () from /lib/x86_64-linux-gnu/libc.so.6
      #30 0x0000000000000000 in ?? ()
      

      4 all threads' stack traces from 10.0 are attached:

      • threads1_active – from the time when some connections are already killed, but there is still activity on the server;
      • threads2_still – from the time when all incoming requests are finished, only killed threads are hanging;
      • threads3_shutdown - from the time after 'shutdown' command was issued, but the server is still responding;
      • threads4_shutdown_not_responding – from the time after 'shutdown' command was issued and the server stopped responding, but mysqld process is still there.

      Reproducible on all of 5.5, 10.0, 10.1, 10.2.

      Important notes:

      • With given server settings, the table in question is quite big, but not that big. If a query is not killed, it might take 3-4 minutes to finish on the same server, same machine; but not 10+ minutes like the killed query takes.
      • The type of query is not important; I'm using COUNT just to produce small result set while still having a long enough query, but otherwise aggregate functions are not necessary here.
      • I could only reproduce it on a debug build. Maybe release versions are just faster, or maybe they are essentially different.
      • I'm not sure whether other tables are affected. If it's only a weird behavior with this particular table and only on a debug server, it is not a big problem, and maybe even is not worth fixing; but my concern is that the root cause is more generic, and it might affect realistic scenarios on release servers, only not so reliably. We always have some mysterious external reports about processlists full of killed queries, about server hanging on shutdown, and such. Maybe it's somehow related.

      To reproduce with RQG (try different value of threads and innodb-buffer-pool-size, depending on what your machine is capable of:

      is.yy

      query:
         SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`;
      

      command line

      perl ./runall-new.pl \
      --threads=16 \
      --duration=600 \
      --queries=100M \
      --grammar=is.yy \
      --reporters=QueryTimeout \
      --mysqld=--innodb-buffer-pool-size=4G \
      --skip-gendata \
      --skip-shutdown \
      --basedir=<your basedir> \
      --vardir=<your vardir>  
      

      (I recommend using RQG from https://github.com/elenst/rqg , that's the version for MariaDB which is currently maintained).

      The test will pass, as it does not have any monitors to detect deadlocks and such (intentionally, to avoid unrelated queries); but you can monitor the processlist and error log separately to see what is happening.

        Attachments

        1. threads1_active
          357 kB
        2. threads2_still
          337 kB
        3. threads3_shutdown
          259 kB
        4. threads4_shutdown_not_responding
          257 kB

          Activity

            People

            • Assignee:
              svoj Sergey Vojtovich
              Reporter:
              elenst Elena Stepanova
            • Votes:
              1 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: