InnoDB: Failing assertion: trx_sys->descr_n_used <= (trx_sys->rw_trx_list).count in file trx0trx.cc line 1492

[roel@qaserver 290300]$ cat cmd240
ps -ef | grep 'cmdrun_240' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /ssd/290300/cmdrun_240
mkdir /ssd/290300/cmdrun_240
cd /ssd/randgen
bash -c "set -o pipefail; perl /ssd/randgen/runall.pl --queries=100000000 --seed=190 --duration=300 --querytimeout=60 --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --mysqld=--slow_query_log --mysqld=--userstat --views --validator=Transformer --threads=25 --mysqld=--innodb_file_per_table=1 --basedir=/ssd/Percona-Server-5.6.12-rc60.4-405-debug.Linux.x86_64 --gendata=/ssd/randgen/conf/drizzle/outer_join_drizzle.zz --grammar=/tmp/416647/92.yy --mtr-build-thread=708 --mask=4769 --vardir1=/ssd/290300/cmdrun_240 > /ssd/290300/cmdrun240.log 2>&1"

[roel@qaserver randgen]$ bzr version-info
revision-id: <email address hidden>
date: 2013-07-01 15:03:36 -0700
build-date: 2013-07-13 08:44:40 +1000
revno: 867
branch-nick: randgen
[roel@qaserver randgen]$ cd /bzr/5.6
[roel@qaserver 5.6]$ bzr version-info
revision-id: <email address hidden>
date: 2013-07-12 09:09:16 +0000
build-date: 2013-07-13 08:44:52 +1000
revno: 405
branch-nick: 5.6

I tried to find the root cause of this bug by code analysis, but to no avail. All possible code paths involving trx descriptors management seem to comply with the invariant enforced by the failing assertion.

I also tried reproducing it locally using the randgen info posted here, but randgen is failing with STATUS_PERL_FAILURE after a few minutes with lots of obscure messages about a syntax error.

How reproducible is this bug? Can I get a core file to debug?

Alexey, thanks! Further work;

1. I tried reproducing this bug on recent binaries, without success
2. I verified recent logs for "descr_n_used" text, none found
3. Bug seems to be low frequency occurrence to start with

Removing 56qual tag, and marking as incomplete ftm, until seen again (if at all).

One small improvement is still possible; we could have try to reproduce the original environment as closely as possible, then gradually change one step at the time to see if/where bug is resoved, but this seems like unnecessary resource use given other variables.

FWIW I hit this at least once in local MTR testing, on rpl_parallel testcase. The run was started as --parallel=7 on a 4-core machine. I'll see if it saved the core dump. Unfortunately this was on a feature branch, not trunk.

Unfortunately I lost the original binary. This is one is rebuilt from identical tree with identical options, and it appears to load the core dump OK. But of course the bets are still off.

The feature branch sources were copied to lp:~laurynas-biveinis/percona-server/bug-1200788-repro if needed.

#6 0x0000000000d599d0 in trx_commit_in_memory (trx=0x7f5c6002e7a8, lsn=1954621) at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innobase/trx/trx0trx.cc:1496
1496 ut_ad(trx_sys->descr_n_used <= UT_LIST_GET_LEN(trx_sys->rw_trx_list));
(gdb) print trx_sys->descr_n_used
$1 = 1
(gdb) print trx_sys->rw_trx_list
$2 = {count = 1, start = 0x7f5c700196f8, end = 0x7f5c700196f8}

(gdb) bt
#0 0x00007f5cb2056f2c in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:62
#1 0x0000000000adb1f5 in my_write_core (sig=6) at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/mysys/stacktrace.c:422
#2 0x0000000000736961 in handle_fatal_signal (sig=6) at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/sql/signal_handler.cc:251
#3 <signal handler called>
#4 0x00007f5cb149b037 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5 0x00007f5cb149e698 in __GI_abort () at abort.c:90
#6 0x0000000000d599d0 in trx_commit_in_memory (trx=0x7f5c6002e7a8, lsn=1954621) at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innobase/trx/trx0trx.cc:1496
#7 0x0000000000d59e73 in trx_commit_low (trx=0x7f5c6002e7a8, mtr=0x7f5ca1b4a630) at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innobase/trx/trx0trx.cc:1566
#8 0x0000000000d59eff in trx_commit (trx=0x7f5c6002e7a8) at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innobase/trx/trx0trx.cc:1589
#9 0x0000000000d5a7eb in trx_commit_for_mysql (trx=0x7f5c6002e7a8) at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innobase/trx/trx0trx.cc:1815
#10 0x0000000000e0890f in dict_stats_exec_sql (pinfo=0x7f5c6002d328, sql=0x1130000 "ize,\n:stat_description\n);\nEND;")
    at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innobase/dict/dict0stats.cc:298
#11 0x0000000000e0c1b8 in dict_stats_save_index_stat (index=0x7f5c6002da80, last_update=1380173996, stat_name=0x112eb07 "->magic_n == 375767", stat_value=1, sample_size=0x0,
    stat_description=0x11303e0 "le statistics for table %s: %s\n") at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innobase/dict/dict0stats.cc:2169
#12 0x0000000000e0c65c in dict_stats_save (table_orig=0x7f5c70081708) at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innobase/dict/dict0stats.cc:2314
#13 0x0000000000e0dc3d in dict_stats_update (table=0x7f5c70081708, stats_upd_option=DICT_STATS_RECALC_PERSISTENT)
    at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innobase/dict/dict0stats.cc:2949
#14 0x0000000000e10d02 in dict_stats_process_entry_from_recalc_pool () at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innobase/dict/dict0stats_bg.cc:302
#15 0x0000000000e10de4 in dict_stats_thread (arg=0x0) at /home/laurynas/percona/src/xtradb-thread-priority-flag/Percona-Server/storage/innob...

Seen again in 5.6.13-rc60.5-450-debug in 5.6-QA branch (custom randgen)

The check

 ut_ad(trx_sys->descr_n_used <= UT_LIST_GET_LEN(trx_sys->rw_trx_list));

in trx_commit_in_memory() happens outside trx_sys->mutex protection.

Indeed, it's rather a merge regression from 5.5. The invariant is supposed to be enforced whenever trx_sys->rw_trx_list is modified, i.e. when trx_sys->mutex is locked. Which is done earlier in the same function. The same assertion later (with trx_sys->mutex released) is therefore redundant. I will remove it.

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