[MDEV-10269] Killed queries from I_S stay in 'Killed' state for long time and don't let server shut down Created: 2016-06-21  Updated: 2018-03-23  Resolved: 2018-03-23

Status: Closed
Project: MariaDB Server
Component/s: Locking, Storage Engine - Aria, Storage Engine - InnoDB
Affects Version/s: 5.5, 10.0, 10.1
Fix Version/s: 10.1.32

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergey Vojtovich
Resolution: Fixed Votes: 1
Labels: None

Attachments: HTML File threads1_active     HTML File threads2_still     HTML File threads3_shutdown     HTML File threads4_shutdown_not_responding    
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.

 Comments   
Comment by Sergey Vojtovich [ 2018-03-13 ]

It seem to be debug only issue, at least there're quite a few expensive things done under mutex.

In effect all threads are waiting for this one on cache_mutex:

Thread 6 (Thread 0x7f1bfcadb700 (LWP 30642)):
 
#0  0x00007f1d4ecc6a30 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
 
#1  0x00007f1d4ecc6b61 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
 
#2  0x00007f1d4ecc7f0e in _Unwind_Backtrace () from /lib/x86_64-linux-gnu/libgcc_s.so.1
 
#3  0x00007f1d4efd89c8 in backtrace () from /lib/x86_64-linux-gnu/libc.so.6
 
#4  0x0000000000e7fae6 in sf_malloc (size=32, my_flags=0) at /home/elenst/git/10.0/mysys/safemalloc.c:138
 
#5  0x0000000000e6e9ef in my_malloc (size=32, my_flags=0) at /home/elenst/git/10.0/mysys/my_malloc.c:100
 
#6  0x0000000000a4e371 in info_add_lock (block=0x7f1d3ddad850, wl=1 '\001') at /home/elenst/git/10.0/storage/maria/ma_pagecache.c:2293
 
#7  0x0000000000a4fa0b in make_lock_and_pin (pagecache=0x208aee0 <maria_pagecache_var>, block=0x7f1d3ddad850, lock=PAGECACHE_LOCK_WRITE, pin=PAGECACHE_PIN, any=0 '\000') at /home/elenst/git/10.0/storage/maria/ma_pagecache.c:2602
 
#8  0x0000000000a51633 in pagecache_read (pagecache=0x208aee0 <maria_pagecache_var>, file=0x7f1c0aacd498, pageno=1684, level=0, buff=0x0, type=PAGECACHE_PLAIN_PAGE, lock=PAGECACHE_LOCK_WRITE, page_link=0x7f1bfcad8a40) at /home/elenst/git/10.0/storage/maria/ma_pagecache.c:3425
 
#9  0x0000000000a86063 in get_head_or_tail_page (info=0x7f1c0aacd070, block=0x7f1c173ef478, buff=0x7f1c0aacd7a0 "", length=139, page_type=1, lock=PAGECACHE_LOCK_WRITE, res=0x7f1bfcad8b00) at /home/elenst/git/10.0/storage/maria/ma_blockrec.c:1752
 
#10 0x0000000000a8a833 in allocate_and_write_block_record (info=0x7f1c0aacd070, record=0x7f1c0abef088 "\031\002", row=0x7f1c0aacd0c8, undo_lsn=1) at /home/elenst/git/10.0/storage/maria/ma_blockrec.c:3507
 
#11 0x0000000000a8aab9 in _ma_write_init_block_record (info=0x7f1c0aacd070, record=0x7f1c0abef088 "\031\002") at /home/elenst/git/10.0/storage/maria/ma_blockrec.c:3568
 
#12 0x0000000000a9bc43 in maria_write (info=0x7f1c0aacd070, record=0x7f1c0abef088 "\031\002") at /home/elenst/git/10.0/storage/maria/ma_write.c:156
 
#13 0x0000000000a273a1 in ha_maria::write_row (this=0x7f1c170c5c88, buf=0x7f1c0abef088 "\031\002") at /home/elenst/git/10.0/storage/maria/ha_maria.cc:1280
 
#14 0x00000000006d9606 in handler::ha_write_tmp_row (this=0x7f1c170c5c88, buf=0x7f1c0abef088 "\031\002") at /home/elenst/git/10.0/sql/sql_class.h:4993
 
#15 0x00000000006e80e7 in schema_table_store_record (thd=0x7f1c19a31070, table=0x7f1c18bfd088) at /home/elenst/git/10.0/sql/sql_show.cc:3542
 
#16 0x0000000000b85846 in i_s_innodb_buffer_page_fill (thd=0x7f1c19a31070, tables=0x7f1c0dbfc418, info_array=0x7f1c170d1078, num_page=10000) at /home/elenst/git/10.0/storage/xtradb/handler/i_s.cc:4992
 
#17 0x0000000000b85f9e in i_s_innodb_fill_buffer_pool (thd=0x7f1c19a31070, tables=0x7f1c0dbfc418, buf_pool=0x7f1d4e49ddf8, pool_id=2) at /home/elenst/git/10.0/storage/xtradb/handler/i_s.cc:5209
 
#18 0x0000000000b860bf in i_s_innodb_buffer_page_fill_table (thd=0x7f1c19a31070, tables=0x7f1c0dbfc418) at /home/elenst/git/10.0/storage/xtradb/handler/i_s.cc:5256
 
#19 0x00000000006f9b19 in get_schema_tables_result (join=0x7f1c0dbfd970, executed_place=PROCESSED_BY_JOIN_EXEC) at /home/elenst/git/10.0/sql/sql_show.cc:8168
 
#20 0x000000000069c30a in JOIN::exec_inner (this=0x7f1c0dbfd970) at /home/elenst/git/10.0/sql/sql_select.cc:2538
 
#21 0x000000000069b8fe in JOIN::exec (this=0x7f1c0dbfd970) at /home/elenst/git/10.0/sql/sql_select.cc:2373
 
#22 0x000000000069ef3b in mysql_select (thd=0x7f1c19a31070, rref_pointer_array=0x7f1c19a35348, tables=0x7f1c0dbfc418, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, result=0x7f1c0dbfd950, unit=0x7f1c19a349e0, select_lex=0x7f1c19a350d0) at /home/elenst/git/10.0/sql/sql_select.cc:3308
 
#23 0x0000000000694f03 in handle_select (thd=0x7f1c19a31070, lex=0x7f1c19a34918, result=0x7f1c0dbfd950, setup_tables_done_option=0) at /home/elenst/git/10.0/sql/sql_select.cc:373
 
#24 0x0000000000667b05 in execute_sqlcom_select (thd=0x7f1c19a31070, all_tables=0x7f1c0dbfc418) at /home/elenst/git/10.0/sql/sql_parse.cc:5293
 
#25 0x000000000065fcf9 in mysql_execute_command (thd=0x7f1c19a31070) at /home/elenst/git/10.0/sql/sql_parse.cc:2562
 
#26 0x000000000066a90d in mysql_parse (thd=0x7f1c19a31070, rawbuf=0x7f1c0dbfc088 "SELECT COUNT(*) FROM INFORMATION_SCHEMA.`INNODB_BUFFER_PAGE`", length=60, parser_state=0x7f1bfcada5f0) at /home/elenst/git/10.0/sql/sql_parse.cc:6574
 
#27 0x000000000065ce95 in dispatch_command (command=COM_QUERY, thd=0x7f1c19a31070, packet=0x7f1c19a37071 "", packet_length=60) at /home/elenst/git/10.0/sql/sql_parse.cc:1308
 
#28 0x000000000065c114 in do_command (thd=0x7f1c19a31070) at /home/elenst/git/10.0/sql/sql_parse.cc:998
 
#29 0x0000000000786f7b in do_handle_one_connection (thd_arg=0x7f1c19a31070) at /home/elenst/git/10.0/sql/sql_connect.cc:1378
 
#30 0x0000000000786ced in handle_one_connection (arg=0x7f1c19a31070) at /home/elenst/git/10.0/sql/sql_connect.cc:1293
 
#31 0x00007f1d500d1e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
 
#32 0x00007f1d4efc1cbd in clone () from /lib/x86_64-linux-gnu/libc.so.6
 
#33 0x0000000000000000 in ?? ()

Either this thread didn't notice kill signal or it was lost somehow.

elenst, could you confirm (if you have it on top of your mind) all threads executing I_S queries were killed?

Comment by Sergey Vojtovich [ 2018-03-20 ]

serg, please review fix for this bug at https://github.com/MariaDB/server/commit/21566f3d077bdc4098452ec1ff98c885011e6179

Comment by Sergei Golubchik [ 2018-03-22 ]

Ok to push, after removing the redundant thd->send_kill_message()

Comment by Sergey Vojtovich [ 2018-03-23 ]

I will do as you suggest, but...

Without thd->send_kill_message() I get "Error 1105 Unknown error", and even that is only visible through "SHOW WARNINGS".

There is some strange error handling done in get_schema_tables_result(), which is probably out of the scope of this bug:

  if (thd->is_error())
 
  {
 
    /*
 
      This hack is here, because I_S code uses thd->clear_error() a lot.
 
      Which means, a Warnings_only_error_handler cannot handle the error
 
      corectly as it does not know whether an error is real (e.g. caused
 
      by tab->select_cond->val_int()) or will be cleared later.
 
      Thus it ignores all errors, and the real one (that is, the error
 
      that was not cleared) is pushed now.
 
 
 
      It also means that an audit plugin cannot process the error correctly
 
      either. See also thd->clear_error()
 
    */
 
    thd->get_stmt_da()->push_warning(thd,
 
                                     thd->get_stmt_da()->sql_errno(),
 
                                     thd->get_stmt_da()->get_sqlstate(),
 
                                     Sql_condition::WARN_LEVEL_ERROR,
 
                                     thd->get_stmt_da()->message());
 
  }
 
  else if (result)
 
    my_error(ER_UNKNOWN_ERROR, MYF(0));

Comment by Sergey Vojtovich [ 2018-03-23 ]

It broke wait_until_disconnected.inc, because it doesn't expect "Unknown error" (it runs "show status"). If I make "Unknown error" expected, lots of tests start to fail.

So I'd leave thd->send_kill_message() for now.

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