Record Lock Issue Version 4

Venky_78 · March 19, 2018, 2:15am

Our erpnext system is performing extremely slowly when it comes to submitting records. We have found that this has something to do with how erpnext inserts records into db.

I can see that people discussed about this on github or so and advised that it’s been fixed already on ver 4. Why are we still having it?

Below is the output,

MariaDB [(none)]> SHOW ENGINE INNODB STATUS\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
180315 23:41:12 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 11 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 523 1_second, 522 sleeps, 51 10_second, 10 background, 10 flush
srv_master_thread log flush and writes: 498
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 158, signal count 171
Mutex spin waits 124, rounds 2190, OS waits 64
RW-shared spins 66, rounds 1699, OS waits 55
RW-excl spins 6, rounds 1249, OS waits 38
Spin rounds per wait: 17.66 mutex, 25.74 RW-shared, 208.17 RW-excl
--------
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
16173 OS file reads, 4200 OS file writes, 715 OS fsyncs
0.91 reads/s, 16384 avg bytes/read, 8.54 writes/s, 1.36 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 11, seg size 13, 110 merges
merged operations:
 insert 106, delete mark 8, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 10624951, node heap has 291 buffer(s)
1475.32 hash searches/s, 4005.09 non-hash searches/s
---
LOG
---
Log sequence number 86536803129
Log flushed up to   86536803129
Last checkpoint at  86536803129
Max checkpoint age    7782360
Checkpoint age target 7539162
Modified age          0
Checkpoint age        0
0 pending log writes, 0 pending chkp writes
248 log i/o's done, 0.36 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 5510266880; in additional pool allocated 0
Total memory allocated by read views 312
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 89771568        (84999608 + 4771960)
    Page hash           5313416 (buffer pool 0 only)
    Dictionary cache    22067084        (21251312 + 815772)
    File system         680128  (82672 + 597456)
    Lock system         13313888        (13281976 + 31912)
    Recovery system     0       (0 + 0)
Dictionary memory allocated 815772
Buffer pool size        327679
Buffer pool size, bytes 5368692736
Free buffers            311200
Database pages          16187
Old database pages      5995
Modified db pages       0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 5, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 16077, created 110, written 3848
0.91 reads/s, 0.27 creates/s, 7.91 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 16187, 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
3 read views open inside InnoDB
2 transactions active inside InnoDB
2 out of 1000 descriptors used
---OLDEST VIEW---
Normal read view
Read view low limit trx n:o C42336
Read view up limit trx id C42335
Read view low limit trx id C42336
Read view individually stored trx ids:
Read view trx id C42335
-----------------
Main thread process no. 3986, id 139924187641600, state: flushing log
Number of rows inserted 138, updated 18602, deleted 113, read 49331442
0.18 inserts/s, 46.09 updates/s, 0.09 deletes/s, 139685.39 reads/s
------------
TRANSACTIONS
------------
Trx id counter C4236A
Purge done for trx's n:o < C4233E undo n:o < 0
History list length 742
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 129, OS thread handle 0x7f442257f700, query id 640359 localhost root
SHOW ENGINE INNODB STATUS
---TRANSACTION C42369, ACTIVE 41 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1
MySQL thread id 128, OS thread handle 0x7f4422536700, query id 568922 localhost 1deafd0bf3 update
insert into `tabNotification Count`
                                (`count`, `modified_by`, `name`, `parent`, `for_doctype`, `creation`, `modified`, `open_count`, `idx`, `parenttype`, `owner`, `docstatus`, `parentfield`) values (NULL, 'MaliM@digitales.com.au', '9259fd7bd6e3e922f277a3bd3578798de327e47557eab3c86a2221e4', NULL, 'Purchase Order', '2018-03-16 14:40:31.833094', '2018-03-16 14:40:31.833094', 45, NULL, NULL, 'MaliM@digitales.com.au', 0, NULL)
Trx read view will not see trx with id >= C4236A, sees < C42335
------- TRX HAS BEEN WAITING 41 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1615 page no 4 n bits 280 index `for_doctype` of table `1deafd0bf3`.`tabNotification Count` trx id C42369 lock_mode X locks gap before rec insert intention waiting
------------------
TABLE LOCK table `1deafd0bf3`.`tabNotification Count` trx id C42369 lock mode IX
RECORD LOCKS space id 1615 page no 4 n bits 280 index `for_doctype` of table `1deafd0bf3`.`tabNotification Count` trx id C42369 lock_mode X locks gap before rec insert intention waiting
---TRANSACTION C42335, ACTIVE 369 sec fetching rows
mysql tables in use 1, locked 0
261 lock struct(s), heap size 31160, 2564 row lock(s), undo log entries 18549
MySQL thread id 80, OS thread handle 0x7f4422611700, query id 640358 localhost 1deafd0bf3 Sorting result
select * from `tabPricing Rule`
                where (item_code='PF7944'  or  ifnull(item_group, '') in ('All Item Groups', 'DVD') or brand=NULL)
                        and docstatus < 2 and ifnull(disable, 0) = 0
                        and ifnull(buying, 0) = 1  and ifnull(company, '') in ('Digitales', '') and ifnull(customer, '') = '' and ifnull(supplier, '') in ('All Interactive Distribution', '') and ifnull(supplier_type, '') in ('Stock supplier', '') and ifnull(campaign, '') = '' and ifnull(sales_partner, '') = '' and ifnull(for_price_list, '') in ('Standard Buying', '') and '2018-02-27' between ifnull(valid_from, '2000-01-01')
                        and ifnul
Trx read view will not see trx with id >= C42336, sees < C42336
TABLE LOCK table `1deafd0bf3`.`tabSales Order` trx id C42335 lock mode IX
RECORD LOCKS space id 3973 page no 882 n bits 88 index `PRIMARY` of table `1deafd0bf3`.`tabSales Order` trx id C42335 lock_mode X locks rec but not gap
TABLE LOCK table `1deafd0bf3`.`tabSales Order Item` trx id C42335 lock mode IX
RECORD LOCKS space id 3980 page no 2954 n bits 88 index `PRIMARY` of table `1deafd0bf3`.`tabSales Order Item` trx id C42335 lock_mode X locks rec but not gap
RECORD LOCKS space id 3980 page no 1843 n bits 80 index `PRIMARY` of table `1deafd0bf3`.`tabSales Order Item` trx id C42335 lock_mode X locks rec but not gap
RECORD LOCKS space id 3980 page no 1842 n bits 88 index `PRIMARY` of table `1deafd0bf3`.`tabSales Order Item` trx id C42335 lock_mode X locks rec but not gap
RECORD LOCKS space id 3980 page no 1845 n bits 80 index `PRIMARY` of table `1deafd0bf3`.`tabSales Order Item` trx id C42335 lock_mode X locks rec but not gap
RECORD LOCKS space id 3980 page no 1844 n bits 88 index `PRIMARY` of table `1deafd0bf3`.`tabSales Order Item` trx id C42335 lock_mode X locks rec but not gap
RECORD LOCKS space id 3980 page no 1916 n bits 80 index `PRIMARY` of table `1deafd0bf3`.`tabSales Order Item` trx id C42335 lock_mode X locks rec but not gap
RECORD LOCKS space id 3980 page no 1854 n bits 88 index `PRIMARY` of table `1deafd0bf3`.`tabSales Order Item` trx id C42335 lock_mode X locks rec but not gap
TOO MANY LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS
----------------------------
END OF INNODB MONITOR OUTPUT
============================
1 row in set (0.01 sec)

Venky_78 · March 21, 2018, 2:49am

Anyone?? This seems an ERPNext error, the way erpnext handles queries.

nabinhait · March 21, 2018, 5:27am

It is really really difficult to debug any issue of version 4. We are on version 10 now and v11 will be released within a month.Why don’t you consider upgrading your system? There is a huge chance that your issue will be automatically fixed.

Venky_78 · March 21, 2018, 9:42am

Thanks nabinhait

We are planning to jump but stuck because of existing customisation on ver 4. These customisation are mixed up with default erpnext code and not easy to identify.

We are trying our best to make a transition, however we need to keep our work going on v4 meanwhile and this record locking issue is making it harder day by day.

Can you help in any possible way?

clarkej · March 21, 2018, 4:06pm

At the heart of this you have a fundamental resource problem you must address?

clarkej · March 21, 2018, 4:58pm

No sign or history of your efforts re your problem -

Two ideas to suggest

browse and profile the client side code to identify what this is about here?
on the database side profile what resource constraints are at play - perhaps adjust parameter values?

This forum is a gold mine of ideas and gems that will require effort on your part to dig up

good luck!

Venky_78 · March 23, 2018, 4:03am

Thanks, I’ll look into the forum.

clarkej · March 23, 2018, 6:10am

Figure out some empirical test cases to profile and analyze the problem for eg double the RAM, # of processor cores, half the # users, identify transaction types and uses cases where the problem does and does not occur - collect some timings in a spreadsheet and collect and compare SHOW ENGINE INNODB STATUS\G reports.

This may whet your appetite ERPNext Scalability

edit: you might also want to seriously consider upgrade