Bug #58536 Failing assertion: loop_count < 5 in storage/innobase/log/log0log.c line 1376
Submitted: 27 Nov 2010 22:00 Modified: 28 Feb 2017 11:10
Reporter: Elena Stepanova Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.6.1-m5-debug OS:Any
Assigned to: Sunny Bains CPU Architecture:Any

[27 Nov 2010 22:00] Elena Stepanova
Description:
On slave:

InnoDB: Assertion failure in thread 1887832384 in file mysql-5.6.1-m5/storage/innobase/log/log0log.c line 1376
InnoDB: Failing assertion: loop_count < 5
InnoDB: We intentionally generate a memory trap.

#5  0x00002b2e258f5fb0 in abort () from /lib64/libc.so.6
#6  0x0000000000a44837 in log_write_up_to (lsn=235497040, wait=91, flush_to_disk=1)
    at mysql-5.6.1-m5/storage/innobase/log/log0log.c:1376
#7  0x0000000000a4507e in log_buffer_sync_in_background (flush=1)
    at mysql-5.6.1-m5/storage/innobase/log/log0log.c:1609
#8  0x000000000099c112 in srv_sync_log_buffer_in_background ()
    at mysql-5.6.1-m5/storage/innobase/srv/srv0srv.c:2112
#9  0x000000000099c668 in srv_master_thread (arg=0x0)
    at mysql-5.6.1-m5/storage/innobase/srv/srv0srv.c:2355
#10 0x00002b2e25214143 in start_thread () from /lib64/libpthread.so.0
#11 0x00002b2e259858cd in clone () from /lib64/libc.so.6
#12 0x0000000000000000 in ?? ()

How to repeat:
If the failure is repeatable, a test case will be provided.
[28 Nov 2010 23:04] Sunny Bains
This looks like a debug assertion. 5 seems to be an arbitrary choice. My first guess
is that increasing the value to say 10 should fix it in debug code without affecting
correctness.
[29 Nov 2010 18:51] Mikhail Izioumtchenko
there was a time I was seeing it for a while, then it would disappear.
I looked at the code and decided it was a harmless thing triggered
by known IO slowdowns on that machine.
We could either go with Sunny proposal or consider removing this assertion
altogether.
[15 Dec 2010 15:27] Elena Stepanova
Based on comments by Sunny and Michael, I'm switching this to Verified -- please do whatever you find most appropriate.
[4 Apr 2013 18:50] Roel Van de Paar
Seeing this lots in Percona Server 5.6 debug build also. I would expect this assert to show up *lots* in most QA related testing.It would be great to see this fixed.

2013-04-04 21:01:45 1df73700  InnoDB: Assertion failure in thread 502740736 in file log0log.cc line 1351
InnoDB: Failing assertion: loop_count < 5
[4 Apr 2013 18:52] Roel Van de Paar
Error log

Attachment: master_26_040413-1146.err (application/octet-stream, text), 1.08 MiB.

[4 Apr 2013 18:53] Roel Van de Paar
thread apply all bt on core

Attachment: gdb_26_040413-1146_STD.txt (text/plain), 55.48 KiB.

[4 Apr 2013 18:53] Roel Van de Paar
thread apply all bt FULL on core

Attachment: gdb_26_040413-1146_FULL.txt (text/plain), 199.80 KiB.

[5 Apr 2013 15:14] Roel Van de Paar
The workaround (as suggested earlier in this bug) does indeed avoid the crash. If the reasoning (which I have not checked) of s/5/10/ is correct, can we please have this fixed ASAP?

=== modified file 'Percona-Server/storage/innobase/log/log0log.cc'
--- Percona-Server/storage/innobase/log/log0log.cc      2013-03-16 12:27:34 +0000
+++ Percona-Server/storage/innobase/log/log0log.cc      2013-04-04 20:02:58 +0000
@@ -1348,7 +1348,7 @@
 #ifdef UNIV_DEBUG
        loop_count++;

-       ut_ad(loop_count < 5);
+       ut_ad(loop_count < 10);

 # if 0
        if (loop_count > 2) {
[5 Apr 2013 15:17] Roel Van de Paar
Random thought: if 5 was not arbitrary, maybe <= 5 was intended? Did not verify if that works, but may be a lead during debugging.
[5 Apr 2013 20:44] Roel Van de Paar
More news. <10 results in much less assertion 'crashes', but they are still seen very occasionally: 

2013-04-05 01:45:04 1e373700  InnoDB: Assertion failure in thread 506935040 in file log0log.cc line 1351
InnoDB: Failing assertion: loop_count < 10

So, the workaround works, but even 10 is not enough yet it seems.
[5 Apr 2013 20:54] Roel Van de Paar
It was suggested earlier in the bug it may be related to i/o slowness etc. I can confirm that the box that this happened on was loaded significantly with quite a few simultaneous RQG threads. So, the issue may be load related and as such the number may indeed be "arbitrary". If so, can we maybe set it to 25 orso (or even 40?) to have a more sensible value? If the idea is to detect infinite loops, even a higher number (100) may be quite fine.
[3 Aug 2013 5:40] Roel Van de Paar
This is also present in 5.5...

Any updates on a fix for this?
[3 Aug 2013 5:41] Roel Van de Paar
5.5. occurence error log

Attachment: master_112_290713-0548.err (application/octet-stream, text), 1.37 MiB.

[5 Aug 2013 22:16] Roel Van de Paar
Correction: [3 Aug 5:40] & [3 Aug 5:41]; they are another 5.6 occurrence. Not confirmed if 5.5 is affected.
[23 Aug 2013 23:32] Roel Van de Paar
Any updates? Still seeing this heaps in testing.
[21 Jul 2014 9:27] Ramesh Sivaraman
Also seen in 5.5, please update versions affected

vardir1_613/log/master.err:140714  7:49:24  InnoDB: Assertion failure in thread 140294100514560 in file log0log.c line 409
vardir1_613/log/master.err:InnoDB: Failing assertion: ++count < 50
vardir1_613/log/master.err:/data/bench/qa55dbg/Percona-Server-5.5.37-rel35.0-662-debug.Linux.x86_64/bin/mysqld(handle_fatal_signal+0x314)[0x6c266c]
vardir1_613/log/master.err-/lib64/libc.so.6(gsignal+0x35)[0x7f98c97478e5]
[28 Feb 2017 11:10] Elena Stepanova
As Marko Mäkelä points out in https://jira.mariadb.org/browse/MDEV-12127, this problem was actually fixed in 5.7 in scope of WL#6044, the limit was increased from 5 to 128. I will try to close this report, from the interface it looks like I am allowed to.