[MDEV-13471] Test failure on innodb.log_file_size,4k - Jira

Jan Lindström (Inactive) created issue - 2017-08-08 12:46

Jan Lindström (Inactive) made changes - 2017-08-09 05:40

Field	Original Value	New Value
Status	Open [ 1 ]	In Progress [ 3 ]

Jan Lindström (Inactive) made changes - 2017-08-09 05:41

Fix Version/s		5.5-galera [ 21900 ]
Fix Version/s		10.0-galera [ 21901 ]
Fix Version/s	5.5 [ 15800 ]

Jan Lindström (Inactive) made changes - 2017-08-09 05:41

Affects Version/s		5.5-galera [ 21900 ]
Affects Version/s		10.0-galera [ 21901 ]
Affects Version/s		10.1 [ 16100 ]
Affects Version/s	5.5 [ 15800 ]

Jan Lindström (Inactive) made changes - 2017-08-09 05:41

Affects Version/s

10.2 [ 14601 ]

Jan Lindström (Inactive) made changes - 2017-08-09 05:41

Fix Version/s

10.1 [ 16100 ]

Jan Lindström (Inactive) made changes - 2017-08-09 05:41

Fix Version/s

10.2 [ 14601 ]

Jan Lindström (Inactive) made changes - 2017-08-09 07:08

Priority

Major [ 3 ]

Critical [ 2 ]

Jan Lindström (Inactive) added a comment - 2017-08-09 07:09

https://github.com/MariaDB/server/commit/b4a4e79865399a443abc6a54c809eaf60d460fee

This does not really require Galera knowledge.

Jan Lindström (Inactive) added a comment - 2017-08-09 07:09 https://github.com/MariaDB/server/commit/b4a4e79865399a443abc6a54c809eaf60d460fee This does not really require Galera knowledge.

Jan Lindström (Inactive) made changes - 2017-08-09 07:09

Assignee	Jan Lindström [ jplindst ]	Marko Mäkelä [ marko ]
Status	In Progress [ 3 ]	In Review [ 10002 ]

Marko Mäkelä made changes - 2017-08-10 05:07

Description

WSREP XID is stored trx_sys_header to position 4066-3500 that overlaps rseg undo slots causing following kind of error:

{noformat}
170808 12:51:17 [ERROR] InnoDB: Unable to open undo tablespace './undo30579'.
170808 12:51:17 [ERROR] Plugin 'InnoDB' init function returned error.
170808 12:51:17 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
{noformat}

In debug build this could also cause innodb-alter-tempfile,4k,innodb_plugin:

{noformat}
2017-08-08 12:56:39 7f1f4b3edf40 InnoDB: Assertion failure in thread 139772383125312 in file buf0buf.cc line 2635
InnoDB: Failing assertion: (!((zip_size) & ((zip_size) - 1)))
{noformat}

For reference see:
https://github.com/codership/galera/issues/398

WSREP XID is stored in the TRX_SYS page at innodb_page_size-3500, which overlaps with rseg undo slots, causing the following kind of error:

{noformat}
170808 12:51:17 [ERROR] InnoDB: Unable to open undo tablespace './undo30579'.
170808 12:51:17 [ERROR] Plugin 'InnoDB' init function returned error.
170808 12:51:17 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
{noformat}

In debug build this could also cause innodb-alter-tempfile,4k,innodb_plugin:

{noformat}
2017-08-08 12:56:39 7f1f4b3edf40 InnoDB: Assertion failure in thread 139772383125312 in file buf0buf.cc line 2635
InnoDB: Failing assertion: (!((zip_size) & ((zip_size) - 1)))
{noformat}

For reference see:
https://github.com/codership/galera/issues/398

Marko Mäkelä added a comment - 2017-08-10 06:55

The problem is that with innodb_page_size=4k, the Galera WSREP XID would be written to byte offset 4096-3500, overwriting rollback segment slots in a TRX_SYS page.
The first affected slot would be partly overwritten with a "wsre" tag:

#define TRX_SYS_WSREP_XID_MAGIC_N 0x77737265

In the first affected slot, the least significant 16 bits of TRX_SYS_RSEG_SPACE would be overwritten with 0x7773, and the most significant 16 bits of TRX_SYS_RSEG_PAGE_NO would be overwritten with 0x7265.

The default value of innodb_undo_logs (or innodb_rollback_segments) always was 128 in MariaDB Server 10.x. It might have been possible to avoid this collision when using a non-default smaller value for that parameter. But, by default, Galera would never work with innodb_page_size=4k due to this collision.

Note: In slot 0, we should always have the TRX_SYS_RSEG_SPACE:TRX_SYS_RSEG_PAGE_NO pair 0:6. In slots 1 to 127, if the space_id is 0, the page number would be allocated from the system tablespace. If the database was used for a long time with innodb_undo_logs=1 (or if it was originally created before this parameter was introduced), it is possible that the subsequent rollback segment slots would have very high page numbers.

In slots 1 to 127, if the space_id is not 0, the page number should always be 3, because the page is allocated straight after the undo tablespace creation.

Originally, the undo tablespace ID would always be between 0 and 127. Starting with MySQL 5.6.36 which introduced
Bug #25551311 BACKPORT BUG #23517560 REMOVE SPACE_ID RESTRICTION FOR UNDO TABLESPACES
(merged to MariaDB 10.0.31)
it is possible for an undo tablespace ID to be 0x7773. But in this case, the page number should be 3, not 0x72650003.

This is just the first collision. The WSREP XID data would overwrite subsequent slots.
Because it looks like Galera never really worked with innodb_page_size=4k, we can simply move the WSREP XID data fields to a safe place.

Marko Mäkelä added a comment - 2017-08-10 06:55 The problem is that with innodb_page_size=4k, the Galera WSREP XID would be written to byte offset 4096-3500, overwriting rollback segment slots in a TRX_SYS page. The first affected slot would be partly overwritten with a "wsre" tag: #define TRX_SYS_WSREP_XID_MAGIC_N 0x77737265 In the first affected slot, the least significant 16 bits of TRX_SYS_RSEG_SPACE would be overwritten with 0x7773, and the most significant 16 bits of TRX_SYS_RSEG_PAGE_NO would be overwritten with 0x7265. The default value of innodb_undo_logs (or innodb_rollback_segments) always was 128 in MariaDB Server 10.x. It might have been possible to avoid this collision when using a non-default smaller value for that parameter. But, by default, Galera would never work with innodb_page_size=4k due to this collision. Note: In slot 0, we should always have the TRX_SYS_RSEG_SPACE:TRX_SYS_RSEG_PAGE_NO pair 0:6. In slots 1 to 127, if the space_id is 0, the page number would be allocated from the system tablespace. If the database was used for a long time with innodb_undo_logs=1 (or if it was originally created before this parameter was introduced), it is possible that the subsequent rollback segment slots would have very high page numbers. In slots 1 to 127, if the space_id is not 0, the page number should always be 3, because the page is allocated straight after the undo tablespace creation. Originally, the undo tablespace ID would always be between 0 and 127. Starting with MySQL 5.6.36 which introduced Bug #25551311 BACKPORT BUG #23517560 REMOVE SPACE_ID RESTRICTION FOR UNDO TABLESPACES ( merged to MariaDB 10.0.31 ) it is possible for an undo tablespace ID to be 0x7773. But in this case, the page number should be 3, not 0x72650003. This is just the first collision. The WSREP XID data would overwrite subsequent slots. Because it looks like Galera never really worked with innodb_page_size=4k, we can simply move the WSREP XID data fields to a safe place.

Marko Mäkelä added a comment - 2017-08-10 07:10

Please simplify the patch. We do not need to deal with 2 locations of the WSREP XID information when using innodb_page_size=4k.

Marko Mäkelä added a comment - 2017-08-10 07:10 Please simplify the patch. We do not need to deal with 2 locations of the WSREP XID information when using innodb_page_size=4k.

Marko Mäkelä made changes - 2017-08-10 07:10

Assignee	Marko Mäkelä [ marko ]	Jan Lindström [ jplindst ]
Status	In Review [ 10002 ]	Stalled [ 10000 ]

Jan Lindström (Inactive) made changes - 2017-08-10 08:38

Affects Version/s

5.5-galera [ 21900 ]

Jan Lindström (Inactive) made changes - 2017-08-10 08:38

Fix Version/s

5.5-galera [ 21900 ]

Jan Lindström (Inactive) added a comment - 2017-08-10 08:39

5.5-galera not effected.

Jan Lindström (Inactive) added a comment - 2017-08-10 08:39 5.5-galera not effected.

Elena Stepanova made changes - 2017-08-18 09:37

Comment

[ Is this buildbot failure related, or should it be filed separately?
http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/4856/steps/test/logs/stdio
{noformat}
innodb.log_file_size '4k,innodb' w1 [ fail ] Found warnings/errors in server log file!
        Test ended at 2017-08-15 11:46:41
line
170815 11:45:43 [ERROR] mysqld got exception 0xc0000005 ;

Attempting backtrace. You can use the following information to find out

^ Found warnings in D:/winx64-debug/build/mysql-test/var/1/log/mysqld.1.err
ok

- saving 'D:/winx64-debug/build/mysql-test/var/1/log/innodb.log_file_size-4k,innodb/' to 'D:/winx64-debug/build/mysql-test/var/log/innodb.log_file_size-4k,innodb/'
- found 'mysqld.dmp' (0/5)

Trying 'cdb' to get a backtrace
Output from cdb follows. Faulting thread is printed twice,with and without function parameters
Search for STACK_TEXT to see the stack trace of
the faulting thread. Callstacks of other threads are printed after it.

Microsoft (R) Windows Debugger Version 10.0.10586.567 AMD64
Copyright (c) Microsoft Corporation. All rights reserved.

Loading Dump File [D:\winx64-debug\build\mysql-test\var\log\innodb.log_file_size-4k,innodb\mysqld.1\data\mysqld.dmp]
User Mini Dump File: Only registers, stack and portions of memory are available

Response Time (ms) Location
OK .

Response Time (ms) Location
OK .
Deferred cache*C:\cdb_symbols
Symbol search path is: .;cache*C:\cdb_symbols
Executable search path is: .
Windows 8.1 Version 9600 MP (4 procs) Free x64
Product: Server, suite: TerminalServer DataCenter SingleUserTS
Built by: 6.3.9600.18217 (winblue_ltsb.160124-0053)
Machine Name:
Debug session time: Tue Aug 15 11:45:48.000 2017 (UTC + 0:00)
System Uptime: not available
Process Uptime: 0 days 0:00:14.000
.............................
This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(1138.89c): Access violation - code c0000005 (first/second chance not available)
ntdll!ZwGetContextThread:
             ret
0:001> cdb: Reading initial command '!sym prompts off; !analyze -v; .ecxr; !for_each_frame dv /t;!uniqstack -p;q'
quiet mode - symbol prompts off

Module name Error
KERNELBASE PDB not found : .\symbols\dll\kernelbase.pdb
                       PDB not found : cache*c:\cdb_symbols

You can troubleshoot most symbol related issues by turning on symbol loading diagnostics (!sym noisy) and repeating the command that caused symbols to be loaded.
You should also verify that your symbol search path (.sympath) is correct.

DUMP_CLASS: 2

DUMP_QUALIFIER: 400

CONTEXT: (.ecxr)
rax=0000000000000000 rbx=00007ff6475d1718 rcx=00000000fffffffc
rdx=0000000000000208 rsi=0000000000000208 rdi=0000000000000000
rip=00007ffab045dd8e rsp=0000005fb4aaef80 rbp=00007ff643f6a000
r8=ffffffffffffffff r9=00007ff643f6a000 r10=0000000000000000
r11=0000000000000246 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl nz ac pe cy
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010213
ntdll!RtlLockHeap:
         inc dword ptr [rax+24h] ds:00000000`00000024=????????
Resetting default scope

FAULTING_IP:
ntdll!RtlLockHeap+13e
         inc dword ptr [rax+24h]

EXCEPTION_RECORD: (.exr -1)
ExceptionAddress: 00007ffab045dd8e (ntdll!RtlLockHeap)
   ExceptionCode: c0000005 (Access violation)
  ExceptionFlags: 00000000
NumberParameters: 2
   Parameter[0]: 0000000000000001
   Parameter[1]: 0000000000000024
Attempt to write to address 0000000000000024

BUGCHECK_STR: 59153753

WRONG_SYMBOLS_TIMESTAMP: 59153753

WRONG_SYMBOLS_SIZE: 1ad000

FAULTING_MODULE: 00007ffab0420000 ntdll

DEBUG_FLR_IMAGE_TIMESTAMP: 59153753

ADDITIONAL_DEBUG_TEXT:
You can run '.symfix; .reload' to try to fix the symbol path and load symbols. ; Followup set based on attribute [Is_ChosenCrashFollowupThread] from Frame:[0] on thread:[PSEUDO_THREAD]

LAST_CONTROL_TRANSFER: from 0000000000000000 to 0000000000000000

ANALYSIS_SESSION_HOST: MARIADB-02

ANALYSIS_SESSION_TIME: 08-15-2017 11:46:42.0086

ANALYSIS_VERSION: 10.0.10586.567 amd64fre

STACK_TEXT:
wrong_symbols!WRONG_SYMBOLS

STACK_COMMAND: .ecxr ; kb ; ** Pseudo Context ** ; kb

THREAD_SHA1_HASH_MOD_FUNC: 8b50e467776d7660ec74f0fcf6059a449f38bc9a

THREAD_SHA1_HASH_MOD_FUNC_OFFSET: 386be9b62a7535c96acfda43762924bd7c0bcb71

THREAD_SHA1_HASH_MOD: 1c9266d4d33f329668e953be351439450e48d114

SYMBOL_STACK_INDEX: 0

FOLLOWUP_NAME: MachineOwner

EXCEPTION_CODE: (NTSTATUS) 0x59153753 - <Unable to get error code text>

EXCEPTION_CODE_STR: 59153753

FAILURE_EXCEPTION_CODE: 59153753

EXCEPTION_STR: PRIVATE_SYMBOLS

PROCESS_NAME: ntdll.wrong.symbols.dll

IMAGE_NAME: ntdll.wrong.symbols.dll

MODULE_NAME: ntdll_wrong_symbols

SYMBOL_NAME: ntdll_wrong_symbols!591537531AD000

BUCKET_ID: PRIVATE_SYMBOLS_X64_6.3.9600.17415_(winblue_r4.141028-1500)_TIMESTAMP_170512-041723

DEFAULT_BUCKET_ID: PRIVATE_SYMBOLS_X64_6.3.9600.17415_(winblue_r4.141028-1500)_TIMESTAMP_170512-041723

PRIMARY_PROBLEM_CLASS: PRIVATE_SYMBOLS

BUCKET_ID_OFFSET: 0

BUCKET_ID_MODULE_STR: ntdll_wrong_symbols

BUCKET_ID_MODVER_STR:

BUCKET_ID_PREFIX_STR: PRIVATE_SYMBOLS_X64_6.3.9600.17415_(winblue_r4.141028-1500)_TIMESTAMP_170512-041723

FAILURE_PROBLEM_CLASS: PRIVATE_SYMBOLS_X64_6.3.9600.17415_(winblue_r4.141028-1500)_TIMESTAMP_170512-041723

FAILURE_IMAGE_NAME: ntdll.wrong.symbols.dll

FAILURE_FUNCTION_NAME: 591537531AD000

BUCKET_ID_FUNCTION_STR: 591537531AD000

FAILURE_SYMBOL_NAME: ntdll.wrong.symbols.dll!591537531AD000

FAILURE_BUCKET_ID: PRIVATE_SYMBOLS_X64_6.3.9600.17415_(winblue_r4.141028-1500)_TIMESTAMP_170512-041723_59153753_ntdll.wrong.symbols.dll!591537531AD000

TARGET_TIME: 2017-08-15T11:45:48.000Z

OSBUILD: 9600

OSSERVICEPACK: 17415

SERVICEPACK_NUMBER: 0

OS_REVISION: 0

SUITE_MASK: 400

PRODUCT_TYPE: 3

OSPLATFORM_TYPE: x64

OSNAME: Windows 8.1

OSEDITION: Windows 8.1 Server TerminalServer DataCenter SingleUserTS

OS_LOCALE:

USER_LCID: 0

OSBUILD_TIMESTAMP: 2014-10-29 02:45:30

BUILDDATESTAMP_STR: 141028-1500

BUILDLAB_STR: winblue_r4

BUILDOSVER_STR: 6.3.9600.17415

ANALYSIS_SESSION_ELAPSED_TIME: 5bc

ANALYSIS_SOURCE: UM

FAILURE_ID_HASH_STRING: um:private_symbols_x64_6.3.9600.17415_(winblue_r4.141028-1500)_timestamp_170512-041723_59153753_ntdll.wrong.symbols.dll!591537531ad000

FAILURE_ID_HASH: {27595ce3-e414-f8be-5eee-ae574cd7b2ea}

Followup: MachineOwner
---------

rax=0000000000000000 rbx=00007ff6475d1718 rcx=00000000fffffffc
rdx=0000000000000208 rsi=0000000000000208 rdi=0000000000000000
rip=00007ffab045dd8e rsp=0000005fb4aaef80 rbp=00007ff643f6a000
r8=ffffffffffffffff r9=00007ff643f6a000 r10=0000000000000000
r11=0000000000000246 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl nz ac pe cy
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010213
ntdll!RtlLockHeap:
         inc dword ptr [rax+24h] ds:00000000`00000024=????????
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
ntdll!RtlLockHeap
Unable to enumerate locals, Win32 error 0n318
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
ntdll!RtlEnterCriticalSection
Unable to enumerate locals, Win32 error 0n318
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
mysqld!inline_mysql_mutex_lock [d:\winx64-debug\build\src\include\mysql\psi\mysql_thread.h @ 683]
struct st_mysql_mutex * that = 0x00007ff6`475d1718
char * src_file = 0x00007ff6`45b50f70 "D:\winx64-debug\build\src\sql\sql_class.cc"
unsigned int src_line = 0xed5
int result = 0n-858993460
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
mysqld!Statement_map::~Statement_map [d:\winx64-debug\build\src\sql\sql_class.cc @ 3798]
class Statement_map * this = 0x0000005f`b9748488
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
mysqld!THD::~THD [d:\winx64-debug\build\src\sql\sql_class.cc @ 1638]
class THD * this = 0x0000005f`b97473f8
struct _db_stack_frame_ _db_stack_frame_ = struct _db_stack_frame_
class THD * orig_thd = 0x0000005f`b97473f8
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
mysqld!THD::`scalar deleting destructor'
class THD * this = 0x0000005f`b97473f8
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
mysqld!threadpool_remove_connection [d:\winx64-debug\build\src\sql\threadpool_common.cc @ 302]
class THD * thd = 0x0000005f`b97473f8
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
mysqld!tp_callback [d:\winx64-debug\build\src\sql\threadpool_common.cc @ 218]
struct TP_connection * c = 0x0000005f`b926a130
struct Worker_thread_context worker_context = struct Worker_thread_context
class THD * thd = 0x0000005f`b97473f8
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
mysqld!tp_callback [d:\winx64-debug\build\src\sql\threadpool_win.cc @ 378]
struct _TP_CALLBACK_INSTANCE * instance = 0x0000005f`b4aaf568
void * context = 0x0000005f`b926a130
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
mysqld!work_callback [d:\winx64-debug\build\src\sql\threadpool_win.cc @ 452]
struct _TP_CALLBACK_INSTANCE * instance = 0x0000005f`b4aaf568
void * context = 0x0000005f`b926a130
struct _TP_WORK * work = 0x0000005f`b9735ea0
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
ntdll!RtlFreeUnicodeString
Unable to enumerate locals, Win32 error 0n318
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
ntdll!RtlFreeUnicodeString
Unable to enumerate locals, Win32 error 0n318
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
kernel32!BaseThreadInitThunk
Unable to enumerate locals, HRESULT 0x80004005
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
ntdll!RtlUserThreadStart
Unable to enumerate locals, Win32 error 0n318
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
ntdll!RtlLockHeap
Processing 2 threads, please wait

. 0 Id: 1138.128c Suspend: 0 Teb: 00007ff6`4409e000 Unfrozen
      Priority: 0 Priority class: 32

mysqld!__crt_stdio_output::output_processor<wchar_t,__crt_stdio_output::stream_output_adapter<wchar_t>,__crt_stdio_output::standard_base<wchar_t,__crt_stdio_output::stream_output_adapter<wchar_t> > >::type_case_integer(unsigned int radix = 0xa, bool capital_hexits = false) [d:\th\minkernel\crts\ucrt\inc\corecrt_internal_stdio_output.h @ 2451]
(Inline Function) --------`-------- mysqld!__crt_stdio_output::output_processor<wchar_t,__crt_stdio_output::stream_output_adapter<wchar_t>,__crt_stdio_output::standard_base<wchar_t,__crt_stdio_output::stream_output_adapter<wchar_t> > >::type_case_d [d:\th\minkernel\crts\ucrt\inc\corecrt_internal_stdio_output.h @ 2402]
mysqld!__crt_stdio_output::output_processor<wchar_t,__crt_stdio_output::stream_output_adapter<wchar_t>,__crt_stdio_output::standard_base<wchar_t,__crt_stdio_output::stream_output_adapter<wchar_t> > >::state_case_type(void) [d:\th\minkernel\crts\ucrt\inc\corecrt_internal_stdio_output.h @ 2013]
mysqld!__crt_stdio_output::output_processor<wchar_t,__crt_stdio_output::stream_output_adapter<wchar_t>,__crt_stdio_output::standard_base<wchar_t,__crt_stdio_output::stream_output_adapter<wchar_t> > >::process(void) [d:\th\minkernel\crts\ucrt\inc\corecrt_internal_stdio_output.h @ 1644]
mysqld!<lambda_dd75445284c072d0bd3768540cc698fa>::operator()(void) [d:\th\minkernel\crts\ucrt\src\appcrt\stdio\output.cpp @ 46]
mysqld!__crt_seh_guarded_call<int>::operator()<<lambda_7b91131dde12e1c3dfc74ff76b3f2eac>,<lambda_dd75445284c072d0bd3768540cc698fa> & __ptr64,<lambda_16bc4ecb55b4718497c16bceaea2ceaf> >(class __acrt_lock_stream_and_call::__l3::<lambda_7b91131dde12e1c3dfc74ff76b3f2eac> * setup = 0xcccccccc`cccccccc, class common_vfprintf::__l11::<lambda_dd75445284c072d0bd3768540cc698fa> * action = 0x0000005f`b481ed28, class __acrt_lock_stream_and_call::__l4::<lambda_16bc4ecb55b4718497c16bceaea2ceaf> * cleanup = 0x0000005f`b481ed18) [d:\th\minkernel\crts\ucrt\devdiv\vcruntime\inc\internal_shared.h @ 199]
(Inline Function) --------`-------- mysqld!__acrt_lock_stream_and_call [d:\th\minkernel\crts\ucrt\inc\corecrt_internal_stdio.h @ 255]
(Inline Function) --------`-------- mysqld!common_vfprintf [d:\th\minkernel\crts\ucrt\src\appcrt\stdio\output.cpp @ 35]
mysqld!__stdio_common_vfwprintf(unsigned int64 options = <Value unavailable error>, struct _iobuf * stream = <Value unavailable error>, wchar_t * format = <Value unavailable error>, struct __crt_locale_pointers * locale = <Value unavailable error>, char * arglist = 0x0000005f`b481edc0 "0???") [d:\th\minkernel\crts\ucrt\src\appcrt\stdio\output.cpp @ 70]
(Inline Function) --------`-------- mysqld!_vfwprintf_l [d:\th\minkernel\crts\ucrt\inc\corecrt_wstdio.h @ 304]
mysqld!fwprintf(struct _iobuf * _Stream = 0x00007ff6`475b5fa0, wchar_t * _Format = 0x00007ff6`470cc7e0 "Assertion failed: %Ts, file %Ts, line %d.") [d:\th\minkernel\crts\ucrt\inc\corecrt_wstdio.h @ 503]
mysqld!common_assert_to_stderr<wchar_t>(wchar_t * expression = 0x00007ff6`45d29730 "global_status_var.global_memory_used == 0", wchar_t * file_name = 0x00007ff6`45d296e0 "D:\winx64-debug\build\src\sql\mysqld.cc", unsigned int line_number = 0x875) [d:\th\minkernel\crts\ucrt\src\appcrt\startup\assert.cpp @ 148]
(Inline Function) --------`-------- mysqld!common_assert [d:\th\minkernel\crts\ucrt\src\appcrt\startup\assert.cpp @ 383]
mysqld!_wassert(wchar_t * expression = 0x00007ff6`45d29730 "global_status_var.global_memory_used == 0", wchar_t * file_name = 0x00007ff6`45d296e0 "D:\winx64-debug\build\src\sql\mysqld.cc", unsigned int line_number = 0x875) [d:\th\minkernel\crts\ucrt\src\appcrt\startup\assert.cpp @ 404]
mysqld!mysqld_exit(int exit_code = 0n0) [d:\winx64-debug\build\src\sql\mysqld.cc @ 2165]
mysqld!win_main(int argc = 0n148, char ** argv = 0x0000005f`b48d21b8) [d:\winx64-debug\build\src\sql\mysqld.cc @ 6081]
mysqld!mysql_service(void * p = 0x00000000`00000000) [d:\winx64-debug\build\src\sql\mysqld.cc @ 6103]
mysqld!mysqld_main(int argc = 0n25, char ** argv = 0x0000005f`b48c1fc0) [d:\winx64-debug\build\src\sql\mysqld.cc @ 6296]
mysqld!main(int argc = 0n25, char ** argv = 0x0000005f`b48c1fc0) [d:\winx64-debug\build\src\sql\main.cc @ 26]
(Inline Function) --------`-------- mysqld!invoke_main [f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl @ 64]
mysqld!__scrt_common_main_seh(void) [f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl @ 259]
kernel32!BaseThreadInitThunk
ntdll!RtlUserThreadStart

. 1 Id: 1138.89c Suspend: 0 Teb: 00007ff6`43f6a000 Unfrozen
      Priority: 0 Priority class: 32

ntdll!ZwGetContextThread

Total threads: 2
quit:
{noformat} ]

Marko Mäkelä made changes - 2017-08-18 09:37

Comment

[ [~elenst], if you look at the [server error log|http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/4856/steps/test/logs/mysqld.1.err.1] corresponding to the crash, it probably is a duplicate of the known problem: a memory leak somewhere.
{noformat}
Assertion failed: global_status_var.global_memory_used == 0, file D:\winx64-debug\build\src\sql\mysqld.cc, line Minidump written to D:\winx64-debug\build\mysql-test\var\1\mysqld.1\data\mysqld.dmp
{noformat}
The open issues ~~MDEV-11208~~ and MDEV-12445 seem to be exactly about this.

As far as I can tell, InnoDB refused to start up. In 10.2 there should be no InnoDB shutdown problem after that.
{noformat}
2017-08-15 11:45:40 4748 [Note] InnoDB: Trx id counter is 10240
2017-08-15 11:45:40 4748 [Note] InnoDB: Starting final batch to recover 1 pages from redo log.
2017-08-15 11:45:41 4748 [Note] InnoDB: Resizing redo log from 3*5242880 to 2*5242880 bytes; LSN=2743701
2017-08-15 11:45:41 4748 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[2380] with error Generic error
2017-08-15 11:45:41 4748 [Note] InnoDB: Starting shutdown...
2017-08-15 11:45:41 4748 [ERROR] Plugin 'InnoDB' init function returned error.
2017-08-15 11:45:41 4748 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
{noformat}
This may look suspicious at the first sight, but the failure is due to debug instrumentation in the test:
{code:SQL}
--let $restart_parameters= --debug=d,innodb_log_abort_3
--source include/restart_mysqld.inc
--error ER_UNKNOWN_STORAGE_ENGINE
SELECT * FROM t1;
{code}
So, InnoDB is definitely not to blame here. ]

Jan Lindström (Inactive) made changes - 2017-08-18 09:37

Comment

[ Does not look same is that even InnoDB related ? ]

Jan Lindström (Inactive) added a comment - 2017-08-22 11:10

10.0.32-galera:

commit 391b1af0fbb9723ce768d0b06830865fa983a8dd

Author: Jan Lindström <jan.lindstrom@mariadb.com>

Date:   Thu Aug 10 13:09:27 2017 +0300

    MDEV-13471: Test failure on innodb.log_file_size,4k

    Problem was that 4k page size is not really supported in

    Galera. For reference see:

            codership/galera#398

    Page size 4k is problematic because WSREP XID info location

    that was set to constant UNIV_PAGE_SIZE - 3500 and that is conflicting

    with rseg undo slots location if there is lot of undo tablespaces.

    Undo tablespace identifiers and page numbers require

    at least 126*8=1024 bytes starting from offset 56. Therefore,

    WSREP XID startig from offset 596 would overwrite several

    space_id,page_no pairs starting from 72th undo log tablespace

    space_id,page_no pair at offset 594.

    This will cause InnoDB startup failure seen as

    [ERROR] InnoDB: Unable to open undo tablespace './undo30579'.

    Originally, the undo tablespace ID would always be between

    0 and 127. Starting with MySQL 5.6.36 which introduced

    Bug #25551311 BACKPORT BUG #23517560 REMOVE SPACE_ID RESTRICTION

    FOR UNDO TABLESPACES (merged to MariaDB 10.0.31)

    it is possible for an undo tablespace ID to be 0x7773. But in

    this case, the page number should be 3, not 0x72650003.

    This is just the first collision. The WSREP XID data would

    overwrite subsequent slots.

    trx0sys.h

    trx0sys.cc

            Code formatting and add comments.

Jan Lindström (Inactive) added a comment - 2017-08-22 11:10 10.0.32-galera: commit 391b1af0fbb9723ce768d0b06830865fa983a8dd Author: Jan Lindström <jan.lindstrom@mariadb.com> Date: Thu Aug 10 13:09:27 2017 +0300 MDEV-13471: Test failure on innodb.log_file_size,4k Problem was that 4k page size is not really supported in Galera. For reference see: codership/galera#398 Page size 4k is problematic because WSREP XID info location that was set to constant UNIV_PAGE_SIZE - 3500 and that is conflicting with rseg undo slots location if there is lot of undo tablespaces. Undo tablespace identifiers and page numbers require at least 126*8=1024 bytes starting from offset 56. Therefore, WSREP XID startig from offset 596 would overwrite several space_id,page_no pairs starting from 72th undo log tablespace space_id,page_no pair at offset 594. This will cause InnoDB startup failure seen as [ERROR] InnoDB: Unable to open undo tablespace './undo30579'. Originally, the undo tablespace ID would always be between 0 and 127. Starting with MySQL 5.6.36 which introduced Bug #25551311 BACKPORT BUG #23517560 REMOVE SPACE_ID RESTRICTION FOR UNDO TABLESPACES (merged to MariaDB 10.0.31) it is possible for an undo tablespace ID to be 0x7773. But in this case, the page number should be 3, not 0x72650003. This is just the first collision. The WSREP XID data would overwrite subsequent slots. trx0sys.h trx0sys.cc Code formatting and add comments.

Marko Mäkelä made changes - 2017-08-31 15:36

Fix Version/s		10.1.27 [ 22609 ]
Fix Version/s		10.2.9 [ 22611 ]
Fix Version/s		10.3.2 [ 22533 ]
Fix Version/s		10.0.32-galera [ 22538 ]
Fix Version/s	10.2 [ 14601 ]
Fix Version/s	10.1 [ 16100 ]
Fix Version/s	10.0-galera [ 21901 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2021-05-13 15:30

Affects Version/s

10.0-galera [ 21901 ]

Sergei Golubchik made changes - 2021-12-06 21:45

Workflow

MariaDB v3 [ 81947 ]

MariaDB v4 [ 152580 ]

MariaDB Server

Test failure on innodb.log_file_size,4k

Details

Description

Attachments

Activity

People

Dates

Git Integration