Bug #88967 Semaphore wait has lasted > 600 seconds mysqld restart
Submitted: 19 Dec 2017 11:24 Modified: 20 Jan 2018 14:46
Reporter: 耀 赵 Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:5.7.16 OS:CentOS
Assigned to: CPU Architecture:Any
Tags: semaphore wait has lasted > 600 seconds

[19 Dec 2017 11:24] 耀 赵
Description:
when add column,the mysqld crash and resatrt.
here is innodb monitor:
=====================================
2017-12-19 18:30:48 0x7fb604b34700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 278 srv_active, 0 srv_shutdown, 4098 srv_idle
srv_master_thread log flush and writes: 4376
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 978
--Thread 140418808006400 has waited at buf0flu.cc line 1209 for 934.00 seconds the semaphore:
SX-lock on RW-latch at 0x7fbdd54f15d8 created in file buf0buf.cc line 1457
a writer (thread id 140419412686592) has reserved it in mode  SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time read locked in file not yet reserved line 0
Last time write locked in file /export/home/pb2/build/sb_0-20577873-1475085368.25/mysql-5.7.16/storage/innobase/fsp/fsp0fsp.cc line 167
OS WAIT ARRAY INFO: signal count 805
RW-shared spins 0, rounds 1594, OS waits 618
RW-excl spins 0, rounds 1043, OS waits 15
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 1594.00 RW-shared, 1043.00 RW-excl, 0.00 RW-sx

at end mysqld is crash and err log is :

InnoDB: ###### Diagnostic info printed to the standard error stream
2017-12-19T18:31:07.990291+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-19 18:31:07 0x7fb605535700  InnoDB: Assertion failure in thread 140419750123264 in file ut0ut.cc line 916
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
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: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
10:31:07 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=2097152
max_used_connections=16
max_threads=3000
thread_count=8
connection_count=7
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 18480223 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 = 0 thread_stack 0x30000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x35)[0xf1dff5]
/usr/local/mysql/bin/mysqld(handle_fatal_signal+0x4a4)[0x79d3b4]
/lib64/libpthread.so.0[0x39b240f790]
/lib64/libc.so.6(gsignal+0x35)[0x39b2032625]
/lib64/libc.so.6(abort+0x175)[0x39b2033e05]
/usr/local/mysql/bin/mysqld[0x1159d65]
/usr/local/mysql/bin/mysqld(_ZN2ib5fatalD1Ev+0xb3)[0x115e8b3]
/usr/local/mysql/bin/mysqld(srv_error_monitor_thread+0x98a)[0x110bc7a]
/lib64/libpthread.so.0[0x39b2407a51]
/lib64/libc.so.6(clone+0x6d)[0x39b20e896d]

How to repeat:
unknown!!
[19 Dec 2017 11:32] 耀 赵
=====================================
2017-12-19 18:30:48 0x7fb604b34700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 278 srv_active, 0 srv_shutdown, 4098 srv_idle
srv_master_thread log flush and writes: 4376
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 978
--Thread 140418808006400 has waited at buf0flu.cc line 1209 for 934.00 seconds the semaphore:
SX-lock on RW-latch at 0x7fbdd54f15d8 created in file buf0buf.cc line 1457
a writer (thread id 140419412686592) has reserved it in mode  SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time read locked in file not yet reserved line 0
Last time write locked in file /export/home/pb2/build/sb_0-20577873-1475085368.25/mysql-5.7.16/storage/innobase/fsp/fsp0fsp.cc line 167
OS WAIT ARRAY INFO: signal count 805
RW-shared spins 0, rounds 1594, OS waits 618
RW-excl spins 0, rounds 1043, OS waits 15
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 1594.00 RW-shared, 1043.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 957165
Purge done for trx's n:o < 957154 undo n:o < 3 state: running but idle
History list length 1163
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421928419820944, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421928419821856, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421928419817296, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 957164, ACTIVE (PREPARED) 850 sec
5 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 7
MySQL thread id 4419, OS thread handle 140419410478848, query id 34306 192.168.76.61 xe-erp starting
commit
---TRANSACTION 957162, ACTIVE (PREPARED) 855 sec committing
4 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 3, OS thread handle 140419413088000, query id 34281 192.168.76.62 xe-erp starting
commit
---TRANSACTION 957151, ACTIVE 944 sec reading clustered index
mysql tables in use 1, locked 1
0 lock struct(s), heap size 1136, 0 row lock(s)
MySQL thread id 6358, OS thread handle 140419412686592, query id 34079 localhost root altering table
alter table xe_ven_order_info add purchase_type int(1) DEFAULT NULL COMMENT '采购类型 1 零采 2 整柜'
Trx read view will not see trx with id >= 957153, sees < 957152
--------
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
8433 OS file reads, 7648 OS file writes, 3652 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 231 merges
merged operations:
 insert 223, delete mark 54, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 7967797, node heap has 4 buffer(s)
Hash table size 7967797, node heap has 0 buffer(s)
Hash table size 7967797, node heap has 4 buffer(s)
Hash table size 7967797, node heap has 0 buffer(s)
Hash table size 7967797, node heap has 0 buffer(s)
Hash table size 7967797, node heap has 1 buffer(s)
Hash table size 7967797, node heap has 1 buffer(s)
Hash table size 7967797, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 33168610738
Log flushed up to   33168610738
Pages flushed up to 33168408342
Last checkpoint at  33168408342
0 pending log flushes, 0 pending chkp writes
1719 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 32987152384
Dictionary memory allocated 2756828
Buffer pool size   1965840
Free buffers       1951225
Database pages     14605
Old database pages 5411
Modified db pages  6399
Pending reads      0
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 5, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 8163, created 6442, written 5400
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 14605, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=3310, Main thread ID=140419729143552, state: sleeping
Number of rows inserted 933, updated 434, deleted 132, read 55145
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
[19 Dec 2017 17:59] MySQL Verification Team
Hi!

Thank you for your report. 

Do note that you have not supplied us with sufficient info. We need all tables that were involved in this assert and the exact SQL statement that you have run when this assert occurred.

Also, please use latest 5.7 release as there were lots of bugs fixed after 5.7.16.
[20 Dec 2017 2:07] 耀 赵
hi Sinisa Milivojevic:

here is table struct:
CREATE TABLE "xe_ven_order_info" (
  "id" int(10) NOT NULL AUTO_INCREMENT COMMENT '标识',
  "order_id" varchar(20) NOT NULL COMMENT '订单号',
  "user_id" varchar(32) NOT NULL COMMENT '下单用户标识',
  "user_code" varchar(50) NOT NULL COMMENT '供应商编码',
  "ven_name" varchar(50) DEFAULT NULL COMMENT '供应商名称(有店铺名称先店铺,没有取供应商名称)',
  "ip_addr" varchar(50) DEFAULT NULL COMMENT 'ip地址',
  "source_id" varchar(128) DEFAULT NULL COMMENT '来源标识(设备号)',
  "order_status" int(1) DEFAULT NULL COMMENT '订单状态 :1 已完成 2 已发货 3待发货 4已取消 5 待分配 6待审核',
  "total_amount" decimal(15,2) DEFAULT NULL COMMENT '订单总金额',
  "pay_amount" decimal(15,2) DEFAULT NULL COMMENT '订单支付金额 = 订单总金额+运费总金额-优惠总金额-特批优惠金额',
  "difference_amount" decimal(15,2) DEFAULT NULL COMMENT '差异金额',
  "goods_amount" decimal(15,2) DEFAULT NULL COMMENT '商品总金额',
  "fre_amount" decimal(15,2) DEFAULT NULL COMMENT '运费总金额',
  "pmt_amount" decimal(15,2) DEFAULT NULL COMMENT '优惠总金额 =优惠券总金额+ 商品促销优惠总金额+ 订单促销优惠金额+ 订单减免总金额+ 使用积分优惠金额',
  "cpns_pmt_aomount" decimal(15,2) DEFAULT NULL COMMENT '优惠券总金额',
  "pay_status" int(1) DEFAULT NULL COMMENT '付款状态  1:已支付,2:未支付',
  "pay_type" int(1) DEFAULT NULL COMMENT '支付类型 4: 在线支付1:货到付款2:到店自提3:银行汇款',
  "pay_channel" int(1) DEFAULT NULL COMMENT '支付渠道1:支付宝2:微信3:余额 4:网银支付5:POS支付 6 :快捷支付',
  "pay_number" varchar(50) DEFAULT NULL COMMENT '支付流水号',
  "pay_time" datetime DEFAULT NULL COMMENT '支付成功时间',
  "ship_type" int(1) DEFAULT NULL COMMENT '配送方式 1 配送 2 委托自提 3 到店自提'',',
  "ship_car_id" int(10) DEFAULT NULL COMMENT '配送车辆信息id',
  "ship_car_des" varchar(50) DEFAULT NULL COMMENT '指定车辆信息',
  "order_source" int(1) DEFAULT NULL COMMENT '订单来源 4 pc 1:android 2:ios 3:微信 5:代客下单 6:其它',
  "order_type" int(1) DEFAULT NULL COMMENT '订单类型  1一口价 2询报价',
  "ca_consignee" varchar(100) DEFAULT NULL COMMENT '收货人',
  "ca_province_id" varchar(10) DEFAULT NULL COMMENT '省份标识',
  "ca_city_id" varchar(10) DEFAULT NULL COMMENT '城市标识',
  "ca_area_id" varchar(10) DEFAULT NULL COMMENT '地区标识',
  "ca_street" varchar(200) DEFAULT NULL COMMENT '详细街道地址',
  "ca_phone" varchar(15) DEFAULT NULL COMMENT '电话',
  "ca_postal_code" varchar(20) DEFAULT NULL COMMENT '邮政编码',
  "order_remark" varchar(200) DEFAULT NULL COMMENT '订单备注',
  "creater_user" varchar(50) DEFAULT NULL COMMENT '创建人',
  "create_date" datetime DEFAULT NULL COMMENT '创建日期',
  "modfiy_user" varchar(50) DEFAULT NULL COMMENT '修改者',
  "modify_date" datetime DEFAULT NULL COMMENT '修改日期',
  "version" int(5) DEFAULT '0' COMMENT '版本号',
  "auto_matic" int(1) DEFAULT NULL COMMENT '1:自动分配  2:手动分配',
  "vendor_remark" varchar(200) DEFAULT NULL COMMENT '卖家备注',
  "store_name" varchar(200) DEFAULT NULL COMMENT '店铺名称',
  "login_account" varchar(100) DEFAULT NULL COMMENT '用户名',
  "epay_account" varchar(100) DEFAULT NULL COMMENT '下单用户对应的易支付账户',
  "tax_type" int(1) DEFAULT NULL COMMENT '发票类型 1:普通发票   2:增值税发票',
  "tax_title" int(1) DEFAULT NULL COMMENT '发票抬头 1 公司 2 个人',
  "tax_company" varchar(200) DEFAULT NULL COMMENT '发票单位名称',
  "tax_content" int(1) DEFAULT NULL COMMENT '发票内容 1明细 2 生鲜食品',
  "tax_com_addr" varchar(50) DEFAULT NULL COMMENT '发票公司地址',
  "tax_com_phone" varchar(20) DEFAULT NULL COMMENT '发票公司电话''',
  "tax_bank_name" varchar(50) DEFAULT NULL COMMENT '开户银行',
  "tax_bank_card_num" varchar(50) DEFAULT NULL COMMENT '开户银行账号',
  "tax_num" varchar(100) DEFAULT NULL COMMENT '发票公司税号',
  "cancel_remark" varchar(200) DEFAULT NULL COMMENT '取消备注',
  "cancel_status" int(1) DEFAULT NULL COMMENT '取消原因 1:缺货取消 2:其他',
  "cancel_time" datetime DEFAULT NULL COMMENT '取消时间',
  "cancel_user" varchar(50) DEFAULT NULL COMMENT '取消人',
  "verify_time" datetime DEFAULT NULL COMMENT '审核时间',
  "verify_user" varchar(50) DEFAULT NULL COMMENT '审核人',
  "salesman_id" int(12) DEFAULT NULL COMMENT '业务员ID(客户经理标识)',
  "salesman_phone" varchar(15) DEFAULT NULL COMMENT '业务员电话(客户经理手机号)',
  "salesman_name" varchar(50) DEFAULT NULL COMMENT '业务员姓名(客户经理姓名)',
  "order_exception" int(1) DEFAULT '1' COMMENT '是否是异常订单 1:无问题 2:有问题',
  "frozen_order" int(1) DEFAULT NULL COMMENT '1:冻品  2:,鲜品',
  "send_time" datetime DEFAULT NULL COMMENT '发货日期',
  "special_disamount" decimal(15,2) DEFAULT NULL COMMENT '特批优惠金额',
  "confirm_goods_type" int(1) DEFAULT NULL COMMENT '是否自主确认收货 1 客户自己 2 系统确认收货',
  "confirm_goods_time" datetime DEFAULT NULL COMMENT '确认收货时间',
  "have_pig" int(1) DEFAULT NULL COMMENT '是否清真订单 1 非清真 2清真',
  "split_order_status" int(1) DEFAULT '1' COMMENT '拆分订单:1未拆分,2已拆分',
  "parent_orderid" varchar(20) DEFAULT '0' COMMENT '已拆分订单父订单号',
  "del_flag" int(1) DEFAULT '1' COMMENT '是否删除 1未删除 2已删除',
  "print_status" int(1) DEFAULT '1' COMMENT '打印状态  1、未打印  2、已打印',
  "zp_order" int(1) DEFAULT '1' COMMENT '众品订单:1不是, 2是',
  "order_mark" varchar(15) DEFAULT NULL COMMENT '订单标记 1已锁定 2已拆分 3特批优惠 4修改运费5缺货',
  "lock_status" int(1) DEFAULT NULL COMMENT '锁单状态:1未锁定 2已锁定',
  "confirm_send_num" int(1) DEFAULT '1' COMMENT '确认实发数量 1:未确认 2:已确认',
  "m_order_id" varchar(20) DEFAULT NULL COMMENT '主订单号',
  "system_remark" varchar(200) DEFAULT NULL COMMENT '系统备注',
  "lock_remark" varchar(200) DEFAULT NULL COMMENT '锁单备注',
  "order_saleman_id" int(10) DEFAULT NULL COMMENT '订单销售人(货到付款用到)-下单业务员标识',
  "order_cod_mobile" varchar(12) DEFAULT NULL COMMENT '货到付款手机号-下单业务员',
  "auto_operation_flag" int(1) DEFAULT NULL COMMENT '运营模式 1 自运营 2代运营',
  "ven_type" int(1) DEFAULT NULL COMMENT '商户性质 1 自营 2 三方',
  "sap_status" int(1) DEFAULT '0' COMMENT 'SAP传输标示,0为未传输,1位传输成功',
  "channel_flag" int(1) DEFAULT '2' COMMENT '是否为引流导入订单 1:是 2:否',
  "batch_id" varchar(20) DEFAULT NULL COMMENT '批次号(引流订单)',
  "epay_rece_amt" decimal(15,2) DEFAULT NULL COMMENT '订单应收金额=订单实发金额+实发运费金额',
  "check_batch_num" varchar(20) DEFAULT NULL COMMENT '审核波次号',
  "print_batch_num" varchar(20) DEFAULT NULL COMMENT '打印批次号',
  "purchase_type" int(1) DEFAULT NULL COMMENT '采购类型 1 零采 2 整柜',
  PRIMARY KEY ("id"),
  UNIQUE KEY "index_order_id" ("order_id") USING BTREE,
  KEY "idx_create_date" ("create_date"),
  KEY "idx_user_code_status" ("user_code","order_status"),
  KEY "idx_user_order_excep" ("user_code","order_exception"),
  KEY "idx_modify_date" ("modify_date"),
  KEY "idx_parent_orderid" ("parent_orderid"),
  KEY "idx_salesman_id" ("salesman_id"),
  KEY "idx_user_id" ("user_id")
) ENGINE=InnoDB AUTO_INCREMENT=4064278 DEFAULT CHARSET=utf8mb4
;

here is my alter statment:

alter table xe_ven_order_info add  "purchase_type" int(1) DEFAULT NULL COMMENT '采购类型 1 零采 2 整柜';

this statment case the mysqld process is crash.

rows of table: 2025786.

Thanks!
[20 Dec 2017 14:46] MySQL Verification Team
Hi!

Please read all our instructions. When we write that we need all tables involved in the assert, it is not only their structure, but also their data that we need.

As we wrote, please try to repeat the assert with our latest 5.7 release, like 5.7.21.
[21 Jan 2018 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".