Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Incomplete
-
10.3.18, 10.3.22
-
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
- relates to
-
MDEV-13689 [Draft] 10.1.10 : InnoDB: Failing assertion: addr.page == FIL_NULL || addr.boffset >= FIL_PAGE_DATA
-
- Closed
-
- links to
Activity
Transition | Time In Source Status | Execution Times |
---|
|
1087d 26m | 1 |
|
28d 5h 37m | 1 |