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

Maria DB server crases during an insert

    XMLWordPrintable

    Details

      Description

      After some hours of normal usage, server suddenly crashes with no apparent reason.

      2019-06-01 9:11:24 0 [Note] InnoDB: Using Linux native AIO
      2019-06-01 9:11:24 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2019-06-01 9:11:24 0 [Note] InnoDB: Uses event mutexes
      2019-06-01 9:11:24 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
      2019-06-01 9:11:24 0 [Note] InnoDB: Number of pools: 1
      2019-06-01 9:11:24 0 [Note] InnoDB: Using SSE2 crc32 instructions
      2019-06-01 9:11:24 0 [Note] InnoDB: Initializing buffer pool, total size = 8G, instances = 8, chunk size = 128M
      2019-06-01 9:11:25 0 [Note] InnoDB: Completed initialization of buffer pool
      2019-06-01 9:11:25 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2019-06-01 9:11:25 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=9540742029
      2019-06-01 9:11:25 0 [Note] InnoDB: Starting final batch to recover 2076 pages from redo log.
      2019-06-01 9:11:26 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
      2019-06-01 9:11:26 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      2019-06-01 9:11:26 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      2019-06-01 9:11:26 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      2019-06-01 9:11:26 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
      2019-06-01 9:11:26 0 [Note] InnoDB: Waiting for purge to start
      2019-06-01 9:11:26 0 [Note] InnoDB: 10.3.15 started; log sequence number 9542695020; transaction id 485290
      2019-06-01 9:11:26 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
      2019-06-01 9:11:26 0 [Note] Plugin 'FEEDBACK' is disabled.
      2019-06-01 9:11:26 0 [Note] Recovering after a crash using tc.log
      2019-06-01 9:11:26 0 [Note] Starting crash recovery...
      2019-06-01 9:11:26 0 [Note] Crash recovery finished.
      2019-06-01 9:11:26 0 [Note] Server socket created on IP: '::'.
      2019-06-01 9:11:26 6 [Note] Event Scheduler: scheduler thread started with id 6
      2019-06-01 9:11:26 0 [Note] Reading of all Master_info entries succeded
      2019-06-01 9:11:26 0 [Note] Added new Master_info '' to hash table
      2019-06-01 9:11:26 0 [Note] /usr/sbin/mysqld: ready for connections.
      Version: '10.3.15-MariaDB' socket: '/var/lib/mysql/mysql.sock' port: 3306 MariaDB Server
      2019-06-01 09:11:29 0x7f9b18148700 InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.3.15/storage/innobase/btr/btr0cur.cc line 338
      InnoDB: Failing assertion: btr_page_get_prev(get_block->frame, mtr) == page_get_page_no(page)
      InnoDB: We intentionally generate a memory trap.
      InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
      InnoDB: If you get repeated assertion failures or crashes, even
      InnoDB: immediately after the mysqld startup, there may be
      InnoDB: corruption in the InnoDB tablespace. Please refer to
      InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
      InnoDB: about forcing recovery.
      190601 9:11:29 [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.

      To report this bug, see https://mariadb.com/kb/en/reporting-bugs

      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.

      Server version: 10.3.15-MariaDB
      key_buffer_size=134217728
      read_buffer_size=131072
      max_used_connections=7
      max_threads=153
      thread_count=14
      It is possible that mysqld could use up to
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467420 K bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.

      Thread pointer: 0x7f986c0009a8
      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 = 0x7f9b18147d00 thread_stack 0x49000
      /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55d9878d191e]
      /usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x55d98736e53f]
      sigaction.c:0(__restore_rt)[0x7f9b38a145d0]
      :0(__GI_raise)[0x7f9b36ce7207]
      :0(__GI_abort)[0x7f9b36ce88f8]
      /usr/sbin/mysqld(+0x4c5e9c)[0x55d9870b5e9c]
      /usr/sbin/mysqld(+0xa858a1)[0x55d9876758a1]
      /usr/sbin/mysqld(+0xa91a30)[0x55d987681a30]
      /usr/sbin/mysqld(+0x9d17a3)[0x55d9875c17a3]
      /usr/sbin/mysqld(+0x9d300f)[0x55d9875c300f]
      /usr/sbin/mysqld(+0x9d333a)[0x55d9875c333a]
      /usr/sbin/mysqld(+0x9e3541)[0x55d9875d3541]
      /usr/sbin/mysqld(+0x927450)[0x55d987517450]
      /usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0x1af)[0x55d987379e1f]
      /usr/sbin/mysqld(+0xcb694a)[0x55d9878a694a]
      /usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0xcb)[0x55d987379d3b]
      /usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP12st_copy_info+0x6a)[0x55d9871681fa]
      /usr/sbin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0x13bc)[0x55d98716eb5c]
      /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x3bf8)[0x55d9871995f8]
      /usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x22b)[0x55d98719ebdb]
      /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x1d3e)[0x55d9871a18de]
      /usr/sbin/mysqld(_Z10do_commandP3THD+0x13e)[0x55d9871a273e]
      /usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x1aa)[0x55d98727379a]
      /usr/sbin/mysqld(handle_one_connection+0x3d)[0x55d9872738bd]
      /usr/sbin/mysqld(+0xc9629d)[0x55d98788629d]
      pthread_create.c:0(start_thread)[0x7f9b38a0cdd5]
      /lib64/libc.so.6(clone+0x6d)[0x7f9b36daeead]

      Trying to get some variables.
      Some pointers may be invalid and cause the dump to abort.
      Query (0x7f986c00f520): insert into history_uint (itemid,clock,ns,value) values (48713,1559341794,137300824,1),(57923,1559341794,137300824,1),(45829,1559341794,137300824,1),(63773,1559341811,156325756,0),(28797,1559341813,715543958,1329428),(56342,1559341813,827687814,0),(43904,1559341813,827687814,1),(43898,1559341813,827687814,0),(56343,1559341813,827687814,0),(56341,1559341813,827687814,1),(43883,1559341813,827687814,1),(43907,1559341813,827687814,0),(56332,1559341813,827687814,49856),(56334,1559341813,827687814,1),(56339,1559341813,827687814,0),(43877,1559341813,827687814,1884456),(56340,1559341813,827687814,0),(43910,1559341813,827687814,0),(43901,1559341813,827687814,0),(60069,1559341813,873829365,1),(60081,1559341813,873829365,175864),(60087,1559341813,873829365,0),(60083,1559341813,873829365,0),(60082,1559341813,873829365,156104),(60070,1559341813,873829365,1),(60065,1559341813,873829365,0),(60064,1559341813,873829365,93560),(60084,1559341813,873829365,0),(60071,1559341813,873829365,1),(60093,1559341813,873829365,0),(60096,1559341813,873829365,0),(60092,1559341813,873829365,1),(60090,1559341813,873829365,1),(60091,1559341813,873829365,1),(65679,1559341813,882659459,0),(65682,1559341813,882659459,0),(65666,1559341813,882659459,187968),(65681,1559341813,882659459,0),(65683,1559341813,882659459,1),(65684,1559341813,882659459,1),(65680,1559341813,882659459,0),(65669,1559341813,882659459,1),(65686,1559341813,882659459,0),(65670,1559341813,882659459,1),(65667,1559341813,882659459,100000000),(65688,1559341813,882659459,0),(65685,1559341813,882659459,0),(65687,1559341813,882659459,0),(65674,1559341813,882659459,0),(45015,1559341813,893576314,1),(45017,1559341813,893576314,1),(45192,1559341813,893576314,1),(45014,1559341813,893576314,1),(45193,1559341813,893576314,1),(45189,1559341813,893576314,1),(45016,1559341813,893576314,1),(45188,1559341813,893576314,1),(45187,1559341813,893576314,1),(45190,1559341813,893576314,1),(45191,1559341813,893576314,1),(54839,1559341813,894622908,0),(54833,1559341813,894622908,0),(54840,1559341813,894622908,0),(54822,1559341813,894622908,1),(54830,1559341813,894622908,31784),(54817,1559341813,894622908,32808),(54834,1559341813,894622908,0),(54831,1559341813,894622908,0),(54832,1559341813,894622908,0),(54837,1559341813,894622908,0),(54835,1559341813,894622908,1),(54836,1559341813,894622908,1),(54821,1559341813,894622908,1),(54838,1559341813,894622908,0),(61033,1559341813,947652018,3221221376)
      Connection ID (thread ID): 12
      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,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on

      The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
      information that should help you find out what is causing the crash.
      Writing a core file...
      Working directory at /var/lib/mysql
      Resource Limits:
      Limit Soft Limit Hard Limit Units
      Max cpu time unlimited unlimited seconds
      Max file size unlimited unlimited bytes
      Max data size unlimited unlimited bytes
      Max stack size 8388608 unlimited bytes
      Max core file size 0 unlimited bytes
      Max resident set unlimited unlimited bytes
      Max processes 63450 63450 processes
      Max open files 16364 16364 files
      Max locked memory 65536 65536 bytes
      Max address space unlimited unlimited bytes
      Max file locks unlimited unlimited locks
      Max pending signals 63450 63450 signals
      Max msgqueue size 819200 819200 bytes
      Max nice priority 0 0
      Max realtime priority 0 0
      Max realtime timeout unlimited unlimited us
      Core pattern: core

      2019-06-01 9:11:35 0 [Note] InnoDB: Using Linux native AIO
      2019-06-01 9:11:35 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2019-06-01 9:11:35 0 [Note] InnoDB: Uses event mutexes
      2019-06-01 9:11:35 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
      2019-06-01 9:11:35 0 [Note] InnoDB: Number of pools: 1
      2019-06-01 9:11:35 0 [Note] InnoDB: Using SSE2 crc32 instructions
      2019-06-01 9:11:35 0 [Note] InnoDB: Initializing buffer pool, total size = 8G, instances = 8, chunk size = 128M
      2019-06-01 9:11:35 0 [Note] InnoDB: Completed initialization of buffer pool
      2019-06-01 9:11:35 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2019-06-01 9:11:35 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=9542695560
      2019-06-01 9:11:36 0 [Note] InnoDB: 4 transaction(s) which must be rolled back or cleaned up in total 1521 row operations to undo
      2019-06-01 9:11:36 0 [Note] InnoDB: Trx id counter is 485346
      2019-06-01 9:11:36 0 [Note] InnoDB: Starting final batch to recover 2069 pages from redo log.
      2019-06-01 9:11:36 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
      2019-06-01 9:11:36 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
      2019-06-01 9:11:36 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      2019-06-01 9:11:36 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      2019-06-01 9:11:36 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      2019-06-01 9:11:36 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
      2019-06-01 9:11:37 0 [Note] InnoDB: Waiting for purge to start
      2019-06-01 9:11:37 0 [Note] InnoDB: 10.3.15 started; log sequence number 9543917942; transaction id 485348
      2019-06-01 9:11:37 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
      2019-06-01 9:11:37 0 [Note] Plugin 'FEEDBACK' is disabled.
      2019-06-01 9:11:37 0 [Note] Recovering after a crash using tc.log
      2019-06-01 9:11:37 0 [Note] Starting crash recovery...
      2019-06-01 9:11:37 0 [Note] Crash recovery finished.
      2019-06-01 9:11:37 0 [Note] Server socket created on IP: '::'.
      2019-06-01 9:11:37 6 [Note] Event Scheduler: scheduler thread started with id 6
      2019-06-01 9:11:37 0 [Note] Reading of all Master_info entries succeded
      2019-06-01 9:11:37 0 [Note] Added new Master_info '' to hash table
      2019-06-01 9:11:37 0 [Note] /usr/sbin/mysqld: ready for connections.
      Version: '10.3.15-MariaDB' socket: '/var/lib/mysql/mysql.sock' port: 3306 MariaDB Server
      2019-06-01 9:11:37 0 [Note] InnoDB: Rolled back recovered transaction 485322
      2019-06-01 9:11:37 0 [Note] InnoDB: Rolled back recovered transaction 485312
      2019-06-01 9:11:37 0 [Note] InnoDB: Rolled back recovered transaction 485345
      2019-06-01 9:11:37 0 [Note] InnoDB: Rolled back recovered transaction 485311
      2019-06-01 9:11:37 0 [Note] InnoDB: Rollback of non-prepared transactions completed

      I attached serveral txt files with the actual config and status.

      After a "hard" restart server works again but again randomly crashes again.

      Any Idea, could be a bug?

        Attachments

        1. global.status.txt
          61 kB
        2. global.var.txt
          461 kB
        3. innodb.status.txt
          59 kB

          Issue Links

            Activity

              People

              Assignee:
              marko Marko Mäkelä
              Reporter:
              fcolladop Fernando Collado
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated: