[MDEV-6455] MariaDB/TokuDB crash during "join update/set" operation Created: 2014-07-18  Updated: 2014-11-14  Resolved: 2014-11-14

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - TokuDB
Affects Version/s: 10.0.12
Fix Version/s: 10.0.14

Type: Bug Priority: Major
Reporter: Thomas Trede Assignee: Unassigned
Resolution: Fixed Votes: 0
Labels: tokudb
Environment:

CentOS 6.5 running in Citrix Xen VM, 16 GB RAM, 4 CPU cores, 200GB HDD



 Description   

During a somewhat big "join update/set" operation, MariaDB/TokuDB crashes for unknown reason.
While watching the processlist, the initial join-query succeeds with some million rows; but the update operation causes the crash after some 100.000s updates.
Here is information from the mysqld.log file:

/home/buildbot/buildbot/build/mariadb-10.0.12/storage/tokudb/ft-index/ft/ft-flusher.cc:1949 toku_ft_flush_node_on_background_thread: Assertion `toku_bnc_n_entries(BNC(parent, childnum))>0' failed (errno=0)
: Success
Backtrace: (Note: toku_do_assert=0x0x7fa91e8791a0)
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z19db_env_do_backtraceP8_IO_FILE+0x1b)[0x7fa91e876b2b]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x71c53)[0x7fa91e876c53]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x71ccd)[0x7fa91e876ccd]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z39toku_ft_flush_node_on_background_threadP2ftP6ftnode+0x270)[0x7fa91e902490]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xfd610)[0x7fa91e902610]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x109430)[0x7fa91e90e430]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xdfcda)[0x7fa91e8e4cda]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xe0268)[0x7fa91e8e5268]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z20toku_ft_root_put_msgP2ftP6ft_msgP11txn_gc_info+0x531)[0x7fa91e8e6081]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z19toku_ft_send_insertP9ft_handleP10__toku_dbtS2_P6xids_t11ft_msg_typeP11txn_gc_info+0x2f)[0x7fa91e8e718f]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z20toku_ft_maybe_insertP9ft_handleP10__toku_dbtS2_P7tokutxnb10__toku_lsnb11ft_msg_type+0x1ce)[0x7fa91e9381ae]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x45e51)[0x7fa91e84ae51]
/usr/lib64/mysql/plugin/ha_tokudb.so(_Z19env_update_multipleP13__toku_db_envP9__toku_dbP13__toku_db_txnP10__toku_dbtS6_S6_S6_jPS2_PjjP9DBT_ARRAYjSA_+0xeb8)
[0x7fa91e9315a8]
/usr/lib64/mysql/plugin/ha_tokudb.so(_ZN9ha_tokudb10update_rowEPKhPh+0x510)[0x7fa91e869c10]
/usr/sbin/mysqld(_ZN7handler13ha_update_rowEPKhPh+0x162)[0x72eb32]
/usr/sbin/mysqld(_ZN12multi_update10do_updatesEv+0x63f)[0x66562f]
/usr/sbin/mysqld(_ZN12multi_update8send_eofEv+0x288)[0x6659d8]
/usr/sbin/mysqld[0x60c74e]
/usr/sbin/mysqld(_ZN4JOIN10exec_innerEv+0xa3d)[0x61f5cd]
/usr/sbin/mysqld(_ZN4JOIN4execEv+0x11)[0x621441]
/usr/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x1dd)
[0x61e00d]
/usr/sbin/mysqld(_Z18mysql_multi_updateP3THDP10TABLE_LISTP4ListI4ItemES6_PS4_y15enum_duplicatesbP18st_select_lex_unitP13st_select_lexPP12multi_update+0x1ba
)[0x664e5a]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x4667)[0x5d3a27]
/usr/sbin/mysqld[0x5d5b12]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1b20)[0x5d7cd0]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x453)[0x6950e3]
/usr/sbin/mysqld(handle_one_connection+0x42)[0x6951b2]
/lib64/libpthread.so.0[0x3b530079d1]
/lib64/libc.so.6(clone+0x6d)[0x3b52ce8b5d]



 Comments   
Comment by Thomas Trede [ 2014-07-18 ]

more information from logfile:

Server version: 10.0.12-MariaDB
key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=35
max_threads=1002
thread_count=2
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2233828 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x7fa92f90b008
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 = 0x7fa8e6ffed10 thread_stack 0x30000
(my_addr_resolve failure: fork)
/usr/sbin/mysqld(my_print_stacktrace+0x2b) [0xb6c14b]
/usr/sbin/mysqld(handle_fatal_signal+0x398) [0x7255f8]
/lib64/libpthread.so.0() [0x3b5300f710]
/lib64/libc.so.6(gsignal+0x35) [0x3b52c32925]
/lib64/libc.so.6(abort+0x175) [0x3b52c34105]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x71c58) [0x7fa91e876c58]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x71ccd) [0x7fa91e876ccd]
/usr/lib64/mysql/plugin/ha_tokudb.so(toku_ft_flush_node_on_background_thread(ft*, ftnode*)+0x270) [0x7fa91e902490]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xfd610) [0x7fa91e902610]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x109430) [0x7fa91e90e430]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xdfcda) [0x7fa91e8e4cda]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0xe0268) [0x7fa91e8e5268]
/usr/lib64/mysql/plugin/ha_tokudb.so(toku_ft_root_put_msg(ft*, ft_msg*, txn_gc_info*)+0x531) [0x7fa91e8e6081]
/usr/lib64/mysql/plugin/ha_tokudb.so(toku_ft_send_insert(ft_handle*, __toku_dbt*, __toku_dbt*, xids_t*, ft_msg_type, txn_gc_info*)+0x2f) [0x7fa91e8e718f]
/usr/lib64/mysql/plugin/ha_tokudb.so(toku_ft_maybe_insert(ft_handle*, __toku_dbt*, __toku_dbt*, tokutxn*, bool, __toku_lsn, bool, ft_msg_type)+0x1ce) [0x7fa91e9381ae]
/usr/lib64/mysql/plugin/ha_tokudb.so(+0x45e51) [0x7fa91e84ae51]
/usr/lib64/mysql/plugin/ha_tokudb.so(env_update_multiple(__toku_db_env*, __toku_db*, __toku_db_txn*, __toku_dbt*, __toku_dbt*, __toku_dbt*, __toku_dbt*, unsigned int, __toku_db**, unsigned int*, unsigned int, DBT_ARRAY*, unsigned int, DBT_ARRAY*)+0xeb8) [0x7fa91e9315a8]
/usr/lib64/mysql/plugin/ha_tokudb.so(ha_tokudb::update_row(unsigned char const*, unsigned char*)+0x510) [0x7fa91e869c10]
/usr/sbin/mysqld(handler::ha_update_row(unsigned char const*, unsigned char*)+0x162) [0x72eb32]
/usr/sbin/mysqld(multi_update::do_updates()+0x63f) [0x66562f]
/usr/sbin/mysqld(multi_update::send_eof()+0x288) [0x6659d8]
/usr/sbin/mysqld() [0x60c74e]
/usr/sbin/mysqld(JOIN::exec_inner()+0xa3d) [0x61f5cd]
/usr/sbin/mysqld(JOIN::exec()+0x11) [0x621441]
/usr/sbin/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*)+0x1dd) [0x61e00d]
/usr/sbin/mysqld(mysql_multi_update(THD*, TABLE_LIST*, List<Item>*, List<Item>*, Item*, unsigned long long, enum_duplicates, bool, st_select_lex_unit*, st_select_lex*, multi_update**)+0x1ba) [0x664e5a]
/usr/sbin/mysqld(mysql_execute_command(THD*)+0x4667) [0x5d3a27]
/usr/sbin/mysqld() [0x5d5b12]
/usr/sbin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x1b20) [0x5d7cd0]
/usr/sbin/mysqld(do_handle_one_connection(THD*)+0x453) [0x6950e3]
/usr/sbin/mysqld(handle_one_connection+0x42) [0x6951b2]
/lib64/libpthread.so.0() [0x3b530079d1]
/lib64/libc.so.6(clone+0x6d) [0x3b52ce8b5d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fa91fdf5020): is an invalid pointer
Connection ID (thread ID): 39
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on

Comment by Thomas Trede [ 2014-07-18 ]

and some more:
Engine status:

BUILD_ID = 0
Env panic code: 18446744073709551615
Env panic string: /home/buildbot/buildbot/build/mariadb-10.0.12/storage/tokudb/ft-index/ft/ft-flusher.cc:1949 toku_ft_flush_node_on_background_thread: Assertion `toku_bnc_n_entries(BNC(parent, childnum))>0' failed (errno=0)
 
time of environment creation: Thu Jul 17 15:57:29 2014
time of engine startup: Thu Jul 17 18:06:46 2014
time now: Thu Jul 17 18:27:04 2014
db opens: 21
db closes: 0
num open dbs now: 21
max open dbs: 21
period, in ms, that recovery log is automatically fsynced: 0
dictionary inserts: 0
dictionary inserts fail: 0
dictionary deletes: 0
dictionary deletes fail: 0
dictionary updates: 0
dictionary updates fail: 0
dictionary broadcast updates: 0
dictionary broadcast updates fail: 0
dictionary multi inserts: 0
dictionary multi inserts fail: 0
dictionary multi deletes: 0
dictionary multi deletes fail: 0
dictionary updates multi: 1047215
dictionary updates multi fail: 0
le: max committed xr: 1
le: max provisional xr: 1
le: expanded: 0
le: max memsize: 33555636
le: size of leafentries before garbage collection (during message application): 0
le: size of leafentries after garbage collection (during message application): 0
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: 40
checkpoint: last checkpoint began : Thu Jul 17 18:26:50 2014
checkpoint: last complete checkpoint began : Thu Jul 17 18:25:50 2014
checkpoint: last complete checkpoint ended: Thu Jul 17 18:26:43 2014
checkpoint: time spent during checkpoint (begin and end phases): Thu Jan  1 01:08:28 1970
checkpoint: time spent during last checkpoint (begin and end phases): Thu Jan  1 01:00:53 1970
checkpoint: last complete checkpoint LSN: 2922576
checkpoint: checkpoints taken : 20
checkpoint: checkpoints failed: 0
checkpoint: waiters now: 0
checkpoint: waiters max: 0
checkpoint: non-checkpoint client wait on mo lock: 1
checkpoint: non-checkpoint client wait on cs lock: 0
checkpoint: checkpoint begin time: 21496
checkpoint: long checkpoint begin time: 0
checkpoint: long checkpoint begin count: 0
cachetable: miss: 2798
cachetable: miss time: 62707634
cachetable: prefetches: 8302
cachetable: size current: 8397896929
cachetable: size limit: 8866803712
cachetable: size writing: 0
cachetable: size nonleaf: 674308578
cachetable: size leaf: 7705226534
cachetable: size rollback: 13949432
cachetable: size cachepressure: 42377125556
cachetable: evictions: 3341
cachetable: cleaner executions: 1700
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
locktree: memory size: 472244280
locktree: memory size limit: 1041241600
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: 23
locktree: number of pending lock requests: 0
locktree: number of locktrees eligible for the STO: 1
locktree: number of times a locktree ended the STO early: 6
locktree: time spent ending the STO early (seconds): 0.332885
locktree: number of wait locks: 0
locktree: time waiting for locks: 0
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: 1011712
ft: descriptor set: 0
ft: messages ignored by leaf due to msn: 1757830
ft: total search retries due to TRY_AGAIN: 550038
ft: searches requiring more tries than the height of the tree: 0
ft: searches requiring more tries than the height of the tree plus three: 0
ft: leaf nodes flushed to disk (not for checkpoint): 72
ft: leaf nodes flushed to disk (not for checkpoint) (bytes): 16884736
ft: leaf nodes flushed to disk (not for checkpoint) (uncompressed bytes): 193465673
ft: leaf nodes flushed to disk (not for checkpoint) (seconds): 0.840663
ft: nonleaf nodes flushed to disk (not for checkpoint): 37
ft: nonleaf nodes flushed to disk (not for checkpoint) (bytes): 11178496
ft: nonleaf nodes flushed to disk (not for checkpoint) (uncompressed bytes): 84142202
ft: nonleaf nodes flushed to disk (not for checkpoint) (seconds): 0.127216
ft: leaf nodes flushed to disk (for checkpoint): 6618
ft: leaf nodes flushed to disk (for checkpoint) (bytes): 2739340288
ft: leaf nodes flushed to disk (for checkpoint) (uncompressed bytes): 21982717205
ft: leaf nodes flushed to disk (for checkpoint) (seconds): 49.301726
ft: nonleaf nodes flushed to disk (for checkpoint): 1143
ft: nonleaf nodes flushed to disk (for checkpoint) (bytes): 376702464
ft: nonleaf nodes flushed to disk (for checkpoint) (uncompressed bytes): 2639054206
ft: nonleaf nodes flushed to disk (for checkpoint) (seconds): 8.593302
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: 1097
ft: nonleaf node partial evictions (bytes): 143847510
ft: leaf node partial evictions: 905417
ft: leaf node partial evictions (bytes): 181693901100
ft: leaf node full evictions: 1717
ft: leaf node full evictions (bytes): 6444247392
ft: nonleaf node full evictions: 1620
ft: nonleaf node full evictions (bytes): 5026910060
ft: leaf nodes created: 644
ft: nonleaf nodes created: 72
ft: leaf nodes destroyed: 7695
ft: nonleaf nodes destroyed: 2722
ft: bytes of messages injected at root (all trees): 12461142619
ft: bytes of messages flushed from h1 nodes to leaves: 12339553799
ft: bytes of messages currently in trees (estimate): 121588820
ft: messages injected at root: 1047215
ft: broadcast messages injected at root: 0
ft: basements decompressed as a target of a query: 0
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: 5722
ft: buffers decompressed for prelocked range: 162
ft: buffers decompressed for prefetch: 0
ft: buffers decompressed for write: 5851
ft: pivots fetched for query: 827
ft: pivots fetched for query (bytes): 26236928
ft: pivots fetched for query (seconds): 3.139837
ft: pivots fetched for prefetch: 8302
ft: pivots fetched for prefetch (bytes): 271721472
ft: pivots fetched for prefetch (seconds): 20.796390
ft: pivots fetched for write: 1
ft: pivots fetched for write (bytes): 512
ft: pivots fetched for write (seconds): 0.000006
ft: basements fetched as a target of a query: 527331
ft: basements fetched as a target of a query (bytes): 6296807936
ft: basements fetched as a target of a query (seconds): 52.693165
ft: basements fetched for prelocked range: 28791
ft: basements fetched for prelocked range (bytes): 323332608
ft: basements fetched for prelocked range (seconds): 10.045533
ft: basements fetched for prefetch: 340328
ft: basements fetched for prefetch (bytes): 3891359232
ft: basements fetched for prefetch (seconds): 104.352300
ft: basements fetched for write: 80078
ft: basements fetched for write (bytes): 897083904
ft: basements fetched for write (seconds): 18.536824
ft: buffers fetched as a target of a query: 2
ft: buffers fetched as a target of a query (bytes): 1024
ft: buffers fetched as a target of a query (seconds): 0.000027
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: 243
ft: buffers fetched for write (bytes): 3901440
ft: buffers fetched for write (seconds): 0.001830
ft: leaf compression to memory (seconds): 441.775154
ft: leaf serialization to memory (seconds): 28.849370
ft: leaf decompression to memory (seconds): 242.033000
ft: leaf deserialization to memory (seconds): 64.561302
ft: nonleaf compression to memory (seconds): 64.947525
ft: nonleaf serialization to memory (seconds): 2.120138
ft: nonleaf decompression to memory (seconds): 15.787684
ft: nonleaf deserialization to memory (seconds): 6.257656
ft: promotion: roots split: 0
ft: promotion: leaf roots injected into: 0
ft: promotion: h1 roots injected into: 0
ft: promotion: injections at depth 0: 1124
ft: promotion: injections at depth 1: 8063
ft: promotion: injections at depth 2: 1028309
ft: promotion: injections at depth 3: 9719
ft: promotion: injections lower than depth 3: 1
ft: promotion: stopped because of a nonempty buffer: 10332
ft: promotion: stopped at height 1: 12
ft: promotion: stopped because the child was locked or not at all in memory: 0
ft: promotion: stopped because the child was not fully in memory: 26
ft: promotion: stopped anyway, after locking the child: 1
ft: basement nodes deserialized with fixed-keysize: 976524
ft: basement nodes deserialized with variable-keysize: 6
ft flusher: total nodes potentially flushed by cleaner thread: 505
ft flusher: height-one nodes flushed by cleaner thread: 465
ft flusher: height-greater-than-one nodes flushed by cleaner thread: 40
ft flusher: nodes cleaned which had empty buffers: 15
ft flusher: nodes dirtied by cleaner thread: 957
ft flusher: max bytes in a buffer flushed by cleaner thread: 3630386
ft flusher: min bytes in a buffer flushed by cleaner thread: 36
ft flusher: total bytes in buffers flushed by cleaner thread: 487934002
ft flusher: max workdone in a buffer flushed by cleaner thread: 469990417
ft flusher: min workdone in a buffer flushed by cleaner thread: 0
ft flusher: total workdone in buffers flushed by cleaner thread: 4141834199
ft flusher: times cleaner thread tries to merge a leaf: 0
ft flusher: cleaner thread leaf merges in progress: 0
ft flusher: cleaner thread leaf merges successful: 0
ft flusher: nodes dirtied by cleaner thread leaf merges: 0
ft flusher: total number of flushes done by flusher threads or cleaner threads: 8192
ft flusher: number of in memory flushes: 8192
ft flusher: number of flushes that read something off disk: 0
ft flusher: number of flushes that triggered another flush in child: 64
ft flusher: number of flushes that triggered 1 cascading flush: 58
ft flusher: number of flushes that triggered 2 cascading flushes: 6
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: 644
ft flusher: nonleaf node splits: 72
ft flusher: leaf node merges: 0
ft flusher: nonleaf node merges: 0
ft flusher: leaf node balances: 0
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: 39
txn: begin read only: 2
txn: successful commits: 39
txn: aborts: 1
logger: next LSN: 3017987
logger: writes: 790
logger: writes (bytes): 12491202839
logger: writes (uncompressed bytes): 12491202839
logger: writes (seconds): 13.450704
logger: count: 3
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: 5
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.3.1-0-g9ef9d9e8c271cdf14f664b871a8f98c827714784
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: 260506585
filesystem: fsync count: 297
filesystem: long fsync time: 251458210
filesystem: long fsync count: 114
context: tree traversals blocked by a full fetch: 0
context: tree traversals blocked by a partial fetch: 0
context: tree traversals blocked by a full eviction: 0
context: tree traversals blocked by a partial eviction: 8
context: tree traversals blocked by a message injection: 56
context: tree traversals blocked by a message application: 0
context: tree traversals blocked by a flush: 8079
context: tree traversals blocked by a the cleaner thread: 1
context: tree traversals blocked by something uninstrumented: 7157
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: 0
context: promotion blocked by a message application: 0
context: promotion blocked by a flush: 0
context: promotion blocked by the cleaner thread: 0
context: promotion blocked by something uninstrumented: 0
context: something uninstrumented blocked by something uninstrumented: 0
 
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
140717 18:27:04 [ERROR] 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.

Comment by Rich Prohaska [ 2014-07-18 ]

Is this a reproducible crash?

Comment by Thomas Trede [ 2014-07-18 ]

Yes, it is reproducible.

Comment by Elena Stepanova [ 2014-07-19 ]

rtgman,

Would you be able to provide the UPDATE statement and the data dump of the involved tables? (You can upload the data to the private section of our FTP server, so only MariaDB developers would have access to it).
If you can't upload the data, please at least provide the structures of the involved tables.

Thanks.

Comment by Thomas Trede [ 2014-07-19 ]

Here is the update-statement which causes the tokudb-crash:
update query (

update bsm__stm_stored_message as msg inner join bsm__stm_statistics stats on msg.id = stats.stmMailId set msg.incomingDate = stats.incomingDate, msg.quarantineIn = stats.quarantineIn, msg.quarantineOut = stats.quarantineOut, msg.storedDate = stats.storedDate;

)

I cannot upload the table contents, but I will provide the structure.

Comment by Thomas Trede [ 2014-07-19 ]

Table formats:

show create table bsm__stm_stored_message\G
*************************** 1. row ***************************
       Table: bsm__stm_stored_message
Create Table: CREATE TABLE `bsm__stm_stored_message` (
  `id` bigint(11) NOT NULL AUTO_INCREMENT,
  `filename` varchar(255) DEFAULT NULL,
  `subject` varchar(255) DEFAULT NULL,
  `spamSignature` varchar(255) DEFAULT NULL,
  `attachmentsCount` bigint(11) DEFAULT NULL,
  `headerDate` datetime DEFAULT NULL,
  `uncompressedSize` bigint(11) DEFAULT NULL,
  `compressedSize` bigint(11) DEFAULT NULL,
  `processingStatus` int(11) DEFAULT NULL,
  `md5` varchar(255) DEFAULT NULL,
  `importMd5` varchar(255) DEFAULT NULL,
  `oneTimePassword` varchar(255) DEFAULT NULL,
  `deleted` tinyint(1) DEFAULT NULL,
  `textInFull` mediumtext,
  `cryptKeyId` bigint(20) DEFAULT NULL,
  `referenceNumber` varchar(255) DEFAULT NULL,
  `varcharFFU1` varchar(255) DEFAULT NULL,
  `varcharFFU2` varchar(255) DEFAULT NULL,
  `varcharFFU3` varchar(255) DEFAULT NULL,
  `varcharFFU4` varchar(255) DEFAULT NULL,
  `varcharFFU5` varchar(255) DEFAULT NULL,
  `varcharFFU6` varchar(255) DEFAULT NULL,
  `bigintFFU1` bigint(11) DEFAULT NULL,
  `bigintFFU2` bigint(11) DEFAULT NULL,
  `bigintFFU3` bigint(11) DEFAULT NULL,
  `bigintFFU4` bigint(11) DEFAULT NULL,
  `booleanFFU1` tinyint(1) NOT NULL DEFAULT '0',
  `booleanFFU2` tinyint(1) NOT NULL DEFAULT '0',
  `booleanFFU3` tinyint(1) NOT NULL DEFAULT '0',
  `booleanFFU4` tinyint(1) NOT NULL DEFAULT '0',
  `dateFFU1` datetime DEFAULT NULL,
  `dateFFU2` datetime DEFAULT NULL,
  `incomingDate` datetime NOT NULL,
  `quarantineIn` datetime NOT NULL,
  `quarantineOut` datetime NOT NULL,
  `stmMailId` bigint(20) NOT NULL,
  `storedDate` datetime NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=TokuDB AUTO_INCREMENT=1487060 DEFAULT CHARSET=latin1 `compression`='tokudb_zlib'

show create table bsm__stm_statistics\G
*************************** 1. row ***************************
       Table: bsm__stm_statistics
Create Table: CREATE TABLE `bsm__stm_statistics` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `incomingDate` datetime DEFAULT NULL,
  `quarantineIn` datetime DEFAULT NULL,
  `quarantineOut` datetime DEFAULT NULL,
  `stmMailId` bigint(20) DEFAULT NULL,
  `storedDate` datetime DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `FK7A823F327BE63FDA` (`stmMailId`)
) ENGINE=TokuDB AUTO_INCREMENT=1487021 DEFAULT CHARSET=latin1 `compression`='tokudb_zlib'

Comment by Thomas Trede [ 2014-07-19 ]

Table formats:

CREATE TABLE `bsm__stm_stored_message` (
  `id` bigint(11) NOT NULL AUTO_INCREMENT,
  `filename` varchar(255) DEFAULT NULL,
  `subject` varchar(255) DEFAULT NULL,
  `spamSignature` varchar(255) DEFAULT NULL,
  `attachmentsCount` bigint(11) DEFAULT NULL,
  `headerDate` datetime DEFAULT NULL,
  `uncompressedSize` bigint(11) DEFAULT NULL,
  `compressedSize` bigint(11) DEFAULT NULL,
  `processingStatus` int(11) DEFAULT NULL,
  `md5` varchar(255) DEFAULT NULL,
  `importMd5` varchar(255) DEFAULT NULL,
  `oneTimePassword` varchar(255) DEFAULT NULL,
  `deleted` tinyint(1) DEFAULT NULL,
  `textInFull` mediumtext,
  `cryptKeyId` bigint(20) DEFAULT NULL,
  `referenceNumber` varchar(255) DEFAULT NULL,
  `varcharFFU1` varchar(255) DEFAULT NULL,
  `varcharFFU2` varchar(255) DEFAULT NULL,
  `varcharFFU3` varchar(255) DEFAULT NULL,
  `varcharFFU4` varchar(255) DEFAULT NULL,
  `varcharFFU5` varchar(255) DEFAULT NULL,
  `varcharFFU6` varchar(255) DEFAULT NULL,
  `bigintFFU1` bigint(11) DEFAULT NULL,
  `bigintFFU2` bigint(11) DEFAULT NULL,
  `bigintFFU3` bigint(11) DEFAULT NULL,
  `bigintFFU4` bigint(11) DEFAULT NULL,
  `booleanFFU1` tinyint(1) NOT NULL DEFAULT '0',
  `booleanFFU2` tinyint(1) NOT NULL DEFAULT '0',
  `booleanFFU3` tinyint(1) NOT NULL DEFAULT '0',
  `booleanFFU4` tinyint(1) NOT NULL DEFAULT '0',
  `dateFFU1` datetime DEFAULT NULL,
  `dateFFU2` datetime DEFAULT NULL,
  `incomingDate` datetime NOT NULL,
  `quarantineIn` datetime NOT NULL,
  `quarantineOut` datetime NOT NULL,
  `stmMailId` bigint(20) NOT NULL,
  `storedDate` datetime NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=TokuDB AUTO_INCREMENT=1487060 DEFAULT CHARSET=latin1 `compression`='tokudb_zlib'

CREATE TABLE `bsm__stm_statistics` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `incomingDate` datetime DEFAULT NULL,
  `quarantineIn` datetime DEFAULT NULL,
  `quarantineOut` datetime DEFAULT NULL,
  `stmMailId` bigint(20) DEFAULT NULL,
  `storedDate` datetime DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `FK7A823F327BE63FDA` (`stmMailId`)
) ENGINE=TokuDB AUTO_INCREMENT=1487021 DEFAULT CHARSET=latin1 `compression`='tokudb_zlib'

Comment by Thomas Trede [ 2014-07-19 ]

And the table statistics:

MariaDB [bytstor]> show table status where name = 'bsm__stm_statistics';
+---------------------+--------+---------+------------+---------+----------------+-------------+---------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+-----------------------------+---------+
| Name                | Engine | Version | Row_format | Rows    | Avg_row_length | Data_length | Max_data_length     | Index_length | Data_free | Auto_increment | Create_time         | Update_time         | Check_time | Collation         | Checksum | Create_options              | Comment |
+---------------------+--------+---------+------------+---------+----------------+-------------+---------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+-----------------------------+---------+
| bsm__stm_statistics | TokuDB |      10 | Fixed      | 1487020 |             49 |    72863980 | 9223372036854775807 |     26766344 |  32497664 |        1487021 | 2014-07-17 19:32:59 | 2014-07-17 19:33:53 | NULL       | latin1_swedish_ci |     NULL | `compression`='tokudb_zlib' |         |
+---------------------+--------+---------+------------+---------+----------------+-------------+---------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+-----------------------------+---------+

MariaDB [bytstor]> show table status where name = 'bsm__stm_stored_message';
+-------------------------+--------+---------+------------+---------+----------------+-------------+---------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+-----------------------------+---------+
| Name                    | Engine | Version | Row_format | Rows    | Avg_row_length | Data_length | Max_data_length     | Index_length | Data_free | Auto_increment | Create_time         | Update_time         | Check_time | Collation         | Checksum | Create_options              | Comment |
+-------------------------+--------+---------+------------+---------+----------------+-------------+---------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+-----------------------------+---------+
| bsm__stm_stored_message | TokuDB |      10 | Dynamic    | 1487059 |          12529 | 18632224685 | 9223372036854775807 |            0 |   3948544 |        1487060 | 2014-07-17 20:20:39 | 2014-07-17 20:31:50 | NULL       | latin1_swedish_ci |     NULL | `compression`='tokudb_zlib' |         |
+-------------------------+--------+---------+------------+---------+----------------+-------------+---------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+-----------------------------+---------+
1 row in set (0.00 sec)
 

Comment by Elena Stepanova [ 2014-07-19 ]

prohaska7,
Do you think it's enough information for you to look into the problem?

Comment by Rich Prohaska [ 2014-07-21 ]

Hello,
We have chasing this assert for a while, but have not been able to reproduce it. If you have a reproducer, then we can use it to figure out what is going wrong and fix it. This assert is data dependent. It would be great if we could get a copy of the fractal tree files that are used by the update. If this is not possible, then could you run a debug version of mariadb, turn on core files for mysqld, try to crash mysqld, and give us the core file?

Comment by Thomas Trede [ 2014-07-21 ]

Hello,
due to privacy regulations we are not able to provide the original data.
However, we can run your debug version of mariadb, and can try to get those core files.
What do we need to do for that?

Comment by Elena Stepanova [ 2014-07-21 ]

Do you normally use a MariaDB binary package, or do you build the server from source?
If you use binaries, we can build a debug mysqld binary for you. If you build yourself, run cmake with -DCMAKE_BUILD_TYPE=Debug

Comment by Thomas Trede [ 2014-07-21 ]

We are using binary package inside CentOS 6.5.

Comment by Thomas Trede [ 2014-07-23 ]

Hello,
can you please provide the debug mysqld file/package?
Thank you & regards,

Comment by Elena Stepanova [ 2014-07-23 ]

Hi Thomas,

Please try binaries from here: ftp://ftp.askmonty.org/public/mdev6455/
Hopefully you will only need to replace mysqld and ha_tokudb.so – I tried them on CentOS 6.3, they seem to work together (you cannot replace only mysqld).

But in case you use more plugins, I've also built RPMs, you can either install them or extract necessary binaries from them. I didn't check the packages though.

Please let us know whether it works for you.

And as usual, creating a backup before changing binaries is a good idea.

Comment by Rich Prohaska [ 2014-07-28 ]

Hello Thomas,
If you have a core file, I would really like to get it.

If using a debug build is not easy, then perhaps a core file on a release build would yield some useful information.

Comment by Thomas Trede [ 2014-08-15 ]

Hello,
sorry for the delay.
For the beginning I have now generated a "normal" core dumps. The compressed size ist ca. 210 MB.
The upload limit is 10 MB.
=> Thus, how do I get this core dump to you?
Thank you & regards,
Thomas

Comment by Thomas Trede [ 2014-08-15 ]

Hello,
now I have also generated a core-dump with the debug-builds.
Same question: How do I get the (large) files to you?
Thank you & regards,
Thomas

Comment by Elena Stepanova [ 2014-08-15 ]

You can upload the files to ftp.askmonty.org/private, unless Rich wants them somewhere else.

Comment by Thomas Trede [ 2014-08-15 ]

Hello Elena,
I have uploaded two files to the mentioned location:
MDEV-6455-core-debug.6034.gz (from mysqld with debug)
MDEV-6455-core-normal.3934.gz (form "regular" mysqld)

Please shout, if you need anything else.

Thank you & kind regards,
Thomas

Comment by Thomas Trede [ 2014-08-25 ]

Hello,
it has been some time, since I have uploaded the debug files.
Are you fine with that, or do you need something else for further analysis of this issue?
Thank you & kind regards,
Thomas

Comment by Elena Stepanova [ 2014-08-25 ]

I couldn't get a decent stack trace from the coredump on Debian due to library mismatch, and my CentOS installations are rusty, so I need to install 6.5 to see if it works better there. If so, I will pass it over to Tokutek team for an expert look.

Is it okay to put the coredumps into the public section of our FTP, or do you prefer to keep them private?

prohaska7, in case we need to keep the coredumps private, please let me know where you want them to be uploaded.

Comment by Thomas Trede [ 2014-08-26 ]

Hello Elena,
for the time being, I prefer to keep the coredumps private.
Thank you & kind regards,
Thomas

Comment by Rich Prohaska [ 2014-08-26 ]

Thanks for getting the core files. We examined them and found the bug in the TokuDB fractal tree indexing code. We are tracking the fix in Tokutek's bug tracking system as https://tokutek.atlassian.net/browse/FT-590.

Comment by Thomas Trede [ 2014-09-03 ]

Hello Rich,
fine, that you have found the root-cause/bug for this issue.
Now in the Tokutek bug tracking, they tell, that this will be fixed in tokudb 7.5.0.
In MariaDB 10 we are somewhere at tokudb-version 7.1.5; when will we see this fix in MariaDB?
It looks like, that this is very, very far away...
Thank you & kind regards,
Thomas

Comment by Rich Prohaska [ 2014-09-04 ]

TokuDB 7.5.0 will be available in the middle of sept from Tokutek and I expect that it will be pulled into Mariadb 10 sometime after that.

If you want to experiment on your own, the patch to the tokudb source is very simple. See the commit here: https://tokutek.atlassian.net/browse/FT-590

Comment by Rich Prohaska [ 2014-10-03 ]

Fixed 10.0.14

Generated at Thu Feb 08 07:12:02 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.