Bug #38568 Falcon assertion in Record::release - useCount > 0
Submitted: 5 Aug 2008 11:47 Modified: 15 May 2009 13:49
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S1 (Critical)
Version:6.0-falcon OS:Any
Assigned to: Kevin Lewis CPU Architecture:Any
Tags: F_RECORD TREE, pb2, pushbuild, test failure
Triage: Triaged: D1 (Critical)

[5 Aug 2008 11:47] Philip Stoev
Description:
When executing and insert/update scenario with chill_threshold=8K, Falcon asserted as follows:

#0  0x085b2241 in Record::release (this=0xa61cfc98) at Record.cpp:525
#1  0x0853043c in Table::fetchForUpdate (this=0xb7452e98, transaction=0xb7275940, source=0xa61cfc98, usingIndex=true) at Table.cpp:3539
#2  0x0851b925 in StorageDatabase::nextIndexed (this=0xb70dc130, storageTable=0xb4ec1ce0, recordBitmap=0xb7226c60, recordNumber=1, lockForUpdate=true)
    at StorageDatabase.cpp:428
#3  0x08521e67 in StorageTable::nextIndexed (this=0xb4ec1ce0, recordNumber=0, lockForUpdate=true) at StorageTable.cpp:182
#4  0x08514fcc in StorageInterface::index_next (this=0xb81dd98, buf=0xb81df60 "") at ha_falcon.cpp:1597
#5  0x08513bf9 in StorageInterface::read_range_first (this=0xb81dd98, start_key=0x0, end_key=0xb81de3c, eq_range_arg=false, sorted=false)
    at ha_falcon.cpp:1565
#6  0x083ce5fa in handler::multi_range_read_next (this=0xb81dd98, range_info=0xa729e170) at handler.cc:4258
#7  0x083aeeef in QUICK_RANGE_SELECT::get_next (this=0xa6e9fc00) at opt_range.cc:8518
#8  0x083c8897 in rr_quick (info=0xa729e33c) at records.cc:298
#9  0x0835fc35 in mysql_update (thd=0xa7f982c0, table_list=0xb678b00, fields=@0xa7f99758, values=@0xa7f99988, conds=0xb679188, order_num=0, order=0x0,
    limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:573
#10 0x082bf817 in mysql_execute_command (thd=0xa7f982c0) at sql_parse.cc:2846
#11 0x082c63e1 in mysql_parse (thd=0xa7f982c0, inBuf=0xb6787e8 "UPDATE B AS X SET `pk` = 164 WHERE X . `int_key` < 197", length=54,
    found_semicolon=0xa729f270) at sql_parse.cc:5809
#12 0x082c6e55 in dispatch_command (command=COM_QUERY, thd=0xa7f982c0, packet=0xa7f9a619 "UPDATE B AS X SET `pk` = 164 WHERE X . `int_key` < 197",
    packet_length=54) at sql_parse.cc:1050
#13 0x082c8145 in do_command (thd=0xa7f982c0) at sql_parse.cc:723
#14 0x082b5e23 in handle_one_connection (arg=0xa7f982c0) at sql_connect.cc:1153
#15 0x0057d32f in start_thread () from /lib/libpthread.so.0
#16 0x0049a27e in clone () from /lib/libc.so.6

520             INTERLOCKED_INCREMENT (useCount);
521     }
522
523     void Record::release()
524     {
525             ASSERT (useCount > 0); <<<<<<<<<<<<<<<< HERE
526
527             if (INTERLOCKED_DECREMENT (useCount) == 0)
528                     {
529                     /*** debugging only

(gdb) print * this
Cannot access memory at address 0xa61cfc98

How to repeat:
If this is repeatable, a test case will be provided.

Suggested fix:
It appears that in StorageDatabase::nextIndexed(), a bad pointer to a Record was created. This pointer was passed down the call stack a few levels before the issue was detected. Maybe some extra assertions would have helped catch this closer to the source.
[20 Feb 2009 15:04] Hakan Küçükyılmaz
Similar failure is seen with DBT2 run on lu0009:

090220 14:19:59 [Note] /data0/work/mysql/mysql-6.0-falcon/sql/mysqld: ready for connections.
Version: '6.0.10-alpha'  socket: '/tmp/mysql.sock'  port: 3306  'MySQL-Community-Server'
[Falcon] Error: assertion (record->useCount >= 2) failed at line 3534 in file Table.cpp

090220 14:21:55 - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=8388608
read_buffer_size=1048576
max_used_connections=64
max_threads=1601
thread_count=64
connection_count=64
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4935933 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x7f0170027a30
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x400530e0 thread_stack 0x40000
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(my_print_stacktrace+0x2e) [0xb0c3de]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(handle_segfault+0x373) [0x685c53]
/lib/libpthread.so.0 [0x7f01783300f0]
/lib/libpthread.so.0(raise+0x2b) [0x7f017832ffab]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(Error::error(char const*, ...)+0x109) [0x8977f9]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(Table::fetchForUpdate(Transaction*, Record*, bool)+0x334) [0x8b46
f4]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(StorageDatabase::nextIndexed(StorageTable*, void*, int, bool)+0x8
9) [0x89eab9]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(StorageInterface::index_next(unsigned char*)+0x103) [0x8925d3]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(StorageInterface::read_range_first(st_key_range const*, st_key_ra
nge const*, bool, bool)+0x74) [0x891dd4]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(handler::multi_range_read_next(char**)+0x92) [0x78d132]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(QUICK_RANGE_SELECT::get_next()+0x36) [0x76eb46]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld [0x78900e]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*,
unsigned int, st_order*, unsigned long long, enum_duplicates, bool)+0x91d) [0x728c9d]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(mysql_execute_command(THD*)+0xee4) [0x697904]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(mysql_parse(THD*, char const*, unsigned int, char const**)+0x3b9)
 [0x69c039]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+
0xb4c) [0x69cfbc]
/data0/work/mysql/mysql-6.0-falcon/sql/mysqld(handle_one_connection+0x1a1) [0x68f931]
/lib/libpthread.so.0 [0x7f01783283ea]
/lib/libc.so.6(clone+0x6d) [0x7f017729acbd]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x3a480c8 = UPDATE order_line
SET ol_delivery_d = current_timestamp
WHERE ol_o_id = 2101
  AND ol_w_id = 1
  AND ol_d_id = 1
thd->thread_id=20
thd->killed=NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
pure virtual method called
terminate called without an active exception
[13 Mar 2009 15:29] John Embretsen
Also seen when running stress_tx_rr (transactional stress test suite), using 8 concurrent threads against mysql-6.0-falcon-team branch as of 2009-03-13.

090313 16:00:26 [Note] /home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld: ready for connections.
Version: '6.0.11-alpha-debug-log'  socket: '/tmp/hvwABaaWDu/master.sock'  port: 9306  Source distribution
[Falcon] Error: assertion (useCount > 0) failed at line 551 in file Record.cpp

090313 16:05:45 - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=10
max_threads=151
thread_count=8
connection_count=8
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 60022 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0xada36638
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0xae4f0fb0 thread_stack 0x30c00
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(my_print_stacktrace+0x32) [0x8864d95]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(handle_segfault+0x2cd) [0x82b92b1]
[0xb80cc400]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(Error::debugBreak()+0x12) [0x85d66f4]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(Error::error(char const*, ...)+0x98) [0x85d678e]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(Error::assertionFailed(char const*, char const*, int)+0x27) [0x85d6837]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(Record::release()+0x24) [0x860f2d8]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(StorageDatabase::nextRow(StorageTable*, int, bool)+0x17f) [0x8570cd3]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(StorageTable::next(int, bool)+0x3a) [0x85775a0]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(StorageInterface::rnd_next(unsigned char*)+0x92) [0x85685e4]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(rr_sequential(READ_RECORD*)+0x78) [0x83fb68e]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(sub_select(JOIN*, st_join_table*, bool)+0x212) [0x83419e1]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld [0x834e3e8]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(JOIN::exec()+0x20a9) [0x83653d3]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*)+0x30f) [0x835fee8]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(handle_select(THD*, LEX*, select_result*, unsigned long)+0x1ec) [0x83656cf]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(mysql_execute_command(THD*)+0x1cbc) [0x82cc0c4]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(mysql_parse(THD*, char const*, unsigned int, char const**)+0x22f) [0x82d3bb8]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x9f2) [0x82d473a]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(do_command(THD*)+0x244) [0x82d5cfe]
/home/johnemb/dev/mysql/bzr-repos/mysql-6.0-falcon-team-jsandbox/sql/mysqld(handle_one_connection+0x11d) [0x82c3074]
/lib/tls/i686/cmov/libpthread.so.0 [0xb808050f]
/lib/tls/i686/cmov/libc.so.6(clone+0x5e) [0xb7e887ee]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0xad38658 = CREATE TEMPORARY TABLE tmp2 (PRIMARY KEY (`pk`), KEY (`int1_key`), KEY (`int2_key`), UNIQUE (`int1_unique`), UNIQUE (`int2_unique`)) SELECT * from t1
thd->thread_id=2393
thd->killed=NOT_KILLED
[15 Mar 2009 12:53] Kevin Lewis
Without line numbers, I cannot tell which call to Record::release() was the problem. This bug reflects various conditions in which the useCount seems to be unbalanced.  There are two such call stacks.
[16 Mar 2009 8:08] John Embretsen
Stack trace with line numbers from crash during stress_tx_rr test.

Attachment: gdb-stacktrace_stress_tx_rr.txt (text/plain), 33.88 KiB.

[16 Mar 2009 8:11] John Embretsen
Here is part of the stack trace with line numbers from the latest crash/assert. For details, see the attached gdb output.

Error::assertionFailed(char const*, char const*, int)
 storage/falcon/Error.cpp:79
Record::release()
 storage/falcon/Record.cpp:551
StorageDatabase::nextRow(StorageTable*, int, bool)
 storage/falcon/StorageDatabase.cpp:317
StorageTable::next(int, bool)
 storage/falcon/StorageTable.cpp:158
StorageInterface::rnd_next(unsigned char*)
 storage/falcon/ha_falcon.cpp:651
rr_sequential(READ_RECORD*)
 sql/records.cc:390
sub_select(JOIN*, st_join_table*, bool)
 sql/sql_select.cc:16245
do_select
 sql/sql_select.cc:15786
(...)
[12 Apr 2009 14:57] Philip Stoev
Now happens more than once in the new Cycle Manager - on 2 out of 57 test runs. It also has happened with DBT2 and with workloads using all-default Falcon options, with no explicit chill/thaw settings.

# 15:54:27 #7  0x00000000009831bf in Error::assertionFailed (
# 15:54:27     text=0xe7cfb5 "useCount > 0", fileName=0xe7cf80 "Record.cpp", line=542)
# 15:54:27     at Error.cpp:78
# 15:54:27 #8  0x0000000000a249a8 in Record::release (this=0x2aaab4fa2328)
# 15:54:27     at Record.cpp:542
# 15:54:27 #9  0x00000000009d5181 in CycleManager::cycleManager (this=0x2aaaaadee2a8)
# 15:54:27     at CycleManager.cpp:124
# 15:54:27 #10 0x00000000009d540b in CycleManager::cycleManager (arg=0x2aaaaadee2a8)
# 15:54:27     at CycleManager.cpp:49
# 15:54:27 #11 0x00000000009b04cf in Thread::thread (this=0x2aaaaadf8838)
# 15:54:27     at Thread.cpp:167
# 15:54:27 #12 0x00000000009b06f7 in Thread::thread (parameter=0x2aaaaadf8838)
# 15:54:27     at Thread.cpp:146
# 15:54:27 #13 0x0000003587a062f7 in start_thread () from /lib64/libpthread.so.0
# 15:54:27 #14 0x0000003586ed1b6d in clone () from /lib64/libc.so.6
# 15:54:30 Using host libthread_db library "/lib64/libthread_db.so.1".
# 15:54:30 Core was generated by `/export/home/pb2/test/sb_1-462247-1239511953.98/mysql-6.0.11-alpha-linux-x86_64'.
# 15:54:30 Program terminated with signal 6, Aborted.
# 15:54:30 #0  0x0000003587a0b122 in pthread_kill () from /lib64/libpthread.so.0

Requesting re-triage to SR60BETA, I hope Kevin would agree.
[13 Apr 2009 5:12] Kevin Lewis
Philip,  Can you provide the RQG settings that cause this to fail 2 out of 57 times?  This is an old bug.  The code and the tests have evolved.  What is the best way to reproduce it now?
[13 Apr 2009 12:06] Philip Stoev
To reproduce:

perl runall.pl    --engine=Falcon   --reporters=Deadlock,ErrorLog,Backtrace,Recovery,Shutdown   --mysqld=--loose-falcon-lock-wait-timeout=1   --mysqld=--loose-innodb-lock-wait-timeout=1   --mysqld=--log-output=none   --mysqld=--skip-safemalloc   --mysqld=--transaction-isolation=SERIALIZABLE --mysqld=--falcon-page-size=4K --mem --rows=1000 --threads=4 --mysqld=--falcon-use-supernodes=0   --mask=7447   --queries=100000000   --duration=900   --basedir=/build/bzr/6.0-falcon-team  --gendata=conf/combinations.zz  --grammar=conf/combinations.yy 

Note that I have no idea why record memory gets exhausted in this test. I see no reason for that, so it may be a bug on its own.
[13 Apr 2009 15:20] Kevin Lewis
Philip, This is the first mention of "record memory gets exhausted".  Does that have anything to do with reproducing this bug?
[13 Apr 2009 15:24] Philip Stoev
Kevin, at least some of the occurrences of "useCount > 0" happened without the "record memory is exhausted" message. Therefore, those may be two separate things. Let me know if you want a separate bug for the "record memory is exhausted" issue.
[16 Apr 2009 11:55] Kevin Lewis
On April 13, when Philip last repeated this bug, there existed a memory leak due to a patch for bug#44161 on April 10.  It was fixed on April 14.
[16 Apr 2009 12:10] Bugs System
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/72280

3128 Kevin Lewis	2009-04-16
      Bug#38568 - This patch may help to fix this bug.  Needs testing.
      
      All changes to Record::priorVersion are now done using 
      COMPARE_EXCHANGE_POINTER instead of direct assignments so that 
      we can be assured that a pointer was not lost.  If this fails, there are several 
      new FATAL errors, which is better than continuing with a race condition.  
      The only direct assignments left are in the RecordVersion constructors.
      
      When pruning, a call is made to clearPriorVersion and the following code 
      may or may not actually prune those records.  If not, they need to be 
      re-attached with setPriorVersion.  That was a possible but very rare 
      memory leak.
      
      In clearPriorVersion, instead of crashing with FATAL if the CAS fails,
      it will just return NULL so the pruning for that record will be skipped.
      This change in behavior might prevent a race condition.
[23 Apr 2009 7:22] Bugs System
Pushed into 6.0.11-alpha (revid:alik@sun.com-20090423071213-afmyrzvolemph7mz) (version source revid:hky@sun.com-20090421195958-j33v1cuo3yer9niu) (merge vers: 6.0.11-alpha) (pib:6)
[28 Apr 2009 17:14] Kevin Lewis
Philip Stoev reports that this bug no longer occurs, after a weekend battery of tests.
[1 May 2009 18:27] Bugs System
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/73244

2703 Kevin Lewis	2009-05-01
      Bug#38568 continued;  This is only a cleanup patch to the previous patch which uses COMPARE_EXCHANGE_POINTER on all calls that update RecordVersion::priorVersion.  Jim Starkey originally intended the priorRecord chain to be accessed in a completely non-blocking manner.  This use of CAS should be unneccessary, in theory.  It is used in order to try and catch any conflicting code path in which two separate threads may want to update a priorVersion pointer simultaneously, or nearly so on separate CPUs.  So these CAS assignments are enclosed in a new macro called  USE_CAS_FOR_PRIOR_VERSION  in this patch.  If there is no perceptible performance cost with this, the CAS code may become permanent and this patch can be undone.
      
      Basically, this patch  allows one to revert to the old direct assignments of priorVersion in order to test the performance.  That is done by commenting out 
      #define USE_CAS_FOR_PRIOR_VERSION
[15 May 2009 13:49] MC Brown
Internal/test failure. No changelog entry required.