Bug #41831 Error: assertion (record->state != recLock) failed at line 1999 in file Table.cp
Submitted: 2 Jan 2009 20:44 Modified: 15 May 2009 12:56
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S1 (Critical)
Version:6.0-falcon-team OS:Any
Assigned to: Kevin Lewis CPU Architecture:Any
Tags: F_SCAVENGER
Triage: Triaged: D1 (Critical)

[2 Jan 2009 20:44] Philip Stoev
Description:
When executing a simple random workload, Falcon asserted as follows:

#0  0x000000315b00c216 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000006563de in handle_segfault (sig=6) at mysqld.cc:2671
#2  <signal handler called>
#3  0x000000315b00efab in raise () from /lib64/libpthread.so.0
#4  0x00000000008a6d88 in Error::debugBreak () at Error.cpp:94
#5  Error::error (string=<value optimized out>) at Error.cpp:71
#6  0x0000000000861844 in Table::expungeRecordVersions (this=0x7fa9dd725db0, record=0x8cb1688, recordScavenge=0x7fa9d1bf5e30) at Table.cpp:1999
#7  0x00000000008d635c in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=<value optimized out>)
    at RecordVersion.cpp:208
#8  0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#9  0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#10 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#11 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#12 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#13 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#14 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#15 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#16 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#17 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#18 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#19 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#20 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#21 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#22 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#23 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#24 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#25 0x00000000008d6345 in RecordVersion::scavenge (this=0xffffffffffffffff, recordScavenge=0x7fa9d1bf5e30, lockType=6) at RecordVersion.cpp:227
#26 0x00000000008d2eac in RecordLeaf::retireRecords (this=<value optimized out>, table=0x7fa9dd725db0, base=0, recordScavenge=0x7fa9d1bf5e30)
    at RecordLeaf.cpp:173
#27 0x000000000093506c in RecordGroup::retireRecords (this=<value optimized out>, table=0x7fa9dd725db0, base=<value optimized out>,
    recordScavenge=0x7fa9d1bf5e30) at RecordGroup.cpp:124
#28 0x000000000085e053 in Table::retireRecords (this=0x7fa9dd725db0, recordScavenge=0x7fa9d1bf5e30) at Table.cpp:1885
#29 0x000000000089803b in Database::retireRecords (this=0x7fa9dd5b5bb8, forced=false) at Database.cpp:1820
#30 0x00000000008982d2 in Database::scavenge (this=0x7fa9dd5b5bb8) at Database.cpp:1740
#31 0x00000000008e2346 in Scavenger::scavenge (this=<value optimized out>) at Scavenger.cpp:58
#32 Scavenger::execute (this=0x7fa9dd3bddb0, scheduler=0x7fa9dd3bdcd0) at Scavenger.cpp:68
#33 0x00000000008e387c in Scheduler::schedule (this=0x7fa9dd3bdcd0) at Scheduler.cpp:137
#34 0x000000000086c153 in Thread::thread (this=0x7fa9dd3c7d68) at Thread.cpp:167
#35 0x000000000086c321 in Thread::thread (parameter=0x355a) at Thread.cpp:146
#36 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
#37 0x000000315a4e627d in clone () from /lib64/libc.so.6

(gdb) list
1994            return false;
1995    }
1996
1997    void Table::expungeRecordVersions(RecordVersion *record, RecordScavenge *recordScavenge)
1998    {
1999            ASSERT(record->state != recLock);
2000
2001            Record *prior = record->clearPriorVersion();
2002
2003            if (recordScavenge)

(gdb) print record->state
$1 = 4 '\004'

How to repeat:
If this is repeatable, a test case will be provided.
[7 Jan 2009 18:35] Kevin Lewis
Philip,  Please be aware that the new scavenger code will move this assert to;

+void RecordLeaf::pruneRecords (Table *table, int base, RecordScavenge *recordScavenge)
 {
 . . .
+		ASSERT(oldestVisible->state != recLock);

Since the algorithm is different, it is possible that the conditions that lead to this strange bug are no longer around.  Those changes will be pushed to falcon-team shortly.  See Bug#34893, Bug#36700, Bug#40342, Bug#40801
[8 Jan 2009 5:31] Kevin Lewis
I was able to reproduce this bug with RQG and the new assert mentioned previously with the new scavenger code.  

The records being pruned are in a strange state. 
The base record is state=recDeleted, 
next prior is recLocked in the same transaction, 
next prior is a record version from a previous transaction.

The delete should have used the lock record instead of creating its own record version.

+		data	{record=0x00000000}
		useCount	1	
		recordNumber	5091	
		size	88	
		generation	1	
		highWater	-13108	
		encoding	0	
		state	1  	{recDeleted}
		active	1
-		[RecordVersion]	
    virtualOffset	2422945
+		transaction	0x00000000
+		nextInTrans	0x00000000
+		prevInTrans	0x00000000
    transactionId	8327
    savePointId	4
    superceded	false	
-		priorVersion
    +		data	{record=0x00000000 }	
        useCount	2	
        recordNumber	5091	
        size	88	
        generation	1	
        highWater	-13108	
        encoding	0	
        state	4	   	{recLocked}
        active	0	
    -		[RecordVersion]
        virtualOffset	0	
    +		transaction	0x00000000 
    +		nextInTrans	0x00000000 
    +		prevInTrans	0x00000000 
        transactionId	8327
        savePointId	0
        superceded	true
    -		priorVersion	0x068333a0 
        +		data	{record=0x06833778 }
            useCount	1
        +		format	0x0418ebc8 
            recordNumber	5091
            size	101
            generation	1
            highWater	2
            encoding	4
            state	0
            active	0
        -		[RecordVersion]	
        +		priorVersion	0x00000000 
            virtualOffset	2420023
        +		transaction	0x00000000
        +		nextInTrans	0x00000000
        +		prevInTrans	0x00000000
            transactionId	8321
            savePointId	0	int
            superceded	false
[15 Jan 2009 4:33] Kevin Lewis
Move to patch pending.  I tested this code quite a bit. 
falcon_record_cache_memory_leak2 ran 25 times straight. 

The trigger somehow failed to send a message to commits@lists.mysql.com today, so here is the changeset info
revno: 2959
revision-id: klewis@mysql.com-20090114223344-og8t9pw03ckyexdw
committer: Kevin Lewis <klewis@mysql.com>
branch nick: mysql-6.0-falcon-team
timestamp: Wed 2009-01-14 16:33:44 -0600
message:
  Bug#42080, Bug#41831  In both of these bugs, the scavenger was pruning
  records that it should not have.  The record version chosen to start
  pruning is returned from RecordScavenge::inventoryRecord().  This
  function is improved so that only the oldest visible record is returned.
  In addition, Recordversion::committedbefore() is added to simplify
  the code and read RecordVersion::transaction only once since it can be
  set to null at any time.
[15 Jan 2009 4:36] Kevin Lewis
Found this message in Bug#42080;

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/63294

2959 Kevin Lewis	2009-01-14
      Bug#42080, Bug#41831  In both of these bugs, the scavenger was pruning
      records that it should not have.  The record version chosen to start 
      pruning is returned from RecordScavenge::inventoryRecord().  This 
      function is improved so that only the oldest visible record is returned.
      In addition, Recordversion::committedbefore() is added to simplify 
      the code and read RecordVersion::transaction only once since it can be 
      set to null at any time.
[28 Jan 2009 7:24] Vladislav Vaintroub
Assertion has been seen again with the latest Falcon-team,
yet on another location (RecordLeaf, line 143)

Following RQG command  was used to crash:

perl runall.pl   --mysqld=--falcon-page-size=8K      --rows=100   --threads=16   --mask=59   --queries=1000000   --duration=300   --basedir=G:\bzr\mysql-6.0-falcon-team   --engine=Falcon   --grammar=conf/combinations.yy   --gendata=conf/combinations.zz   --reporter=Deadlock,ErrorLog,Backtrace,Recovery   --mysqld=--loose-falcon-lock-wait-timeout=1   --mysqld=--log-output=none

Callstack:
 	mysqld.exe!Error::error(const char * string=0x0000000140afd238, ...)  Line 73	C++
 	mysqld.exe!Error::assertionFailed(const char * text=0x0000000140b28440, const char * fileName=0x0000000140b28428, int line=0x0000008f)  Line 79	C++
>	mysqld.exe!RecordLeaf::pruneRecords(Table * table=0x0000000004dbeb08, int base=0x00000001, RecordScavenge * recordScavenge=0x0000000005d9f7c0)  Line 143 + 0x2a bytes	C++
 	mysqld.exe!RecordGroup::pruneRecords(Table * table=0x0000000004dbeb08, int base=0x00000000, RecordScavenge * recordScavenge=0x0000000005d9f7c0)  Line 123	C++
 	mysqld.exe!Table::pruneRecords(RecordScavenge * recordScavenge=0x0000000005d9f7c0)  Line 1907 + 0x37 bytes	C++
 	mysqld.exe!Database::pruneRecords(RecordScavenge * recordScavenge=0x0000000005d9f7c0)  Line 1855 + 0x12 bytes	C++
 	mysqld.exe!Database::scavengeRecords()  Line 1806	C++
 	mysqld.exe!Database::scavenge()  Line 1771	C++
 	mysqld.exe!Database::scavengerThreadMain()  Line 1932	C++
 	mysqld.exe!Database::scavengerThreadMain(void * database=0x0000000004c10c28)  Line 1920	C++
 	mysqld.exe!Thread::thread()  Line 168	C++
 	mysqld.exe!Thread::thread(void * parameter=0x0000000004e2b0e8)  Line 146	C++
[30 Jan 2009 5:35] Kevin Lewis
Putting this bug back to patch queued because the other assert was fixed.  The current assert is still happenning and is tracked by Bug#42340 : Falcon assertion (oldestVisible->state != recLock) in RecordLeaf::pruneRecords, line 143
[13 Feb 2009 7:24] Bugs System
Pushed into 6.0.10-alpha (revid:alik@sun.com-20090211182317-uagkyj01fk30p1f8) (version source revid:klewis@mysql.com-20090114223344-og8t9pw03ckyexdw) (merge vers: 6.0.10-alpha) (pib:6)
[15 May 2009 12:56] MC Brown
An entry has been added to the 6.0.10 changelog: 

The Falcon storage engine has been updated to incorporate new code for the built-in scavenger service, which handles the caching of records in memory. This fixes a number of different issues related to the visibility of different records during certain operations and improves the memory usage.