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

Waiting for page_cleaner to finish flushing of buffer pool over 4 hours , InnoDB: Assertion failure in file innobase/include/fut0lst.ic line 85

    XMLWordPrintable

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Incomplete
    • 10.3.18, 10.3.22
    • N/A
    • None
    • CentOS Linux release 7.3.1611 (Core)
      MariaDB 10.3.18 , MariaDB 10.3.22

    Description

      Hi,
      Usually , It is very fast to update table by primary key , but we encountered row lock on 5000+ update statements on master server,
      all write operator very slow suddently, It show( id field is primary key) in proxy error log:
      2020-04-19 13:23:34 MySQL_Session.cpp:4322:handler(): [WARNING] Error during query on schema "db_user" , 1205, Lock wait timeout exceeded; try restarting transaction . digest_text = "UPDATE `tb_last_update` SET `uid`=?, `type`=?, `ip`=?, `update_date`=? WHERE `id`=?"

      after execute switchover for master and slave, we stop old master , but mysql stop very slow.
      after 4 hours , we force restart os, lately, mysql could normal start all the time.
      Now, We restore new instance from full backup. Please help confirm , thanks.

      core dump file: core.22237.gz

      mysql error log:
      2020-04-19 19:30:58 1 [Note] InnoDB: Truncating UNDO tablespace 1
      2020-04-19 19:37:10 0 [Note] /usr/sbin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
      2020-04-19 19:37:10 2784 [Note] Stop semi-sync binlog_dump to slave (server_id: 103108)
      2020-04-19 19:37:10 0 [Note] Event Scheduler: Purging the queue. 0 events
      2020-04-19 19:37:10 0 [Note] InnoDB: FTS optimize thread exiting.
      2020-04-19 19:38:48 1 [Note] InnoDB: Truncated UNDO tablespace 1
      200419 19:38:48 server_audit: STOPPED
      2020-04-19 19:38:48 0 [Note] InnoDB: Starting shutdown...
      2020-04-19 19:38:48 0 [Note] InnoDB: Dumping buffer pool(s) to /data1/mysql/data/ib_buffer_pool
      2020-04-19 19:38:48 0 [Note] InnoDB: Instance 0, restricted to 65536 pages due to innodb_buf_pool_dump_pct=25
      2020-04-19 19:38:48 0 [Note] InnoDB: Instance 1, restricted to 65536 pages due to innodb_buf_pool_dump_pct=25
      2020-04-19 19:38:48 0 [Note] InnoDB: Instance 2, restricted to 65536 pages due to innodb_buf_pool_dump_pct=25
      2020-04-19 19:38:48 0 [Note] InnoDB: Instance 3, restricted to 65536 pages due to innodb_buf_pool_dump_pct=25
      2020-04-19 19:38:48 0 [Note] InnoDB: Instance 4, restricted to 65536 pages due to innodb_buf_pool_dump_pct=25
      2020-04-19 19:38:48 0 [Note] InnoDB: Instance 5, restricted to 65536 pages due to innodb_buf_pool_dump_pct=25
      2020-04-19 19:38:48 0 [Note] InnoDB: Instance 6, restricted to 65536 pages due to innodb_buf_pool_dump_pct=25
      2020-04-19 19:38:48 0 [Note] InnoDB: Instance 7, restricted to 65536 pages due to innodb_buf_pool_dump_pct=25
      2020-04-19 19:38:48 0 [Note] InnoDB: Buffer pool(s) dump completed at 200419 19:38:48
      2020-04-19 19:39:48 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2020-04-19 19:40:49 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2020-04-19 19:41:49 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2020-04-19 19:42:49 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2020-04-19 19:43:49 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2020-04-19 19:44:49 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2020-04-19 19:45:49 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      ......
      020-04-19 23:06:17 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2020-04-19 23:07:17 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2020-04-19 23:08:17 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2020-04-19 23:09:17 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
      2020-04-19 23:25:22 0 [ERROR] mysqld: Can't open shared library '/usr/lib64/mysql/plugin/semisync_master.so' (errno: 0, cannot open shared object file: No such file or directory)
      2020-04-19 23:25:22 0 [ERROR] mysqld: Can't open shared library '/usr/lib64/mysql/plugin/semisync_slave.so' (errno: 0, cannot open shared object file: No such file or directory)
      2020-04-19 23:25:22 0 [Warning] The parameter innodb_file_format is deprecated and has no effect. It may be removed in future releases. See https://mariadb.com/kb/en/library/xtradbinnodb-file-format/
      2020-04-19 23:25:22 0 [Note] InnoDB: Using Linux native AIO
      2020-04-19 23:25:22 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2020-04-19 23:25:22 0 [Note] InnoDB: Uses event mutexes
      2020-04-19 23:25:22 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
      2020-04-19 23:25:22 0 [Note] InnoDB: Number of pools: 1
      2020-04-19 23:25:22 0 [Note] InnoDB: Using SSE2 crc32 instructions
      2020-04-19 23:25:22 0 [Note] InnoDB: Initializing buffer pool, total size = 32G, instances = 8, chunk size = 128M
      2020-04-19 23:25:23 0 [Note] InnoDB: Completed initialization of buffer pool
      2020-04-19 23:25:24 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2020-04-19 23:25:24 0 [Note] InnoDB: Opened 4 undo tablespaces
      2020-04-19 23:25:24 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=17768187528390
      2020-04-19 23:25:39 0 [Note] InnoDB: Read redo log up to LSN=17765121390592
      2020-04-19 23:25:54 0 [Note] InnoDB: Read redo log up to LSN=17767243118592
      2020-04-19 23:26:20 0 [Note] InnoDB: Recovered page [page id: space=81598, page number=45017485] from the doublewrite buffer.
      2020-04-19 23:26:20 0 [Note] InnoDB: Recovered page [page id: space=81598, page number=45012970] from the doublewrite buffer.
      2020-04-19 23:26:20 0 [Note] InnoDB: Recovered page [page id: space=81598, page number=2863741] from the doublewrite buffer.
      2020-04-19 23:26:20 0 [Note] InnoDB: Recovered page [page id: space=81450, page number=20625701] from the doublewrite buffer.
      ......
      2020-04-19 23:26:21 0 [Note] InnoDB: Read redo log up to LSN=17768187906560
      2020-04-19 23:26:25 0 [Note] InnoDB: Starting final batch to recover 681444 pages from redo log.
      2020-04-19 23:26:36 0 [Note] InnoDB: To recover: 529354 pages from log
      2020-04-19 23:26:51 0 [Note] InnoDB: To recover: 180719 pages from log
      2020-04-19 23:26:58 0 [Note] InnoDB: Last binlog file '/data1/mysql/log/master-bin.001700', position 1022737240
      2020-04-19 23:26:59 0 [Note] InnoDB: 128 out of 128 rollback segments in 4 undo tablespaces are active.
      2020-04-19 23:26:59 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      2020-04-19 23:26:59 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      2020-04-19 23:26:59 0 [Note] InnoDB: Setting file '/data1/mysql/data/ibtmp1' size to 64 MB. Physically writing the file full; Please wait ...
      2020-04-19 23:27:01 0 [Note] InnoDB: File '/data1/mysql/data/ibtmp1' size is now 64 MB.
      2020-04-19 23:27:01 0 [Note] InnoDB: Waiting for purge to start
      2020-04-19 23:27:01 0 [Note] InnoDB: 10.3.18 started; log sequence number 17768187906286; transaction id 34488705119
      2020-04-19 23:27:01 0 [Note] InnoDB: Loading buffer pool(s) from /data1/mysql/data/ib_buffer_pool
      2020-04-19 23:27:01 0 [Note] Plugin 'FEEDBACK' is disabled.
      200419 23:27:01 server_audit: server_audit_excl_users set to 'pmm,zabbixm'.
      200419 23:27:01 server_audit: MariaDB Audit Plugin version 1.4.8 STARTED.
      200419 23:27:01 server_audit: logging started to the file /data1/mysql/auditlog/server_audit.log.
      2020-04-19 23:27:01 0 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
      2020-04-19 23:27:01 0 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
      2020-04-19 23:27:01 0 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
      2020-04-19 23:27:01 0 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
      2020-04-19 23:27:01 0 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
      2020-04-19 23:27:01 0 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
      2020-04-19 23:27:01 0 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
      2020-04-19 23:27:01 0 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
      2020-04-19 23:27:01 0 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
      2020-04-19 23:27:01 0 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
      2020-04-19 23:27:01 0 [Warning] InnoDB: Retry attempts for reading partial data failed.
      2020-04-19 23:27:01 0 [ERROR] InnoDB: Tried to read 16384 bytes at offset 24756224, but was only able to read 0
      2020-04-19 23:27:01 0 [Warning] InnoDB: Retry attempts for reading partial data failed.
      2020-04-19 23:27:01 0 [ERROR] InnoDB: Tried to read 16384 bytes at offset 24756224, but was only able to read 0
      2020-04-19 23:27:01 0 [ERROR] InnoDB: File (unknown): 'read' returned OS error 0. Cannot continue operation
      200419 23:27:01 [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.18-MariaDB-log
      key_buffer_size=16777216
      read_buffer_size=131072
      max_used_connections=0
      max_threads=8002
      thread_count=6
      It is possible that mysqld could use up to
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 17608883 K bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.

      Thread pointer: 0x0
      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 = 0x0 thread_stack 0x49000
      /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x7f7401a0206e]
      /usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x7f740149f11f]
      sigaction.c:0(__restore_rt)[0x7f74008e0370]
      :0(__GI_raise)[0x7f73fedee1d7]
      :0(__GI_abort)[0x7f73fedef8c8]
      /usr/sbin/mysqld(+0x994835)[0x7f74016a4835]
      /usr/sbin/mysqld(+0x994d03)[0x7f74016a4d03]
      /usr/sbin/mysqld(+0x99ba4f)[0x7f74016aba4f]
      /usr/sbin/mysqld(+0xb26dc8)[0x7f7401836dc8]
      /usr/sbin/mysqld(+0xadc3d8)[0x7f74017ec3d8]
      /usr/sbin/mysqld(+0xac829d)[0x7f74017d829d]
      /usr/sbin/mysqld(+0xac86e6)[0x7f74017d86e6]
      pthread_create.c:0(start_thread)[0x7f74008d8dc5]
      /lib64/libc.so.6(clone+0x6d)[0x7f73feeb076d]
      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 /data1/mysql/data
      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 unlimited unlimited bytes
      Max resident set unlimited unlimited bytes
      Max processes 102400 102400 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 385995 385995 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

      2020-04-19 23:38:41 0 [Note] InnoDB: Using Linux native AIO
      2020-04-19 23:38:41 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2020-04-19 23:38:41 0 [Note] InnoDB: Uses event mutexes
      2020-04-19 23:38:41 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
      2020-04-19 23:38:41 0 [Note] InnoDB: Number of pools: 1
      2020-04-19 23:38:41 0 [Note] InnoDB: Using SSE2 crc32 instructions
      2020-04-19 23:38:41 0 [Note] InnoDB: Initializing buffer pool, total size = 32G, instances = 8, chunk size = 128M
      2020-04-19 23:38:42 0 [Note] InnoDB: Completed initialization of buffer pool
      2020-04-19 23:38:43 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2020-04-19 23:38:43 0 [Note] InnoDB: Opened 4 undo tablespaces
      2020-04-19 23:38:43 0x7f5b36a038c0 InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.3.18/storage/innobase/include/fut0lst.ic line 85
      InnoDB: Failing assertion: addr.page == FIL_NULL || addr.boffset >= FIL_PAGE_DATA
      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.
      200419 23:38:43 [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.18-MariaDB-log
      key_buffer_size=16777216
      read_buffer_size=131072
      max_used_connections=0
      max_threads=8002
      thread_count=0
      It is possible that mysqld could use up to
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 17608883 K bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.

      Thread pointer: 0x0
      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 = 0x0 thread_stack 0x49000
      /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x7f5b3773706e]
      /usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x7f5b371d411f]
      sigaction.c:0(__restore_rt)[0x7f5b363e1370]
      :0(__GI_raise)[0x7f5b348ef1d7]
      :0(__GI_abort)[0x7f5b348f08c8]
      /usr/sbin/mysqld(+0x4d3856)[0x7f5b36f18856]
      /usr/sbin/mysqld(+0x4d37c4)[0x7f5b36f187c4]
      /usr/sbin/mysqld(+0xa74417)[0x7f5b374b9417]
      /usr/sbin/mysqld(+0xa5ff72)[0x7f5b374a4f72]
      /usr/sbin/mysqld(+0xa6d0f8)[0x7f5b374b20f8]
      /usr/sbin/mysqld(+0xa3532b)[0x7f5b3747a32b]
      /usr/sbin/mysqld(+0x9257e1)[0x7f5b3736a7e1]
      /usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x64)[0x7f5b371d6854]
      /usr/sbin/mysqld(+0x5c5760)[0x7f5b3700a760]
      /usr/sbin/mysqld(_Z11plugin_initPiPPci+0x9ba)[0x7f5b3700b8ea]
      /usr/sbin/mysqld(+0x4f8ec1)[0x7f5b36f3dec1]
      /usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x4ae)[0x7f5b36f440be]
      /lib64/libc.so.6(__libc_start_main+0xf5)[0x7f5b348dbb35]
      /usr/sbin/mysqld(+0x4f2add)[0x7f5b36f37add]
      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.

      Attachments

        Issue Links

          Activity

            People

              marko Marko Mäkelä
              sysdljr sysdljr
              Votes:
              1 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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