Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Cannot Reproduce
-
10.2.2, 10.3.0, 10.4.0
Description
With the following patch applied, the test gcol.innodb_virtual_debug_purge would crash in purge:
diff --git a/storage/innobase/row/row0row.cc b/storage/innobase/row/row0row.cc
|
index ad4991fb4e9..80513f7223e 100644
|
--- a/storage/innobase/row/row0row.cc
|
+++ b/storage/innobase/row/row0row.cc
|
@@ -127,6 +127,7 @@ row_build_index_entry_low(
|
|
ut_ad(dfield_is_null(dfield2) ||
|
dfield_get_len(dfield2) == 0 || dfield2->data);
|
+ ut_ad(dfield2->type.mtype != DATA_MISSING);
|
} else {
|
dfield2 = dtuple_get_nth_field(row, col_no);
|
ut_ad(dfield_get_type(dfield2)->mtype == DATA_MISSING |
|
10.2 af6077b5358198384eb873ce26f88e7a7ecfe106 |
#8 0x000056493cb05ca4 in row_build_index_entry_low (row=0x7fb5c400aa00,
|
ext=0x0, index=0x7fb598040a58, heap=0x7fb5c4008890, flag=1)
|
at /mariadb/10.2/storage/innobase/row/row0row.cc:130
|
#9 0x000056493caffbbc in row_purge_del_mark (node=0x56493ed4d0f8)
|
at /mariadb/10.2/storage/innobase/row/row0purge.cc:788
|
#10 0x000056493cb00826 in row_purge_record_func (node=0x56493ed4d0f8,
|
undo_rec=0x56493ed4d6a8 "", thr=0x56493ed4cf40, updated_extern=false)
|
at /mariadb/10.2/storage/innobase/row/row0purge.cc:1102
|
…
|
Thread 11 (Thread 0x7fb5ebfff700 (LWP 29131)):
|
…
|
#6 0x000056493c56a7e2 in debug_sync (thd=0x7fb598000cf8,
|
sync_point_name=0x56493d0bf389 "inplace_after_index_build", name_len=25)
|
at /mariadb/10.2/sql/debug_sync.cc:1552
|
#7 0x000056493c9e1ede in ha_innobase::inplace_alter_table (
|
this=0x7fb59807ffb0, altered_table=0x7fb5980f41e8,
|
ha_alter_info=0x7fb5ebffb5a0)
|
at /mariadb/10.2/storage/innobase/handler/handler0alter.cc:6532
|
#8 0x000056493c61089d in handler::ha_inplace_alter_table (this=
|
0x7fb59807ffb0, altered_table=0x7fb5980f41e8,
|
ha_alter_info=0x7fb5ebffb5a0) at /mariadb/10.2/sql/handler.h:3783
|
#9 0x000056493c6071a7 in mysql_inplace_alter_table (thd=0x7fb598000cf8,
|
table_list=0x7fb598011838, table=0x7fb598059668,
|
altered_table=0x7fb5980f41e8, ha_alter_info=0x7fb5ebffb5a0,
|
inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE,
|
target_mdl_request=0x7fb5ebffb610, alter_ctx=0x7fb5ebffc1d0)
|
at /mariadb/10.2/sql/sql_table.cc:7365
|
#10 0x000056493c60c7c8 in mysql_alter_table (thd=0x7fb598000cf8,
|
new_db=0x7fb598011e48 "test", new_name=0x0, create_info=0x7fb5ebffcdf0,
|
table_list=0x7fb598011838, alter_info=0x7fb5ebffcd40, order_num=0,
|
order=0x0, ignore=false) at /mariadb/10.2/sql/sql_table.cc:9390
|
#11 0x000056493c6844f7 in Sql_cmd_alter_table::execute (this=0x7fb598011f28,
|
thd=0x7fb598000cf8) at /mariadb/10.2/sql/sql_alter.cc:323
|
#12 0x000056493c542078 in mysql_execute_command (thd=0x7fb598000cf8)
|
at /mariadb/10.2/sql/sql_parse.cc:6225
|
#13 0x000056493c54709e in mysql_parse (thd=0x7fb598000cf8,
|
rawbuf=0x7fb598011710 "ALTER TABLE t1 ADD INDEX idx (c), ALGORITHM=INPLACE, LOCK=NONE", length=62, parser_state=0x7fb5ebffe1b0, is_com_multi=false,
|
is_next_command=false) at /mariadb/10.2/sql/sql_parse.cc:8011
|
This seems related to a MySQL 5.7 bug fix that worked around a similar issue by introducing the function row_purge_skip_uncommitted_virtual_index(). In this case, the ALTER TABLE has already completed the index creation inside InnoDB, but the metadata change has not been committed. The following assertion appears to be valid:
diff --git a/storage/innobase/row/row0row.cc b/storage/innobase/row/row0row.cc
|
index ad4991fb4e9..3f4308d4bed 100644
|
--- a/storage/innobase/row/row0row.cc
|
+++ b/storage/innobase/row/row0row.cc
|
@@ -127,6 +127,8 @@ row_build_index_entry_low(
|
|
ut_ad(dfield_is_null(dfield2) ||
|
dfield_get_len(dfield2) == 0 || dfield2->data);
|
+ ut_ad(dfield2->type.mtype != DATA_MISSING
|
+ || !index->is_committed());
|
} else {
|
dfield2 = dtuple_get_nth_field(row, col_no);
|
ut_ad(dfield_get_type(dfield2)->mtype == DATA_MISSING |
As noted in MDEV-11657, a better approach would be to write each key to the undo log record explicitly. Then purge and rollback should avoid evaluating any virtual columns.
Attachments
Issue Links
- relates to
-
-
- Closed
-
-
MDEV-5800 indexes on virtual (not materialized) columns
-
- Closed
-
-
-
- Open
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
(1 relates to)
Activity
The debug assertion that I added did fail at least once on buildbot:
|
10.3 67f06cadc3e340b707cae3925d59e2e209ca87a8 |
CURRENT_TEST: gcol.innodb_virtual_fk_restart
|
mysqltest: At line 22: query 'DROP TABLE t2, t1' failed: 2013: Lost connection to MySQL server during query
|
…
|
mysqld.exe!_wassert()[assert.cpp:404]
|
mysqld.exe!row_build_index_entry_low()[row0row.cc:258]
|
mysqld.exe!row_purge_upd_exist_or_extern_func()[row0purge.cc:915]
|
mysqld.exe!row_purge_record_func()[row0purge.cc:1211]
|
I wonder if any other fix than a change of the undo log format is possible.
I've got this on the reasonably recent10.2 (853a0a4368), assume it's the same:
mysqld: /home/travis/src/storage/innobase/row/row0row.cc:131: dtuple_t* row_build_index_entry_low(const dtuple_t*, const row_ext_t*, dict_index_t*, mem_heap_t*, ulint): Assertion `dfield2->type.mtype != 0 || !index->is_committed()' failed.
|
181017 22:30:52 [ERROR] mysqld got signal 6 ;
|
|
|
#7 0x00007f920a8e1ca2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
|
#8 0x000056185bc5ff77 in row_build_index_entry_low (row=0x7f91fc6b0f50, ext=0x0, index=0x56185e2ad318, heap=0x7f91fc496de0, flag=1) at /home/travis/src/storage/innobase/row/row0row.cc:130
|
#9 0x000056185bc59aef in row_purge_del_mark (node=0x56185df9da80) at /home/travis/src/storage/innobase/row/row0purge.cc:790
|
#10 0x000056185bc5a763 in row_purge_record_func (node=0x56185df9da80, undo_rec=0x56185dddf6e0 "", thr=0x56185df9d9c8, updated_extern=false) at /home/travis/src/storage/innobase/row/row0purge.cc:1102
|
#11 0x000056185bc5a9df in row_purge (node=0x56185df9da80, undo_rec=0x56185dddf6e0 "", thr=0x56185df9d9c8) at /home/travis/src/storage/innobase/row/row0purge.cc:1163
|
#12 0x000056185bc5ad1b in row_purge_step (thr=0x56185df9d9c8) at /home/travis/src/storage/innobase/row/row0purge.cc:1249
|
#13 0x000056185bbeb468 in que_thr_step (thr=0x56185df9d9c8) at /home/travis/src/storage/innobase/que/que0que.cc:1049
|
#14 0x000056185bbeb663 in que_run_threads_low (thr=0x56185df9d9c8) at /home/travis/src/storage/innobase/que/que0que.cc:1111
|
#15 0x000056185bbeb80d in que_run_threads (thr=0x56185df9d9c8) at /home/travis/src/storage/innobase/que/que0que.cc:1151
|
#16 0x000056185bca6646 in srv_task_execute () at /home/travis/src/storage/innobase/srv/srv0srv.cc:2538
|
#17 0x000056185bca6794 in srv_worker_thread (arg=0x0) at /home/travis/src/storage/innobase/srv/srv0srv.cc:2585
|
#18 0x00007f920b4a3184 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
|
#19 0x00007f920a9afffd in clone () from /lib/x86_64-linux-gnu/libc.so.6
|
Now also in buildbot on 10.3:
http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/10606
|
10.3 67f06cadc3e340b707cae3925d59e2e2 |
gcol.innodb_virtual_fk_restart 'innodb' w1 [ fail ]
|
Test ended at 2018-10-18 12:32:00
|
|
|
CURRENT_TEST: gcol.innodb_virtual_fk_restart
|
mysqltest: At line 22: query 'DROP TABLE t2, t1' failed: 2013: Lost connection to MySQL server during query
|
|
|
The result from queries just before the failure was:
|
< snip >
|
# Add the VIRTUAL INDEX contains fk constraINT column
|
# using INPLACE alter operatiON
|
CREATE TABLE t1(fld1 INT NOT NULL PRIMARY KEY) engine=innodb;
|
CREATE TABLE t2(fld1 INT NOT NULL, fld2 INT NOT NULL,
|
fld3 INT AS (fld2) VIRTUAL, KEY(fld1),
|
FOREIGN KEY(fld1) REFERENCES t1(fld1) ON UPDATE CASCADE) engine=innodb;
|
INSERT INTO t1(fld1) VALUES(1);
|
INSERT INTO t2(fld1, fld2) VALUES(1, 2);
|
UPDATE t1 SET fld1= 2;
|
SELECT fld3, fld1 FROM t2;
|
fld3 fld1
|
2 2
|
alter TABLE t2 ADD INDEX vk(fld3, fld1), ALGORITHM=INPLACE;
|
UPDATE t1 SET fld1=3;
|
SELECT fld3, fld1 FROM t2;
|
fld3 fld1
|
2 3
|
DROP TABLE t2, t1;
|
|
|
More results from queries before failure can be found in D:\winx64-debug\build\mysql-test\var\1\log\innodb_virtual_fk_restart.log
|
|
|
|
|
Server [mysqld.1 - pid: 4280, winpid: 4280, exit: 65280] failed during test run
|
Server log from this test:
|
----------SERVER LOG START-----------
|
2018-10-18 12:31:45 0 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe (initiated by: root[root] @ localhost [::1]): Normal shutdown
|
2018-10-18 12:31:45 0 [Note] InnoDB: FTS optimize thread exiting.
|
2018-10-18 12:31:45 0 [Note] Event Scheduler: Purging the queue. 0 events
|
2018-10-18 12:31:45 0 [Note] InnoDB: Starting shutdown...
|
2018-10-18 12:31:45 0 [Note] InnoDB: Dumping buffer pool(s) to D:\winx64-debug\build\mysql-test\var\1\mysqld.1\data\ib_buffer_pool
|
2018-10-18 12:31:45 0 [Note] InnoDB: Instance 0, restricted to 128 pages due to innodb_buf_pool_dump_pct=25
|
2018-10-18 12:31:45 0 [Note] InnoDB: Buffer pool(s) dump completed at 181018 12:31:45
|
2018-10-18 12:31:47 0 [Note] InnoDB: Shutdown completed; log sequence number 4968658; transaction id 4552
|
2018-10-18 12:31:47 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
|
2018-10-18 12:31:47 0 [Note] Debug sync points hit: 119222
|
2018-10-18 12:31:47 0 [Note] Debug sync points executed: 9
|
2018-10-18 12:31:47 0 [Note] Debug sync points max active per thread: 1
|
2018-10-18 12:31:47 0 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe: Shutdown complete
|
|
|
2018-10-18 12:31:48 0 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe (mysqld 10.3.11-MariaDB-debug-log) starting as process 6616 ...
|
2018-10-18 12:31:49 0 [Note] Plugin 'SEQUENCE' is disabled.
|
2018-10-18 12:31:49 0 [Note] Plugin 'partition' is disabled.
|
2018-10-18 12:31:49 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2018-10-18 12:31:49 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
|
2018-10-18 12:31:49 0 [Note] InnoDB: Uses event mutexes
|
2018-10-18 12:31:49 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
|
2018-10-18 12:31:49 0 [Note] InnoDB: Number of pools: 1
|
2018-10-18 12:31:49 0 [Note] InnoDB: Using SSE2 crc32 instructions
|
2018-10-18 12:31:49 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
|
2018-10-18 12:31:49 0 [Note] InnoDB: Completed initialization of buffer pool
|
2018-10-18 12:31:49 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
|
2018-10-18 12:31:49 0 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2018-10-18 12:31:49 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2018-10-18 12:31:49 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
|
2018-10-18 12:31:50 0 [Note] InnoDB: Waiting for purge to start
|
2018-10-18 12:31:50 0 [Note] InnoDB: Waiting for purge to start
|
2018-10-18 12:31:50 0 [Note] InnoDB: Waiting for purge to start
|
2018-10-18 12:31:50 0 [Note] InnoDB: Waiting for purge to start
|
2018-10-18 12:31:50 0 [Note] InnoDB: Waiting for purge to start
|
2018-10-18 12:31:50 0 [Note] InnoDB: Waiting for purge to start
|
2018-10-18 12:31:50 0 [Note] InnoDB: Waiting for purge to start
|
2018-10-18 12:31:50 0 [Note] InnoDB: Waiting for purge to start
|
2018-10-18 12:31:50 0 [Note] InnoDB: Waiting for purge to start
|
2018-10-18 12:31:51 0 [Note] InnoDB: 10.3.11 started; log sequence number 4968658; transaction id 4554
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_CMP' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'user_variables' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
|
2018-10-18 12:31:51 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
|
2018-10-18 12:31:51 0 [Warning] D:/winx64-debug/build/sql//Debug/mysqld.exe: unknown option '--loose-pam-debug'
|
2018-10-18 12:31:51 0 [Note] InnoDB: Loading buffer pool(s) from D:\winx64-debug\build\mysql-test\var\1\mysqld.1\data\ib_buffer_pool
|
2018-10-18 12:31:51 0 [Note] InnoDB: Buffer pool(s) load completed at 181018 12:31:51
|
2018-10-18 12:31:51 0 [Note] Server socket created on IP: '::'.
|
2018-10-18 12:31:51 0 [Note] Reading of all Master_info entries succeded
|
2018-10-18 12:31:51 0 [Note] Added new Master_info '' to hash table
|
2018-10-18 12:31:51 0 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe: ready for connections.
|
Version: '10.3.11-MariaDB-debug-log' socket: '' port: 16080 Source distribution
|
Assertion failed: dfield2->type.mtype != 0 || !index->is_committed(), file d:\winx64-debug\build\src\storage\innobase\row\row0row.cc, line 259
|
181018 12:31:51 [ERROR] mysqld got exception 0x80000003 ;
|
This could be because you hit a bug. It is also possible that this binary
|
or one of the libraries it was linked against is corrupt, improperly built,
|
or misconfigured. This error can also be caused by malfunctioning hardware.
|
|
|
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
|
|
|
We will try our best to scrape up some info that will hopefully help
|
diagnose the problem, but since we have already crashed,
|
something is definitely wrong and this may fail.
|
|
|
Server version: 10.3.11-MariaDB-debug-log
|
key_buffer_size=1048576
|
read_buffer_size=131072
|
max_used_connections=1
|
max_threads=65537
|
thread_count=7
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4351 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0xe6167d1bd8
|
Attempting backtrace. You can use the following information to find out
|
where mysqld died. If you see no messages after this, something went
|
terribly wrong...
|
mysqld.exe!my_sigabrt_handler()[my_thr_init.c:485]
|
mysqld.exe!raise()[signal.cpp:516]
|
mysqld.exe!abort()[abort.cpp:71]
|
mysqld.exe!common_assert_to_stderr<wchar_t>()[assert.cpp:149]
|
mysqld.exe!_wassert()[assert.cpp:404]
|
mysqld.exe!row_build_index_entry_low()[row0row.cc:258]
|
mysqld.exe!row_purge_upd_exist_or_extern_func()[row0purge.cc:915]
|
mysqld.exe!row_purge_record_func()[row0purge.cc:1211]
|
mysqld.exe!row_purge()[row0purge.cc:1254]
|
mysqld.exe!row_purge_step()[row0purge.cc:1342]
|
mysqld.exe!que_thr_step()[que0que.cc:1046]
|
mysqld.exe!que_run_threads_low()[que0que.cc:1108]
|
mysqld.exe!que_run_threads()[que0que.cc:1150]
|
mysqld.exe!srv_task_execute()[srv0srv.cc:2455]
|
mysqld.exe!srv_worker_thread()[srv0srv.cc:2502]
|
KERNEL32.DLL!BaseThreadInitThunk()
|
ntdll.dll!RtlUserThreadStart()
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x0):
|
Connection ID (thread ID): 2
|
Status: NOT_KILLED
|
|
|
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
|
The failures were not updated since 2018. I think they might've been resolved due to lots of new fixes.
Anyway, I did run ./mtr -mem --suite=gcol '-do-test=innodb_virtual.*' --parallel=8 --repeat=100 to make sure
I added the debug assertion, to help catch any problems in this area in the future.
The undo log format change would be tracked in MDEV-11657.