[MDEV-25773] sysbench-TPCC failed to prepare with extremely slow execution Created: 2021-05-25  Updated: 2021-07-23  Resolved: 2021-07-23

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.5.7, 10.5.8, 10.5.9, 10.5.10, 10.6.0, 10.6.1
Fix Version/s: 10.5.12, 10.6.3

Type: Bug Priority: Critical
Reporter: VAROQUI Stephane Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: performance, regression

Attachments: HTML File mystack2     File stack.dropdatabase     File stack.prepare    
Issue Links:
PartOf
includes MDEV-25801 DROP DATABASE very slow after innodb ... Closed
Problem/Incident
is caused by MDEV-23399 10.5 performance regression with IO-b... Closed
Relates
relates to MDEV-25800 DROP TABLE unnecessarily accesses .ib... Open

 Description   
209 root fdfe::ad:37134 sbtest Query 2446 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
210 root fdfe::ad:37150 sbtest Query 2449 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
211 root fdfe::ad:37170 sbtest Query 2431 Update INSERT INTO stock6 (s_i_id, s_w_id, s_quantity, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_dist_0 0.000
212 root fdfe::ad:37182 sbtest Query 2432 Update INSERT INTO stock4 (s_i_id, s_w_id, s_quantity, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_dist_0 0.000
214 root fdfe::ad:37196 sbtest Query 2450 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
213 root fdfe::ad:37190 sbtest Query 2449 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
215 root fdfe::ad:37208 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
216 root fdfe::ad:37216 sbtest Query 2432 Update INSERT INTO stock6 (s_i_id, s_w_id, s_quantity, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_dist_0 0.000
217 root fdfe::ad:37220 sbtest Query 2433 Update INSERT INTO order_line6 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
218 root fdfe::ad:37232 sbtest Query 2432 Update INSERT INTO stock3 (s_i_id, s_w_id, s_quantity, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_dist_0 0.000
219 root fdfe::ad:37242 sbtest Query 2432 Update INSERT INTO order_line6 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
224 root fdfe::ad:37266 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
220 root fdfe::ad:37248 sbtest Query 2432 Update INSERT INTO customer7 (c_id, c_d_id, c_w_id, c_first, c_middle, c_last, c_street_1, c_street_2, c_ 0.000
221 root fdfe::ad:37250 sbtest Query 2433 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
222 root fdfe::ad:37258 sbtest Query 2432 Update INSERT INTO order_line3 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
223 root fdfe::ad:37262 sbtest Query 2448 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
225 root fdfe::ad:37270 sbtest Query 2434 Update INSERT INTO history6 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
226 root fdfe::ad:37272 sbtest Query 2463 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
227 root fdfe::ad:37274 sbtest Query 2434 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
228 root fdfe::ad:37276 sbtest Query 2433 Update INSERT INTO order_line3 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
229 root fdfe::ad:37278 sbtest Query 2448 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
230 root fdfe::ad:37280 sbtest Query 2453 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
231 root fdfe::ad:37282 sbtest Query 2464 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
232 root fdfe::ad:37284 sbtest Query 2449 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
233 root fdfe::ad:37286 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
234 root fdfe::ad:37288 sbtest Query 2445 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
235 root fdfe::ad:37290 sbtest Query 2465 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
236 root fdfe::ad:37292 sbtest Query 2433 Update INSERT INTO history7 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
237 root fdfe::ad:37294 sbtest Query 2463 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
238 root fdfe::ad:37296 sbtest Query 2449 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
239 root fdfe::ad:37298 sbtest Query 2433 Update INSERT INTO order_line4 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
240 root fdfe::ad:37300 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
241 root fdfe::ad:37302 sbtest Query 2433 Update INSERT INTO orders4 (o_id, o_d_id, o_w_id, o_c_id, o_entry_d, o_carrier_id, o_ol_cnt, o_all_local) 0.000
242 root fdfe::ad:37304 sbtest Query 2432 Update INSERT INTO stock5 (s_i_id, s_w_id, s_quantity, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_dist_0 0.000
243 root fdfe::ad:37306 sbtest Query 2432 Update INSERT INTO order_line4 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
244 root fdfe::ad:37308 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
245 root fdfe::ad:37310 sbtest Query 2448 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
246 root fdfe::ad:37312 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
247 root fdfe::ad:37314 sbtest Query 2434 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
248 root fdfe::ad:37316 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
249 root fdfe::ad:37318 sbtest Query 2432 Update INSERT INTO stock7 (s_i_id, s_w_id, s_quantity, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_dist_0 0.000
250 root fdfe::ad:37320 sbtest Query 2447 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
251 root fdfe::ad:37322 sbtest Query 2432 Update INSERT INTO order_line3 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
252 root fdfe::ad:37324 sbtest Query 2432 Update INSERT INTO stock4 (s_i_id, s_w_id, s_quantity, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_dist_0 0.000
253 root fdfe::ad:37326 sbtest Query 2451 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
254 root fdfe::ad:37328 sbtest Query 2450 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
255 root fdfe::ad:37330 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
256 root fdfe::ad:37332 sbtest Query 2449 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
257 root fdfe::ad:37334 sbtest Query 2449 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
258 root fdfe::ad:37336 sbtest Query 2451 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
259 root fdfe::ad:37338 sbtest Query 2432 Update INSERT INTO customer5 (c_id, c_d_id, c_w_id, c_first, c_middle, c_last, c_street_1, c_street_2, c_ 0.000
260 root fdfe::ad:37340 sbtest Query 2454 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
261 root fdfe::ad:37342 sbtest Query 2433 Update INSERT INTO order_line6 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
262 root fdfe::ad:37344 sbtest Query 2433 Update INSERT INTO stock4 (s_i_id, s_w_id, s_quantity, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_dist_0 0.000
263 root fdfe::ad:37346 sbtest Query 2450 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
264 root fdfe::ad:37348 sbtest Query 2433 Update INSERT INTO order_line3 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
265 root fdfe::ad:37350 sbtest Query 2453 Update INSERT INTO history3 (h_c_id, h_c_d_id, h_c_w_id, h_d_id, h_w_id, h_date, h_amount, h_data) values 0.000
266 root fdfe::ad:37352 sbtest Query 2432 Update INSERT INTO stock6 (s_i_id, s_w_id, s_quantity, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_dist_0 0.000
267 root fdfe::ad:37354 sbtest Query 2432 Update INSERT INTO stock7 (s_i_id, s_w_id, s_quantity, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_dist_0 0.000
268 root fdfe::ad:37356 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
270 root fdfe::ad:37360 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
271 root fdfe::ad:37362 sbtest Query 2433 Update INSERT INTO order_line3 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
269 root fdfe::ad:37358 sbtest Query 2433 Update INSERT INTO order_line5 (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_deliver 0.000
272 root fdfe::ad:37366 sbtest Query 2433 Update INSERT INTO orders3 (o_id, o_d_id, o_w_id, o_c_id, o_entry_d, o_carrier_id, o_ol_cnt, o_all_local) 0.000
1540 root localhost NULL Query 250 Filling schema table show status like 'Uptime' 0.000
1653 root localhost NULL Query 0 starting show processlist 0.000

SELECT * FROM information_schema.metadata_lock_info;
--------------------------------------------------------------------------------------+

THREAD_ID LOCK_MODE LOCK_DURATION LOCK_TYPE TABLE_SCHEMA TABLE_NAME

--------------------------------------------------------------------------------------+

235 MDL_BACKUP_TRANS_DML NULL Backup lock    
231 MDL_BACKUP_TRANS_DML NULL Backup lock    
226 MDL_BACKUP_TRANS_DML NULL Backup lock    
237 MDL_BACKUP_TRANS_DML NULL Backup lock    
260 MDL_BACKUP_TRANS_DML NULL Backup lock    
230 MDL_BACKUP_TRANS_DML NULL Backup lock    
265 MDL_BACKUP_TRANS_DML NULL Backup lock    
253 MDL_BACKUP_TRANS_DML NULL Backup lock    
258 MDL_BACKUP_TRANS_DML NULL Backup lock    
254 MDL_BACKUP_TRANS_DML NULL Backup lock    
214 MDL_BACKUP_TRANS_DML NULL Backup lock    
263 MDL_BACKUP_TRANS_DML NULL Backup lock    
213 MDL_BACKUP_TRANS_DML NULL Backup lock    
238 MDL_BACKUP_TRANS_DML NULL Backup lock    
232 MDL_BACKUP_TRANS_DML NULL Backup lock    
257 MDL_BACKUP_TRANS_DML NULL Backup lock    
210 MDL_BACKUP_TRANS_DML NULL Backup lock    
256 MDL_BACKUP_TRANS_DML NULL Backup lock    
229 MDL_BACKUP_TRANS_DML NULL Backup lock    
245 MDL_BACKUP_TRANS_DML NULL Backup lock    
223 MDL_BACKUP_TRANS_DML NULL Backup lock    
250 MDL_BACKUP_TRANS_DML NULL Backup lock    
209 MDL_BACKUP_TRANS_DML NULL Backup lock    
234 MDL_BACKUP_TRANS_DML NULL Backup lock    
227 MDL_BACKUP_TRANS_DML NULL Backup lock    
247 MDL_BACKUP_TRANS_DML NULL Backup lock    
225 MDL_BACKUP_TRANS_DML NULL Backup lock    
228 MDL_BACKUP_TRANS_DML NULL Backup lock    
261 MDL_BACKUP_TRANS_DML NULL Backup lock    
269 MDL_BACKUP_TRANS_DML NULL Backup lock    
244 MDL_BACKUP_TRANS_DML NULL Backup lock    
217 MDL_BACKUP_TRANS_DML NULL Backup lock    
255 MDL_BACKUP_TRANS_DML NULL Backup lock    
233 MDL_BACKUP_TRANS_DML NULL Backup lock    
241 MDL_BACKUP_TRANS_DML NULL Backup lock    
239 MDL_BACKUP_TRANS_DML NULL Backup lock    
215 MDL_BACKUP_TRANS_DML NULL Backup lock    
270 MDL_BACKUP_TRANS_DML NULL Backup lock    
224 MDL_BACKUP_TRANS_DML NULL Backup lock    
236 MDL_BACKUP_TRANS_DML NULL Backup lock    
264 MDL_BACKUP_TRANS_DML NULL Backup lock    
271 MDL_BACKUP_TRANS_DML NULL Backup lock    
272 MDL_BACKUP_TRANS_DML NULL Backup lock    
268 MDL_BACKUP_TRANS_DML NULL Backup lock    
246 MDL_BACKUP_TRANS_DML NULL Backup lock    
221 MDL_BACKUP_TRANS_DML NULL Backup lock    
240 MDL_BACKUP_TRANS_DML NULL Backup lock    
262 MDL_BACKUP_TRANS_DML NULL Backup lock    
248 MDL_BACKUP_TRANS_DML NULL Backup lock    
212 MDL_BACKUP_TRANS_DML NULL Backup lock    
222 MDL_BACKUP_TRANS_DML NULL Backup lock    
249 MDL_BACKUP_TRANS_DML NULL Backup lock    
219 MDL_BACKUP_TRANS_DML NULL Backup lock    
242 MDL_BACKUP_TRANS_DML NULL Backup lock    
218 MDL_BACKUP_TRANS_DML NULL Backup lock    
259 MDL_BACKUP_TRANS_DML NULL Backup lock    
220 MDL_BACKUP_TRANS_DML NULL Backup lock    
216 MDL_BACKUP_TRANS_DML NULL Backup lock    
252 MDL_BACKUP_TRANS_DML NULL Backup lock    
266 MDL_BACKUP_TRANS_DML NULL Backup lock    
251 MDL_BACKUP_TRANS_DML NULL Backup lock    
243 MDL_BACKUP_TRANS_DML NULL Backup lock    
267 MDL_BACKUP_TRANS_DML NULL Backup lock    
211 MDL_BACKUP_TRANS_DML NULL Backup lock    
261 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line6
217 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line6
219 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line6
216 MDL_SHARED_READ NULL Table metadata lock sbtest order_line6
266 MDL_SHARED_READ NULL Table metadata lock sbtest order_line6
211 MDL_SHARED_READ NULL Table metadata lock sbtest order_line6
249 MDL_SHARED_WRITE NULL Table metadata lock sbtest stock7
267 MDL_SHARED_WRITE NULL Table metadata lock sbtest stock7
259 MDL_SHARED_READ NULL Table metadata lock sbtest history5
218 MDL_SHARED_WRITE NULL Table metadata lock sbtest stock3
241 MDL_SHARED_READ NULL Table metadata lock sbtest order_line4
239 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line4
262 MDL_SHARED_READ NULL Table metadata lock sbtest order_line4
212 MDL_SHARED_READ NULL Table metadata lock sbtest order_line4
252 MDL_SHARED_READ NULL Table metadata lock sbtest order_line4
243 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line4
236 MDL_SHARED_WRITE NULL Table metadata lock sbtest history7
220 MDL_SHARED_READ NULL Table metadata lock sbtest history7
241 MDL_SHARED_READ NULL Table metadata lock sbtest new_orders4
241 MDL_SHARED_WRITE NULL Table metadata lock sbtest orders4
235 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
231 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
226 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
237 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
260 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
230 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
265 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
253 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
258 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
254 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
214 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
263 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
213 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
238 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
232 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
257 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
210 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
256 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
229 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
245 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
223 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
250 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
209 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
234 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
227 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
221 MDL_SHARED_WRITE NULL Table metadata lock sbtest history3
242 MDL_SHARED_WRITE NULL Table metadata lock sbtest stock5
220 MDL_SHARED_WRITE NULL Table metadata lock sbtest customer7
259 MDL_SHARED_READ NULL Table metadata lock sbtest orders5
225 MDL_SHARED_WRITE NULL Table metadata lock sbtest history6
247 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
269 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
244 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
255 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
233 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
215 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
270 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
224 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
268 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
246 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
240 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
248 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line5
242 MDL_SHARED_READ NULL Table metadata lock sbtest order_line5
259 MDL_SHARED_WRITE NULL Table metadata lock sbtest customer5
262 MDL_SHARED_WRITE NULL Table metadata lock sbtest stock4
212 MDL_SHARED_WRITE NULL Table metadata lock sbtest stock4
252 MDL_SHARED_WRITE NULL Table metadata lock sbtest stock4
272 MDL_SHARED_WRITE NULL Table metadata lock sbtest orders3
249 MDL_SHARED_READ NULL Table metadata lock sbtest order_line7
267 MDL_SHARED_READ NULL Table metadata lock sbtest order_line7
228 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line3
264 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line3
271 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line3
272 MDL_SHARED_READ NULL Table metadata lock sbtest order_line3
222 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line3
218 MDL_SHARED_READ NULL Table metadata lock sbtest order_line3
251 MDL_SHARED_WRITE NULL Table metadata lock sbtest order_line3
272 MDL_SHARED_READ NULL Table metadata lock sbtest new_orders3
216 MDL_SHARED_WRITE NULL Table metadata lock sbtest stock6
266 MDL_SHARED_WRITE NULL Table metadata lock sbtest stock6
211 MDL_SHARED_WRITE NULL Table metadata lock sbtest stock6
220 MDL_SHARED_READ NULL Table metadata lock sbtest orders7

--------------------------------------------------------------------------------------+
146 rows in set (0.001 sec)

i was able to make it prepare with mariadb 10.5.9 and O_DSYNC

My only change since that Are :

upgrade to docker mariadb 10.5.10

[mysqld]
loose_innodb_undo_tablespaces=64
loose_innodb_undo_log_truncate=1
innodb_flush_method = 0_DIRECT

i'm refining to try to found out what change break the prepare

 Comments   
Comment by VAROQUI Stephane [ 2021-05-25 ]

When removing the undo log splitting i was able to run the prepare step correctly with 64 threads

Nota when i was failing we get the following error log

2021-05-25 17:36:09 0 [Warning] option 'innodb-read-io-threads': unsigned value 128 adjusted to 64
2021-05-25 17:36:09 0 [Warning] option 'innodb-write-io-threads': unsigned value 80 adjusted to 64
2021-05-25 17:36:09 0 [Warning] The parameter innodb_buffer_pool_instances is deprecated and has no effect.
2021-05-25 17:36:09 0 [Warning] The parameter innodb_concurrency_tickets is deprecated and has no effect.
2021-05-25 17:36:09 0 [Note] InnoDB: Uses event mutexes
2021-05-25 17:36:09 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2021-05-25 17:36:09 0 [Note] InnoDB: Number of pools: 1
2021-05-25 17:36:09 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2021-05-25 17:36:09 0 [Note] mysqld: O_TMPFILE is not supported on /var/lib/mysql/.system/tmp (disabling future attempts)
2021-05-25 17:36:09 0 [Note] InnoDB: Using Linux native AIO
2021-05-25 17:36:09 0 [Note] InnoDB: Initializing buffer pool, total size = 329907175424, chunk size = 134217728
2021-05-25 17:36:13 0 [Note] InnoDB: Completed initialization of buffer pool
2021-05-25 17:36:13 0 [Note] InnoDB: Opened 64 undo tablespaces
2021-05-25 17:36:13 0 [Note] InnoDB: Opened 64 undo tablespaces
2021-05-25 17:36:13 0 [Note] InnoDB: 128 rollback segments in 64 undo tablespaces are active.
2021-05-25 17:36:13 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-05-25 17:36:13 0 [Note] InnoDB: Setting file '/var/lib/mysql/.system/innodb/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2021-05-25 17:36:13 0 [Note] InnoDB: File '/var/lib/mysql/.system/innodb/ibtmp1' size is now 12 MB.
2021-05-25 17:36:13 0 [Note] InnoDB: 10.5.10 started; log sequence number 68496; transaction id 20
2021-05-25 17:36:13 0 [Note] Plugin 'FEEDBACK' is disabled.
2021-05-25 17:36:13 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/.system/innodb/ib_buffer_pool
2021-05-25 17:36:13 0 [Warning] mysqld: unknown variable 'loose_server_audit_file_path=/var/lib/mysql/.system/logs/audit.log'
2021-05-25 17:36:13 0 [Warning] mysqld: unknown variable 'loose_sql_error_log_filename=/var/lib/mysql/.system/logs/sql-error.log'
2021-05-25 17:36:13 0 [Warning] mysqld: unknown variable 'loose_binlog_row_query_log_events=1'
2021-05-25 17:36:13 0 [Note] Server socket created on IP: '::'.
2021-05-25 17:36:13 0 [Note] Server socket created on IP: '::'.
2021-05-25 17:36:13 0 [Warning] 'proxies_priv' entry '@% root@db2.benchdrbd.svc.rs1' ignored in --skip-name-resolve mode.
2021-05-25 17:36:13 0 [Note] Reading of all Master_info entries succeeded
2021-05-25 17:36:13 0 [Note] Added new Master_info '' to hash table
2021-05-25 17:36:13 0 [Note] mysqld: ready for connections.
Version: '10.5.10-MariaDB-1:10.5.10+maria~focal-log' socket: '/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
2021-05-25 17:36:13 0 [Note] InnoDB: Buffer pool(s) load completed at 210525 17:36:13
2021-05-25 17:41:58 273 [Warning] Access denied for user 'root'@'localhost' (using password: NO)
2021-05-25 17:41:58 274 [Warning] Access denied for user 'root'@'localhost' (using password: NO)
2021-05-25 17:41:58 275 [Warning] Access denied for user 'root'@'localhost' (using password: NO)
2021-05-25 17:41:59 276 [Warning] Access denied for user 'root'@'localhost' (using password: NO)
2021-05-25 17:42:00 277 [Warning] Access denied for user 'root'@'localhost' (using password: NO)
2021-05-25 17:50:20 0 [Note] InnoDB: Truncating //var/lib/mysql/.system/innodb/undo/undo001
2021-05-25 17:54:28 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139415460419328 has waited at row0ins.cc line 2633 for 248.00 seconds the semaphore:
X-lock on RW-latch at 0x7f14c01d1778 created in file buf0buf.cc line 1221
a writer (thread id 139414935987968) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file row0ins.cc line 2633
2021-05-25 17:54:28 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139414945511168 has waited at row0ins.cc line 2633 for 248.00 seconds the semaphore:
X-lock on RW-latch at 0x7f14c01d1778 created in file buf0buf.cc line 1221
a writer (thread id 139414935987968) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file row0ins.cc line 2633
2021-05-25 17:54:28 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139414941517568 has waited at row0ins.cc line 2633 for 248.00 seconds the semaphore:
X-lock on RW-latch at 0x7f14c01d1778 created in file buf0buf.cc line 1221
a writer (thread id 139414935987968) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time write locked in file row0ins.cc line 2633
2021-05-25 17:54:28 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139414932301568 has waited at row0ins.cc line 2633 for 248.00 seconds the semaphore:
X-lock on RW-latch at 0x7f14c01d1778 created in file buf0buf.cc line 1221
a writer (thread id 139414935987968) has reserved it in mode exclusive

Comment by VAROQUI Stephane [ 2021-05-25 ]

Here is the config used

01_default_log.cnf:innodb_print_all_deadlocks = 1

01_default_path.cnf:innodb_data_home_dir = /var/lib/mysql/.system/innodb

01_default_path.cnf:innodb_log_group_home_dir = /var/lib/mysql/.system/innodb/redo

01_default_path.cnf:loose_innodb_undo_directory = //var/lib/mysql/.system/innodb/undo

01_engine_innodb.cnf:innodb_file_format = barracuda

01_engine_innodb.cnf:innodb_force_primary_key = 1

01_engine_innodb.cnf:innodb_default_row_format=dynamic

01_engine_innodb.cnf:#innodb_defragment = 1

01_engine_innodb.cnf:innodb_lock_schedule_algorithm=fcfs

01_engine_innodb.cnf:innodb-page-cleaners= 128

01_engine_innodb.cnf:innodb_buffer_pool_size = 314572M

01_engine_innodb.cnf:innodb_buffer_pool_instances = 40

01_engine_innodb.cnf:innodb_read_io_threads = 128

01_engine_innodb.cnf:innodb_write_io_threads = 80

01_engine_innodb.cnf:innodb_io_capacity = 13333

01_engine_innodb.cnf:innodb_io_capacity_max = 40000

01_engine_innodb.cnf:innodb_max_dirty_pages_pct = 40

01_engine_innodb.cnf:innodb_max_dirty_pages_pct_lwm = 20

01_engine_innodb.cnf:innodb_log_file_size = 20480M

01_engine_innodb.cnf:innodb_log_buffer_size = 16M

01_engine_innodb.cnf:loose_innodb_purge_threads = 4

01_engine_innodb.cnf:innodb_adaptive_hash_index = 0

01_engine_innodb.cnf:innodb_file_per_table= 1

01_engine_innodb.cnf:innodb_log_files_in_group = 1

01_engine_innodb.cnf:innodb_flush_neighbors = 1

01_engine_innodb.cnf:innodb_thread_concurrency = 0

01_engine_innodb.cnf:innodb_flush_method = O_DIRECT

01_engine_innodb.cnf:innodb_autoinc_lock_mode = 2

01_engine_innodb.cnf:innodb_stats_on_metadata = 0

01_engine_innodb.cnf:innodb_buffer_pool_dump_at_shutdown = 1

01_engine_innodb.cnf:innodb_buffer_pool_load_at_startup = 1

01_engine_innodb.cnf:innodb_open_files = 16384

01_engine_innodb.cnf:innodb_concurrency_tickets = 5000

01_engine_innodb.cnf:innodb_print_all_deadlocks = 1

01_engine_innodb.cnf:innodb_large_prefix = 1

01_engine_innodb.cnf:innodb_file_format = barracuda

01_engine_innodb.cnf:innodb_default_row_format=dynamic

50_with_disk_ssd.cnf:loose_innodb_flush_neighbors = 0

50_with_disk_ssd.cnf:loose_innodb_change_buffering=none

Comment by VAROQUI Stephane [ 2021-05-26 ]

The faulty parameter is innodb_undo_log_truncate=1 without truncation of undo log it all worked as expected

Comment by VAROQUI Stephane [ 2021-05-26 ]

128 epoll_wait,io_poll_wait,get_event,::,::,start_thread,clone
48 _lll_lock_wait,GI__pthread_mutex_lock,::,::,::,tpool::task_group::execute,tpool::thread_pool_generic::worker_main,libstdc+::(libstdc+.so.6),start_thread,clone
36 futex_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_wait,::,::,::,::,::,::,::,::,::,::,handler::ha_write_row,write_record,mysql_insert,mysql_execute_command,mysql_parse,dispatch_command,do_command,tp_callback,::,::,start_thread,clone
25 futex_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_wait,::,::,::,::,::,::,::,::,::,::,::,::,handler::ha_write_row,write_record,mysql_insert,mysql_execute_command,mysql_parse,dispatch_command,do_command,tp_callback,::,::,start_thread,clone
7 futex_abstimed_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_timedwait,tpool::thread_pool_generic::wait_for_tasks,tpool::thread_pool_generic::get_task,tpool::thread_pool_generic::worker_main,libstdc+::??(libstdc+.so.6),start_thread,clone
2 futex_abstimed_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_timedwait,::,::,start_thread,clone
1 ::,::,::,::,tpool::task_group::execute,tpool::thread_pool_generic::worker_main,libstdc+::??(libstdc+.so.6),start_thread,clone
1 syscall,tpool::aio_linux::getevent_thread_routine,libstdc+::??(libstdc+.so.6),start_thread,clone
1 _lll_lock_wait,GI__pthread_mutex_lock,::,::,::??,start_thread,clone
1 _lll_lock_wait,GI__pthread_mutex_lock,::,::,::,::,ha_show_status,mysql_execute_command,mysql_parse,dispatch_command,do_command,tp_callback,::,::,start_thread,clone
1 _lll_lock_wait,GI__pthread_mutex_lock,::,::,::,::,::,::,::,handler::ha_write_row,write_record,mysql_insert,mysql_execute_command,mysql_parse,dispatch_command,do_command,tp_callback,::,::??,start_thread,clone
1 _lll_lock_wait,GI__pthread_mutex_lock,::,::,::,::,::,::,::,::,::,::,handler::ha_write_row,write_record,mysql_insert,mysql_execute_command,mysql_parse,dispatch_command,do_command,tp_callback,::,::,start_thread,clone
1 _GI__sigtimedwait,signal_hand,::??,start_thread,clone
1 _GI_poll,handle_connections_sockets,mysqld_main,_libc_start_main,_start
1 futex_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_wait,::,::,::,tpool::thread_pool_generic::timer_generic::execute,tpool::task::execute,tpool::thread_pool_generic::worker_main,libstdc+::(libstdc+.so.6),start_thread,clone
1 futex_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_wait,::,::,::,::,::,::,::,::,::,::,::,tpool::thread_pool_generic::timer_generic::execute,tpool::task::execute,tpool::thread_pool_generic::worker_main,libstdc+::(libstdc+.so.6),start_thread,clone
1 futex_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_wait,::,::,::,::,::,::,::,::,::,handler::ha_write_row,write_record,mysql_insert,mysql_execute_command,mysql_parse,dispatch_command,do_command,tp_callback,::,::??,start_thread,clone
1 futex_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_wait,handle_manager,::??,start_thread,clone
1 futex_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_wait,binlog_background_thread,::??,start_thread,clone
1 futex_abstimed_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_timedwait,::,::,::??,start_thread,clone
1 futex_abstimed_wait_cancelable,_pthread_cond_wait_common,_pthread_cond_timedwait,get_event,::,::,start_thread,clone

Comment by VAROQUI Stephane [ 2021-05-26 ]

mystack2

Comment by VAROQUI Stephane [ 2021-05-27 ]

drop database freezing after restart stack

Comment by VAROQUI Stephane [ 2021-05-27 ]

stack.dropdatabase

Comment by Marko Mäkelä [ 2021-05-27 ]

A quick observation for stack.dropdatabase is that the DROP TABLE that is being executed as part of DROP DATABASE is unnecessarily reading from the data file:

#7  buf_read_page (page_id=..., zip_size=zip_size@entry=0) at ./storage/innobase/buf/buf0rea.cc:483
 
#8  0x0000564b53867a6b in buf_page_get_low (page_id=..., zip_size=<optimized out>, rw_latch=<optimized out>, guess=<optimized out>, mode=<optimized out>, mtr=<optimized out>, err=<optimized out>, allow_ibuf_merge=<optimized out>) at ./storage/innobase/buf/buf0buf.cc:2671
 
#9  0x0000564b53895a9c in dict_load_table_one (name=..., ignore_err=<optimized out>, fk_tables=...) at ./storage/innobase/include/fil0fil.h:698
 
#10 0x0000564b53896119 in dict_load_table (name=name@entry=0x7f497dc76ea0 "sbtest/customer1", ignore_err=ignore_err@entry=6) at ./storage/innobase/include/dict0types.h:105
 
#11 0x0000564b53888943 in dict_table_open_on_name (table_name=table_name@entry=0x7f497dc76ea0 "sbtest/customer1", dict_locked=dict_locked@entry=1, try_drop=try_drop@entry=0, ignore_err=ignore_err@entry=6) at ./storage/innobase/dict/dict0dict.cc:1110
 
#12 0x0000564b537d1890 in row_drop_table_for_mysql (name=name@entry=0x7f497dc76ea0 "sbtest/customer1", trx=trx@entry=0x7fb140f88210, sqlcom=sqlcom@entry=SQLCOM_DROP_DB, create_failed=create_failed@entry=false, nonatomic=nonatomic@entry=true) at ./storage/innobase/row/row0mysql.cc:3252

We already optimized the write side of this in MDEV-21069. That is, we will skip updating the allocation metadata in .ibd files if the entire file is going to be deleted.
This thread is blocked waiting for buf_pool.mutex. Another thread is waiting for it in buf_stats_get_pool_info(), for SHOW ENGINE INNODB STATUS. Likewise, several write completion callbacks are waiting for it in buf_page_write_complete(). This will certainly block the progress of DROP DATABASE, which is trying to allocate a free page. If all pages are dirty, no page will be allocated.

But, which thread is holding the buf_pool.mutex? Thread 72:

#3  0x0000564b530db262 in inline_mysql_mutex_lock (that=<optimized out>, src_file=0x564b53bdda28 "/home/buildbot/buildbot/build/mariadb-10.6.1/storage/innobase/buf/buf0flu.cc", src_line=391) at ./include/mysql/psi/mysql_thread.h:746
 
#4  buf_page_write_complete (request=...) at ./storage/innobase/buf/buf0flu.cc:391


  mysql_mutex_lock(&buf_pool.mutex);
 
  bpage->set_io_fix(BUF_IO_NONE);
 
  mysql_mutex_lock(&buf_pool.flush_list_mutex);

Next question: which thread is holding buf_pool.flush_list_mutex? I just wanted to post a quick update.

Was the hang on 10.5 with the corrupted mystack2 also related to a DROP operation by chance?

Comment by VAROQUI Stephane [ 2021-05-27 ]

stack.dropdatabase is from 10.6.1 but mystack2 is from tpcc sysbench on 10.5

Comment by VAROQUI Stephane [ 2021-05-27 ]

And the prepare freeze stack.prepare

Comment by Marko Mäkelä [ 2021-05-27 ]

For the initially reported problem, stack.prepare suggests that the problem is due to a huge buf_pool.flush_list that is being scanned in buf_flush_dirty_pages() while holding buf_pool.flush_list_mutex. That code was refactored in MDEV-23399.

In most callers, we are not be interested in the count that is returned by buf_flush_dirty_pages(), and we could abort the scan on the first match. But still, if the first dirty pages for the tablespace would be noticed somewhere deep inside the list, we spend a lot of time scanning the list. Possibly we will have to implement a special version of buf_flush_lists() that would only process the pages of the requested tablespace, like the code was before MDEV-23399.

I tried to debug stack.dropdatabase further, but I could not determine which thread would be holding buf_pool.flush_list_mutex, nor was I able to find anything wrong with the usage of that mutex. Also the buf_flush_page_cleaner thread is waiting for that mutex. I hope that you can reproduce and file a separate bug, providing the output of thread apply all backtrace and print buf_pool.flush_list_mutex from a new hang.

Comment by Marko Mäkelä [ 2021-05-27 ]

Based on the additional information in MDEV-25801, I do not think that this is a genuine hang, but extremely slow execution (basically, buf_pool.flush_list_mutex contention due to an O(n²) algorithm).

Comment by Marko Mäkelä [ 2021-05-28 ]

While rewriting all DROP code for MDEV-25506 today, I concluded that ever since the page flushing logic was rewritten in MDEV-23855, buf_flush_remove_pages() only needs to be called in ALTER TABLE…DISCARD TABLESPACE, but not for any other DDL. Actually, it should suffice to call that in IMPORT TABLESPACE when the tablespace is being imported with a tablespace ID that belongs to a previously discarded tablespace whose pages are still located in the buffer pool.

For undo tablespace truncation, it should be best to rewrite buf_flush_dirty_pages() so that it will ‘push down’ a tablespace ID filter, to avoid ‘collateral damage’ of writing out any pages of other tablespaces.

Comment by Marko Mäkelä [ 2021-07-23 ]

I think that the reported performance regression must have been fixed in MDEV-25801.

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