Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.5.2
-
None
Description
Workflow of RQG test
|
|
1. Create DB server and start it
|
2. One session starts to run some SQL stream against this server
|
3. At some point of time and not related to the state (waiting for result, sending statement, ...) of the ongoing 2. the server process gets killed (KILL and not TERM).
|
4. Make some copy of the data content+logs etc. of the killed server.
|
5. Try to restart the killed server.
|
|
5. fails with
|
2020-03-31 16:17:25 0 [Note] /home/mleich/10.5/bld_debug/sql/mysqld (mysqld 10.5.2-MariaDB-debug-log) starting as process 111337 ...
|
...
|
2020-03-31 16:17:25 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=174187931
|
2020-03-31 16:17:25 0 [ERROR] InnoDB: Malformed log record; set innodb_force_recovery=1 to ignore.
|
2020-03-31 16:17:25 0 [Note] InnoDB: Dump from the start of the mini-transaction (LSN=173906840) to 100 bytes after the record:
|
<some data>
|
2020-03-31 16:17:27 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1537] with error Generic error
|
...
|
2020-03-31 16:17:27 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
|
|
RQG
|
git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich1
|
origin/experimental d417497b476e263428422b4640cf63b8e9d16afe 2020-03-30T17:17:54+02:00
|
|
MariaDB
|
origin/10.5 718f18599a9bcf1e7c2d3f18416fca4f7124d00d 2020-03-26T16:05:25+02:00
|
build with debug
|
|
perl rqg.pl \
|
--duration=120 \
|
--queries=10000000 \
|
--threads=1 \
|
--no_mask \
|
--seed=random \
|
--gendata=conf/engines/many_indexes.zz \
|
--rpl_mode=none \
|
--engine=InnoDB \
|
--mysqld=--innodb_stats_persistent=off \
|
--mysqld=--lock-wait-timeout=86400 \
|
--mysqld=--log-output=none \
|
--mysqld=--slave_net_timeout=60 \
|
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
|
--mysqld=--loose-table_lock_wait_timeout=50 \
|
--mysqld=--net_write_timeout=60 \
|
--mysqld=--connect_timeout=60 \
|
--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
|
--mysqld=--log_bin_trust_function_creators=1 \
|
--mysqld=--loose-idle_transaction_timeout=0 \
|
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
|
--mysqld=--interactive_timeout=28800 \
|
--mysqld=--innodb_page_size=32K \
|
--mysqld=--wait_timeout=28800 \
|
--mysqld=--innodb-lock-wait-timeout=50 \
|
--mysqld=--loose-idle_write_transaction_timeout=0 \
|
--mysqld=--loose_innodb_use_native_aio=1 \
|
--mysqld=--log-bin \
|
--mysqld=--net_read_timeout=30 \
|
--reporters=CrashRecovery1,Deadlock1,ErrorLog,None,ServerDead \
|
--validators=None \
|
--grammar=c00000.yy \
|
--workdir=<local settings> \
|
--vardir=<local settings> \
|
--mtr-build-thread=<local settings> \
|
--basedir1=<path to MariaDB binaries> \
|
--script_debug=_nix
|
There might be several replay attempts required.
|
Attachments
Issue Links
- is caused by
-
MDEV-12353 Efficient InnoDB redo log record format
-
- Closed
-
Activity
Field | Original Value | New Value |
---|---|---|
Description |
{noformat}
Workflow of RQG test 1. Create DB server and start it 2. One session starts to run some SQL stream against this server 3. At some point of time and not related to the state (waiting for result, sending statement, ...) of the ongoing 2. the server process gets killed (KILL and not TERM). 4. Make some copy of the data content+logs etc. of the killed server. 5. Try to restart the killed server. 5. fails with 2020-03-31 16:17:25 0 [Note] /home/mleich/10.5/bld_debug/sql/mysqld (mysqld 10.5.2-MariaDB-debug-log) starting as process 111337 ... ... 2020-03-31 16:17:25 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=174187931 2020-03-31 16:17:25 0 [ERROR] InnoDB: Malformed log record; set innodb_force_recovery=1 to ignore. 2020-03-31 16:17:25 0 [Note] InnoDB: Dump from the start of the mini-transaction (LSN=173906840) to 100 bytes after the record: <some data> 2020-03-31 16:17:27 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1537] with error Generic error ... 2020-03-31 16:17:27 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. RQG git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich1 origin/experimental d417497b476e263428422b4640cf63b8e9d16afe 2020-03-30T17:17:54+02:00 MariaDB origin/10.5 718f18599a9bcf1e7c2d3f18416fca4f7124d00d 2020-03-26T16:05:25+02:00 build with debug {noformat} |
{noformat}
Workflow of RQG test 1. Create DB server and start it 2. One session starts to run some SQL stream against this server 3. At some point of time and not related to the state (waiting for result, sending statement, ...) of the ongoing 2. the server process gets killed (KILL and not TERM). 4. Make some copy of the data content+logs etc. of the killed server. 5. Try to restart the killed server. 5. fails with 2020-03-31 16:17:25 0 [Note] /home/mleich/10.5/bld_debug/sql/mysqld (mysqld 10.5.2-MariaDB-debug-log) starting as process 111337 ... ... 2020-03-31 16:17:25 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=174187931 2020-03-31 16:17:25 0 [ERROR] InnoDB: Malformed log record; set innodb_force_recovery=1 to ignore. 2020-03-31 16:17:25 0 [Note] InnoDB: Dump from the start of the mini-transaction (LSN=173906840) to 100 bytes after the record: <some data> 2020-03-31 16:17:27 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1537] with error Generic error ... 2020-03-31 16:17:27 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. RQG git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich1 origin/experimental d417497b476e263428422b4640cf63b8e9d16afe 2020-03-30T17:17:54+02:00 MariaDB origin/10.5 718f18599a9bcf1e7c2d3f18416fca4f7124d00d 2020-03-26T16:05:25+02:00 build with debug perl rqg.pl \ --duration=120 \ --queries=10000000 \ --threads=1 \ --no_mask \ --seed=random \ --gendata=conf/engines/many_indexes.zz \ --rpl_mode=none \ --engine=InnoDB \ --mysqld=--innodb_stats_persistent=off \ --mysqld=--lock-wait-timeout=86400 \ --mysqld=--log-output=none \ --mysqld=--slave_net_timeout=60 \ --mysqld=--loose-debug_assert_on_not_freed_memory=0 \ --mysqld=--loose-table_lock_wait_timeout=50 \ --mysqld=--net_write_timeout=60 \ --mysqld=--connect_timeout=60 \ --mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \ --mysqld=--log_bin_trust_function_creators=1 \ --mysqld=--loose-idle_transaction_timeout=0 \ --mysqld=--loose-idle_readonly_transaction_timeout=0 \ --mysqld=--interactive_timeout=28800 \ --mysqld=--innodb_page_size=32K \ --mysqld=--wait_timeout=28800 \ --mysqld=--innodb-lock-wait-timeout=50 \ --mysqld=--loose-idle_write_transaction_timeout=0 \ --mysqld=--loose_innodb_use_native_aio=1 \ --mysqld=--log-bin \ --mysqld=--net_read_timeout=30 \ --reporters=CrashRecovery1,Deadlock1,ErrorLog,None,ServerDead \ --validators=None \ --grammar=c00000.yy \ --workdir=<local settings> \ --vardir=<local settings> \ --mtr-build-thread=764 \ --basedir1=<path to MariaDB binaries> \ --script_debug=_nix {noformat} |
Attachment | c00000.yy [ 51047 ] |
Description |
{noformat}
Workflow of RQG test 1. Create DB server and start it 2. One session starts to run some SQL stream against this server 3. At some point of time and not related to the state (waiting for result, sending statement, ...) of the ongoing 2. the server process gets killed (KILL and not TERM). 4. Make some copy of the data content+logs etc. of the killed server. 5. Try to restart the killed server. 5. fails with 2020-03-31 16:17:25 0 [Note] /home/mleich/10.5/bld_debug/sql/mysqld (mysqld 10.5.2-MariaDB-debug-log) starting as process 111337 ... ... 2020-03-31 16:17:25 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=174187931 2020-03-31 16:17:25 0 [ERROR] InnoDB: Malformed log record; set innodb_force_recovery=1 to ignore. 2020-03-31 16:17:25 0 [Note] InnoDB: Dump from the start of the mini-transaction (LSN=173906840) to 100 bytes after the record: <some data> 2020-03-31 16:17:27 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1537] with error Generic error ... 2020-03-31 16:17:27 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. RQG git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich1 origin/experimental d417497b476e263428422b4640cf63b8e9d16afe 2020-03-30T17:17:54+02:00 MariaDB origin/10.5 718f18599a9bcf1e7c2d3f18416fca4f7124d00d 2020-03-26T16:05:25+02:00 build with debug perl rqg.pl \ --duration=120 \ --queries=10000000 \ --threads=1 \ --no_mask \ --seed=random \ --gendata=conf/engines/many_indexes.zz \ --rpl_mode=none \ --engine=InnoDB \ --mysqld=--innodb_stats_persistent=off \ --mysqld=--lock-wait-timeout=86400 \ --mysqld=--log-output=none \ --mysqld=--slave_net_timeout=60 \ --mysqld=--loose-debug_assert_on_not_freed_memory=0 \ --mysqld=--loose-table_lock_wait_timeout=50 \ --mysqld=--net_write_timeout=60 \ --mysqld=--connect_timeout=60 \ --mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \ --mysqld=--log_bin_trust_function_creators=1 \ --mysqld=--loose-idle_transaction_timeout=0 \ --mysqld=--loose-idle_readonly_transaction_timeout=0 \ --mysqld=--interactive_timeout=28800 \ --mysqld=--innodb_page_size=32K \ --mysqld=--wait_timeout=28800 \ --mysqld=--innodb-lock-wait-timeout=50 \ --mysqld=--loose-idle_write_transaction_timeout=0 \ --mysqld=--loose_innodb_use_native_aio=1 \ --mysqld=--log-bin \ --mysqld=--net_read_timeout=30 \ --reporters=CrashRecovery1,Deadlock1,ErrorLog,None,ServerDead \ --validators=None \ --grammar=c00000.yy \ --workdir=<local settings> \ --vardir=<local settings> \ --mtr-build-thread=764 \ --basedir1=<path to MariaDB binaries> \ --script_debug=_nix {noformat} |
{noformat}
Workflow of RQG test 1. Create DB server and start it 2. One session starts to run some SQL stream against this server 3. At some point of time and not related to the state (waiting for result, sending statement, ...) of the ongoing 2. the server process gets killed (KILL and not TERM). 4. Make some copy of the data content+logs etc. of the killed server. 5. Try to restart the killed server. 5. fails with 2020-03-31 16:17:25 0 [Note] /home/mleich/10.5/bld_debug/sql/mysqld (mysqld 10.5.2-MariaDB-debug-log) starting as process 111337 ... ... 2020-03-31 16:17:25 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=174187931 2020-03-31 16:17:25 0 [ERROR] InnoDB: Malformed log record; set innodb_force_recovery=1 to ignore. 2020-03-31 16:17:25 0 [Note] InnoDB: Dump from the start of the mini-transaction (LSN=173906840) to 100 bytes after the record: <some data> 2020-03-31 16:17:27 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1537] with error Generic error ... 2020-03-31 16:17:27 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. RQG git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich1 origin/experimental d417497b476e263428422b4640cf63b8e9d16afe 2020-03-30T17:17:54+02:00 MariaDB origin/10.5 718f18599a9bcf1e7c2d3f18416fca4f7124d00d 2020-03-26T16:05:25+02:00 build with debug perl rqg.pl \ --duration=120 \ --queries=10000000 \ --threads=1 \ --no_mask \ --seed=random \ --gendata=conf/engines/many_indexes.zz \ --rpl_mode=none \ --engine=InnoDB \ --mysqld=--innodb_stats_persistent=off \ --mysqld=--lock-wait-timeout=86400 \ --mysqld=--log-output=none \ --mysqld=--slave_net_timeout=60 \ --mysqld=--loose-debug_assert_on_not_freed_memory=0 \ --mysqld=--loose-table_lock_wait_timeout=50 \ --mysqld=--net_write_timeout=60 \ --mysqld=--connect_timeout=60 \ --mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \ --mysqld=--log_bin_trust_function_creators=1 \ --mysqld=--loose-idle_transaction_timeout=0 \ --mysqld=--loose-idle_readonly_transaction_timeout=0 \ --mysqld=--interactive_timeout=28800 \ --mysqld=--innodb_page_size=32K \ --mysqld=--wait_timeout=28800 \ --mysqld=--innodb-lock-wait-timeout=50 \ --mysqld=--loose-idle_write_transaction_timeout=0 \ --mysqld=--loose_innodb_use_native_aio=1 \ --mysqld=--log-bin \ --mysqld=--net_read_timeout=30 \ --reporters=CrashRecovery1,Deadlock1,ErrorLog,None,ServerDead \ --validators=None \ --grammar=c00000.yy \ --workdir=<local settings> \ --vardir=<local settings> \ --mtr-build-thread=<local settings> \ --basedir1=<path to MariaDB binaries> \ --script_debug=_nix There might be several replay attempts required. {noformat} |
Assignee | Matthias Leich [ mleich ] | Marko Mäkelä [ marko ] |
Summary | Draft: Crash recovery fails with [ERROR] InnoDB: Malformed log record | Crash recovery fails with [ERROR] InnoDB: Malformed log record |
Status | Open [ 1 ] | In Progress [ 3 ] |
Link |
This issue is caused by |
Comment |
[ Unfortunately it did not help.
/home/mleich/RQG_RR/storage/1585841382/000177.tgz ] |
Fix Version/s | 10.5.3 [ 24263 ] | |
Fix Version/s | 10.5 [ 23123 ] | |
Resolution | Fixed [ 1 ] | |
Status | In Progress [ 3 ] | Fixed [ 6 ] |
Workflow | MariaDB v3 [ 106448 ] | MariaDB v4 [ 157526 ] |