Percona Server with XtraDB

Failing assertion: ++count < 50 in file log0log.cc line 308 | abort in log_open from mtr_log_reserve_and_write

Reported by Roel Van de Paar on 2013-06-21
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Percona Server
Status tracked in 5.6
5.1
Undecided
Unassigned
5.5
Undecided
Unassigned
5.6
High
Sergei Glushchenko

Bug Description

2013-06-20 15:26:25 7f85c81fc700 InnoDB: Assertion failure in thread 140212564903680 in file log0log.cc line 308
InnoDB: Failing assertion: ++count < 50

Thread 1 (LWP 29188):
+bt
#0 0x0000003fdde328a5 in raise () from /lib64/libc.so.6
#1 0x0000003fdde34085 in abort () from /lib64/libc.so.6
#2 0x0000000000a35520 in log_open (len=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/log/log0log.cc:308
#3 0x0000000000a4940e in mtr_log_reserve_and_write (mtr=0x7f85ccf67840) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/mtr/mtr0mtr.cc:278
#4 mtr_commit (mtr=0x7f85ccf67840) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/mtr/mtr0mtr.cc:323
#5 0x0000000000b3f273 in btr_store_big_rec_extern_fields (index=0x7f8578048898, rec_block=<optimized out>, rec=0x7f85d43bb49d "\200", offsets=0x7f8578076c90, big_rec_vec=0x7f8578061fc8, btr_mtr=0x7f85ccf67e10, op=BTR_STORE_INSERT) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/btr/btr0cur.cc:4973
#6 0x0000000000a939ee in row_ins_index_entry_big_rec_func (entry=0x7f85d43bb49d, big_rec=0x7f8578061fc8, offsets=0x7f8578076c90, heap=0x7f85ccf68c98, index=0x7f8578048898, file=<optimized out>, thd=0x36c4f80, line=2529) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:2840
#7 0x0000000000a97f07 in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x7f8578048898, n_uniq=<optimized out>, entry=0x7f8578045cd8, n_ext=0, thr=0x7f85780419b0) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:2529
#8 0x0000000000a9a075 in row_ins_clust_index_entry (index=0x7f8578048898, entry=0x7f8578045cd8, thr=0x7f85780419b0, n_ext=0) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:2887
#9 0x0000000000a9b7f7 in row_ins_index_entry (thr=0x7f85780419b0, entry=0x7f8578045cd8, index=0x7f8578048898) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:2981
#10 row_ins_index_entry_step (thr=0x7f85780419b0, node=0x7f85780414c8) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:3058
#11 row_ins (thr=0x7f85780419b0, node=0x7f85780414c8) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:3198
#12 row_ins_step (thr=0x7f85780419b0) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:3323
#13 0x0000000000aae1ec in row_insert_for_mysql (mysql_rec=<optimized out>, prebuilt=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0mysql.cc:1312
#14 0x00000000009ea39e in ha_innobase::write_row (this=0x7f857803dd50, record=0x7f8578047b90 "") at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/handler/ha_innodb.cc:6929
#15 0x00000000005b7b04 in handler::ha_write_row (this=0x7f857803dd50, buf=0x7f8578047b90 "") at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/handler.cc:7414
#16 0x00000000006f8540 in write_record (thd=0x36c4f80, table=0x7f857803c4c0, info=0x7f8578005a70, update=0x7f8578005ae8) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_insert.cc:1905
#17 0x00000000006f9035 in select_insert::send_data (this=0x7f8578005a30, values=...) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_insert.cc:3681
#18 0x00000000006eacf8 in end_send (join=0x7f8578005b68, join_tab=0x7f85780504e8, end_of_records=false) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_executor.cc:2775
#19 0x00000000006ec2d3 in evaluate_join_record (join=0x7f8578005b68, join_tab=0x7f85780501e8) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_executor.cc:1598
#20 0x00000000006f09b6 in sub_select (join=0x7f8578005b68, join_tab=0x7f85780501e8, end_of_records=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_executor.cc:1273
#21 0x00000000006f22e6 in do_select (join=0x7f8578005b68) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_executor.cc:930
#22 JOIN::exec (this=0x7f8578005b68) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_executor.cc:191
#23 0x000000000073c800 in mysql_execute_select (free_join=true, select_lex=0x36c7a48, thd=0x36c4f80) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_select.cc:1101
#24 mysql_select (thd=0x36c4f80, tables=0x7f85780054b8, wild_num=1, fields=..., conds=0x0, order=<optimized out>, group=0x36c7b48, having=0x0, select_options=3489925888, result=0x7f8578005a30, unit=0x36c7400, select_lex=0x36c7a48) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_select.cc:1222
#25 0x000000000073d2c3 in handle_select (thd=0x36c4f80, result=0x7f8578005a30, setup_tables_done_option=1073741824) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_select.cc:111
#26 0x0000000000719dc4 in mysql_execute_command (thd=0x36c4f80) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_parse.cc:3714
#27 0x000000000071b8b8 in mysql_parse (thd=0x36c4f80, rawbuf=0x36c7338 "p\234\065\001", length=<optimized out>, parser_state=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_parse.cc:6451
#28 0x000000000071c923 in dispatch_command (command=COM_QUERY, thd=0x36c4f80, packet=0x3628c31 " INSERT INTO z SELECT * FROM `table500_innodb_default_int` ", packet_length=59) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_parse.cc:1376
#29 0x000000000071d86b in do_command (thd=0x36c4f80) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_parse.cc:1051
#30 0x00000000006e261f in do_handle_one_connection (thd_arg=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_connect.cc:1615
#31 0x00000000006e2707 in handle_one_connection (arg=0x36c4f80) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_connect.cc:1526
#32 0x00000000009beb49 in pfs_spawn_thread (arg=0x3673a80) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/perfschema/pfs.cc:1853
#33 0x0000003fde207851 in start_thread () from /lib64/libpthread.so.0
#34 0x0000003fddee890d in clone () from /lib64/libc.so.6

Aborts in other threads also, see attaches

Related branches

Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :

[roel@qaserver 402661]$ cat cmd215
ps -ef | grep 'cmdrun_215' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /ssd2/402661/cmdrun_215
mkdir /ssd2/402661/cmdrun_215
cd /ssd2/randgen
bash -c "set -o pipefail; perl runall.pl --queries=100000000 --seed=734 --duration=300 --querytimeout=60 --short_column_names --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --grammar=conf/percona_qa/5.6/5.6.yy --gendata=conf/percona_qa/5.6/5.6.zz --basedir=/ssd2/Percona-Server-5.6.11-rc60.3-383-debug.Linux.x86_64 --threads=25 --no-mask --notnull --validator=Transformer --mysqld=--innodb_track_changed_pages=1 --mysqld=--innodb_max_bitmap_file_size=4097 --mysqld=--innodb_changed_pages=ON --mysqld=--innodb_max_changed_pages=2 --mysqld=--slow_query_log --mysqld=--userstat --mysqld=--innodb_log_archive=1 --mysqld=--innodb_log_arch_dir=/ssd2/402661/_epoch/1371731005793221699 --mysqld=--innodb_log_arch_expire_sec=120 --mysqld=--innodb_log_file_size=1048576 --mysqld=--innodb_log_files_in_group=10 --mysqld=--innodb_log_buffer_size=10485761 --mysqld=--innodb_flush_log_at_trx_commit=2 --mysqld=--query_cache_type=1 --mysqld=--query_cache_size=1048576 --mysqld=--innodb_flush_method=O_DIRECT --mysqld=--innodb_file_per_table=1 --mtr-build-thread=794 --mask=24562 --vardir1=/ssd2/402661/cmdrun_215 > /ssd2/402661/cmdrun215.log 2>&1"

The stacktrace points to log archiving. Vlad, can you take a look?

tags: added: alog
Roel Van de Paar (roel11) wrote :

See also bug 1193332

Roel Van de Paar (roel11) wrote :

Seen again in last RQG run

vardir1_135/log/master.err:201z-08-18 04:04:40 7f8e61862700 InnoDB: Assertion failure in thread 140249498265344 in file log0log.cc line 308

summary: - Failing assertion: ++count < 50 in file log0log.cc line 308
+ Failing assertion: ++count < 50 in file log0log.cc line 308 | abort in
+ log_open from mtr_log_reserve_and_write
Roel Van de Paar (roel11) wrote :

Upgrade to qablock: seen in many runs.

tags: added: qablock
tags: added: 56qual
Roel Van de Paar (roel11) wrote :

Sergei pushed diag for this in 441. Seen in 443, so diag should now be present in logs as put in. Adding new error log + stacks.

Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :

count = 50,
log->lsn = 280659578,
log->archived_lsn = 280659456,
archived_lsn_age = 2019450,
log->max_archived_lsn_age = 2027520,
len_upper_limit = 22556
2013-09-20 12:45:33 7ff919e85700 InnoDB: Assertion failure in thread 140707858241280 in file log0log.cc line 323
InnoDB: Failing assertion: ++count < 50

Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :

A completely different occurrence

count = 50,
log->lsn = 601188478,
log->archived_lsn = 601186304,
archived_lsn_age = 1972350,
log->max_archived_lsn_age = 1998848,
len_upper_limit = 36880
2013-09-20 11:14:44 7f3ebc15a700 InnoDB: Assertion failure in thread 139907420235520 in file log0log.cc line 323
InnoDB: Failing assertion: ++count < 50

Roel Van de Paar (roel11) wrote :

And another one preceded by many DB_FAIL

[...]
row_undo_ins_remove_sec_low returning DB_FAIL
row_undo_ins_remove_sec_low returning DB_FAIL
count = 50,
log->lsn = 3078566879,
log->archived_lsn = 2986906112,
archived_lsn_age = 94282207,
log->max_archived_lsn_age = 94287872,
len_upper_limit = 22556
count = 50,
log->lsn = 3078566879,
log->archived_lsn = 2986906112,
archived_lsn_age = 94282207,
log->max_archived_lsn_age = 94287872,
len_upper_limit = 21878
2013-09-20 11:38:46 7f15f41e8700 InnoDB: Assertion failure in thread 139732266682112 in file log0log.cc line 323
InnoDB: Failing assertion: ++count < 50

Roel Van de Paar (roel11) wrote :

(yes... it printed twice)

Roel Van de Paar (roel11) wrote :

And yet another one

count = 50,
log->lsn = 46701611,
log->archived_lsn = 46698496,
archived_lsn_age = 1973291,
log->max_archived_lsn_age = 1998848,
len_upper_limit = 36892
2013-09-20 09:52:42 7f433d6d3700 InnoDB: Assertion failure in thread 139926770104064 in file log0log.cc line 323
InnoDB: Failing assertion: ++count < 50

Roel Van de Paar (roel11) wrote :

In #15 I note in 2nd print len_upper_limit is different

My best guess is that combination of following circumstance led to this failure:

1. Log file size 1M while log buffer is 10M
2. We write BLOB's trying to write about 22K
3. Long transactions
4. Log tracking enabled
5. There is no concurrent threads

This is what happening:

log_open fails on log_check_tracking_margin 50 times after it passes (count == 50) and goes to log_archiving, which is needed because log age is too old and we need to free up more space in log files. It makes the space needed, but count is already 50, so assertion failure raised.

Roel Van de Paar (roel11) wrote :

Ack. Adding some more occurrences with mysqld options used for verification of analysis

Roel Van de Paar (roel11) wrote :

innodb_log_file_size=1048576 (1MB)
innodb_log_buffer_size @ Default 1048576 (1MB)

Diag:

count = 50,
log->lsn = 63347964,
log->archived_lsn = 63347712,
archived_lsn_age = 967932,
log->max_archived_lsn_age = 980992,
len_upper_limit = 22556
2013-09-24 16:30:20 1cb39700 InnoDB: Assertion failure in thread 481531648 in file log0log.cc line 323
InnoDB: Failing assertion: ++count < 50

Roel Van de Paar (roel11) wrote :

innodb_log_file_size=1048576 (1MB)
innodb_log_buffer_size @ Default 1048576 (1MB)

Diag:

count = 50,
log->lsn = 95207963,
log->archived_lsn = 95207936,
archived_lsn_age = 972315,
log->max_archived_lsn_age = 980992,
len_upper_limit = 22573
2013-09-24 16:25:09 7f328f45c700 InnoDB: Assertion failure in thread 139855128807168 in file log0log.cc line 323
InnoDB: Failing assertion: ++count < 50

Roel Van de Paar (roel11) wrote :

All have similar innodb_log_file_size=1048576 (1MB), so likely of little interest.

If indeed we have runs with innodb_log_buffer_size > innodb_log_file_size then accepting such setup in the first place is an (unrelated to the core issue) upstream bug?

Re. the core issue it looks to me (haven't fully thought through) that the margins must be checked in parallel, in the same loop iterations, i.e instead of

if (tracking margin violated) {
   count++;
   sleep;
   goto loop;
}
if (archiving margin violated) {
  count++;
  archive;
  goto loop;
}

we should have something like

if (either margin violated) {
   if (archiving margin violated) {
     archive;
   } else {
     sleep;
   }
   count++;
   goto loop;
}

Roel Van de Paar (roel11) wrote :

Adding quite a few more logs from latest run on revid 454 (5.6.13-rc60.5-454) of 5.6-QA tree. Sergei; note that these are additional ones to the ones I provided you with on IRC (though they may be included, cannot recall which ones I sampled to you)

Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :

There definitely seems to be an interaction between threads as discussed, two threads in abort(), one actually reaching the assert first + 2 diag streams to error log

Roel Van de Paar (roel11) wrote :

As per Sergei, this may cause long stalls when both log archiving and log tracking turned on.

tags: removed: 56qual
Roel Van de Paar (roel11) wrote :

Needs two features enabled, one of which is beta.

I can reproduce this by running following script:

for i in {1..30} ; do

 (
 (echo "create table tbl_$i (blb longblob, blb2 longblob, blb3 longblob, blb4 longblob) engine=InnoDB;";
 for j in {1..1000} ; do
  # echo 'insert into tbl values (1,2,3,4);'
  echo "insert into tbl_$i (blb, blb2, blb3, blb4) values (LOAD_FILE('../../std_data/Index.xml'), LOAD_FILE('../../std_data/Index.xml'), LOAD_FILE('../../std_data/Index.xml'), LOAD_FILE('../../std_data/Index.xml'));";
 done) | ../client/mysql -uroot --socket=/Users/sergei/percona/repo/ps-bug1193319/5.6-ps-bug1193319/obj/mysql-test/var/tmp/mysqld.1.sock test ) &
done
wait

It is harder to hit with large log file size, but still possible by increasing the range for $i in the script.
Moving check for log tracking margin to be the last makes bug harder to hit and failures becoming little different.
I see two or more threads in log_open loop fails together like they are doing this synchronously.

After I modified the loop to continue to check margins instead of going to the beginning of the loop, situation seems improved.

++count < 50 assert can be violated with only log archiving turned on, as well as with only log tracking turned on.

in fact even without log archiving and log tracking I see ++count < 50 failures. You have to make log small enough (like 1M)

Download full text (3.6 KiB)

Saw 10 out of 50 threads ut_ad simultaneously on unmodified code. Log buffer size = 10M, log file size = 10.

013-10-31 15:01:42 10d80f0002013-10-31 15:01:42 10d0930002013-10-31 15:01:42 10de2d0002013-10-31 15:01:42 10d9e40002013-10-31 15:01:42 10d8950002013-10-31 15:01:42 10d00d0002013-10-31 15:01:42 10d0500002013-10-31 15:01:42 10d7030002013-10-31 15:01:42 10d0d60002013-10-31 15:01:42 10da270002013-10-31 15:01:42 10d4eb000 InnoDB: Assertion failure in thread 4521521152 in file log0log.cc line 308
  InnoDB: Assertion failure in thread 4513673216 in file log0log.cc line 308
  InnoDB: Assertion failure in thread 4527935488 in file log0log.cc line 308
  InnoDB: Assertion failure in thread 4523442176 in file log0log.cc line 308
  InnoDB: Assertion failure in thread 4522070016 in file log0log.cc line 308
  InnoDB: Assertion failure in thread 4513124352 in file log0log.cc line 308
  InnoDB: Assertion failure in thread 4513398784 in file log0log.cc line 308
  InnoDB: Assertion failure in thread 4520423424 in file log0log.cc line 308
  InnoDB: Assertion failure in thread 4513947648 in file log0log.cc line 308
  InnoDB: Assertion failure in thread 4523716608 in file log0log.cc line 308
  InnoDB: Assertion failure in thread 4518227968 in file log0log.cc line 308
InnoDB: Failing assertion: ++count < 50
InnoDB: Failing assertion: ++count < 50
InnoDB: Failing assertion: ++count < 50
InnoDB: Failing assertion: ++count < 50
InnoDB: Failing assertion: ++count < 50
InnoDB: Failing assertion: ++count < 50
InnoDB: Failing assertion: ++count < 50
InnoDB: Failing assertion: ++count < 50
InnoDB: Failing assertion: ++count < 50
InnoDB: Failing assertion: ++count < 50
InnoDB: Failing assertion: ++count < 50
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB table...

Read more...

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

Other bug subscribers