Project

General

Profile

操作問い合わせ #3543

JobArrangerServerにてデッドロックが発生

Added by Anonymous 8 months ago. Updated 7 months ago.

Status:
回答中
Priority:
高め
Assignee:
-
Start date:
09/28/2020

Description

お世話になっております。
9/26 13時頃にJobArrangerServerにてデッドロックが発生し、ジョブネットが実行中のまま固まってしまう事象を確認しました。
発生原因について確認いただくことは可能でしょうか。もしくは、確認するべきmysql側の設定項目等ございますでしょうか。

また、当事象が発生するとジョブが実行中の状態のままとなってしまいますが、回避方法はございますでしょうか。

114236:20200926:130013.344 [ERROR] [Z3005] query failed: [1213] Deadlock found when trying to get lock; try restarting transaction [insert into ja_run_value_before_table (inner_job_id, inner_jobnet_id, value_name, before_value) select 876687, inner_jobnet_id, value_name, after_value from ja_run_value_after_table where inner_job_id = 876685]
114236:20200926:130013.347 [WARN] [JAVALUE300003] In ja_value_after_before() can not insert the data. inner_job_id: 876685

[root@prod-zabbix01 ~]# mysql --version
mysql Ver 15.1 Distrib 5.5.50-MariaDB, for Linux (x86_64) using readline 5.1


Files

jobarg_server.log (381 KB) jobarg_server.log Anonymous, 09/28/2020 02:52 PM

Updated by Anonymous 8 months ago

SHOW ENGINE INNODB STATUSの結果を追記いたしました。確認結果は別件ですが、同じSQL分で発生している模様です。

MariaDB [(none)]> SHOW ENGINE INNODB STATUS; | InnoDB | | =====================================
200930 16:31:06 INNODB MONITOR OUTPUT =====================================
Per second averages calculated from the last 13 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 72775401 1_second, 72274627 sleeps, 7277429 10_second, 1570 background, 1470 flush
srv_master_thread log flush and writes: 48316105
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 89372546, signal count 173571907
Mutex spin waits 253331384, rounds 1499719209, OS waits 25293145
RW-shared spins 178798184, rounds 1889722693, OS waits 30486451
RW-excl spins 31364801, rounds 1232410955, OS waits 28616159
Spin rounds per wait: 5.92 mutex, 10.57 RW-shared, 39.29 RW-excl
------------------------
LATEST FOREIGN KEY ERROR
------------------------
191030 10:29:29 Transaction:
TRANSACTION 53BFD9FF, ACTIVE 1 sec inserting
mysql tables in use 1, locked 1
6 lock struct(s), heap size 1248, 6 row lock(s), undo log entries 14
MySQL thread id 8926523, OS thread handle 0x7f1da888c700, query id 1689679790 10.238.3.33 zabbix update
insert into ja_flow_control_table (jobnet_id,start_job_id,end_job_id,update_date,created_date,flow_type,flow_width) values (?,?,?,?,?,?,?)
Foreign key constraint fails for table `zabbix`.`ja_flow_control_table`:
,
CONSTRAINT `ja_flow_control_fk2` FOREIGN KEY (`jobnet_id`, `end_job_id`, `update_date`) REFERENCES `ja_job_control_table` (`jobnet_id`, `job_id`, `update_date`) ON DELETE CASCADE ON UPDATE CASCADE
Trying to add in child table, in index `ja_flow_control_fk2` tuple:
DATA TUPLE: 4 fields;
0: len 17; hex 735f73665f6e696d3030335f6a6e303031; asc s_sf_nim003_jn001;;
1: len 22; hex 645f73665f6e696d3030335f6a6e3030315f6a303031; asc d_sf_nim003_jn001_j001;;
2: len 8; hex 0000125d10ec145b; asc ] [;;
3: len 4; hex 49462d31; asc IF-1;;

But in parent table `zabbix`.`ja_job_control_table`, in index `PRIMARY`,
the closest match we can find is record:
PHYSICAL RECORD: n_fields 15; compact format; info bits 0
0: len 17; hex 735f73665f6e696d3030335f6a6e303031; asc s_sf_nim003_jn001;;
1: len 22; hex 735f73665f6e696d3030335f6a6e3030315f6a303031; asc s_sf_nim003_jn001_j001;;
2: len 8; hex 0000125d10ec145b; asc ] [;;
3: len 6; hex 000053bfd9ff; asc S ;;
4: len 7; hex 9b000f402002a4; asc @ ;;
5: len 4; hex 5d8b1dcc; asc ] ;;
6: len 4; hex 80000004; asc ;;
7: len 4; hex 80000129; asc );;
8: len 4; hex 800000af; asc ;;
9: len 30; hex e4bc81e6a5ade5afa9e69fbbe68385e5a0b1e58f96e8bebce382b7e382a7; asc ; (total 54 bytes);
10: len 4; hex 80000000; asc ;;
11: len 4; hex 80000000; asc ;;
12: len 4; hex 80000000; asc ;;
13: SQL NULL;
14: SQL NULL;

--------
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 (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
1103449721 OS file reads, 2571700473 OS file writes, 381051377 OS fsyncs
24.77 reads/s, 16384 avg bytes/read, 37.92 writes/s, 8.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 26, free list len 82, seg size 109, 240004538 merges
merged operations:
insert 556056113, delete mark 2932519, delete 1797872
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 276671, node heap has 157 buffer(s)
5738.40 hash searches/s, 426.35 non-hash searches/s
---
LOG
---
Log sequence number 2224507850687
Log flushed up to 2224507848891
Last checkpoint at 2224505527967
Max checkpoint age 7782360
Checkpoint age target 7539162
Modified age 2308725
Checkpoint age 2322720
0 pending log writes, 0 pending chkp writes
281380707 log i/o's done, 4.23 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137756672; in additional pool allocated 0
Total memory allocated by read views 6320
Internal hash tables (constant factor + variable factor)
Adaptive hash index 4789872 (2213368 + 2576504)
Page hash 139112 (buffer pool 0 only)
Dictionary cache 1833721 (554768 + 1278953)
File system 83536 (82672 + 864)
Lock system 343400 (332872 + 10528)
Recovery system 0 (0 + 0)
Dictionary memory allocated 1278953
Buffer pool size 8191
Buffer pool size, bytes 134201344
Free buffers 0
Database pages 8034
Old database pages 2946
Modified db pages 3425
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 2032752351, not young 0
17.15 youngs/s, 0.00 non-youngs/s
Pages read 1103451767, created 38439890, written 2223233667
24.77 reads/s, 0.46 creates/s, 31.61 writes/s
Buffer pool hit rate 998 / 1000, young-making rate 1 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 8034, unzip_LRU len: 0
I/O sum1743:cur8, unzip sum0:cur0
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
0 transactions active inside InnoDB
0 out of 1000 descriptors used
---OLDEST VIEW---
Normal read view
Read view low limit trx n:o 1375771E9
Read view up limit trx id 1375771E9
Read view low limit trx id 1375771E9
Read view individually stored trx ids:
-----------------
Main thread process no. 2971, id 139765426849536, state: sleeping
Number of rows inserted 4071858735, updated 236245159, deleted 3973919745, read 255225836954
80.53 inserts/s, 3.62 updates/s, 0.00 deletes/s, 11978.23 reads/s
------------------------
LATEST DETECTED DEADLOCK
------------------------
200927 21:30:07
  • (1) TRANSACTION:
    TRANSACTION 134FC0799, ACTIVE 0 sec inserting
    mysql tables in use 2, locked 2
    LOCK WAIT 8 lock struct(s), heap size 1248, 5 row lock(s), undo log entries 7
    MySQL thread id 20842247, OS thread handle 0x7f1d9c0c5700, query id 14020756596 localhost zabbix Sending data
    insert into ja_run_value_before_table (inner_job_id, inner_jobnet_id, value_name, before_value) select 888366, inner_jobnet_id, value_name, after_value from ja_run_value_after_table where inner_job_id = 888364
  • (1) WAITING FOR THIS LOCK TO BE GRANTED:
    RECORD LOCKS space id 0 page no 872 n bits 296 index `ja_run_value_before_fk1` of table `zabbix`.`ja_run_value_before_table` trx id 134FC0799 lock_mode X locks gap before rec insert intention waiting
  • (2) TRANSACTION:
    TRANSACTION 134FC0797, ACTIVE 0 sec setting auto-inc lock
    mysql tables in use 2, locked 2
    19 lock struct(s), heap size 3112, 51 row lock(s), undo log entries 28
    MySQL thread id 20717818, OS thread handle 0x7f1dc43bd700, query id 14020756612 localhost zabbix Sending data
    insert into ja_run_value_before_table (inner_job_id, inner_jobnet_id, value_name, before_value) select 888385, inner_jobnet_id, value_name, after_value from ja_run_value_after_table where inner_job_id = 888386
  • (2) HOLDS THE LOCK:
    RECORD LOCKS space id 0 page no 872 n bits 296 index `ja_run_value_before_fk1` of table `zabbix`.`ja_run_value_before_table` trx id 134FC0797 lock_mode X
  • (2) WAITING FOR THIS LOCK TO BE GRANTED:
    TABLE LOCK table `zabbix`.`ja_run_value_before_table` trx id 134FC0797 lock mode AUTO-INC waiting
  • WE ROLL BACK TRANSACTION (1)
    ------------
    TRANSACTIONS
    ------------
    Trx id counter 137577224
    Purge done for trx's n:o < 13757719A undo n:o < 0
    History list length 2093
    LIST OF TRANSACTIONS FOR EACH SESSION:
    ---TRANSACTION 0, not started
    MySQL thread id 20935136, OS thread handle 0x7f1da8089700, query id 14119975655 localhost root
    SHOW ENGINE INNODB STATUS
    ---TRANSACTION 1375771E7, not started
    MySQL thread id 20926243, OS thread handle 0x7f1d9c1e9700, query id 14119975383 localhost zabbix
    ---TRANSACTION 1375771E4, not started
    MySQL thread id 20926240, OS thread handle 0x7f1da871f700, query id 14119975380 localhost zabbix
    ---TRANSACTION 1375771D3, not started
    MySQL thread id 20926242, OS thread handle 0x7f1da89f9700, query id 14119975331 localhost zabbix
    ---TRANSACTION 1375771EB, not started
    MySQL thread id 20926241, OS thread handle 0x7f1da8768700, query id 14119975391 localhost zabbix
    ---TRANSACTION 137577223, not started
    MySQL thread id 20926238, OS thread handle 0x7f1dc40e0700, query id 14119975654 localhost zabbix
    ---TRANSACTION 1375771E8, not started
    MySQL thread id 20926239, OS thread handle 0x7f1da85fb700, query id 14119975384 localhost zabbix
    ---TRANSACTION 1375771D0, not started
    MySQL thread id 20842888, OS thread handle 0x7f1da8ad4700, query id 14119975323 localhost zabbix
    ---TRANSACTION 137577010, not started
    MySQL thread id 20842876, OS thread handle 0x7f1da868d700, query id 14119973601 localhost zabbix
    ---TRANSACTION 137577127, not started
    MySQL thread id 20718759, OS thread handle 0x7f1da8843700, query id 14119974657 localhost zabbix
    ---TRANSACTION 137576209, not started
    MySQL thread id 19086145, OS thread handle 0x7f1d9c4c3700, query id 14119966090 localhost zabbix
    ---TRANSACTION 1375756F0, not started
    MySQL thread id 11517568, OS thread handle 0x7f1da848e700, query id 14119955838 localhost zabbix
    ---TRANSACTION 137575C97, not started
    MySQL thread id 346890, OS thread handle 0x7f1dc4129700, query id 14119960891 localhost zabbix
    ---TRANSACTION 137575FB8, not started
    MySQL thread id 35, OS thread handle 0x7f1da89b0700, query id 14119963900 localhost zabbix
    ---TRANSACTION 137577018, not started
    MySQL thread id 16, OS thread handle 0x7f1da8cd3700, query id 14119973618 localhost zabbix
    ---TRANSACTION 137576C1E, not started
    MySQL thread id 25, OS thread handle 0x7f1da8a8b700, query id 14119969910 localhost zabbix
    ---TRANSACTION 13756DD70, not started
    MySQL thread id 22, OS thread handle 0x7f1da8b66700, query id 14119874176 localhost zabbix
    ---TRANSACTION 137576EF1, not started
    MySQL thread id 14, OS thread handle 0x7f1dc4097700, query id 14119972507 localhost zabbix
    ---TRANSACTION 13757459F, not started
    MySQL thread id 21, OS thread handle 0x7f1da8baf700, query id 14119944240 localhost zabbix
    ---TRANSACTION 1375771EE, not started
    MySQL thread id 18, OS thread handle 0x7f1da8c41700, query id 14119975397 localhost zabbix
    ---TRANSACTION 1375771D1, not started
    MySQL thread id 9, OS thread handle 0x7f1dc4299700, query id 14119975327 localhost zabbix
    ---TRANSACTION 137576CF4, not started
    MySQL thread id 26, OS thread handle 0x7f1da8a42700, query id 14119970662 localhost zabbix
    ---TRANSACTION 137573754, not started
    MySQL thread id 23, OS thread handle 0x7f1da8b1d700, query id 14119936386 localhost zabbix
    ---TRANSACTION 137577198, not started
    MySQL thread id 19, OS thread handle 0x7f1da8bf8700, query id 14119975064 localhost zabbix
    ---TRANSACTION 13757717C, not started
    MySQL thread id 8, OS thread handle 0x7f1dc42e2700, query id 14119974995 localhost zabbix
    ---TRANSACTION 137575887, not started
    MySQL thread id 20, OS thread handle 0x7f1dc4374700, query id 14119956822 localhost zabbix
    ---TRANSACTION 1375771ED, not started
    MySQL thread id 17, OS thread handle 0x7f1da8c8a700, query id 14119975393 localhost zabbix
    ---TRANSACTION 13757717B, not started
    MySQL thread id 10, OS thread handle 0x7f1dc4250700, query id 14119974989 localhost zabbix
    ----------------------------
    END OF INNODB MONITOR OUTPUT ============================ |

Updated by 保守サポート 担当 7 months ago

  • Status changed from 新規登録 to 回答中

ジョブアレンジャーのご利用ありがとうございます。

このケースは以下と同様の問題の可能性があります。
https://www.jobarranger.info/redmine/issues/2002
ご確認お願いいたします。

速やかな返信・サポートの為サポート契約をご検討頂ければ幸甚です。
宜しくお願い致します。

Also available in: Atom PDF