InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.

Bug #1738526 reported by tuna on 2017-12-16
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC
New
Undecided
Unassigned

Bug Description

InnoDB: ###### Diagnostic info printed to the standard error stream
2017-12-16T14:50:25.748953+08:00 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2017-12-16 14:50:25 0x7f9e5febd700 InnoDB: Assertion failure in thread 140318190851840 in file ut0ut.cc line 917
InnoDB: We intentionally generate a memory trap

tuna (ant750505) wrote :

Percona XtraDB Cluster crash(2 nodes)

tuna (ant750505) wrote :

Hi,How to upload the error.log and trace file?

tuna (ant750505) wrote :
Download full text (4.8 KiB)

DB version:mysqld --version
mysqld Ver 5.7.18-15-57 for Linux on x86_64 (Percona XtraDB Cluster (GPL), Release rel15, Revision 7693d6e, WSREP version 29.20, wsrep_29.20)

OS: cat /etc/redhat-release
CentOS release 6.7 (Final)

uname -a
Linux 10_103_30_112 2.6.32-573.el6.x86_64 #1 SMP Thu Jul 23 15:44:03 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

my.cnf
[client]
default-character-set=utf8

[mysqld]
#For 5.7 add time_zone
default-time_zone='+8:00'
log_timestamps='SYSTEM'

#character set
character-set-server=utf8
collation-server=utf8_bin

basedir=/usr
datadir=/DATA/my3306/pxcdata
port=3306
socket=/DATA/my3306/mysql.sock
pid_file=mysqld.pid
tmpdir=/DATA/my3306/pxcdata
innodb_data_file_path=ibdata1:200M;ibdata2:10M:autoextend
innodb_file_per_table=1
server_id=301123306
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

#log set
log_error=/DATA/my3306/alert.log
log-output=FILE
slow_query_log=1
slow_query_log_file=/DATA/my3306/slow.log
long_query_time=0.5
general_log_file=/DATA/my3306/general.log
general_log=0

#binlog & relaylog
log_bin=mysql-bin
log_slave_updates=1
binlog_format=row
#relay_log=mysql-relay-bin
expire_logs_days=14
#gtid_mode=on
enforce_gtid_consistency=1
binlog_cache_size=4M
max_binlog_cache_size=2G
max_binlog_size=1G

open_files_limit=64000
transaction-isolation=READ-COMMITTED
skip-name-resolve=1
interactive_timeout=7200
wait_timeout=7200
innodb-status-file=1

back_log=1024
max_connections=1000
max_connect_errors=1000000
max_allowed_packet=64M
explicit_defaults_for_timestamp=true

table_open_cache=1024
table_definition_cache=1024
table_open_cache_instances=64
thread_stack=512K

sort_buffer_size=4M
join_buffer_size=4M
thread_cache_size=768
query_cache_size=0
query_cache_type=0
tmp_table_size=32M
max_heap_table_size=32M

key_buffer_size=32M
read_buffer_size=8M
read_rnd_buffer_size=4M
bulk_insert_buffer_size=64M

innodb_thread_concurrency=16
innodb_sync_spin_loops=100
innodb_spin_wait_delay=30

#memery set
innodb_buffer_pool_size=50G
innodb_log_buffer_size=32M
innodb_log_file_size=2G
innodb_log_files_in_group=3
innodb_max_undo_log_size=4G
innodb_max_dirty_pages_pct=90
innodb_lock_wait_timeout=120

#For buffer warm
innodb_buffer_pool_dump_at_shutdown=on
innodb_buffer_pool_load_at_startup=on

innodb_write_io_threads=8
innodb_read_io_threads=8
innodb_purge_threads=4
innodb_page_cleaners=4
innodb_open_files=64000
innodb_max_dirty_pages_pct=50
innodb_lru_scan_depth=4000
innodb_checksum_algorithm=crc32
innodb_rollback_on_timeout=1
innodb_print_all_deadlocks=1
innodb_online_alter_log_max_size=4G
internal_tmp_disk_storage_engine=InnoDB
innodb_status_file=1
#innodb_status_output=1
#innodb_status_output_locks=1
innodb_stats_on_metadata=0

#data security
innodb_flush_log_at_trx_commit=1
sync_binlog=1

#sql-mode set
sql-mode=NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
#sql_mode=NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES

enforce_storage_engine=InnoDB
innodb_io_capacity=4000
innodb_io_capacity_max=4000

#performance_schema
performance_schema=1

#innodb monitor
#innodb_monitor_enable="module_innodb"
#innodb_monitor_enable="module_server"
#innodb_monitor_enable="module_dml"
#innodb_monitor_enable="module_...

Read more...

tuna (ant750505) wrote :
Download full text (6.3 KiB)

mysql> show global status like 'wsrep%';
+----------------------------------+----------------------------------------------------+
| Variable_name | Value |
+----------------------------------+----------------------------------------------------+
| wsrep_local_state_uuid | 5c018094-5273-11e7-9d82-6a3ed29232e8 |
| wsrep_protocol_version | 7 |
| wsrep_last_committed | 334670600 |
| wsrep_replicated | 1179227 |
| wsrep_replicated_bytes | 698270839 |
| wsrep_repl_keys | 4480593 |
| wsrep_repl_keys_bytes | 62966970 |
| wsrep_repl_data_bytes | 559833341 |
| wsrep_repl_other_bytes | 0 |
| wsrep_received | 17969 |
| wsrep_received_bytes | 143974 |
| wsrep_local_commits | 1179227 |
| wsrep_local_cert_failures | 0 |
| wsrep_local_replays | 0 |
| wsrep_local_send_queue | 0 |
| wsrep_local_send_queue_max | 14 |
| wsrep_local_send_queue_min | 0 |
| wsrep_local_send_queue_avg | 0.006466 |
| wsrep_local_recv_queue | 0 |
| wsrep_local_recv_queue_max | 2 |
| wsrep_local_recv_queue_min | 0 |
| wsrep_local_recv_queue_avg | 0.000223 |
| wsrep_local_cached_downto | 333491374 |
| wsrep_flow_control_paused_ns | 0 |
| wsrep_flow_control_paused | 0.000000 |
| wsrep_flow_control_sent | 0 |
| wsrep_flow_control_recv | 0 |
| wsrep_flow_control_interval | [ 141, 141 ] |
| wsrep_flow_control_interval_low | 141 |
| wsrep_flow_control_interval_high | 141 |
| wsrep_flow_control_status | OFF |
| wsrep_cert_deps_distance | 56.274508 |
| wsrep_a...

Read more...

tuna (ant750505) wrote :
Download full text (22.9 KiB)

Some of error log:
2017-12-16T14:38:33.715465+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140306330285824 has waited at row0sel.cc line 3519 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7fa47dece170 created in file buf0buf.cc line 1456
a writer (thread id 140306187093760) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0ins.cc line 2540
Last time write locked in file /mnt/workspace/percona-xtradb-cluster-5.7-redhat-binary/label/centos6-64/rpmbuild/
BUILD/Percona-XtraDB-Cluster-5.7.18-29.20/storage/innobase/include/mtr0mtr.ic line 153
2017-12-16T14:38:33.715616+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140318148892416 has waited at row0row.cc line 989 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7fa47dece170 created in file buf0buf.cc line 1456
a writer (thread id 140306187093760) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0ins.cc line 2540
Last time write locked in file /mnt/workspace/percona-xtradb-cluster-5.7-redhat-binary/label/centos6-64/rpmbuild/
BUILD/Percona-XtraDB-Cluster-5.7.18-29.20/storage/innobase/include/mtr0mtr.ic line 153
2017-12-16T14:38:33.715672+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140306241517312 has waited at row0sel.cc line 3519 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7fa47dece170 created in file buf0buf.cc line 1456
a writer (thread id 140306187093760) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0ins.cc line 2540
Last time write locked in file /mnt/workspace/percona-xtradb-cluster-5.7-redhat-binary/label/centos6-64/rpmbuild/
BUILD/Percona-XtraDB-Cluster-5.7.18-29.20/storage/innobase/include/mtr0mtr.ic line 153
2017-12-16T14:38:33.715745+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140316150900480 has waited at row0sel.cc line 3519 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7fa47dece170 created in file buf0buf.cc line 1456
a writer (thread id 140306187093760) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0ins.cc line 2540
Last time write locked in file /mnt/workspace/percona-xtradb-cluster-5.7-redhat-binary/label/centos6-64/rpmbuild/
BUILD/Percona-XtraDB-Cluster-5.7.18-29.20/storage/innobase/include/mtr0mtr.ic line 153
2017-12-16T14:38:33.715792+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140315453392640 has waited at row0sel.cc line 3519 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7fa47dece170 created in file buf0buf.cc line 1456
a writer (thread id 140306187093760) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0ins.cc line 2540
Last time write locked in file /mnt/workspace/percona-xtradb-cluster-5.7-redhat-binary/label/centos6-64/rpmbuild/
BUILD/Percona-XtraDB-Cluster-5.7.18-29.20/storage/innobase/include/mtr0mtr.ic line 153
2017-12-16T14:38:33.715838+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 1403154...

tuna (ant750505) wrote :

0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 551787966, ACTIVE 942 sec inserting, thread declared inside InnoDB 5000
mysql tables in use 1, locked 1
1 lock struct(s), heap size 1136, 0 row lock(s)
MySQL thread id 717917, OS thread handle 140315486152448, query id 3160890469 10.103.22.58 developer update
insert into pay_record(orderid,payamount,paystatus,paychannel,paytype,createtime,innerorderid,merchantid) values ('p1513406072466741022237',5.0,1,1,6,'2017-12-16 14:34:32','ed2c5258-c34f-4942-8192-5fd8b15f164b',102)
---TRANSACTION 551787961, ACTIVE 942 sec inserting, thread declared inside InnoDB 5000
mysql tables in use 1, locked 1
1 lock struct(s), heap size 1136, 0 row lock(s)
MySQL thread id 718615, OS thread handle 140306289600256, query id 3160889798 10.103.22.177 developer update
insert into pay_record(orderid,payamount,paystatus,paychannel,paytype,createtime,innerorderid,merchantid) values ('p1513406073232468181579',2.0,1,1,6,'2017-12-16 14:34:33','1e9fc20c-e366-40b6-bace-52bde7e04e38',102)
---TRANSACTION 551787948, ACTIVE 942 sec inserting, thread declared inside InnoDB 5000
mysql tables in use 1, locked 1
1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
MySQL thread id 718240, OS thread handle 140306187093760, query id 3160889454 10.103.22.176 developer update
insert into pay_record(orderid,payamount,paystatus,paychannel,paytype,createtime,innerorderid,merchantid) values ('p1513406071869846623684',4.0,1,1,6,'2017-12-16 14:34:31','dbe8a48a-8b24-4466-be2e-15588a09e37d',102)
--------
FILE I/O
--------

Create Table: CREATE TABLE `pay_record` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `orderid` varchar(255) DEFAULT NULL COMMENT '??ID',
  `transactionid` varchar(255) DEFAULT NULL COMMENT '????ID',
  `payamount` decimal(10,2) DEFAULT NULL COMMENT '????',
  `paystatus` tinyint(3) unsigned DEFAULT '1' COMMENT '?????1-????2-????3-???',
  `paychannel` tinyint(4) unsigned DEFAULT NULL COMMENT '?????1-?????2-????3-????4-????',
  `paytype` tinyint(4) unsigned DEFAULT NULL COMMENT '?????1-???2-???3-????4-??',
  `payresult` varchar(3000) DEFAULT NULL COMMENT '?????',
  `createtime` datetime DEFAULT NULL,
  `updatetime` datetime DEFAULT NULL,
  `innerorderid` varchar(255) DEFAULT NULL COMMENT '????ID',
  `merchantid` tinyint(4) DEFAULT NULL COMMENT '?????: 1-??????2-??APP?3-???APP?4-????5-??????6-????????7-??????',
  PRIMARY KEY (`id`),
  UNIQUE KEY `orderid` (`orderid`),
  UNIQUE KEY `idx_payrecord_innerorderid` (`innerorderid`),
  KEY `idx_payrecord_createtime` (`createtime`),
  KEY `idx_payrecord_transactionid` (`transactionid`)
) ENGINE=InnoDB AUTO_INCREMENT=37500995 DEFAULT CHARSET=utf8

tuna (ant750505) wrote :
Download full text (9.9 KiB)

--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (read thread)
I/O thread 7 state: waiting for completed aio requests (read thread)
I/O thread 8 state: waiting for completed aio requests (read thread)
I/O thread 9 state: waiting for completed aio requests (read thread)
I/O thread 10 state: waiting for completed aio requests (write thread)
I/O thread 11 state: waiting for completed aio requests (write thread)
I/O thread 12 state: waiting for completed aio requests (write thread)
I/O thread 13 state: waiting for completed aio requests (write thread)
I/O thread 14 state: waiting for completed aio requests (write thread)
I/O thread 15 state: waiting for completed aio requests (write thread)
I/O thread 16 state: waiting for completed aio requests (write thread)
I/O thread 17 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0, 0, 0, 0, 0] , aio writes: [0, 0, 0, 0, 0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
52951804 OS file reads, 524334224 OS file writes, 418517499 OS fsyncs
0.10 reads/s, 16384 avg bytes/read, 2.60 writes/s, 2.60 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 23, seg size 25, 1641981 merges
merged operations:
 insert 1563573, delete mark 111936, delete 245
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 13279583, node heap has 607 buffer(s)
Hash table size 13279583, node heap has 28998 buffer(s)
Hash table size 13279583, node heap has 24111 buffer(s)
Hash table size 13279583, node heap has 16608 buffer(s)
Hash table size 13279583, node heap has 353 buffer(s)
Hash table size 13279583, node heap has 95 buffer(s)
Hash table size 13279583, node heap has 2257 buffer(s)
Hash table size 13279583, node heap has 25195 buffer(s)
78987.75 hash searches/s, 1185.09 non-hash searches/s
---
LOG
---
Log sequence number 364038702679
Log flushed up to 364038702492
Pages flushed up to 363137869116
Last checkpoint at 363052510229
Max checkpoint age 5216728781
Checkpoint age target 5053706007
Modified age 900833563
Checkpoint age 986192450
0 pending log flushes, 0 pending chkp writes
328680730 log i/o's done, 2.60 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 55889100800
Dictionary memory allocated 7103506
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 2459228992 (849893312 + 1609335680)
    Page hash 6640792 (buffer pool 0 only)
    Dictionary cache 219576834 (212473328 + 7103506)
    File system 1178240 (812272 +...

affects: percona-server → percona-xtradb-cluster
Krunal Bauskar (krunal-bauskar) wrote :

1. Can you re-run the test with innodb_thread_concurrecy=1 or default? Check the related issue here https://bugs.launchpad.net/percona-xtradb-cluster/+bug/1722560.

2. If you still hit the problem we would request a reproducible test-case for further debugging.

tuna (ant750505) wrote :

@Krunal Bauskar
Thanks.
I had set innodb_thread_concurrecy=0.
My DB server crash again.
I reload The new error log when crashed.

tuna (ant750505) wrote :
Download full text (41.3 KiB)

2017-12-29T17:53:31.538067+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140290300778240 has waited at row0ins.cc line 2540 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f9d9cec2810 created in file buf0buf.cc line 1456
a writer (thread id 140299334051584) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3519
Last time write locked in file /mnt/workspace/percona-xtradb-cluster-5.7-redhat-binary/label/centos6-64/rpmbuild/BUILD/Percona-XtraDB-Cluster-5.7.18-29.20/storage/innobase/include/mtr0mtr.ic line 153
2017-12-29T17:53:31.538220+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140299701008128 has waited at row0ins.cc line 2540 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f9d9cec2810 created in file buf0buf.cc line 1456
a writer (thread id 140299334051584) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3519
Last time write locked in file /mnt/workspace/percona-xtradb-cluster-5.7-redhat-binary/label/centos6-64/rpmbuild/BUILD/Percona-XtraDB-Cluster-5.7.18-29.20/storage/innobase/include/mtr0mtr.ic line 153
2017-12-29T17:53:31.538257+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140288321341184 has waited at row0ins.cc line 2540 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f9d9cec2810 created in file buf0buf.cc line 1456
a writer (thread id 140299334051584) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3519
Last time write locked in file /mnt/workspace/percona-xtradb-cluster-5.7-redhat-binary/label/centos6-64/rpmbuild/BUILD/Percona-XtraDB-Cluster-5.7.18-29.20/storage/innobase/include/mtr0mtr.ic line 153
2017-12-29T17:53:31.538290+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140288658458368 has waited at row0sel.cc line 3519 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f9d9cec2810 created in file buf0buf.cc line 1456
a writer (thread id 140299334051584) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3519
Last time write locked in file /mnt/workspace/percona-xtradb-cluster-5.7-redhat-binary/label/centos6-64/rpmbuild/BUILD/Percona-XtraDB-Cluster-5.7.18-29.20/storage/innobase/include/mtr0mtr.ic line 153
2017-12-29T17:53:31.538322+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140288359913216 has waited at row0ins.cc line 2540 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f9d9cec2810 created in file buf0buf.cc line 1456
a writer (thread id 140299334051584) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3519
Last time write locked in file /mnt/workspace/percona-xtradb-cluster-5.7-redhat-binary/label/centos6-64/rpmbuild/BUILD/Percona-XtraDB-Cluster-5.7.18-29.20/storage/innobase/include/mtr0mtr.ic line 153
2017-12-29T17:53:31.538354+08:00 0 [Warning] InnoDB: A long semaphore wait:
--Thread 140299689912064 has waited at ...

So seems like you are hitting the following Percona-Server bug that PXC has inherited from PS.

https://bugs.launchpad.net/percona-server/+bug/1653764

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-2021

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers