Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-6681

TokuDB crash on import of 100+ mln rows

    XMLWordPrintable

    Details

      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:
            serg Sergei Golubchik
            Reporter:
            mikhailian Alexander Mikhailian
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: