[MDEV-16713] Hangs server with repeating log entry Created: 2018-07-09  Updated: 2018-07-25  Resolved: 2018-07-25

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Stored routines
Affects Version/s: 10.2.15, 10.2.16, 10.3.8, 10.2, 10.3
Fix Version/s: 10.2.17, 10.3.9

Type: Bug Priority: Blocker
Reporter: Rich Theobald Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: regression
Environment:

Ubuntu 14.04/18.04

Issue Links:
Problem/Incident
is caused by MDEV-15374 Server hangs and aborts with long sem... Closed
Relates
relates to MDEV-16824 InnoDB should skip MVCC and transacti... Confirmed

 Description   

Works on 10.2.14 but hangs on 10.2.15 and 10.3.8 with repeating log entry:

[ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]

Must kill -9 server

To reproduce, run following test case on fresh install of MariaDB server:

CREATE SCHEMA IF NOT EXISTS test;
 
USE test;
 
 
 
DROP PROCEDURE IF EXISTS foo;
 
DELIMITER $$
 
 
 
CREATE PROCEDURE foo()
 
BEGIN
 
 
 
  DECLARE var INT UNSIGNED;
 
  
  DROP TEMPORARY TABLE IF EXISTS bar;
 
  CREATE TEMPORARY TABLE bar( i1 INT UNSIGNED, i2 INT UNSIGNED, KEY( i1, i2 ) );
 
 
 
  SET TRANSACTION ISOLATION LEVEL READ COMMITTED;
 
  
  START TRANSACTION;
 
 
 
  INSERT INTO bar SET i1 = 1, i2 = 1;
 
 
  UPDATE bar SET i2 = 2;
 
 
 
  SET var = ( SELECT 1 FROM bar );
 
 
 
END
 
$$
 
 
 
DELIMITER ;
 
 
 
CALL foo;



 Comments   
Comment by Elena Stepanova [ 2018-07-09 ]

Thanks for the report and test case, reproducible as described.
The problem appeared in 10.2 tree with this revision:

commit 211842dd86f28f4610bc87ea221730c82c0e2494
 
Author: Thirunarayanan Balathandayuthapani
 
Date:   Mon Apr 23 11:22:58 2018 +0530
 
 
 
    MDEV-15374 Server hangs and aborts with long semaphore wait or assertion `len < ((ulint) srv_page_size)' fails in trx_undo_rec_copy upon ROLLBACK on temporary table

10.2 non-debug 8b0d4cff07

 
2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
 
2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
 
2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
 
2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
 
2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
 
2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
 
...

10.2 debug 8b0d4cff07

 
mysqld: /data/src/10.2/storage/innobase/trx/trx0rec.cc:2232: bool trx_undo_prev_version_build(const rec_t*, mtr_t*, const rec_t*, dict_index_t*, ulint*, mem_heap_t*, rec_t**, mem_heap_t*, const dtuple_t**, ulint): Assertion `!(index->table)->is_temporary()' failed.
 
180710  0:18:49 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f95fe4f0ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x0000559bc2dd0c57 in trx_undo_prev_version_build (index_rec=0x7f95f3cc407e "", index_mtr=0x7f95f8178f40, rec=0x7f95f3cc407e "", index=0x7f95a01601e8, offsets=0x7f95a004a088, heap=0x7f95a004a490, old_vers=0x7f95f8178e28, v_heap=0x0, vrow=0x0, v_status=0) at /data/src/10.2/storage/innobase/trx/trx0rec.cc:2232
 
#9  0x0000559bc2d86461 in row_vers_impl_x_locked_low (clust_rec=0x7f95f3cc407e "", clust_index=0x7f95a01601e8, rec=0x7f95f3cc807e "", index=0x7f95a0044728, offsets=0x7f95f8179ca0, mtr=0x7f95f8178f40) at /data/src/10.2/storage/innobase/row/row0vers.cc:179
 
#10 0x0000559bc2d86a00 in row_vers_impl_x_locked (rec=0x7f95f3cc807e "", index=0x7f95a0044728, offsets=0x7f95f8179ca0) at /data/src/10.2/storage/innobase/row/row0vers.cc:402
 
#11 0x0000559bc2d5bfdc in row_search_mvcc (buf=0x7f95a0045918 "\377", mode=PAGE_CUR_G, prebuilt=0x7f95a0046e78, match_mode=0, direction=0) at /data/src/10.2/storage/innobase/row/row0sel.cc:5039
 
#12 0x0000559bc2bedc03 in ha_innobase::index_read (this=0x7f95a0045128, buf=0x7f95a0045918 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9561
 
#13 0x0000559bc2beee7e in ha_innobase::index_first (this=0x7f95a0045128, buf=0x7f95a0045918 "\377") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9981
 
#14 0x0000559bc28d90f3 in handler::ha_index_first (this=0x7f95a0045128, buf=0x7f95a0045918 "\377") at /data/src/10.2/sql/handler.cc:2719
 
#15 0x0000559bc26d0661 in join_read_first (tab=0x7f95a0043868) at /data/src/10.2/sql/sql_select.cc:19708
 
#16 0x0000559bc26ce0f2 in sub_select (join=0x7f95a00426f0, join_tab=0x7f95a0043868, end_of_records=false) at /data/src/10.2/sql/sql_select.cc:18720
 
#17 0x0000559bc26cd6ed in do_select (join=0x7f95a00426f0, procedure=0x0) at /data/src/10.2/sql/sql_select.cc:18267
 
#18 0x0000559bc26a7dcd in JOIN::exec_inner (this=0x7f95a00426f0) at /data/src/10.2/sql/sql_select.cc:3595
 
#19 0x0000559bc26a727a in JOIN::exec (this=0x7f95a00426f0) at /data/src/10.2/sql/sql_select.cc:3390
 
#20 0x0000559bc29a2e0e in subselect_single_select_engine::exec (this=0x7f95a0170fb8) at /data/src/10.2/sql/item_subselect.cc:3894
 
#21 0x0000559bc2997c6f in Item_subselect::exec (this=0x7f95a0170e38) at /data/src/10.2/sql/item_subselect.cc:722
 
#22 0x0000559bc299997b in Item_singlerow_subselect::val_int (this=0x7f95a0170e38) at /data/src/10.2/sql/item_subselect.cc:1329
 
#23 0x0000559bc28f7af7 in Item::save_in_field (this=0x7f95a0170e38, field=0x7f95a00150a8, no_conversions=false) at /data/src/10.2/sql/item.cc:6507
 
#24 0x0000559bc2a4d593 in sp_eval_expr (thd=0x7f95a0000b00, result_field=0x7f95a00150a8, expr_item_ptr=0x7f95a0171030) at /data/src/10.2/sql/sp_head.cc:430
 
#25 0x0000559bc2a5b6f2 in sp_rcontext::set_variable (this=0x7f95a0013f40, thd=0x7f95a0000b00, field=0x7f95a00150a8, value=0x7f95a0171030) at /data/src/10.2/sql/sp_rcontext.cc:383
 
#26 0x0000559bc2625879 in sp_rcontext::set_variable (this=0x7f95a0013f40, thd=0x7f95a0000b00, var_idx=0, value=0x7f95a0171030) at /data/src/10.2/sql/sp_rcontext.h:201
 
#27 0x0000559bc2a54cb4 in sp_instr_set::exec_core (this=0x7f95a0170ff8, thd=0x7f95a0000b00, nextp=0x7f95f817b1a4) at /data/src/10.2/sql/sp_head.cc:3270
 
#28 0x0000559bc2a54207 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7f95a0171040, thd=0x7f95a0000b00, nextp=0x7f95f817b1a4, open_tables=true, instr=0x7f95a0170ff8) at /data/src/10.2/sql/sp_head.cc:3009
 
#29 0x0000559bc2a54c47 in sp_instr_set::execute (this=0x7f95a0170ff8, thd=0x7f95a0000b00, nextp=0x7f95f817b1a4) at /data/src/10.2/sql/sp_head.cc:3263
 
#30 0x0000559bc2a4fa0b in sp_head::execute (this=0x7f95a00099c8, thd=0x7f95a0000b00, merge_da_on_success=true) at /data/src/10.2/sql/sp_head.cc:1327
 
#31 0x0000559bc2a51a9b in sp_head::execute_procedure (this=0x7f95a00099c8, thd=0x7f95a0000b00, args=0x7f95a0005408) at /data/src/10.2/sql/sp_head.cc:2116
 
#32 0x0000559bc265c6f2 in do_execute_sp (thd=0x7f95a0000b00, sp=0x7f95a00099c8) at /data/src/10.2/sql/sql_parse.cc:2909
 
#33 0x0000559bc2665a35 in mysql_execute_command (thd=0x7f95a0000b00) at /data/src/10.2/sql/sql_parse.cc:5822
 
#34 0x0000559bc266be89 in mysql_parse (thd=0x7f95a0000b00, rawbuf=0x7f95a0012478 "CALL foo", length=8, parser_state=0x7f95f817c200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7995
 
#35 0x0000559bc26599ae in dispatch_command (command=COM_QUERY, thd=0x7f95a0000b00, packet=0x7f95a0075a41 "CALL foo", packet_length=8, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1821
 
#36 0x0000559bc2658311 in do_command (thd=0x7f95a0000b00) at /data/src/10.2/sql/sql_parse.cc:1375
 
#37 0x0000559bc27a95d2 in do_handle_one_connection (connect=0x559bc5ba0c20) at /data/src/10.2/sql/sql_connect.cc:1335
 
#38 0x0000559bc27a935f in handle_one_connection (arg=0x559bc5ba0c20) at /data/src/10.2/sql/sql_connect.cc:1241
 
#39 0x0000559bc2bcb658 in pfs_spawn_thread (arg=0x559bc5b7b720) at /data/src/10.2/storage/perfschema/pfs.cc:1862
 
#40 0x00007f96001c7494 in start_thread (arg=0x7f95f817d700) at pthread_create.c:333
 
#41 0x00007f95fe5ad93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Comment by Marko Mäkelä [ 2018-07-25 ]

This was OK to push.
Please file a follow-up bug that InnoDB should skip all transactional locking and multi-versioning on temporary tables in 10.2+. Temporary tables are always private to a connection, and a connection may only use one transaction at a time, so there cannot ever be locking conflicts or any need for multi-versioning for temporary tables.

Generated at Thu Feb 08 08:31:00 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.