[MDEV-15826] Purge attempts to free BLOB page after BEGIN;INSERT;UPDATE;ROLLBACK Created: 2018-04-09  Updated: 2018-04-24  Resolved: 2018-04-18

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3.0, 10.2.12, 10.2.13, 10.2.14
Fix Version/s: 10.2.15, 10.3.7

Type: Bug Priority: Critical
Reporter: Maximiliano Dumon Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 3
Labels: blob, corruption, purge
Environment:

Ubuntu 16.04, x86-64bits


Attachments: File blob_free.test     File blob_free2.test     File error.log     File sqlCrash.sql    
Issue Links:
Relates
relates to MDEV-9663 InnoDB assertion failure: *cursor->in... Closed
relates to MDEV-11802 innodb.innodb_bug14676111 fails in bu... Closed
relates to MDEV-15874 CREATE TABLE creates extra transaction Open
relates to MDEV-15374 Server hangs and aborts with long sem... Closed

 Description   

MariaDb crashes if you run the attached sql file as soon as you start the service.

I'm sending you the error log with the error. If you can see de file, the startup and the crash inmediatly next. This error generate a database crash with signal 6, but affter the crash we can't startup the database again.

Could you tell me if you have this error in your roadmap?

Thanks!



 Comments   
Comment by Alice Sherepa [ 2018-04-09 ]

2018-04-09 18:16:28 139634814215936 [ERROR] [FATAL] InnoDB: InnoDB is trying to free page [page id: space=4, page number=4] though it is already marked as free in the tablespace! The tablespace free space info is corrupt. You may need to dump your tables and recreate the whole database!Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.

--source include/have_innodb.inc 
 
CREATE or replace TABLE `table1` (
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `table1StatusId` int(10) unsigned NOT NULL,
  `currentItem` mediumblob DEFAULT NULL,
  `creationTime` datetime NOT NULL,
  `creationTimeMicroseconds` mediumint(8) unsigned NOT NULL,
  `table1TypeId` int(10) unsigned NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci COMMENT='@keepAll';
 
CREATE or replace TABLE `table2` (
  `AAAItemId` int(10) unsigned NOT NULL,
  `entityId` int(10) unsigned NOT NULL,
  `startDateInGMT` datetime NOT NULL,
  `endDateInGMT` datetime NOT NULL,
  `hasTime` tinyint(3) unsigned NOT NULL,
  `modificationDateInGMT` datetime NOT NULL,
  `AAAItemPrimaryTypeId` int(10) unsigned NOT NULL,
  `isCompleted` tinyint(3) unsigned NOT NULL,
  `isCreator` tinyint(3) unsigned NOT NULL,
  `isAssignee` tinyint(3) unsigned NOT NULL,
  `isRelatedObject` tinyint(3) unsigned NOT NULL,
  `isGuest` tinyint(3) unsigned NOT NULL,
  `isCreatorOfParentTimeSlot` tinyint(3) unsigned NOT NULL,
  PRIMARY KEY (`AAAItemId`,`entityId`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci COMMENT='@keepAll';
 
SET AUTOCOMMIT=0;
 
INSERT INTO table1 (`creationTime`, `creationTimeMicroseconds`, `table1StatusId`, `table1TypeId`, `currentItem`) VALUES ("2000-01-01 00:00:00", 0, 1, 1, "123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890");
 
UPDATE table1 SET currentItem = "N;" WHERE (id = 1);
CREATE TEMPORARY TABLE IF NOT EXISTS temporaryCopyOftable2 LIKE table2;
INSERT INTO temporaryCopyOftable2 (AAAItemId, entityId, startDateInGMT, endDateInGMT, hasTime, modificationDateInGMT, AAAItemPrimaryTypeId, isCompleted, isCreator, isAssignee, isRelatedObject, isGuest, isCreatorOfParentTimeSlot) VALUES (1, 100010, "2000-01-01 00:00:00", "2000-01-01 00:00:00.000000", 0, "2000-01-01 00:00:00", 2, 0, 1, 0, 0, 0, 0);
 
ROLLBACK;
 
--source include/shutdown_mysqld.inc
-- source include/start_mysqld.inc
drop table table1,table2;

10.2 debug

Thread 1 (Thread 0x7fd1d77fe700 (LWP 29879)):
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1  0x0000564448cb1fea in my_write_core (sig=sig@entry=6) at /home/alice/git/10.2/mysys/stacktrace.c:477
#2  0x00005644487eeb84 in handle_fatal_signal (sig=6) at /home/alice/git/10.2/sql/signal_handler.cc:305
#3  <signal handler called>
#4  0x00007fd203845428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#5  0x00007fd20384702a in __GI_abort () at abort.c:89
#6  0x0000564448ac7893 in ib::fatal::~fatal (this=0x7fd1d77fcdf0, __in_chrg=<optimized out>) at /home/alice/git/10.2/storage/innobase/ut/ut0ut.cc:794
#7  0x0000564448b7bc18 in fseg_free_page_low (seg_inode=seg_inode@entry=0x7fd1fd22c0f2 "", space=space@entry=0x56444aa14c20, offset=offset@entry=4, page_size=..., ahi=ahi@entry=true, mtr=mtr@entry=0x7fd1d77fd120) at /home/alice/git/10.2/storage/innobase/fsp/fsp0fsp.cc:3113
#8  0x0000564448b7cc63 in fseg_free_page_func (seg_header=seg_header@entry=0x7fd1fd23004a "", space_id=4, page=4, ahi=<optimized out>, mtr=mtr@entry=0x7fd1d77fd120) at /home/alice/git/10.2/storage/innobase/fsp/fsp0fsp.cc:3181
#9  0x0000564448acb4a3 in btr_page_free_low (index=index@entry=0x7fd1bc0102f0, block=block@entry=0x7fd1fcf86230, level=level@entry=0, blob=blob@entry=true, mtr=mtr@entry=0x7fd1d77fd120) at /home/alice/git/10.2/storage/innobase/btr/btr0btr.cc:852
#10 0x0000564448ae76e3 in btr_free_externally_stored_field (index=index@entry=0x7fd1bc0102f0, field_ref=0x7fd1fd00012f "", rec=rec@entry=0x0, offsets=offsets@entry=0x0, page_zip=page_zip@entry=0x0, i=i@entry=0, rollback=false, local_mtr=0x7fd1d77fd6d0) at /home/alice/git/10.2/storage/innobase/btr/btr0cur.cc:7346
#11 0x0000564448a50695 in row_purge_upd_exist_or_extern_func (node=node@entry=0x56444aa08348, undo_rec=undo_rec@entry=0x7fd1c800dc98 "\001E\234\001\023") at /home/alice/git/10.2/storage/innobase/row/row0purge.cc:794
#12 0x0000564448a515df in row_purge_record_func (updated_extern=<optimized out>, undo_rec=0x7fd1c800dc98 "\001E\234\001\023", node=<optimized out>) at /home/alice/git/10.2/storage/innobase/row/row0purge.cc:973
#13 row_purge (thr=0x56444a9d85b0, undo_rec=<optimized out>, node=<optimized out>) at /home/alice/git/10.2/storage/innobase/row/row0purge.cc:1017
#14 row_purge_step (thr=thr@entry=0x56444aa08290) at /home/alice/git/10.2/storage/innobase/row/row0purge.cc:1096
#15 0x0000564448a143da in que_thr_step (thr=0x56444aa08290) at /home/alice/git/10.2/storage/innobase/que/que0que.cc:1049
#16 que_run_threads_low (thr=0x56444aa08290) at /home/alice/git/10.2/storage/innobase/que/que0que.cc:1111
#17 que_run_threads (thr=thr@entry=0x56444aa08290) at /home/alice/git/10.2/storage/innobase/que/que0que.cc:1151
#18 0x0000564448a7b893 in srv_task_execute () at /home/alice/git/10.2/storage/innobase/srv/srv0srv.cc:2555
#19 srv_worker_thread (arg=<optimized out>) at /home/alice/git/10.2/storage/innobase/srv/srv0srv.cc:2602
#20 0x00007fd2044826ba in start_thread (arg=0x7fd1d77fe700) at pthread_create.c:333
#21 0x00007fd20391741d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Comment by Maximiliano Dumon [ 2018-04-11 ]

Do you have any update? This bug is blocker to release the MariaDB 10.2 in our infra.

Thanks!

Comment by Alice Sherepa [ 2018-04-11 ]

Stacktrace is the same, as presented in the comment to MDEV-9663.
jplindst, please check if it resolves the current problem after MDEV-9663 will be fixed.

Comment by Guillermo Schulman [ 2018-04-11 ]

Thanks @alice.sherepa and @jplindst
Notice that this issue is affecting us in version 10.2.x but not in 10.1.x while the issue you are relating is reported to affect 10.1.x. Is that expectable?
Thanks again.

Comment by Jan Lindström (Inactive) [ 2018-04-13 ]

Confirmed that 10.1 is not affected and 10.2 is but 10.3 not.

Comment by Jan Lindström (Inactive) [ 2018-04-13 ]

I receive little bit different stack trace with 10.2 commit f638c37abe1ab2e84746829a05144528b8953432:

(gdb) where
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007ffff4e64231 in __GI_abort () at abort.c:79
#2  0x00007ffff4e5b9da in __assert_fail_base (fmt=0x7ffff4faed48 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x555556761618 "mode == 16 || mode == 12 || !fix_block->page.file_page_was_freed", file=file@entry=0x55555675f508 "/home/jan/mysql/10.2-orig/storage/innobase/buf/buf0buf.cc", line=line@entry=4755, function=function@entry=0x555556764e60 <buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*)::__PRETTY_FUNCTION__> "buf_block_t* buf_page_get_gen(const page_id_t&, const page_size_t&, ulint, buf_block_t*, ulint, const char*, unsigned int, mtr_t*, dberr_t*)") at assert.c:92
#3  0x00007ffff4e5ba52 in __GI___assert_fail (assertion=0x555556761618 "mode == 16 || mode == 12 || !fix_block->page.file_page_was_freed", file=0x55555675f508 "/home/jan/mysql/10.2-orig/storage/innobase/buf/buf0buf.cc", line=4755, function=0x555556764e60 <buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*)::__PRETTY_FUNCTION__> "buf_block_t* buf_page_get_gen(const page_id_t&, const page_size_t&, ulint, buf_block_t*, ulint, const char*, unsigned int, mtr_t*, dberr_t*)") at assert.c:101
#4  0x00005555561fa553 in buf_page_get_gen (page_id=..., page_size=..., rw_latch=2, guess=0x0, mode=10, file=0x55555674a6f0 "/home/jan/mysql/10.2-orig/storage/innobase/btr/btr0cur.cc", line=7297, mtr=0x7fffd67fb1b0, err=0x0) at /home/jan/mysql/10.2-orig/storage/innobase/buf/buf0buf.cc:4755
#5  0x00005555561cff95 in btr_free_externally_stored_field (index=0x7fff980a0f68, field_ref=0x7fffef4f012f "", rec=0x0, offsets=0x0, page_zip=0x0, i=0, rollback=false, local_mtr=0x7fffd67fb7a0) at /home/jan/mysql/10.2-orig/storage/innobase/btr/btr0cur.cc:7295
#6  0x00005555560e46e7 in row_purge_upd_exist_or_extern_func (thr=0x555557c42770, node=0x555557c42928, undo_rec=0x555557c42ed8 "\001E\234\001\023") at /home/jan/mysql/10.2-orig/storage/innobase/row/row0purge.cc:790
#7  0x00005555560e4d3c in row_purge_record_func (node=0x555557c42928, undo_rec=0x555557c42ed8 "\001E\234\001\023", thr=0x555557c42770, updated_extern=true) at /home/jan/mysql/10.2-orig/storage/innobase/row/row0purge.cc:973
#8  0x00005555560e4e81 in row_purge (node=0x555557c42928, undo_rec=0x555557c42ed8 "\001E\234\001\023", thr=0x555557c42770) at /home/jan/mysql/10.2-orig/storage/innobase/row/row0purge.cc:1017
#9  0x00005555560e511a in row_purge_step (thr=0x555557c42770) at /home/jan/mysql/10.2-orig/storage/innobase/row/row0purge.cc:1096
#10 0x00005555560757d9 in que_thr_step (thr=0x555557c42770) at /home/jan/mysql/10.2-orig/storage/innobase/que/que0que.cc:1049
#11 0x00005555560759dc in que_run_threads_low (thr=0x555557c42770) at /home/jan/mysql/10.2-orig/storage/innobase/que/que0que.cc:1111
#12 0x0000555556075b85 in que_run_threads (thr=0x555557c42770) at /home/jan/mysql/10.2-orig/storage/innobase/que/que0que.cc:1151
#13 0x0000555556131b3d in srv_task_execute () at /home/jan/mysql/10.2-orig/storage/innobase/srv/srv0srv.cc:2558
#14 0x0000555556131c8b in srv_worker_thread (arg=0x0) at /home/jan/mysql/10.2-orig/storage/innobase/srv/srv0srv.cc:2605
#15 0x00007ffff7bc15aa in start_thread (arg=0x7fffd67fc700) at pthread_create.c:463
#16 0x00007ffff4f24cbf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Jan Lindström (Inactive) [ 2018-04-13 ]

Same assertion as I reported after adding SET GLOBAL innodb_purge_rseg_truncate_frequency = 1; and wait_all_purged.inc after rollback i.e. before drop tables. Attached both test variations to this MDEV.

mysqltest: In included file "/home/jan/mysql/10.2-orig/mysql-test/suite/innodb/include/wait_all_purged.inc": 
included from /home/jan/mysql/10.2-orig/mysql-test/suite/innodb/t/blob_free.test at line 43:
At line 18: query 'let $remaining= `SHOW ENGINE INNODB STATUS`' failed: 2006: MySQL server has gone away

Comment by Maximiliano Dumon [ 2018-04-13 ]

I tested both tests, but the results are the same: "Mysql has gone away":

2018-04-13 11:51:47 140370750154496 [ERROR] [FATAL] InnoDB: InnoDB is trying to free page [page id: space=0, page number=2053] though it is already marked as free in the tablespace! The tablespace free space info is corrupt. You may need to dump your tables and recreate the whole database!Please refer to https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ for information about forcing recovery.

Comment by Marko Mäkelä [ 2018-04-15 ]

I have good reason to believe that this bug is likely to affect all InnoDB versions. I remember this class of failures already in MySQL 5.6 or maybe 5.5, but back then it would not reproduce easily.

Comment by Marko Mäkelä [ 2018-04-15 ]

On a closer investigation, this particular bug cannot affect MariaDB versions before 10.2.2, because CREATE TEMPORARY TABLE would internally be handled not much differently from CREATE TABLE, and creating a persistent table would cause InnoDB to commit the current transaction.
Here is a reduced test case that reproduces the problem:

--source include/have_innodb.inc
SET @saved_frequency = @@GLOBAL.innodb_purge_rseg_truncate_frequency;
SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
CREATE TABLE t1(i TEXT NOT NULL) ENGINE=InnoDB;
BEGIN;
INSERT t1 SET i=REPEAT('1234567890',840);
UPDATE t1 SET i='';
CREATE TEMPORARY TABLE t2(i SERIAL) ENGINE=InnoDB;
INSERT INTO t2 () VALUES ();
ROLLBACK;
--source include/wait_all_purged.inc
DROP TABLE t1;
SET GLOBAL innodb_purge_rseg_truncate_frequency = @saved_frequency;

Comment by Marko Mäkelä [ 2018-04-15 ]

The assertion fails on the first (only) BLOB page. The page was originally freed as part of the ROLLBACK of the INSERT:

#0  buf_page_set_file_page_was_freed (page_id=...)
    at /mariadb/10.2/storage/innobase/buf/buf0buf.cc:3645
#1  0x000055555766b057 in fseg_free_page_func (seg_header=0x7fffecbb804a "", space_id=4, page=4, 
    ahi=true, mtr=0x7fffde4992b0) at /mariadb/10.2/storage/innobase/fsp/fsp0fsp.cc:3180
#2  0x0000555557420c8f in btr_page_free_low (index=0x618000040508, block=0x7fffec6bf8f0, level=0, 
    blob=true, mtr=0x7fffde4992b0) at /mariadb/10.2/storage/innobase/btr/btr0btr.cc:849
#3  0x00005555574824c8 in btr_free_externally_stored_field (index=0x618000040508, 
    field_ref=0x7fffecbb8092 "", rec=0x7fffecbb807f "", offsets=0x61a000082908, page_zip=0x0, i=3, 
    rollback=true, local_mtr=0x7fffde499d50) at /mariadb/10.2/storage/innobase/btr/btr0cur.cc:7345
#4  0x0000555557482868 in btr_rec_free_externally_stored_fields (index=0x618000040508, 
    rec=0x7fffecbb807f "", offsets=0x61a000082908, page_zip=0x0, rollback=true, mtr=0x7fffde499d50)
    at /mariadb/10.2/storage/innobase/btr/btr0cur.cc:7397
#5  0x0000555557478f78 in btr_cur_pessimistic_delete (err=0x7fffde499c90, has_reserved_extents=0, 
    cursor=0x61b000074778, flags=0, rollback=true, mtr=0x7fffde499d50)
    at /mariadb/10.2/storage/innobase/btr/btr0cur.cc:5143
#6  0x00005555577599d5 in row_undo_ins_remove_clust_rec (node=0x61b000074708)
    at /mariadb/10.2/storage/innobase/row/row0uins.cc:160
#7  0x000055555775b928 in row_undo_ins (node=0x61b000074708, thr=0x6170000437e0)
    at /mariadb/10.2/storage/innobase/row/row0uins.cc:508
#8  0x00005555572d08cc in row_undo (node=0x61b000074708, thr=0x6170000437e0)
    at /mariadb/10.2/storage/innobase/row/row0undo.cc:299

In the rollback of a newly inserted record it is the perfectly valid action to free the BLOBs and to delete the record.

Side note: CREATE TEMPORARY TABLE is allocating a new transaction without cleaning up the previous transaction:

#0  0x00005555573cfd52 in trx_sys_get_new_trx_id ()
    at /mariadb/10.2/storage/innobase/include/trx0sys.ic:401
#1  0x00005555573d8232 in trx_start_low (trx=0x7fffecfd1fd8, read_write=true)
    at /mariadb/10.2/storage/innobase/trx/trx0trx.cc:1216
#2  0x00005555573e2840 in trx_start_if_not_started_xa_low (trx=0x7fffecfd1fd8, read_write=true)
    at /mariadb/10.2/storage/innobase/trx/trx0trx.cc:2813
#3  0x000055555721bff9 in row_table_add_foreign_constraints (trx=0x7fffecfd1fd8, 
    sql_string=0x62b000000288 "CREATE TEMPORARY TABLE t2(i SERIAL) ENGINE=InnoDB", sql_length=49, 
    name=0x7fffde4975e0 "mysqld.1/#sql75b4_8_0", reject_fks=1)
    at /mariadb/10.2/storage/innobase/row/row0mysql.cc:2551
#4  0x0000555556f41067 in create_table_info_t::create_table (this=0x7fffde497560)
    at /mariadb/10.2/storage/innobase/handler/ha_innodb.cc:12808
#5  0x0000555556f4258d in ha_innobase::create (this=0x61d000169f08, 
    name=0x7fffde49b0e0 "/mariadb/10.2/bld/mysql-test/var/tmp/mysqld.1/#sql75b4_8_0", 
    form=0x7fffde497b60, create_info=0x7fffde49c1d0)
    at /mariadb/10.2/storage/innobase/handler/ha_innodb.cc:13010
#6  0x00005555569d56db in handler::ha_create (this=0x61d000169f08, 
    name=0x7fffde49b0e0 "/mariadb/10.2/bld/mysql-test/var/tmp/mysqld.1/#sql75b4_8_0", 
    form=0x7fffde497b60, info_arg=0x7fffde49c1d0) at /mariadb/10.2/sql/handler.cc:4371

It is of course completely bogus to add any FOREIGN KEY constraints to TEMPORARY TABLE. But removing that transaction start does not fix the crash:

diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc
index 3f707e5e631..77915c095e5 100644
--- a/storage/innobase/handler/ha_innodb.cc
+++ b/storage/innobase/handler/ha_innodb.cc
@@ -12674,8 +12674,6 @@ create_table_info_t::create_table()
 	int		primary_key_no;
 	uint		i;
 	dict_table_t*	innobase_table = NULL;
-	const char*	stmt;
-	size_t		stmt_len;
 
 	DBUG_ENTER("create_table");
 
@@ -12800,9 +12798,9 @@ create_table_info_t::create_table()
 		dict_table_get_all_fts_indexes(innobase_table, fts->indexes);
 	}
 
-	stmt = innobase_get_stmt_unsafe(m_thd, &stmt_len);
-
-	if (stmt) {
+	size_t stmt_len;
+	if (const char* stmt = (m_flags2 & DICT_TF2_TEMPORARY)
+	    ? NULL : innobase_get_stmt_unsafe(m_thd, &stmt_len)) {
 		dberr_t	err = row_table_add_foreign_constraints(
 			m_trx, stmt, stmt_len, m_table_name,
 			m_create_info->options & HA_LEX_CREATE_TMP_TABLE);

The rollback is correctly initiated on the older transaction. With the above patch, no transaction ID is allocated for the CREATE TEMPORARY TABLE.
The problem is that after the record was deleted by rollback, purge is trying to deallocate the same BLOB another time. This looks like a flaw in the logic for BLOB ownership.
In InnoDB, BLOBs are normally copy-on-write and the BLOB values must be freed by purge, once old records become inaccessible. However, BLOB values are also inherited when the PRIMARY KEY of a record is updated. That is, the BLOB ownership will be transferred from the old delete-marked PRIMARY KEY record to the new record. On the purge of the old record, the BLOB must not be freed, because the record no longer 'owns' it.

In the case of ROLLBACK, the BLOB was already freed, but the update_undo log of the UPDATE was transferred to purge, and for some reason purge attempts to free the BLOB. Purge would do this by directly following the BLOB pointer in the undo log record, without trying to look up the record.

The fix might involve an update of the undo log record in ROLLBACK, so that purge will not attempt to free the BLOB. This must be done very carefully, so that in other cases (such as updating a record that was originally inserted by a different transaction) purge will not fail to free BLOBs that become inaccessible to active read views.

thiru, can you please think of a solution while I will be taking some days off from work? MDEV-13697 may provide some inspiration. Some purge-like actions are already performed in some cases of ROLLBACK.

Comment by Marko Mäkelä [ 2018-04-16 ]

I tried to debug this further on the long flight, but did not make a breakthrough yet.

I believe that that the reason why this test cannot be repeated without the TEMPORARY TABLE (or on MariaDB versions earlier than 10.2) is that purge fails to run (MDEV-11802).

The following is the most minimal test I was able to create so far:

--source include/have_innodb.inc
SET @saved_frequency = @@GLOBAL.innodb_purge_rseg_truncate_frequency;
SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
CREATE TEMPORARY TABLE t2(i SERIAL) ENGINE=InnoDB;
CREATE TABLE t1(i TEXT NOT NULL) ENGINE=InnoDB;
BEGIN;
INSERT t1 SET i=REPEAT('1234567890',840);
UPDATE t1 SET i='';
INSERT INTO t2 () VALUES ();
ROLLBACK;
--source include/wait_all_purged.inc
DROP TABLE t1;
SET GLOBAL innodb_purge_rseg_truncate_frequency = @saved_frequency;

I tried setting a watchpoint on trx_sys->rseg_history_len and breakpoints on row_purge_record_func and trx_undo_set_state_at_finish.

If I remove the INSERT INTO t2, purge will not run for UPDATE t1, even though trx_sys->rseg_history_len will be incremented and decremented for it.

Comment by Thirunarayanan Balathandayuthapani [ 2018-04-17 ]

During rollback we should rollback from last undo log record. But if the last undo log record belongs to
temporary table then we are not following that order.Rollback first process the redo based rollback segments
and then it processes the no-redo rollback segments.

In our case,

trx_roll_try_truncate() 

executed after rollback operation of all undo logs. InnoDB executed
the no-redo rollback segments at last and its undo_no is also greater than redo rollback segment.
By result of this, it will never remove undo logs belongs to redo log segment.

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