[Warning] InnoDB: changed page bitmap file './ib_modified_log_11_951286349.xdb' does not contain a complete run at the end.

[Roel Van de Paar]

Seen like this:

2013-06-20 13:55:59 12023 [Note] /ssd2/Percona-Server-5.6.11-rc60.3-383-debug.Linux.x86_64/bin/mysqld-debug: ready for connections.
Version: '5.6.11-rc60.3-debug-log' socket: '/ssd2/402661/current1_1/tmp/master.sock' port: 13000 Percona Server with XtraDB (GPL), Release rc60.3, Revision 383-debug
2013-06-20 13:57:47 12023 [Warning] InnoDB: changed page bitmap file './ib_modified_log_11_951286349.xdb' does not contain a complete run at the end.

2013-06-20 13:58:54 12023 [ERROR] /ssd2/Percona-Server-5.6.11-rc60.3-383-debug.Linux.x86_64/bin/mysqld-debug: Incorrect information in file: './test/table500_innodb_compressed_key_pk_parts_2_int_autoinc.frm'
2013-06-20 13:59:11 7f63800b3700 InnoDB: Assertion failure in thread 140065326708480 in file btr0btr.ic line 169
InnoDB: Failing assertion: mtr_memo_contains_page(mtr, page, 2) || mtr_memo_contains_page(mtr, page, 1)

Though the assertion bug is already logged in Bug 1192898, attaching the full details here again in case it shows anything about the error.

[Laurynas Biveinis (laurynas-biveinis)]

This error is expected if the server was started on a crashed instance, or say, disk full. Thus need details of the instance.

[Roel Van de Paar (roel11)]

That could have been the case.

Another similar situation:

2013-06-20 14:45:00 20219 [Note] /ssd2/Percona-Server-5.6.11-rc60.3-383-debug.Linux.x86_64/bin/mysqld-debug: ready for connections.
Version: '5.6.11-rc60.3-debug-log' socket: '/ssd2/402661/current1_4/tmp/master.sock' port: 13060 Percona Server with XtraDB (GPL), Release rc60.3, Revision 383-debug
InnoDB: Error: the age of the oldest untracked record exceeds the log group capacity!
InnoDB: Error: stopping the log tracking thread at LSN 105616999
2013-06-20 14:47:59 20219 [ERROR] InnoDB: log tracking bitmap write failed, stopping log tracking thread!

2013-06-20 14:53:38 7fe460152700 InnoDB: Assertion failure in thread 140618841270016 in file btr0btr.ic line 169
InnoDB: Failing assertion: mtr_memo_contains_page(mtr, page, 2) || mtr_memo_contains_page(mtr, page, 1)

Adding logs. Please review these as well.

If similar is expected, please close issue, it's then quite sure disk space.

[Laurynas Biveinis (laurynas-biveinis)]

Is it possible to confirm whether that was really the case?

The "InnoDB: Error: the age of the oldest untracked record exceeds the log group capacity!" is an orthogonal issue.

[Roel Van de Paar (roel11)]

There is also this one:

2013-06-20 12:50:32 3921 [Note] /ssd2/Percona-Server-5.6.11-rc60.3-383-debug.Linux.x86_64/bin/mysqld-debug: ready for connections.
Version: '5.6.11-rc60.3-debug-log' socket: '/ssd2/402661/current1_3/tmp/master.sock' port: 13040 Percona Server with XtraDB (GPL), Release rc60.3, Rev83-debug
2013-06-20 13:20:53 3921 [Warning] InnoDB: changed page bitmap file './ib_modified_log_1_0.xdb' does not contain a complete run at the end.

2013-06-20 13:20:53 3921 [Warning] InnoDB: changed page bitmap file './ib_modified_log_1_0.xdb' does not contain a complete run at the end.

2013-06-20 13:21:04 3921 [Warning] Invalid (old?) table or database name '#sqlf51_1a_0'
2013-06-20 13:21:04 3921 [Warning] Invalid (old?) table or database name '#sqlf51_1a_0'
2013-06-20 13:21:24 3921 [Warning] Invalid (old?) table or database name '#sqlf51_1a_0'
2013-06-20 13:21:24 3921 [Warning] Invalid (old?) table or database name '#sqlf51_1a_0'
2013-06-20 13:21:44 3921 [Warning] Invalid (old?) table or database name '#sqlf51_1a_0'
2013-06-20 13:21:55 7f13a5ac0700 InnoDB: Assertion failure in thread 139722360620800 in file log0log.cc line 308
InnoDB: Failing assertion: ++count < 50

Note the same error, but this time with ib_modified_log_1_0.xdb

It seems somewhat unlikely that the server ran out of disk space, there are 0 relevant warnings/errors in all trials for this run, and this last error is from trial 3, while there are many. In other words, the 3 occurrences above all seem valid ftm.

[Roel Van de Paar (roel11)]

For the failing assertion ++count < 50, see bug 1193319

[Laurynas Biveinis (laurynas-biveinis)]

Roel -

Can you attach ls -lR output of the datadir of this run?

[Roel Van de Paar (roel11)]

Ok, so this issue is seen still regularly, even in recent QA-5.6 tree revisions. Requesting re-triage to high based on that, maybe even critical is warranted, all depends on severity of message itself. I assume original 'medium' was set based on disk space being full or not, but this issue now confirmed reproduces without disk full. Attempting to get good testcase (if needed).

[Roel Van de Paar (roel11)]

2013-09-24 18:05:45 [] [Stage V] [MULTI] All subreducer threads have finished/terminated
2013-09-24 18:05:45 [*] [Stage V] [MULTI] Threads which reproduced the issue: #1 #3 #4 #6 #9 #10
2013-09-24 18:05:45 [*] [Stage V] [MULTI] Only 6 out of 10 threads reproduced the issue: this issue is sporadic

Issue is definitely sporadic

[Roel Van de Paar (roel11)]

Sporadic testcase reduced to:

DROP DATABASE test;CREATE DATABASE test;USE test;
CREATE TABLE t2 (c1 BLOB, c4 VARBINARY ( 32 ) , KEY (c1(1))) ENGINE = InnoDB ROW_FORMAT = FIXED KEY_BLOCK_SIZE = 4;
SET @@global.innodb_log_checkpoint_now = TRUE;
SELECT COUNT(*) FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES;

With these mysqld options:

MYEXTRA="--log-output=none --sql_mode=ONLY_FULL_GROUP_BY --utility-user-password=test --innodb_change_buffering=all --innodb_fast_shutdown=2 --innodb_flush_method=O_DSYNC --innodb_log_buffer_size=1048576 --innodb_log_files_in_group=3 --innodb_max_changed_pages=0 --innodb_track_changed_pages=1 --query_cache_type=1 --readonly-key-cache-block-size=0 --readonly-loose-max-connect-errors=0 --secure-file-priv=/tmp --skip-innodb_doublewrite --slow_query_log --thread_handling=pool-of-threads --transaction-isolation=REPEATABLE-READ --userstat --utility-user-password=test --utility-user-schema-access=mysqlinformation_schema --hidden-key-buffer-size=1 --innodb_purge_threads=4 --innodb_adaptive_hash_index_partitions=8 --innodb_buffer_pool_instances=1 "
MYBASE="/ssd/Percona-Server-5.6.13-rc60.5-443-debug.Linux.x86_64"

Note that any clause, and any mysqld option may be "too much", but it would take more time to debug. Hope this is enough to go on. Note that even the full testcase may be "too much" - i.e. some race always present caused by server options, sql independent, for example

[Laurynas Biveinis (laurynas-biveinis)]

The problem is bitmap writer thread working in parallel with bitmap reader, causing the latter to see partial data in the middle of the write. The workaround is to specify the desired END_LSN in the I_S query. The fix would be -
1) if the bitmap tracking is off, then these diagnostics always apply;
2) if the bitmap tracking is on, check the max current tracked LSN, limit END_LSN by it, do not attempt to read further.

[Roel Van de Paar (roel11)]

Understood. That indeed confirms low prio given data is not corrupted, it's just a wrong offset on reading I_S query.

[Roel Van de Paar (roel11)]

Bug needs a combination of some not-very-often-used factors to occur. So we have agreed to fix this as prio post-GA.

[Roel Van de Paar (roel11)]

The only challenge here is that this is seen heaps in RQG runs, and, it means that the runs end in STATUS_ALARM failure (due to the issue being visible in the error log). Not enough for qablock, as in principle it could be worked around in RQG, but as such it would be great if this was definitely fixed for next point release.

[Shahriyar Rzayev (rzayev-sehriyar)]

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