[MDEV-6681] TokuDB crash on import of 100+ mln rows - Jira

XML

Word

Printable

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.1.0
Fix Version/s: 5.5.40, 10.0.14
Component/s: Storage Engine - TokuDB
Labels:
None

Description

This is a vanilla MySQL 10.1.0 installation on Ubuntu 12.04.4 LTS.

The crash happened when importing three tables each with ~130 mln rows.

The tables were created with ENGINE=TokuDB suffix, no changes were made to the my.cnf file.

Here's the stacktrace from syslog:

Sep  1 18:43:30 ns228599 kernel: Out of memory: Kill process 12016 (mysqld) score 571 or sacrifice child

Sep  1 18:43:30 ns228599 kernel: Killed process 12016 (mysqld) total-vm:41382224kB, anon-rss:38844920kB, file-rss:2204kB

Sep  1 18:43:33 ns228599 mysqld_safe: Number of processes running now: 0

Sep  1 18:43:33 ns228599 mysqld_safe: mysqld restarted

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Using mutexes to ref count buffer pool pages

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: The InnoDB memory heap is disabled

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Compressed tables use zlib 1.2.3.4

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Using Linux native AIO

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Using CPU crc32 instructions

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Initializing buffer pool, size = 4.0G

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Completed initialization of buffer pool

Sep  1 18:43:34 ns228599 mysqld:  InnoDB: at file /home/buildbot/buildbot/build/mariadb-10.1.0/storage/xtradb/os/os0file.cc and at line 2087

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Highest supported file format is Barracuda.

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: The log sequence numbers 1616717 and 1616717 in ibdata files do not match the log sequence number 29393956829 in the ib_logfiles!

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Database was not shutdown normally!

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Starting crash recovery.

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Reading tablespace information from the .ibd files...

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: Restoring possible half-written data pages

Sep  1 18:43:34 ns228599 mysqld: 140901 18:43:34 [Note] InnoDB: from the doublewrite buffer...

Sep  1 18:43:35 ns228599 mysqld: InnoDB: Last MySQL binlog file position 0 33270576, file name /var/log/mysql/mariadb-bin.000166

Sep  1 18:43:35 ns228599 mysqld: 140901 18:43:35 [Note] InnoDB: 128 rollback segment(s) are active.

Sep  1 18:43:35 ns228599 mysqld: 140901 18:43:35 [Note] InnoDB: Waiting for purge to start

Sep  1 18:43:35 ns228599 mysqld: 140901 18:43:35 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.17-65.0 started; log sequence number 29393956829

Sep  1 18:43:35 ns228599 mysqld: 140901 18:43:35 [Note] Plugin 'FEEDBACK' is disabled.

Sep  1 18:43:36 ns228599 mysqld: Mon Sep  1 18:43:36 2014 Tokudb recovery starting in env /data01/mysql/

Sep  1 18:43:36 ns228599 mysqld: Mon Sep  1 18:43:36 2014 Tokudb recovery scanning backward from 36098214

Sep  1 18:43:36 ns228599 mysqld: Mon Sep  1 18:43:36 2014 Tokudb recovery bw_begin_checkpoint at 36098061 timestamp 1409589809468433 (bw_newer)

Sep  1 18:43:37 ns228599 mysqld: Mon Sep  1 18:43:37 2014 Tokudb recovery bw_end_checkpoint at 36030490 timestamp 1409589763269743 xid 36018472 (bw_newer)

Sep  1 18:43:37 ns228599 mysqld: Mon Sep  1 18:43:37 2014 Tokudb recovery bw_begin_checkpoint at 36018472 timestamp 1409589749481367 (bw_between)

Sep  1 18:43:37 ns228599 mysqld: Mon Sep  1 18:43:37 2014 Tokudb recovery turning around at begin checkpoint 36018472 time 13788376

Sep  1 18:43:37 ns228599 mysqld: Mon Sep  1 18:43:37 2014 Tokudb recovery starts scanning forward to 36098214 from 36018472 left 79742 (fw_between)

Sep  1 18:43:48 ns228599 mysqld: Mon Sep  1 18:43:48 2014 Tokudb recovery has 2 live transactions

Sep  1 18:43:48 ns228599 mysqld: Mon Sep  1 18:43:48 2014 Tokudb recovery has 1 prepared transaction

Sep  1 18:43:48 ns228599 mysqld: Mon Sep  1 18:43:48 2014 Tokudb recovery closing 48 dictionaries

Sep  1 18:43:55 ns228599 mysqld: Mon Sep  1 18:43:55 2014 Tokudb recovery making a checkpoint

Sep  1 18:43:57 ns228599 mysqld: Mon Sep  1 18:43:57 2014 Tokudb recovery done

Sep  1 18:43:57 ns228599 mysqld: 140901 18:43:57 [Note] Found 1 prepared transaction(s) in TokuDB

Sep  1 18:43:57 ns228599 mysqld: 140901 18:43:57 [ERROR] Found 1 prepared transactions! It means that mysqld was not shut down properly last time and critical recovery information (last binlog or tc.log file) was manually deleted after a c

rash. You have to start mysqld with --tc-heuristic-recover switch to commit or rollback pending transactions.

Sep  1 18:43:57 ns228599 mysqld: 140901 18:43:57 [ERROR] Aborting

Sep  1 18:43:57 ns228599 mysqld:

Sep  1 18:43:57 ns228599 mysqld: 140901 18:43:57 [ERROR] TokuDB:  Cannot close environment due to open transactions

Sep  1 18:43:57 ns228599 mysqld:

Sep  1 18:43:57 ns228599 mysqld: /home/buildbot/buildbot/build/mariadb-10.1.0/storage/tokudb/hatoku_hton.cc:607 tokudb_end: Assertion `Handlerton: error==0 ' failed (errno=2)

Sep  1 18:43:57 ns228599 mysqld: : No such file or directory

Sep  1 18:43:57 ns228599 mysqld: Backtrace: (Note: toku_do_assert=0x0x7ffb5ac7a340)

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(_Z19db_env_do_backtraceP8_IO_FILE+0x1b)[0x7ffb5ac77cab]

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(+0x72dd3)[0x7ffb5ac77dd3]

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(+0x72e5a)[0x7ffb5ac77e5a]

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(+0x1048d8)[0x7ffb5ad098d8]

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(_Z21toku_hton_assert_failPKcS0_S0_ii+0x7d)[0x7ffb5ac52e4d]

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(+0x514c6)[0x7ffb5ac564c6]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(_Z22ha_finalize_handlertonP13st_plugin_int+0x34)[0x7ffc85bb72f4]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(+0x40d659)[0x7ffc85a75659]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(+0x410fbe)[0x7ffc85a78fbe]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(_Z15plugin_shutdownv+0x243)[0x7ffc85a798b3]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(+0x379994)[0x7ffc859e1994]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(unireg_abort+0x4c)[0x7ffc859e4c1c]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(+0x37fd4d)[0x7ffc859e7d4d]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x4ae)[0x7ffc859ea4ce]

Sep  1 18:43:57 ns228599 mysqld: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed)[0x7ffc837f576d]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(+0x376fc9)[0x7ffc859defc9]

Sep  1 18:43:57 ns228599 mysqld: Engine status:

Sep  1 18:43:57 ns228599 mysqld: Engine status not available: disabled by user.  This should only happen in test programs.

Sep  1 18:43:57 ns228599 mysqld:

Sep  1 18:43:57 ns228599 mysqld: Memory usage:

Sep  1 18:43:57 ns228599 mysqld: Arena 0:

Sep  1 18:43:57 ns228599 mysqld: system bytes     =          0

Sep  1 18:43:57 ns228599 mysqld: in use bytes     =          0

Sep  1 18:43:57 ns228599 mysqld: Total (incl. mmap):

Sep  1 18:43:57 ns228599 mysqld: system bytes     =          0

Sep  1 18:43:57 ns228599 mysqld: in use bytes     =          0

Sep  1 18:43:57 ns228599 mysqld: max mmap regions =          0

Sep  1 18:43:57 ns228599 mysqld: max mmap bytes   =          0

Sep  1 18:43:57 ns228599 mysqld: 140901 18:43:57 [ERROR] mysqld got signal 6 ;

Sep  1 18:43:57 ns228599 mysqld: This could be because you hit a bug. It is also possible that this binary

Sep  1 18:43:57 ns228599 mysqld: or one of the libraries it was linked against is corrupt, improperly built,

Sep  1 18:43:57 ns228599 mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.

Sep  1 18:43:57 ns228599 mysqld:

Sep  1 18:43:57 ns228599 mysqld: To report this bug, see http://kb.askmonty.org/en/reporting-bugs

Sep  1 18:43:57 ns228599 mysqld:

Sep  1 18:43:57 ns228599 mysqld: We will try our best to scrape up some info that will hopefully help

Sep  1 18:43:57 ns228599 mysqld: diagnose the problem, but since we have already crashed,

Sep  1 18:43:57 ns228599 mysqld: something is definitely wrong and this may fail.

Sep  1 18:43:57 ns228599 mysqld:

Sep  1 18:43:57 ns228599 mysqld: Server version: 10.1.0-MariaDB-1~precise

Sep  1 18:43:57 ns228599 mysqld: key_buffer_size=134217728

Sep  1 18:43:57 ns228599 mysqld: read_buffer_size=2097152

Sep  1 18:43:57 ns228599 mysqld: max_used_connections=0

Sep  1 18:43:57 ns228599 mysqld: max_threads=102

Sep  1 18:43:57 ns228599 mysqld: thread_count=0

Sep  1 18:43:57 ns228599 mysqld: It is possible that mysqld could use up to

Sep  1 18:43:57 ns228599 mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 759850 K  bytes of memory

Sep  1 18:43:57 ns228599 mysqld: Hope that's ok; if not, decrease some variables in the equation.

Sep  1 18:43:57 ns228599 mysqld:

Sep  1 18:43:57 ns228599 mysqld: Thread pointer: 0x0x0

Sep  1 18:43:57 ns228599 mysqld: Attempting backtrace. You can use the following information to find out

Sep  1 18:43:57 ns228599 mysqld: where mysqld died. If you see no messages after this, something went

Sep  1 18:43:57 ns228599 mysqld: terribly wrong...

Sep  1 18:43:57 ns228599 mysqld: stack_bottom = 0x0 thread_stack 0x48000

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2b)[0x7ffc8600be9b]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(handle_fatal_signal+0x455)[0x7ffc85bb4f05]

Sep  1 18:43:57 ns228599 mysqld: /lib/x86_64-linux-gnu/libpthread.so.0(+0xfcb0)[0x7ffc85235cb0]

Sep  1 18:43:57 ns228599 mysqld: /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7ffc8380a0d5]

Sep  1 18:43:57 ns228599 mysqld: /lib/x86_64-linux-gnu/libc.so.6(abort+0x17b)[0x7ffc8380d83b]

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(+0x72dd8)[0x7ffb5ac77dd8]

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(+0x72e5a)[0x7ffb5ac77e5a]

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(+0x1048d8)[0x7ffb5ad098d8]

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(_Z21toku_hton_assert_failPKcS0_S0_ii+0x7d)[0x7ffb5ac52e4d]

Sep  1 18:43:57 ns228599 mysqld: /usr/lib/mysql/plugin/ha_tokudb.so(+0x514c6)[0x7ffb5ac564c6]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(_Z22ha_finalize_handlertonP13st_plugin_int+0x34)[0x7ffc85bb72f4]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(+0x40d659)[0x7ffc85a75659]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(+0x410fbe)[0x7ffc85a78fbe]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(_Z15plugin_shutdownv+0x243)[0x7ffc85a798b3]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(+0x379994)[0x7ffc859e1994]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(unireg_abort+0x4c)[0x7ffc859e4c1c]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(+0x37fd4d)[0x7ffc859e7d4d]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x4ae)[0x7ffc859ea4ce]

Sep  1 18:43:57 ns228599 mysqld: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed)[0x7ffc837f576d]

Sep  1 18:43:57 ns228599 mysqld: /usr/sbin/mysqld(+0x376fc9)[0x7ffc859defc9]

Sep  1 18:43:57 ns228599 mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains

Sep  1 18:43:57 ns228599 mysqld: information that should help you find out what is causing the crash.

Sep  1 18:43:58 ns228599 mysqld_safe: mysqld from pid file /var/run/mysqld/mysqld.pid ended

Attachments

Activity

People

Assignee:: Sergei Golubchik

Reporter:: Alexander Mikhailian

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2014-09-02 15:15

Updated:: 2014-09-17 14:01

Resolved:: 2014-09-16 16:31

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.