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

[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?

See also bug 1193332

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

Upgrade to qablock: seen in many runs.

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.

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

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

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

(yes... it printed twice)

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

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.

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

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

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

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;
}

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)

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

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

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)

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...

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