tokudb_compare_two_keys: Assertion `Handlerton: false ' failed (errno=11)

Bug #1501633 reported by Rick Pizzi on 2015-10-01
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
High
Jun Yuan
5.6
Fix Released
High
Jun Yuan

Bug Description

https://tokutek.atlassian.net/browse/DB-884 : TokuDB crashes under sysbench in READ-COMMITTED mode

After upgrading to latest version of Percona Server with TokuDB, on a server with TokuDB only tables, we just got the below crash.

Version: '5.6.26-74.0-log' socket: '/dbstorage/data/mysql/mysql.sock' port: 3306 Percona Server (GPL), Release 74.0, Revision
 32f8dfd
/mnt/workspace/percona-server-5.6-redhat-binary-new/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.26-74.0/storage/tokud
b/hatoku_cmp.cc:1623 tokudb_compare_two_keys: Assertion `Handlerton: false ' failed (errno=11)
: Resource temporarily unavailable
Backtrace: (Note: toku_do_assert=0x0x7f39ca8d7bb0)
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z19db_env_do_backtraceP8_IO_FILE+0x1b)[0x7f39ca96d03b]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x1211c3)[0x7f39ca96d1c3]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x88e17)[0x7f39ca8d4e17]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x8ba28)[0x7f39ca8d7a28]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z21toku_hton_assert_failPKcS0_S0_ii+0x88)[0x7f39ca893e18]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x563ff)[0x7f39ca8a23ff]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x564a3)[0x7f39ca8a24a3]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z33toku_msg_buffer_key_msn_heavisideRKiRK39toku_msg_buffer_key_msn_heaviside_extra+0xa5)[0
x7f39ca8e3d85]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x9a1a4)[0x7f39ca8e61a4]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x9a4a0)[0x7f39ca8e64a0]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z25toku_pin_ftnode_for_queryP9ft_handle10blocknum_sjP9unlockersP9ancestorsRK12pivot_bounds
P18ftnode_fetch_extrabPP6ftnodePb+0x18d)[0x7f39ca92604d]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xd15b2)[0x7f39ca91d5b2]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xd167c)[0x7f39ca91d67c]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xd167c)[0x7f39ca91d67c]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z14toku_ft_searchP9ft_handleP9ft_searchPFijPKvjS4_PvbES5_P9ft_cursorb+0x22d)[0x7f39ca91e60
d]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z24toku_ft_cursor_set_rangeP9ft_cursorP10__toku_dbtS2_PFijPKvjS4_PvbES5_+0x71)[0x7f39ca93e
431]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x12fd98)[0x7f39ca97bd98]
/usr/lib64/mysql/plugin/ha_tokudb.so(_ZN9ha_tokudb10index_readEPhPKhj16ha_rkey_function+0x3b4)[0x7f39ca8ab694]
/usr/sbin/mysqld(_ZN7handler17ha_index_read_mapEPhPKhm16ha_rkey_function+0xb4)[0x59b7f4]
/usr/sbin/mysqld(_ZN12ha_partition36handle_unordered_scan_next_partitionEPh+0x131)[0xb49e11]
/usr/sbin/mysqld(_ZN7handler17ha_index_read_mapEPhPKhm16ha_rkey_function+0x72)[0x59b7b2]
/usr/sbin/mysqld[0x6b900c]
/usr/sbin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0xdd)[0x6b64bd]
[root@dbrumbac logs]# cat bug
Version: '5.6.26-74.0-log' socket: '/dbstorage/data/mysql/mysql.sock' port: 3306 Percona Server (GPL), Release 74.0, Revision 32f8dfd
/mnt/workspace/percona-server-5.6-redhat-binary-new/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.26-74.0/storage/tokudb/hatoku_cmp.cc:1623 tokudb_compare_two_keys: Assertion `Handlerton: false ' failed (errno=11)
: Resource temporarily unavailable
Backtrace: (Note: toku_do_assert=0x0x7f39ca8d7bb0)
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z19db_env_do_backtraceP8_IO_FILE+0x1b)[0x7f39ca96d03b]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x1211c3)[0x7f39ca96d1c3]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x88e17)[0x7f39ca8d4e17]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x8ba28)[0x7f39ca8d7a28]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z21toku_hton_assert_failPKcS0_S0_ii+0x88)[0x7f39ca893e18]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x563ff)[0x7f39ca8a23ff]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x564a3)[0x7f39ca8a24a3]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z33toku_msg_buffer_key_msn_heavisideRKiRK39toku_msg_buffer_key_msn_heaviside_extra+0xa5)[0x7f39ca8e3d85]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x9a1a4)[0x7f39ca8e61a4]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x9a4a0)[0x7f39ca8e64a0]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z25toku_pin_ftnode_for_queryP9ft_handle10blocknum_sjP9unlockersP9ancestorsRK12pivot_boundsP18ftnode_fetch_extrabPP6ftnodePb+0x18d)[0x7f39ca92604d]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xd15b2)[0x7f39ca91d5b2]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xd167c)[0x7f39ca91d67c]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xd167c)[0x7f39ca91d67c]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z14toku_ft_searchP9ft_handleP9ft_searchPFijPKvjS4_PvbES5_P9ft_cursorb+0x22d)[0x7f39ca91e60d]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z24toku_ft_cursor_set_rangeP9ft_cursorP10__toku_dbtS2_PFijPKvjS4_PvbES5_+0x71)[0x7f39ca93e431]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x12fd98)[0x7f39ca97bd98]
/usr/lib64/mysql/plugin/ha_tokudb.so(_ZN9ha_tokudb10index_readEPhPKhj16ha_rkey_function+0x3b4)[0x7f39ca8ab694]
/usr/sbin/mysqld(_ZN7handler17ha_index_read_mapEPhPKhm16ha_rkey_function+0xb4)[0x59b7f4]
/usr/sbin/mysqld(_ZN12ha_partition36handle_unordered_scan_next_partitionEPh+0x131)[0xb49e11]
/usr/sbin/mysqld(_ZN7handler17ha_index_read_mapEPhPKhm16ha_rkey_function+0x72)[0x59b7b2]
/usr/sbin/mysqld[0x6b900c]
/usr/sbin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0xdd)[0x6b64bd]
/usr/sbin/mysqld(_ZN4JOIN4execEv+0x2b8)[0x6b5758]
/usr/sbin/mysqld(_Z12mysql_selectP3THDP10TABLE_LISTjR4ListI4ItemEPS4_P10SQL_I_ListI8st_orderESB_S7_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x275)[0x6ff435]
/usr/sbin/mysqld(_Z13handle_selectP3THDP13select_resultm+0x165)[0x6ffc95]
/usr/sbin/mysqld[0x55c148]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1a9c)[0x6d8d6c]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5a8)[0x6de3f8]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x107c)[0x6dfc0c]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x162)[0x6ac5d2]
/usr/sbin/mysqld(handle_one_connection+0x40)[0x6ac6c0]
/usr/sbin/mysqld(pfs_spawn_thread+0x143)[0xae0673]
/lib64/libpthread.so.0(+0x79d1)[0x7f3a098e79d1]
/lib64/libc.so.6(clone+0x6d)[0x7f3a080018fd]
Engine status:
BUILD_ID = 0
Env panic code: 11
Env panic string: /mnt/workspace/percona-server-5.6-redhat-binary-new/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.26-74.0/storage/tokudb/hatoku_cmp.cc:1623 tokudb_compare_two_keys: Assertion `Handlerton: false ' failed (errno=11)

time of environment creation: Mon May 18 17:25:08 2015
time of engine startup: Thu Oct 1 00:44:54 2015
time now: Thu Oct 1 09:31:33 2015
db opens: 4605
db closes: 3120
num open dbs now: 1485
max open dbs: 1530
period, in ms, that recovery log is automatically fsynced: 5000
dictionary inserts: 109
dictionary inserts fail: 0
dictionary deletes: 1560
dictionary deletes fail: 0
dictionary updates: 0
dictionary updates fail: 0
dictionary broadcast updates: 0
dictionary broadcast updates fail: 0
dictionary multi inserts: 6747980
dictionary multi inserts fail: 0
dictionary multi deletes: 5005366
dictionary multi deletes fail: 0
dictionary updates multi: 0
dictionary updates multi fail: 0
le: max committed xr: 7
le: max provisional xr: 2
le: expanded: 0
le: max memsize: 222016
le: size of leafentries before garbage collection (during message application): 70027701494
le: size of leafentries after garbage collection (during message application): 30673549662
le: size of leafentries before garbage collection (outside message application): 0
le: size of leafentries after garbage collection (outside message application): 0
checkpoint: period: 60
checkpoint: footprint: 0
checkpoint: last checkpoint began: Thu Oct 1 09:30:55 2015
checkpoint: last complete checkpoint began: Thu Oct 1 09:30:55 2015
checkpoint: last complete checkpoint ended: Thu Oct 1 09:31:14 2015
checkpoint: time spent during checkpoint (begin and end phases): 4498
checkpoint: time spent during last checkpoint (begin and end phases): 19
checkpoint: last complete checkpoint LSN: 17047367327
checkpoint: checkpoints taken : 528
checkpoint: checkpoints failed: 0
checkpoint: waiters now: 0
checkpoint: waiters max: 0
checkpoint: non-checkpoint client wait on mo lock: 2245
checkpoint: non-checkpoint client wait on cs lock: 0
checkpoint: checkpoint begin time: 22997928
checkpoint: long checkpoint begin time: 0
checkpoint: long checkpoint begin count: 0
checkpoint: checkpoint end time: 4470540633
checkpoint: long checkpoint end time: 0
checkpoint: long checkpoint end count: 0
cachetable: miss: 315849
cachetable: miss time: 411700880
cachetable: prefetches: 0
cachetable: size current: 67654486018
cachetable: size limit: 68144541696
cachetable: size writing: 0
cachetable: size nonleaf: 47553472939
cachetable: size leaf: 20101005815
cachetable: size rollback: 7264
cachetable: size cachepressure: 142473545729
cachetable: size currently cloned data for checkpoint: 0
cachetable: evictions: 43192
cachetable: cleaner executions: 49873
cachetable: cleaner period: 1
cachetable: cleaner iterations: 5
cachetable: number of waits on cache pressure: 0
cachetable: time waiting on cache pressure: 0
cachetable: number of long waits on cache pressure: 0
cachetable: long time waiting on cache pressure: 0
cachetable: number of threads in pool: 32
cachetable: number of currently active threads in pool: 0
cachetable: number of currently queued work items: 0
cachetable: largest number of queued work items: 2
cachetable: total number of work items processed: 203684
cachetable: total execution time of processing work items: 1980229
cachetable: number of threads in pool: 64
cachetable: number of currently active threads in pool: 0
cachetable: number of currently queued work items: 0
cachetable: largest number of queued work items: 594
cachetable: total number of work items processed: 70591
cachetable: total execution time of processing work items: 900489
cachetable: number of threads in pool: 8
cachetable: number of currently active threads in pool: 0
cachetable: number of currently queued work items: 0
cachetable: largest number of queued work items: 80
cachetable: total number of work items processed: 256246
cachetable: total execution time of processing work items: 1515190
locktree: memory size: 7422
locktree: memory size limit: 8450958848
locktree: number of times lock escalation ran: 0
locktree: time spent running escalation (seconds): 0.000000
locktree: latest post-escalation memory size: 0
locktree: number of locktrees open now: 1487
locktree: number of pending lock requests: 0
locktree: number of locktrees eligible for the STO: 28
locktree: number of times a locktree ended the STO early: 243743
locktree: time spent ending the STO early (seconds): 0.502986
locktree: number of wait locks: 1355
locktree: time waiting for locks: 4503772
locktree: number of long wait locks: 0
locktree: long time waiting for locks: 0
locktree: number of lock timeouts: 0
locktree: number of waits on lock escalation: 0
locktree: time waiting on lock escalation: 0
locktree: number of long waits on lock escalation: 0
locktree: long time waiting on lock escalation: 0
ft: dictionary updates: 0
ft: dictionary broadcast updates: 0
ft: descriptor set: 30
ft: messages ignored by leaf due to msn: 1018296
ft: total search retries due to TRY_AGAIN: 32405023
ft: searches requiring more tries than the height of the tree: 1776
ft: searches requiring more tries than the height of the tree plus three: 16
ft: leaf nodes flushed to disk (not for checkpoint): 189
ft: leaf nodes flushed to disk (not for checkpoint) (bytes): 276290048
ft: leaf nodes flushed to disk (not for checkpoint) (uncompressed bytes): 276195025
ft: leaf nodes flushed to disk (not for checkpoint) (seconds): 0.099028
ft: nonleaf nodes flushed to disk (not for checkpoint): 729
ft: nonleaf nodes flushed to disk (not for checkpoint) (bytes): 1238542336
ft: nonleaf nodes flushed to disk (not for checkpoint) (uncompressed bytes): 1238277978
ft: nonleaf nodes flushed to disk (not for checkpoint) (seconds): 0.522199
ft: leaf nodes flushed to disk (for checkpoint): 264488
ft: leaf nodes flushed to disk (for checkpoint) (bytes): 697929401856
ft: leaf nodes flushed to disk (for checkpoint) (uncompressed bytes): 697751260813
ft: leaf nodes flushed to disk (for checkpoint) (seconds): 308.599785
ft: nonleaf nodes flushed to disk (for checkpoint): 668628
ft: nonleaf nodes flushed to disk (for checkpoint) (bytes): 1087224536576
ft: nonleaf nodes flushed to disk (for checkpoint) (uncompressed bytes): 1086983012713
ft: nonleaf nodes flushed to disk (for checkpoint) (seconds): 485.674055
ft: uncompressed / compressed bytes written (leaf): UNKNOWN STATUS TYPE: 6
ft: uncompressed / compressed bytes written (nonleaf): UNKNOWN STATUS TYPE: 6
ft: uncompressed / compressed bytes written (overall): UNKNOWN STATUS TYPE: 6
ft: nonleaf node partial evictions: 213101
ft: nonleaf node partial evictions (bytes): 11508825527
ft: leaf node partial evictions: 45513645
ft: leaf node partial evictions (bytes): 3654072530088
ft: leaf node full evictions: 39774
ft: leaf node full evictions (bytes): 1717693649
ft: nonleaf node full evictions: 3419
ft: nonleaf node full evictions (bytes): 906435385
ft: leaf nodes created: 6230
ft: nonleaf nodes created: 599
ft: leaf nodes destroyed: 0
ft: nonleaf nodes destroyed: 0
ft: bytes of messages injected at root (all trees): 59380040470
ft: bytes of messages flushed from h1 nodes to leaves: 57382587621
ft: bytes of messages currently in trees (estimate): 1997452849
ft: messages injected at root: 15067864
ft: broadcast messages injected at root: 0
ft: basements decompressed as a target of a query: 1
ft: basements decompressed for prelocked range: 0
ft: basements decompressed for prefetch: 0
ft: basements decompressed for write: 0
ft: buffers decompressed as a target of a query: 385972
ft: buffers decompressed for prelocked range: 0
ft: buffers decompressed for prefetch: 0
ft: buffers decompressed for write: 33118
ft: pivots fetched for query: 291923
ft: pivots fetched for query (bytes): 9563975168
ft: pivots fetched for query (seconds): 144.122663
ft: pivots fetched for prefetch: 0
ft: pivots fetched for prefetch (bytes): 0
ft: pivots fetched for prefetch (seconds): 0.000000
ft: pivots fetched for write: 365
ft: pivots fetched for write (bytes): 11420672
ft: pivots fetched for write (seconds): 0.080375
ft: basements fetched as a target of a query: 36012451
ft: basements fetched as a target of a query (bytes): 2034289994240
ft: basements fetched as a target of a query (seconds): 22817.091520
ft: basements fetched for prelocked range: 3
ft: basements fetched for prelocked range (bytes): 185344
ft: basements fetched for prelocked range (seconds): 0.000041
ft: basements fetched for prefetch: 0
ft: basements fetched for prefetch (bytes): 0
ft: basements fetched for prefetch (seconds): 0.000000
ft: basements fetched for write: 9439887
ft: basements fetched for write (bytes): 510650164224
ft: basements fetched for write (seconds): 1722.169521
ft: buffers fetched as a target of a query: 66814
ft: buffers fetched as a target of a query (bytes): 8161275904
ft: buffers fetched as a target of a query (seconds): 36.717846
ft: buffers fetched for prelocked range: 0
ft: buffers fetched for prelocked range (bytes): 0
ft: buffers fetched for prelocked range (seconds): 0.000000
ft: buffers fetched for prefetch: 0
ft: buffers fetched for prefetch (bytes): 0
ft: buffers fetched for prefetch (seconds): 0.000000
ft: buffers fetched for write: 16157
ft: buffers fetched for write (bytes): 2304186880
ft: buffers fetched for write (seconds): 4.017983
ft: leaf compression to memory (seconds): 242.171640
ft: leaf serialization to memory (seconds): 436.567200
ft: leaf decompression to memory (seconds): 359.646953
ft: leaf deserialization to memory (seconds): 1066.857544
ft: nonleaf compression to memory (seconds): 1301.585790
ft: nonleaf serialization to memory (seconds): 695.911135
ft: nonleaf decompression to memory (seconds): 65.273543
ft: nonleaf deserialization to memory (seconds): 41.904045
ft: promotion: roots split: 14
ft: promotion: leaf roots injected into: 769988
ft: promotion: h1 roots injected into: 6694911
ft: promotion: injections at depth 0: 3906140
ft: promotion: injections at depth 1: 4745654
ft: promotion: injections at depth 2: 619363
ft: promotion: injections at depth 3: 25515
ft: promotion: injections lower than depth 3: 404
ft: promotion: stopped because of a nonempty buffer: 7819916
ft: promotion: stopped at height 1: 11244
ft: promotion: stopped because the child was locked or not at all in memory: 3
ft: promotion: stopped because the child was not fully in memory: 1192
ft: promotion: stopped anyway, after locking the child: 138534
ft: basement nodes deserialized with fixed-keysize: 10836713
ft: basement nodes deserialized with variable-keysize: 34616495
ft: promotion: succeeded in using the rightmost leaf shortcut: 0
ft: promotion: tried the rightmost leaf shorcut but failed (out-of-bounds): 0
ft: promotion: tried the rightmost leaf shorcut but failed (child reactive): 0
ft: cursor skipped deleted leaf entries: 5017366
ft flusher: total nodes potentially flushed by cleaner thread: 21439
ft flusher: height-one nodes flushed by cleaner thread: 19343
ft flusher: height-greater-than-one nodes flushed by cleaner thread: 2096
ft flusher: nodes cleaned which had empty buffers: 0
ft flusher: nodes dirtied by cleaner thread: 42287
ft flusher: max bytes in a buffer flushed by cleaner thread: 2358042
ft flusher: min bytes in a buffer flushed by cleaner thread: 258
ft flusher: total bytes in buffers flushed by cleaner thread: 6356214453
ft flusher: max workdone in a buffer flushed by cleaner thread: 15926196
ft flusher: min workdone in a buffer flushed by cleaner thread: 0
ft flusher: total workdone in buffers flushed by cleaner thread: 16052880323
ft flusher: times cleaner thread tries to merge a leaf: 3
ft flusher: cleaner thread leaf merges in progress: 0
ft flusher: cleaner thread leaf merges successful: 3
ft flusher: nodes dirtied by cleaner thread leaf merges: 4
ft flusher: total number of flushes done by flusher threads or cleaner threads: 240757
ft flusher: number of in memory flushes: 240757
ft flusher: number of flushes that read something off disk: 0
ft flusher: number of flushes that triggered another flush in child: 48047
ft flusher: number of flushes that triggered 1 cascading flush: 48030
ft flusher: number of flushes that triggered 2 cascading flushes: 17
ft flusher: number of flushes that triggered 3 cascading flushes: 0
ft flusher: number of flushes that triggered 4 cascading flushes: 0
ft flusher: number of flushes that triggered 5 cascading flushes: 0
ft flusher: number of flushes that triggered over 5 cascading flushes: 0
ft flusher: leaf node splits: 6185
ft flusher: nonleaf node splits: 585
ft flusher: leaf node merges: 4
ft flusher: nonleaf node merges: 0
ft flusher: leaf node balances: 1
hot: operations ever started: 0
hot: operations successfully completed: 0
hot: operations aborted: 0
hot: max number of flushes from root ever required to optimize a tree: 0
txn: begin: 10147362
txn: begin read only: 4219501
txn: successful commits: 14366231
txn: aborts: 625
logger: next LSN: 17047456909
logger: writes: 9901
logger: writes (bytes): 60007622773
logger: writes (uncompressed bytes): 60007622773
logger: writes (seconds): 35.114355
logger: number of long logger write operations: 0
indexer: number of indexers successfully created: 0
indexer: number of calls to toku_indexer_create_indexer() that failed: 0
indexer: number of calls to indexer->build() succeeded: 0
indexer: number of calls to indexer->build() failed: 0
indexer: number of calls to indexer->close() that succeeded: 0
indexer: number of calls to indexer->close() that failed: 0
indexer: number of calls to indexer->abort(): 0
indexer: number of indexers currently in existence: 0
indexer: max number of indexers that ever existed simultaneously: 0
loader: number of loaders successfully created: 0
loader: number of calls to toku_loader_create_loader() that failed: 0
loader: number of calls to loader->put() succeeded: 0
loader: number of calls to loader->put() failed: 0
loader: number of calls to loader->close() that succeeded: 0
loader: number of calls to loader->close() that failed: 0
loader: number of calls to loader->abort(): 0
loader: number of loaders currently in existence: 0
loader: max number of loaders that ever existed simultaneously: 0
memory: number of malloc operations: 0
memory: number of free operations: 0
memory: number of realloc operations: 0
memory: number of malloc operations that failed: 0
memory: number of realloc operations that failed: 2
memory: number of bytes requested: 0
memory: number of bytes used (requested + overhead): 0
memory: number of bytes freed: 0
memory: largest attempted allocation size: 0
memory: size of the last failed allocation attempt: 0
memory: estimated maximum memory footprint: 0
memory: mallocator version: 3.6.0-0-g46c0af68bd248b04df75e4f92d5fb804c3d75340
memory: mmap threshold: 4194304
filesystem: ENOSPC redzone state: 0
filesystem: threads currently blocked by full disk: 0
filesystem: number of operations rejected by enospc prevention (red zone): 0
filesystem: most recent disk full: Thu Jan 1 01:00:00 1970
filesystem: number of write operations that returned ENOSPC: 0
filesystem: fsync time: 1120687693
filesystem: fsync count: 402109
filesystem: long fsync time: 0
filesystem: long fsync count: 0
context: tree traversals blocked by a full fetch: 5771
context: tree traversals blocked by a partial fetch: 351976
context: tree traversals blocked by a full eviction: 0
context: tree traversals blocked by a partial eviction: 93
context: tree traversals blocked by a message injection: 7135
context: tree traversals blocked by a message application: 60613
context: tree traversals blocked by a flush: 13833
context: tree traversals blocked by a the cleaner thread: 31
context: tree traversals blocked by something uninstrumented: 85212
context: promotion blocked by a full fetch (should never happen): 0
context: promotion blocked by a partial fetch (should never happen): 0
context: promotion blocked by a full eviction (should never happen): 0
context: promotion blocked by a partial eviction (should never happen): 1
context: promotion blocked by a message injection: 936
context: promotion blocked by a message application: 0
context: promotion blocked by a flush: 0
context: promotion blocked by the cleaner thread: 2
context: promotion blocked by something uninstrumented: 4
context: something uninstrumented blocked by something uninstrumented: 47943

Memory usage:
Arena 0:
system bytes = 0
in use bytes = 0
Total (incl. mmap):
system bytes = 0
in use bytes = 0
max mmap regions = 0
max mmap bytes = 0
07:31:33 UTC - 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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

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

Thread pointer: 0x7f353cbfa000
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 = 7f39501b5d00 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8cf68c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x6566d1]
/lib64/libpthread.so.0(+0xf710)[0x7f3a098ef710]
/lib64/libc.so.6(gsignal+0x35)[0x7f3a07f4b625]
/lib64/libc.so.6(abort+0x175)[0x7f3a07f4ce05]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x1211c8)[0x7f39ca96d1c8]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x88e17)[0x7f39ca8d4e17]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x8ba28)[0x7f39ca8d7a28]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z21toku_hton_assert_failPKcS0_S0_ii+0x88)[0x7f39ca893e18]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x563ff)[0x7f39ca8a23ff]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x564a3)[0x7f39ca8a24a3]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z33toku_msg_buffer_key_msn_heavisideRKiRK39toku_msg_buffer_key_msn_heaviside_extra+0xa5)[0x7f39ca8e3d85]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x9a1a4)[0x7f39ca8e61a4]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x9a4a0)[0x7f39ca8e64a0]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z25toku_pin_ftnode_for_queryP9ft_handle10blocknum_sjP9unlockersP9ancestorsRK12pivot_boundsP18ftnode_fetch_extrabPP6ftnodePb+0x18d)[0x7f39ca92604d]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xd15b2)[0x7f39ca91d5b2]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xd167c)[0x7f39ca91d67c]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xd167c)[0x7f39ca91d67c]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z14toku_ft_searchP9ft_handleP9ft_searchPFijPKvjS4_PvbES5_P9ft_cursorb+0x22d)[0x7f39ca91e60d]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z24toku_ft_cursor_set_rangeP9ft_cursorP10__toku_dbtS2_PFijPKvjS4_PvbES5_+0x71)[0x7f39ca93e431]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x12fd98)[0x7f39ca97bd98]
/usr/lib64/mysql/plugin/ha_tokudb.so(_ZN9ha_tokudb10index_readEPhPKhj16ha_rkey_function+0x3b4)[0x7f39ca8ab694]
/usr/sbin/mysqld(_ZN7handler17ha_index_read_mapEPhPKhm16ha_rkey_function+0xb4)[0x59b7f4]
/usr/sbin/mysqld(_ZN12ha_partition36handle_unordered_scan_next_partitionEPh+0x131)[0xb49e11]
/usr/sbin/mysqld(_ZN7handler17ha_index_read_mapEPhPKhm16ha_rkey_function+0x72)[0x59b7b2]
/usr/sbin/mysqld[0x6b900c]
/usr/sbin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0xdd)[0x6b64bd]
/usr/sbin/mysqld(_ZN4JOIN4execEv+0x2b8)[0x6b5758]
/usr/sbin/mysqld(_Z12mysql_selectP3THDP10TABLE_LISTjR4ListI4ItemEPS4_P10SQL_I_ListI8st_orderESB_S7_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x275)[0x6ff435]
/usr/sbin/mysqld(_Z13handle_selectP3THDP13select_resultm+0x165)[0x6ffc95]
/usr/sbin/mysqld[0x55c148]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1a9c)[0x6d8d6c]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5a8)[0x6de3f8]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x107c)[0x6dfc0c]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x162)[0x6ac5d2]
/usr/sbin/mysqld(handle_one_connection+0x40)[0x6ac6c0]
/usr/sbin/mysqld(pfs_spawn_thread+0x143)[0xae0673]
/lib64/libpthread.so.0(+0x79d1)[0x7f3a098e79d1]
/lib64/libc.so.6(clone+0x6d)[0x7f3a080018fd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f361dfa6010): is an invalid pointer
Connection ID (thread ID): 3544
Status: NOT_KILLED

Rick Pizzi (pizzi) wrote :

my.cnf:

[mysql]
port = 3306
socket = /dbstorage/data/mysql/mysql.sock

[mysqld]
port = 3306

user = mysql
socket = /dbstorage/data/mysql/mysql.sock
pid_file = /dbstorage/data/mysql/mysql.pid

# MyISAM #
key_buffer_size = 32M
myisam-recover-options = FORCE,BACKUP

# SAFETY #
max_allowed_packet = 128M
max_connect_errors = 65535
wait_timeout = 3600
skip_name_resolve = 1

# DATA STORAGE #
datadir = /dbstorage/data/mysql
tmpdir = /storage/mysql/tmp

# BINARY LOGGING #
server-id = 888999991
#log_bin = /storage/mysql/binlog/master_binlog
#expire_logs_days = 6
#sync_binlog = 0
#binlog_format = MIXED
#log_slave_updates = 1
#relay-log = mysqld-relay-bin
#read_only = 0
#skip-slave-start = 1
#binlog_cache_size = 10M

# CACHES AND LIMITS #
tmp_table_size = 192M
max_heap_table_size = 192M
sort_buffer_size = 8M
join_buffer_size = 8M
query_cache_type = 0
query_cache_size = 0
max_connections = 2500
thread_cache_size = 100
open_files_limit = 65535
table_definition_cache = 4096
table_open_cache = 4096

# INNODB #
#ignore_builtin_innodb
#plugin-load=innodb=ha_innodb_plugin.so;innodb_trx=ha_innodb_plugin.so;innodb_locks=ha_innodb_plugin.so;innodb_lock_waits=ha_innodb_plugin.so;innodb_cmp=ha_innodb_plugin.so;innodb_cmp_reset=ha_innodb_plugin.so;innodb_cmpmem=ha_innodb_plugin.so;innodb_cmpmem_reset=ha_innodb_plugin.so
innodb_flush_method = O_DIRECT
innodb_log_files_in_group = 2
#innodb_log_file_size = 128M
innodb_log_file_size = 512M
innodb_flush_log_at_trx_commit = 0
innodb_file_per_table = 1
innodb_buffer_pool_size = 64M

#innodb_use_sys_malloc=0
innodb_file_format=barracuda
innodb_log_buffer_size = 64M
innodb_lock_wait_timeout = 120

# NEW PARAMETERS #
innodb_additional_mem_pool_size = 32M
innodb_max_dirty_pages_pct = 90
innodb_write_io_threads=8
innodb_read_io_threads=8

key_buffer_size = 16M
read_rnd_buffer_size = 16M

# LOGGING #
log-error=/dbstorage/data/logs/mysql5_errors.log
log_queries_not_using_indexes = 0
slow_query_log = 1
slow_query_log_file=/dbstorage/data/logs/mysql5_slow_query.log
long_query_time = 1
# back_log = 50

# RPIZZI #

transaction-isolation = READ-COMMITTED
innodb_adaptive_hash_index=OFF
innodb_support_xa=OFF
innodb_stats_on_metadata=0
innodb_adaptive_hash_index=OFF

tokudb_commit_sync=OFF
tokudb_fsync_log_period=5000
tokudb_row_format=tokudb_uncompressed

[mysqld_safe]
thp-setting=never
open-files-limit = 8192

[mysqladmin]
socket = /dbstorage/data/mysql/mysql.sock

Rick Pizzi (pizzi) wrote :

Further notes:

- this server ran for more than 3 months without a single issue, with previous version 5.6.24-72.2-log
- we only stopped, reduced innodb buffer pool from 8G to 64M, upgraded to latest version, restarted

Nothing else changed on OS level or DB level.

thank you

Rick

tags: added: tokudb
Rick Pizzi (pizzi) wrote :

Tried to downgrade to 5.6.24-72, this just did not work. No matter what we did, we were unable to have the TokuDB plugin initialize. Even a complete manual uninstall and reinstall of all the plugins led to an error:

2015-10-01 10:46:00 116816 [ERROR] TokuDB unknown error -100005

Not very meaningful.

George Ormond Lorch III (gl-az) wrote :

We have just recently been seeing this issue when 'transaction-isolation = READ-COMMITTED' and have had some reasonable success reproducing it under a basic sysbench OLTP load.

From my reviews, I see nothing from tokudb 7.5.7 to current in either the tokudb-engine or the fractal tree layer that could/would have introduced it. I suspect that it has been there all along but only recently has it surfaced.

We are looking into it and hope to have a fix soon.

Changed in percona-server:
status: New → Confirmed
importance: Undecided → High
assignee: nobody → George Ormond Lorch III (gl-az)
Changed in percona-server:
status: Confirmed → Triaged
Rick Pizzi (pizzi) wrote :

So, basically, will running with default isolation level of REPEATABLE-READ avoid this bug?
We had the READ-COMMITTED isolation to relax InnoDB, this was before we switched to TokuDB engine.
According to your documentation here https://github.com/percona/tokudb-engine/wiki/Transactions-and-Concurrency, in our use case running with REPEATABLE-READ would be exactly the same.

Thanks
Rick

Changed in percona-server:
status: Triaged → Fix Committed
assignee: George Ormond Lorch III (gl-az) → Jun Yuan (jun-yuan)
milestone: none → 5.6.27-75.0
description: updated

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

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers