Percona Server moved to https://jira.percona.com/projects/PS

Failing assertion: log_bmp_sys->parse_buf_end == log_bmp_sys->parse_buf in log0online.c line 1038

Bug #1108613 reported by Roel Van de Paar
12
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
High
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.6.11-60.3
5.1
Fix Released
High
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.1.69-14.7
5.5
Fix Released
High
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.5.30-30.2
5.6
Fix Released
High
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.6.11-60.3

Bug Description

 InnoDB: Error: the age of the oldest untracked record exceeds the log group capacity!
130128 4:42:20 InnoDB: Assertion failure in thread 140293018244864 in file log0online.c line 1038
InnoDB: Failing assertion: log_bmp_sys->parse_buf_end == log_bmp_sys->parse_buf

But, there are many other errors in the log. Including:

130128 4:16:25 InnoDB: Database was not shut down normally!

While this is a clean MTR/RQG startup.

Start command (mainly for options reference):

[roel@macpro1 892115]$ cat cmd1058
ps -ef | grep 'cmdrun_1058' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /ssd/892115/cmdrun_1058
mkdir /ssd/892115/cmdrun_1058
cd /ssd/randgen
bash -c "set -o pipefail; perl runall.pl --queries=100000000 --seed=20163 --duration=180 --querytimeout=60 --short_column_names --sqltrace --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --grammar=conf/percona_qa/percona_qa.yy --gendata
=conf/percona_qa/percona_qa.zz --basedir=/ssd/Percona-Server-5.5.28-rel29.3-416.Linux.x86_64 --threads=25 --notnull --validator=Transformer --mysqld=--innodb_track_changed_pages=1 --mysqld=--innodb_log_file_size=1048576 --mysqld=--innodb_log_files_in_group=2 --mysqld=--innodb_log_buffer_size=1048576 --mysqld=--innodb_log_block_size=512 --mysqld=--innodb_fast_shutdown=2 --mysqld=--innodb_adaptive_flushing_method=native --mysqld=--innodb_use_global_flush_log_at_trx_commit=0 --mysqld=--userstat --mysqld=--innodb_file_per_table=1 --mtr-build-thread=794 --mask=26889 --vardir1=/ssd/892115/cmdrun_1058 > /ssd/892115/cmdrun1058.log 2>&1"

Assert happens in Percona-Server-5.5.28-rel29.3-416.Linux.x86_64 optimized build.

+bt
#0 0x00007f98980d669c in pthread_kill () from /lib64/libpthread.so.0
#1 0x000000000068832e in handle_fatal_signal (sig=6) at /ssd/QA-16274-5.5/Percona-Server-5.5.28-rel29.3/sql/signal_handler.cc:249
#2 <signal handler called>
#3 0x00007f98972a18a5 in raise () from /lib64/libc.so.6
#4 0x00007f98972a3085 in abort () from /lib64/libc.so.6
#5 0x00000000008de092 in log_online_follow_log_group (contiguous_lsn=957953024, group=0x351dab8) at /ssd/QA-16274-5.5/Percona-Server-5.5.28-rel29.3/storage/innobase/log/log0online.c:1038
#6 log_online_follow_redo_log () at /ssd/QA-16274-5.5/Percona-Server-5.5.28-rel29.3/storage/innobase/log/log0online.c:1178
#7 0x0000000000813555 in srv_redo_log_follow_thread (arg=<optimized out>) at /ssd/QA-16274-5.5/Percona-Server-5.5.28-rel29.3/storage/innobase/srv/srv0srv.c:3080
#8 0x00007f98980d1851 in start_thread () from /lib64/libpthread.so.0
#9 0x00007f989735711d in clone () from /lib64/libc.so.6

Tags: bitmap qa xtradb

Related branches

lp:~laurynas-biveinis/percona-server/BT-16274-bug1108613-5.1
Stewart Smith (community): Approve
George Ormond Lorch III (community): Approve (g2)
Diff: 128 lines (+67/-6)
6 files modified
Percona-Server/mysql-test/suite/innodb_plugin/r/percona_changed_page_bmp.result (+13/-1)
Percona-Server/mysql-test/suite/innodb_plugin/t/percona_changed_page_bmp-master.opt (+1/-1)
Percona-Server/mysql-test/suite/innodb_plugin/t/percona_changed_page_bmp.test (+40/-1)
Percona-Server/storage/innodb_plugin/log/log0log.c (+4/-1)
Percona-Server/storage/innodb_plugin/log/log0online.c (+4/-2)
Percona-Server/storage/innodb_plugin/srv/srv0start.c (+5/-0)
lp:~laurynas-biveinis/percona-server/BT-16274-bug1108613-5.5
Stewart Smith (community): Approve
George Ormond Lorch III (community): Approve (g2)
Diff: 128 lines (+67/-6)
6 files modified
Percona-Server/mysql-test/suite/innodb/r/percona_changed_page_bmp.result (+13/-1)
Percona-Server/mysql-test/suite/innodb/t/percona_changed_page_bmp-master.opt (+1/-1)
Percona-Server/mysql-test/suite/innodb/t/percona_changed_page_bmp.test (+40/-1)
Percona-Server/storage/innobase/log/log0log.c (+4/-1)
Percona-Server/storage/innobase/log/log0online.c (+4/-2)
Percona-Server/storage/innobase/srv/srv0start.c (+5/-0)
lp:~laurynas-biveinis/percona-server/5.6-merge-4
Stewart Smith (community): Approve
Diff: 28652 lines (+8737/-18610)
172 files modified
COPYING.innodb-deadlock-count-patch (+0/-30)
COPYING.show_temp_51 (+13/-0)
Makefile (+2/-2)
Percona-Server/client/mysqldump.c (+121/-21)
Percona-Server/include/errmsg.h (+1/-0)
Percona-Server/libmysql/errmsg.c (+1/-0)
Percona-Server/mysql-test/include/have_pool_of_threads.inc (+0/-4)
Percona-Server/mysql-test/include/log_grep.inc (+0/-41)
Percona-Server/mysql-test/include/percona_query_cache_with_comments.inc (+95/-0)
Percona-Server/mysql-test/include/percona_query_cache_with_comments_begin.inc (+0/-12)
Percona-Server/mysql-test/include/percona_query_cache_with_comments_clear.inc (+5/-0)
Percona-Server/mysql-test/include/percona_query_cache_with_comments_eval.inc (+7/-0)
Percona-Server/mysql-test/include/percona_show_slave_status_nolock.inc (+0/-56)
Percona-Server/mysql-test/r/have_pool_of_threads.require (+2/-0)
Percona-Server/mysql-test/r/percona_bug1170103.result (+19/-0)
Percona-Server/mysql-test/r/percona_bug933969.result (+0/-16)
Percona-Server/mysql-test/r/percona_innodb_deadlock_count.result (+28/-0)
Percona-Server/mysql-test/r/percona_log_slow_admin_statements-config.result (+0/-6)
Percona-Server/mysql-test/r/percona_log_slow_admin_statements-config_foo.result (+7/-0)
Percona-Server/mysql-test/r/percona_log_slow_admin_statements-config_true.result (+0/-6)
Percona-Server/mysql-test/r/percona_log_slow_filter-cl.result (+0/-6)
Percona-Server/mysql-test/r/percona_min_examined_row_limit.result (+0/-35)
Percona-Server/mysql-test/r/percona_mysqldump_innodb_optimize_keys.result (+47/-0)
Percona-Server/mysql-test/r/percona_query_cache_with_comments_crash.result (+21/-0)
Percona-Server/mysql-test/r/percona_query_cache_with_comments_prepared_statements.result (+0/-396)
Percona-Server/mysql-test/r/percona_status_wait_query_cache_mutex.result (+20/-0)
Percona-Server/mysql-test/r/pool_of_threads.result (+2169/-0)
Percona-Server/mysql-test/r/pool_of_threads_high_prio_tickets.result (+2169/-0)
Percona-Server/mysql-test/suite/binlog/r/percona_bug1162085.result (+6/-0)
Percona-Server/mysql-test/suite/binlog/t/percona_bug1162085.test (+30/-0)
Percona-Server/mysql-test/suite/innodb/r/percona_changed_page_bmp.result (+8/-3)
Percona-Server/mysql-test/suite/innodb/t/percona_changed_page_bmp-master.opt (+1/-1)
Percona-Server/mysql-test/suite/innodb/t/percona_changed_page_bmp.test (+16/-3)
Percona-Server/mysql-test/suite/rpl/r/percona_bug860910.result (+0/-23)
Percona-Server/mysql-test/suite/rpl/t/percona_bug860910.test (+0/-38)
Percona-Server/mysql-test/suite/sys_vars/r/extra_max_connections_basic.result (+43/-0)
Percona-Server/mysql-test/suite/sys_vars/r/extra_port_basic.result (+21/-0)
Percona-Server/mysql-test/suite/sys_vars/r/query_exec_id_basic.result (+2/-0)
Percona-Server/mysql-test/suite/sys_vars/r/thread_pool_high_prio_tickets_basic.result (+47/-0)
Percona-Server/mysql-test/suite/sys_vars/r/thread_pool_idle_timeout_basic.result (+47/-0)
Percona-Server/mysql-test/suite/sys_vars/r/thread_pool_max_threads_basic.result (+47/-0)
Percona-Server/mysql-test/suite/sys_vars/r/thread_pool_min_threads_basic.result (+49/-0)
Percona-Server/mysql-test/suite/sys_vars/r/thread_pool_oversubscribe_basic.result (+47/-0)
Percona-Server/mysql-test/suite/sys_vars/r/thread_pool_stall_limit_basic.result (+47/-0)
Percona-Server/mysql-test/suite/sys_vars/t/extra_max_connections_basic.test (+0/-42)
Percona-Server/mysql-test/suite/sys_vars/t/query_exec_id_basic.test (+0/-4)
Percona-Server/mysql-test/suite/sys_vars/t/thread_pool_high_prio_tickets_basic.test (+43/-0)
Percona-Server/mysql-test/suite/sys_vars/t/thread_pool_idle_timeout_basic.test (+0/-43)
Percona-Server/mysql-test/suite/sys_vars/t/thread_pool_min_threads_basic.test (+0/-43)
Percona-Server/mysql-test/suite/sys_vars/t/thread_pool_oversubscribe_basic.test (+0/-43)
Percona-Server/mysql-test/suite/sys_vars/t/thread_pool_size_basic.test (+47/-0)
Percona-Server/mysql-test/suite/sys_vars/t/thread_pool_stall_limit_basic.test (+0/-43)
Percona-Server/mysql-test/t/percona_bug1170103-master.opt (+1/-0)
Percona-Server/mysql-test/t/percona_bug1170103.test (+23/-0)
Percona-Server/mysql-test/t/percona_bug933969.test (+0/-42)
Percona-Server/mysql-test/t/percona_log_slow_admin_statements-config_false.test (+2/-0)
Percona-Server/mysql-test/t/percona_log_slow_admin_statements-config_foo.test (+3/-0)
Percona-Server/mysql-test/t/percona_log_slow_admin_statements-config_true.cnf (+4/-0)
Percona-Server/mysql-test/t/percona_log_slow_slave_statements-cl-master.opt (+0/-1)
Percona-Server/mysql-test/t/percona_log_slow_sp_statements-cl-master.opt (+0/-1)
Percona-Server/mysql-test/t/percona_log_slow_sp_statements-cl.test (+2/-0)
Percona-Server/mysql-test/t/percona_log_slow_verbosity-cl-master.opt (+0/-1)
Percona-Server/mysql-test/t/percona_log_slow_verbosity-cl.test (+0/-2)
Percona-Server/mysql-test/t/percona_mysqldump_innodb_optimize_keys.test (+27/-0)
Percona-Server/mysql-test/t/percona_query_cache_with_comments_prepared_statements.test (+0/-208)
Percona-Server/mysql-test/t/percona_status_wait_query_cache_mutex.test (+0/-35)
Percona-Server/mysql-test/t/percona_xtradb_bug317074.test (+47/-0)
Percona-Server/mysql-test/t/pool_of_threads.cnf (+15/-0)
Percona-Server/mysql-test/t/pool_of_threads_high_prio_tickets.cnf (+16/-0)
Percona-Server/mysql-test/t/pool_of_threads_high_prio_tickets.test (+19/-0)
Percona-Server/mysys/mf_cache.c (+5/-3)
Percona-Server/sql/query_strip_comments.h (+37/-0)
Percona-Server/sql/sys_vars.cc (+7/-0)
Percona-Server/sql/threadpool.h (+72/-0)
Percona-Server/sql/threadpool_common.cc (+367/-0)
Percona-Server/sql/threadpool_unix.cc (+1699/-0)
Percona-Server/sql/threadpool_win.cc (+763/-0)
Percona-Server/storage/innobase/handler/ha_innodb.cc (+4/-0)
Percona-Server/storage/innobase/include/srv0srv.h (+5/-0)
Percona-Server/storage/innobase/log/log0log.cc (+7/-1)
Percona-Server/storage/innobase/read/read0read.cc (+9/-0)
Percona-Server/storage/innobase/row/row0sel.cc (+3/-3)
Percona-Server/storage/innobase/srv/srv0srv.cc (+32/-0)
Percona-Server/storage/innobase/trx/trx0sys.cc (+2/-0)
Percona-Server/storage/innobase/trx/trx0trx.cc (+1/-0)
UDF/configure.ac (+1/-0)
build/build-binary.sh (+1/-0)
build/debian/additions/debian-start (+0/-32)
build/debian/additions/debian-start.inc.sh (+0/-72)
build/debian/compat (+0/-1)
build/debian/rules (+3/-1)
build/percona-server.spec (+15/-10)
build/percona-shared-compat.spec (+1/-1)
build/rpm/mysql-dubious-exports.patch (+0/-127)
doc/source/conf.py (+1/-1)
doc/source/development.rst (+0/-266)
doc/source/diagnostics/user_stats.rst (+0/-242)
doc/source/flexibility/buff_read_ahead_area.rst (+36/-0)
doc/source/management/innodb_expanded_fast_index_creation.rst (+0/-82)
doc/source/management/innodb_fake_changes.rst (+70/-0)
doc/source/management/innodb_kill_idle_trx.rst (+0/-2)
doc/source/percona_xtradb.rst (+13/-0)
doc/source/performance/query_cache_enhance.rst (+123/-0)
doc/source/performance/threadpool.rst (+33/-0)
doc/source/reliability/error_pad.rst (+0/-55)
doc/source/reliability/innodb_corrupt_table_action.rst (+0/-35)
doc/source/upstream-bug-fixes.rst (+40/-16)
python-for-subunit2junitxml/BytesIO.py (+0/-136)
python-for-subunit2junitxml/iso8601/LICENSE (+0/-20)
python-for-subunit2junitxml/iso8601/README (+0/-26)
python-for-subunit2junitxml/iso8601/README.subunit (+0/-5)
python-for-subunit2junitxml/iso8601/setup.py (+0/-58)
python-for-subunit2junitxml/iso8601/test_iso8601.py (+0/-111)
python-for-subunit2junitxml/junitxml/__init__.py (+0/-221)
python-for-subunit2junitxml/junitxml/tests/__init__.py (+0/-16)
python-for-subunit2junitxml/junitxml/tests/test_junitxml.py (+0/-327)
python-for-subunit2junitxml/subunit/__init__.py (+0/-1250)
python-for-subunit2junitxml/subunit/chunked.py (+0/-185)
python-for-subunit2junitxml/subunit/details.py (+0/-119)
python-for-subunit2junitxml/subunit/iso8601.py (+0/-133)
python-for-subunit2junitxml/subunit/progress_model.py (+0/-106)
python-for-subunit2junitxml/subunit/run.py (+0/-73)
python-for-subunit2junitxml/subunit/test_results.py (+0/-492)
python-for-subunit2junitxml/subunit/tests/TestUtil.py (+0/-80)
python-for-subunit2junitxml/subunit/tests/__init__.py (+0/-41)
python-for-subunit2junitxml/subunit/tests/sample-script.py (+0/-21)
python-for-subunit2junitxml/subunit/tests/sample-two-script.py (+0/-7)
python-for-subunit2junitxml/subunit/tests/test_chunked.py (+0/-152)
python-for-subunit2junitxml/subunit/tests/test_details.py (+0/-112)
python-for-subunit2junitxml/subunit/tests/test_progress_model.py (+0/-118)
python-for-subunit2junitxml/subunit/tests/test_subunit_filter.py (+0/-208)
python-for-subunit2junitxml/subunit/tests/test_subunit_stats.py (+0/-84)
python-for-subunit2junitxml/subunit/tests/test_subunit_tags.py (+0/-69)
python-for-subunit2junitxml/subunit/tests/test_tap2subunit.py (+0/-445)
python-for-subunit2junitxml/subunit/tests/test_test_protocol.py (+0/-1299)
python-for-subunit2junitxml/subunit/tests/test_test_results.py (+0/-300)
python-for-subunit2junitxml/testtools/__init__.py (+0/-80)
python-for-subunit2junitxml/testtools/_spinner.py (+0/-316)
python-for-subunit2junitxml/testtools/compat.py (+0/-286)
python-for-subunit2junitxml/testtools/content.py (+0/-238)
python-for-subunit2junitxml/testtools/content_type.py (+0/-33)
python-for-subunit2junitxml/testtools/deferredruntest.py (+0/-335)
python-for-subunit2junitxml/testtools/distutilscmd.py (+0/-62)
python-for-subunit2junitxml/testtools/helpers.py (+0/-64)
python-for-subunit2junitxml/testtools/matchers.py (+0/-785)
python-for-subunit2junitxml/testtools/monkey.py (+0/-97)
python-for-subunit2junitxml/testtools/run.py (+0/-332)
python-for-subunit2junitxml/testtools/runtest.py (+0/-200)
python-for-subunit2junitxml/testtools/testcase.py (+0/-724)
python-for-subunit2junitxml/testtools/testresult/__init__.py (+0/-19)
python-for-subunit2junitxml/testtools/testresult/doubles.py (+0/-111)
python-for-subunit2junitxml/testtools/testresult/real.py (+0/-621)
python-for-subunit2junitxml/testtools/tests/__init__.py (+0/-44)
python-for-subunit2junitxml/testtools/tests/helpers.py (+0/-72)
python-for-subunit2junitxml/testtools/tests/test_compat.py (+0/-257)
python-for-subunit2junitxml/testtools/tests/test_content.py (+0/-223)
python-for-subunit2junitxml/testtools/tests/test_content_type.py (+0/-46)
python-for-subunit2junitxml/testtools/tests/test_deferredruntest.py (+0/-738)
python-for-subunit2junitxml/testtools/tests/test_distutilscmd.py (+0/-90)
python-for-subunit2junitxml/testtools/tests/test_fixturesupport.py (+0/-79)
python-for-subunit2junitxml/testtools/tests/test_helpers.py (+0/-106)
python-for-subunit2junitxml/testtools/tests/test_matchers.py (+0/-695)
python-for-subunit2junitxml/testtools/tests/test_monkey.py (+0/-167)
python-for-subunit2junitxml/testtools/tests/test_run.py (+0/-77)
python-for-subunit2junitxml/testtools/tests/test_runtest.py (+0/-300)
python-for-subunit2junitxml/testtools/tests/test_spinner.py (+0/-332)
python-for-subunit2junitxml/testtools/tests/test_testresult.py (+0/-1372)
python-for-subunit2junitxml/testtools/tests/test_testsuite.py (+0/-53)
python-for-subunit2junitxml/testtools/tests/test_testtools.py (+0/-1143)
python-for-subunit2junitxml/testtools/tests/test_with_with.py (+0/-42)
python-for-subunit2junitxml/testtools/testsuite.py (+0/-87)
python-for-subunit2junitxml/testtools/utils.py (+0/-13)
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

The error log showed a BLOB larger than the log capacity, which probably caused this down the road.

Roel - can you get the SQL of this run?

Revision history for this message
Roel Van de Paar (roel11) wrote :

Laurynas, I can get the SQL, but since it's 25 threaded it will highly likely not reproduce easily. Are you simply interested in reviewing what was executed?

Laurynas Biveinis (laurynas-biveinis)
tags: added: bitmap
Revision history for this message
Roel Van de Paar (roel11) wrote :

Adding the following to this bug after discussion with Laurynas;

InnoDB: Error: the age of the oldest untracked record exceeds the log group capacity!
130127 14:18:22 InnoDB: ERROR: the age of the last checkpoint is 1894472,
InnoDB: which exceeds the log group capacity 1883751.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
InnoDB: Error: the age of the oldest untracked record exceeds the log group capacity!
InnoDB: Error: the age of the oldest untracked record exceeds the log group capacity!

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

This might be due to missing actual overwritten log parse detection, which is (cancelled) work in progress at - https://bazaar.launchpad.net/~vlad-lesin/percona-server/i_s-innodb-log-tracking-status/revision/459

Roel, no need for further analysis of this bug for now.

Revision history for this message
Roel Van de Paar (roel11) wrote :

FYGI, present also in QA-16724-5.5-2 tree at revid Percona-Server-5.5.28-rel29.3-422-debug.Linux.x86_64

130203 18:55:04 InnoDB: Assertion failure in thread 139644531517184 in file log0online.c line 1065
InnoDB: Failing assertion: log_bmp_sys->parse_buf_end == log_bmp_sys->parse_buf

Attaching interesting mysqld error log and stacks.

Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Laurynas Biveinis (laurynas-biveinis)
tags: added: xtradb
Revision history for this message
Roel Van de Paar (roel11) wrote :

Still seen: bug 1233506

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-624

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.