On Submit Lock wait timeout exceeded; try restarting transaction

luckyteam · January 18, 2019, 4:52pm

Getting this error on submit Landed cost Voucher
taking too long to submit document if submitted by chance…
most of the time error in “select for update query in document.py”
erpnext 10.1.64
frappe 10.1.56

Traceback (most recent call last):
File “frappe-bench/apps/frappe/frappe/desk/form/save.py”, line 19, in savedocs
doc.submit()
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 833, in submit
self._submit()
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 822, in _submit
self.save()
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 259, in save
return self._save(*args, **kwargs)
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 310, in _save
self.run_post_save_methods()
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 892, in run_post_save_methods
self.run_method(“on_submit”)
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 757, in run_method
out = Document.hook(fn)(self, *args, **kwargs)
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 1026, in composer
return composed(self, method, *args, **kwargs)
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 1009, in runner
add_to_return_value(self, fn(self, *args, **kwargs))
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 751, in
fn = lambda self, *args, **kwargs: getattr(self, method)(*args, **kwargs)
File “frappe-bench/apps/erpnext/erpnext/stock/doctype/landed_cost_voucher/landed_cost_voucher.py”, line 107, in on_submit
self.update_landed_cost()
File “frappe-bench/apps/erpnext/erpnext/stock/doctype/landed_cost_voucher/landed_cost_voucher.py”, line 131, in update_landed_cost
doc.update_stock_ledger(allow_negative_stock=True, via_landed_cost_voucher=True)
File “frappe-bench/apps/erpnext/erpnext/controllers/buying_controller.py”, line 397, in update_stock_ledger
via_landed_cost_voucher=via_landed_cost_voucher)
File “frappe-bench/apps/erpnext/erpnext/controllers/stock_controller.py”, line 265, in make_sl_entries
make_sl_entries(sl_entries, is_amended, allow_negative_stock, via_landed_cost_voucher)
File “frappe-bench/apps/erpnext/erpnext/stock/stock_ledger.py”, line 23, in make_sl_entries
set_as_cancel(sl_entries[0].get(‘voucher_no’), sl_entries[0].get(‘voucher_type’))
File “frappe-bench/apps/erpnext/erpnext/stock/stock_ledger.py”, line 47, in set_as_cancel
(now(), frappe.session.user, voucher_type, voucher_no))
File “frappe-bench/apps/frappe/frappe/database.py”, line 166, in sql
self._cursor.execute(query, values)
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/cursors.py”, line 170, in execute
result = self._query(query)
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/cursors.py”, line 328, in _query
conn.query(q)
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/connections.py”, line 516, in query
self._affected_rows = self._read_query_result(unbuffered=unbuffered)
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/connections.py”, line 727, in _read_query_result
result.read()
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/connections.py”, line 1066, in read
first_packet = self.connection._read_packet()
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/connections.py”, line 683, in _read_packet
packet.check_error()
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/protocol.py”, line 220, in check_error
err.raise_mysql_exception(self._data)
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/err.py”, line 109, in raise_mysql_exception
raise errorclass(errno, errval)
InternalError: (1205, u’Lock wait timeout exceeded; try restarting transaction’)

Traceback (most recent call last):
File “frappe-bench/apps/frappe/frappe/app.py”, line 62, in application
response = frappe.handler.handle()
File “frappe-bench/apps/frappe/frappe/handler.py”, line 22, in handle
data = execute_cmd(cmd)
File “frappe-bench/apps/frappe/frappe/handler.py”, line 53, in execute_cmd
return frappe.call(method, **frappe.form_dict)
File “frappe-bench/apps/frappe/frappe/init.py”, line 939, in call
return fn(*args, **newargs)
File “frappe-bench/apps/frappe/frappe/desk/form/save.py”, line 19, in savedocs
doc.submit()
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 833, in submit
self._submit()
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 822, in _submit
self.save()
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 259, in save
return self._save(*args, **kwargs)
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 310, in _save
self.run_post_save_methods()
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 892, in run_post_save_methods
self.run_method(“on_submit”)
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 757, in run_method
out = Document.hook(fn)(self, *args, **kwargs)
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 1026, in composer
return composed(self, method, *args, **kwargs)
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 1009, in runner
add_to_return_value(self, fn(self, *args, **kwargs))
File “frappe-bench/apps/frappe/frappe/model/document.py”, line 751, in
fn = lambda self, *args, **kwargs: getattr(self, method)(*args, **kwargs)
File “frappe-bench/apps/erpnext/erpnext/stock/doctype/landed_cost_voucher/landed_cost_voucher.py”, line 107, in on_submit
self.update_landed_cost()
File “frappe-bench/apps/erpnext/erpnext/stock/doctype/landed_cost_voucher/landed_cost_voucher.py”, line 131, in update_landed_cost
doc.update_stock_ledger(allow_negative_stock=True, via_landed_cost_voucher=True)
File “frappe-bench/apps/erpnext/erpnext/controllers/buying_controller.py”, line 397, in update_stock_ledger
via_landed_cost_voucher=via_landed_cost_voucher)
File “frappe-bench/apps/erpnext/erpnext/controllers/stock_controller.py”, line 265, in make_sl_entries
make_sl_entries(sl_entries, is_amended, allow_negative_stock, via_landed_cost_voucher)
File “frappe-bench/apps/erpnext/erpnext/stock/stock_ledger.py”, line 23, in make_sl_entries
set_as_cancel(sl_entries[0].get(‘voucher_no’), sl_entries[0].get(‘voucher_type’))
File “frappe-bench/apps/erpnext/erpnext/stock/stock_ledger.py”, line 47, in set_as_cancel
(now(), frappe.session.user, voucher_type, voucher_no))
File “frappe-bench/apps/frappe/frappe/database.py”, line 166, in sql
self._cursor.execute(query, values)
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/cursors.py”, line 170, in execute
result = self._query(query)
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/cursors.py”, line 328, in _query
conn.query(q)
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/connections.py”, line 516, in query
self._affected_rows = self._read_query_result(unbuffered=unbuffered)
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/connections.py”, line 727, in _read_query_result
result.read()
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/connections.py”, line 1066, in read
first_packet = self.connection._read_packet()
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/connections.py”, line 683, in _read_packet
packet.check_error()
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/protocol.py”, line 220, in check_error
err.raise_mysql_exception(self._data)
File “frappe-bench/env/lib/python2.7/site-packages/pymysql/err.py”, line 109, in raise_mysql_exception
raise errorclass(errno, errval)
InternalError: (1205, u’Lock wait timeout exceeded; try restarting transaction’)

luckyteam · January 18, 2019, 4:55pm

also lock wait time error on submit sales order and invoice…

ile “frappe-bench/apps/frappe/frappe/model/naming.py”, line 48, in set_new_name
set_name_by_naming_series(doc)
File “frappe-bench/apps/frappe/frappe/model/naming.py”, line 69, in set_name_by_naming_series
doc.name = make_autoname(doc.naming_series+‘.#####’, ‘’, doc)
File “frappe-bench/apps/frappe/frappe/model/naming.py”, line 98, in make_autoname
n = parse_naming_series(parts, doctype, doc)
File “frappe-bench/apps/frappe/frappe/model/naming.py”, line 113, in parse_naming_series
part = getseries(n, digits, doctype)
File “frappe-bench/apps/frappe/frappe/model/naming.py”, line 134, in getseries
current = frappe.db.sql(“select current from tabSeries where name=%s for update”, (key,))
File “frappe-bench/apps/frappe/frappe/database.py”, line 166, in sql
self._cursor.execute(query, values)

luckyteam · January 19, 2019, 6:12am

any solution… ?

VamYip · January 21, 2019, 6:58am

If its a high volume table and if you are on self hosted solution, can try identifying missing indexes. Lock Timeouts are often a result of missing indices.

If you are new to performance tuning, can start here:

Can also contribute your findings there.

Thanks,
Vamyip

luckyteam · January 21, 2019, 11:40am

Thanks @VamYip

i read somewhere naming series issue in sales invoice has been fixed … how can i pull only that fix to my erpnext app… if i use bench update will it update whole app to latest version… i want to stick with erpnext 10.1.64 . how to pull changes to my app for that particular version…

EnSeal · July 5, 2019, 11:58pm

Hello Team

how was the issue resolved? i have similar issue here i am still try to resolve

Traceback (most recent call last):
File “/home/ubuntu/xlevel/apps/erpnext/erpnext/accounts/doctype/sales_invoice/pos.py”, line 594, in save_invoice
si.insert(ignore_permissions=True)
File “/home/ubuntu/xlevel/apps/frappe/frappe/model/document.py”, line 217, in insert
self.set_new_name()
File “/home/ubuntu/xlevel/apps/frappe/frappe/model/document.py”, line 378, in set_new_name
set_new_name(self)
File “/home/ubuntu/xlevel/apps/frappe/frappe/model/naming.py”, line 42, in set_new_name
set_name_from_naming_options(autoname, doc)
File “/home/ubuntu/xlevel/apps/frappe/frappe/model/naming.py”, line 71, in set_name_from_naming_options
set_name_by_naming_series(doc)
File “/home/ubuntu/xlevel/apps/frappe/frappe/model/naming.py”, line 87, in set_name_by_naming_series
doc.name = make_autoname(doc.naming_series+‘.#####’, ‘’, doc)
File “/home/ubuntu/xlevel/apps/frappe/frappe/model/naming.py”, line 116, in make_autoname
n = parse_naming_series(parts, doctype, doc)
File “/home/ubuntu/xlevel/apps/frappe/frappe/model/naming.py”, line 131, in parse_naming_series
part = getseries(n, digits, doctype)
File “/home/ubuntu/xlevel/apps/frappe/frappe/model/naming.py”, line 159, in getseries
current = frappe.db.sql(“select current from tabSeries where name=%s for update”, (key,))
File “/home/ubuntu/xlevel/apps/frappe/frappe/database.py”, line 199, in sql
self._cursor.execute(query, values)
File “/home/ubuntu/xlevel/env/local/lib/python2.7/site-packages/pymysql/cursors.py”, line 170, in execute
result = self._query(query)
File “/home/ubuntu/xlevel/env/local/lib/python2.7/site-packages/pymysql/cursors.py”, line 328, in _query
conn.query(q)
File “/home/ubuntu/xlevel/env/local/lib/python2.7/site-packages/pymysql/connections.py”, line 516, in query
self._affected_rows = self._read_query_result(unbuffered=unbuffered)
File “/home/ubuntu/xlevel/env/local/lib/python2.7/site-packages/pymysql/connections.py”, line 727, in _read_query_result
result.read()
File “/home/ubuntu/xlevel/env/local/lib/python2.7/site-packages/pymysql/connections.py”, line 1073, in read
self._read_result_packet(first_packet)
File “/home/ubuntu/xlevel/env/local/lib/python2.7/site-packages/pymysql/connections.py”, line 1143, in _read_result_packet
self._read_rowdata_packet()
File “/home/ubuntu/xlevel/env/local/lib/python2.7/site-packages/pymysql/connections.py”, line 1177, in _read_rowdata_packet
packet = self.connection._read_packet()
File “/home/ubuntu/xlevel/env/local/lib/python2.7/site-packages/pymysql/connections.py”, line 683, in _read_packet
packet.check_error()
File “/home/ubuntu/xlevel/env/local/lib/python2.7/site-packages/pymysql/protocol.py”, line 220, in check_error
err.raise_mysql_exception(self._data)
File “/home/ubuntu/xlevel/env/local/lib/python2.7/site-packages/pymysql/err.py”, line 109, in raise_mysql_exception
raise errorclass(errno, errval)
InternalError: (1205, u’Lock wait timeout exceeded; try restarting transaction’)

adam26d · July 16, 2019, 3:15pm

@EnSeal

How did you fix this one?

EnSeal · July 16, 2019, 3:27pm

Unfortunately, issue has not been fixed… I have been going through pain to have to kill processlist ID everyday…it hasn’t been funny

trentmu · July 16, 2019, 3:51pm

I am not a programmer or DB expert (not even close).

I notice that the table is the Naming Series tabSeries, which on my instance, has no indexes.

I don’t know if this is correct or not, but isn’t transaction locking often related to lack of index?

EnSeal · July 16, 2019, 4:13pm

not sure too either…we might need some gurus to help clarify on this issue…

adam26d · July 18, 2019, 7:39am

@trentmu, I believe it is an indexing issue. In my case the affected terminal has outdated stock so its searching the table Stock Ledger while trying to save an invoice. This takes forever and leads to a timeout.

I’ve tried a few things, like extending the execution time, adding an index, it’s not working yet but I think I should have it within the day. I’ll update with specifics once I resume.

Thanks for your input

adam26d · July 18, 2019, 7:45am

@EnSeal

I see that you’re also dealing with a POS issue. Is yours also not uploading?

In my view ERPNext POS offline needs to simply upload all submitted sales for correction within Sales Invoicing on the server. The current design needs improvement because so many things will go wrong, preventing invoices from uploading, localstorage gets full and new sales transaction are NOT SAVED (i.e. lost).

trentmu · July 18, 2019, 8:56am

I have experienced a handful of lock timeout issues - generally in manufacturing modules, but I guess those could also quite easily be related to indexes. In my case(s), the namingSeries came up here and there, and Subscriptions popped up quite often.

If adding a few indexes to the DB structures will get rid of those, it would be awesome, so I look forward to your conclusions on this

adam26d · July 18, 2019, 6:53pm

Interesting development. I can confirm that my issue is identical to exactly what @EnSeal is experiencing (according to logs and description)

I’ve set a log for slow queries using this simple guide. Reduced the time to 2 seconds and no query is being logged as slow.

The POS Sales Invoices are still not upload except for one, I dont know how exactly. Submitting the invoice is causing a timeout. The terminal messages are whats interesting though:

Full logs:

localStorage cleared
desk.min.js?ver=1563283430.0:86 Cleared App Cache.
desk.min.js?ver=1563283430.0:117 localStorage cleared
desk.min.js?ver=1563283430.0:8701 base_amount: could not find docfield in method precision()
desk.min.js?ver=1563283430.0:8701 amount: could not find docfield in method precision()
2desk.min.js?ver=1563283430.0:8701 base_amount: could not find docfield in method precision()
desk.min.js?ver=1563283430.0:8701 amount: could not find docfield in method precision()
2desk.min.js?ver=1563283430.0:8701 base_amount: could not find docfield in method precision()
desk#Form/Sales%20Invoice/SINV-RET-131424-1:1 Uncaught (in promise) DOMException
desk.min.js?ver=1563283430.0:8701 base_amount: could not find docfield in method precision()
:1 Failed to load resource: the server responded with a status of 504 (Gateway Time-out)
desk.min.js?ver=1563283430.0:1604 Unable to handle failed response
desk.min.js?ver=1563283430.0:1605 TypeError: Cannot read property 'exc' of undefined
    at after_save (form.min.js?ver=1563283430.0:711)
    at Object.error [as error_callback] (form.min.js?ver=1563283430.0:2347)
    at _ (desk.min.js?ver=1563283430.0:1543)
    at Object.<anonymous> (desk.min.js?ver=1563283430.0:1599)
    at i (jquery.min.js:2)
    at Object.fireWith [as rejectWith] (jquery.min.js:2)
    at z (jquery.min.js:4)
    at XMLHttpRequest.<anonymous> (jquery.min.js:4)
(anonymous) @ desk.min.js?ver=1563283430.0:1605
desk.min.js?ver=1563283430.0:8701 base_amount: could not find docfield in method precision()
:1 Failed to load resource: the server responded with a status of 504 (Gateway Time-out)
desk.min.js?ver=1563283430.0:1604 Unable to handle failed response
desk.min.js?ver=1563283430.0:1605 TypeError: Cannot read property 'exc' of undefined
    at after_save (form.min.js?ver=1563283430.0:711)
    at Object.error [as error_callback] (form.min.js?ver=1563283430.0:2347)
    at _ (desk.min.js?ver=1563283430.0:1543)
    at Object.<anonymous> (desk.min.js?ver=1563283430.0:1599)
    at i (jquery.min.js:2)
    at Object.fireWith [as rejectWith] (jquery.min.js:2)
    at z (jquery.min.js:4)
    at XMLHttpRequest.<anonymous> (jquery.min.js:4)
(anonymous) @ desk.min.js?ver=1563283430.0:1605
desk.min.js?ver=1563283430.0:8701 base_amount: could not find docfield in method precision()
:1 Failed to load resource: the server responded with a status of 504 (Gateway Time-out)
desk.min.js?ver=1563283430.0:1604 Unable to handle failed response
desk.min.js?ver=1563283430.0:1605 TypeError: Cannot read property 'exc' of undefined
    at after_save (form.min.js?ver=1563283430.0:711)
    at Object.error [as error_callback] (form.min.js?ver=1563283430.0:2347)
    at _ (desk.min.js?ver=1563283430.0:1543)
    at Object.<anonymous> (desk.min.js?ver=1563283430.0:1599)
    at i (jquery.min.js:2)
    at Object.fireWith [as rejectWith] (jquery.min.js:2)
    at z (jquery.min.js:4)
    at XMLHttpRequest.<anonymous> (jquery.min.js:4)
(anonymous) @ desk.min.js?ver=1563283430.0:1605
desk.min.js?ver=1563283430.0:8701 base_amount: could not find docfield in method precision()
:1 Failed to load resource: the server responded with a status of 504 (Gateway Time-out)
desk.min.js?ver=1563283430.0:1604 Unable to handle failed response
desk.min.js?ver=1563283430.0:1605 TypeError: Cannot read property 'exc' of undefined
    at after_save (form.min.js?ver=1563283430.0:711)
    at Object.error [as error_callback] (form.min.js?ver=1563283430.0:2347)
    at _ (desk.min.js?ver=1563283430.0:1543)
    at Object.<anonymous> (desk.min.js?ver=1563283430.0:1599)
    at i (jquery.min.js:2)
    at Object.fireWith [as rejectWith] (jquery.min.js:2)
    at z (jquery.min.js:4)
    at XMLHttpRequest.<anonymous> (jquery.min.js:4)
(anonymous) @ desk.min.js?ver=1563283430.0:1605
socket.io/?EIO=3&transport=polling&t=Mm6Ikhm:1 Failed to load resource: net::ERR_NETWORK_IO_SUSPENDED
socket.io/?EIO=3&transport=polling&t=Mm6JmrI:1 Failed to load resource: net::ERR_NETWORK_CHANGED
desk.min.js?ver=1563283430.0:8701 base_amount: could not find docfield in method precision()
foodcity.co.zm/:1 Failed to load resource: the server responded with a status of 504 (Gateway Time-out)
desk.min.js?ver=1563283430.0:1604 Unable to handle failed response
desk.min.js?ver=1563283430.0:1605 TypeError: Cannot read property 'exc' of undefined
    at after_save (form.min.js?ver=1563283430.0:711)
    at Object.error [as error_callback] (form.min.js?ver=1563283430.0:2347)
    at _ (desk.min.js?ver=1563283430.0:1543)
    at Object.<anonymous> (desk.min.js?ver=1563283430.0:1599)
    at i (jquery.min.js:2)
    at Object.fireWith [as rejectWith] (jquery.min.js:2)
    at z (jquery.min.js:4)
    at XMLHttpRequest.<anonymous> (jquery.min.js:4)
(anonymous) @ desk.min.js?ver=1563283430.0:1605
i @ jquery.min.js:2
fireWith @ jquery.min.js:2
z @ jquery.min.js:4
(anonymous) @ jquery.min.js:4
libs.min.js?ver=1563283430.0:7295 GET http://foodcity.co.zm/socket.io/?EIO=3&transport=polling&t=Mm6TMii net::ERR_CONNECTION_TIMED_OUT
i.create @ libs.min.js?ver=1563283430.0:7295
i @ libs.min.js?ver=1563283430.0:7295
o.request @ libs.min.js?ver=1563283430.0:7295
o.doPoll @ libs.min.js?ver=1563283430.0:7295
n.poll @ libs.min.js?ver=1563283430.0:7295
n.doOpen @ libs.min.js?ver=1563283430.0:7295
n.open @ libs.min.js?ver=1563283430.0:7295
n.open @ libs.min.js?ver=1563283430.0:7294
n @ libs.min.js?ver=1563283430.0:7294
n @ libs.min.js?ver=1563283430.0:7294
n.open.n.connect @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
setTimeout (async)
n.reconnect @ libs.min.js?ver=1563283430.0:7294
n.onclose @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7295
n.emit @ libs.min.js?ver=1563283430.0:7294
n.onClose @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
n.emit @ libs.min.js?ver=1563283430.0:7294
n.onClose @ libs.min.js?ver=1563283430.0:7295
n.onClose @ libs.min.js?ver=1563283430.0:7295
ws.onclose @ libs.min.js?ver=1563283430.0:7295
libs.min.js?ver=1563283430.0:7295 GET http://foodcity.co.zm/socket.io/?EIO=3&transport=polling&t=Mm6Tb6Z net::ERR_CONNECTION_TIMED_OUT
i.create @ libs.min.js?ver=1563283430.0:7295
i @ libs.min.js?ver=1563283430.0:7295
o.request @ libs.min.js?ver=1563283430.0:7295
o.doPoll @ libs.min.js?ver=1563283430.0:7295
n.poll @ libs.min.js?ver=1563283430.0:7295
n.doOpen @ libs.min.js?ver=1563283430.0:7295
n.open @ libs.min.js?ver=1563283430.0:7295
n.open @ libs.min.js?ver=1563283430.0:7294
n @ libs.min.js?ver=1563283430.0:7294
n @ libs.min.js?ver=1563283430.0:7294
n.open.n.connect @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
setTimeout (async)
n.reconnect @ libs.min.js?ver=1563283430.0:7294
n.onclose @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7295
n.emit @ libs.min.js?ver=1563283430.0:7294
n.onClose @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
setTimeout (async)
n.onHeartbeat @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
setTimeout (async)
n.setPing @ libs.min.js?ver=1563283430.0:7294
n.onHandshake @ libs.min.js?ver=1563283430.0:7294
n.onPacket @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
n.emit @ libs.min.js?ver=1563283430.0:7294
n.onPacket @ libs.min.js?ver=1563283430.0:7295
r @ libs.min.js?ver=1563283430.0:7295
e.decodePayload @ libs.min.js?ver=1563283430.0:7295
n.onData @ libs.min.js?ver=1563283430.0:7295
(anonymous) @ libs.min.js?ver=1563283430.0:7295
n.emit @ libs.min.js?ver=1563283430.0:7294
i.onData @ libs.min.js?ver=1563283430.0:7295
i.onLoad @ libs.min.js?ver=1563283430.0:7295
hasXDR.r.onreadystatechange @ libs.min.js?ver=1563283430.0:7295
XMLHttpRequest.send (async)
i.create @ libs.min.js?ver=1563283430.0:7295
i @ libs.min.js?ver=1563283430.0:7295
o.request @ libs.min.js?ver=1563283430.0:7295
o.doPoll @ libs.min.js?ver=1563283430.0:7295
n.poll @ libs.min.js?ver=1563283430.0:7295
n.doOpen @ libs.min.js?ver=1563283430.0:7295
n.open @ libs.min.js?ver=1563283430.0:7295
n.open @ libs.min.js?ver=1563283430.0:7294
n @ libs.min.js?ver=1563283430.0:7294
n @ libs.min.js?ver=1563283430.0:7294
n.open.n.connect @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
setTimeout (async)
n.reconnect @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
n.emit @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
setTimeout (async)
n.open.n.connect @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
setTimeout (async)
n.reconnect @ libs.min.js?ver=1563283430.0:7294
n.onclose @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7295
n.emit @ libs.min.js?ver=1563283430.0:7294
n.onClose @ libs.min.js?ver=1563283430.0:7294
(anonymous) @ libs.min.js?ver=1563283430.0:7294
n.emit @ libs.min.js?ver=1563283430.0:7294
n.onClose @ libs.min.js?ver=1563283430.0:7295
n.onClose @ libs.min.js?ver=1563283430.0:7295
ws.onclose @ libs.min.js?ver=1563283430.0:7295

UPDATE:

After restarting mysql, I can see some slow queries by running $ mysql > show full processlist;:

153 Seconds ?

153 | f0d63920935f2f82 | localhost:44246 | f0d63920935f2f82 | Query | 0 | init | update tabGL Entry
set fiscal_year=‘2019’, creation=‘2019-07-18 21:29:54.628144’, voucher_type=‘Sales Invoice’, owner=‘Administrator’, cost_center=‘Main - UL’, voucher_no=‘SINV-RET-108784’, modified_by=‘Administrator’, against_voucher=NULL, party_type=NULL, transaction_date=NULL, debit=0, party=NULL, parent=NULL, company=‘Food On The Go’, debit_in_account_currency=0, is_advance=‘No’, docstatus=1, remarks=‘No Remarks’, account_currency=‘ZMW’, account=‘Sales - Kafue - UL’, idx=0, against_voucher_type=NULL, modified=‘2019-07-18 21:29:54.653494’, against=‘Walk in - Complex’, project=NULL, credit=29, parenttype=NULL, is_opening=‘No’, posting_date=‘2019-01-14’, credit_in_account_currency=29, parentfield=NULL where name=‘GL0832101’

MariaDB [(none)]> show full processlist;

+-----+------------------+-----------------+------------------+---------+------+--------------------------+-----------------------------------------------------------------------------------------------------+----------+
| Id  | User             | Host            | db               | Command | Time | State                    | Info                                                                                                | Progress |
+-----+------------------+-----------------+------------------+---------+------+--------------------------+-----------------------------------------------------------------------------------------------------+----------+
|   1 | system user      |                 | NULL             | Daemon  | NULL | InnoDB purge coordinator | NULL                                                                                                |    0.000 |
|   2 | system user      |                 | NULL             | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                                |    0.000 |
|   3 | system user      |                 | NULL             | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                                |    0.000 |
|   4 | system user      |                 | NULL             | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                                |    0.000 |
|   5 | system user      |                 | NULL             | Daemon  | NULL | InnoDB shutdown handler  | NULL                                                                                                |    0.000 |
| 153 | f0d63920935f2f82 | localhost:44246 | f0d63920935f2f82 | Sleep   |    0 |                          | NULL                                                                                                |    0.000 |
| 186 | root             | localhost       | NULL             | Query   |    0 | init                     | show full processlist                                                                               |    0.000 |
| 220 | f0d63920935f2f82 | localhost:45096 | f0d63920935f2f82 | Query   |   49 | statistics               | select modified, docstatus from `tabSales Invoice`
                                        where name = 'SINV-RET-131424-1' for update |    0.000 |
+-----+------------------+-----------------+------------------+---------+------+--------------------------+-----------------------------------------------------------------------------------------------------+----------+
8 rows in set (0.00 sec)

But explain isn’t being very helpful. Does this mean I can’t improve the second query?

MariaDB [f0d63920935f2f82]> explain select modified, docstatus from `tabSales Invoice`
    ->                                         where name = 'SINV-RET-131424-1' for update;
+------+-------------+------------------+-------+---------------+---------+---------+-------+------+-------+
| id   | select_type | table            | type  | possible_keys | key     | key_len | ref   | rows | Extra |
+------+-------------+------------------+-------+---------------+---------+---------+-------+------+-------+
|    1 | SIMPLE      | tabSales Invoice | const | PRIMARY       | PRIMARY | 562     | const |    1 |       |
+------+-------------+------------------+-------+---------------+---------+---------+-------+------+-------+
1 row in set (0.00 sec)

adam26d · July 24, 2019, 8:22am

UPDATE

It seems the issue is the high volume of invoices in local storage. Each of the stuck invoices is triggering a stock update, the result is a large number of cascading queries which leads to timeout. Theres a total of 56400 invoices (typical for retail).

My issue, POS invoices not uploading, has happened twice before. But the cause was different, each of those times a large number of transactions synchronized after resolving the issue. Maybe this time the existing records (to be affected) are just too many.

I have optimised Mariadb, increased my Gunicorn workers, etc. I also tried removing POS customisations. All these didn’t work. Slow query logs are not giving any new results.

For now switching to a different browser allows the terminal to successfully submit new sales. But two months of sales are stuck. This needs to be resolved. My next attempt is to increase timeout period temporarily to something that allows the queries to finish.

trentmu · July 24, 2019, 8:42am

Again I cannot be sure and am just guessing based on a small amount of previous storage performance experiences, but it seems like the “dirty cache buffers” buffers are not clearing.
There’s a mysql setting for this - a decent article/explanation is here…

adam26d · July 24, 2019, 8:56am

Thank you @trentmu

I’ll give this a shot as well and report back

Sanath_Udayawansa2 · November 14, 2019, 7:10am

How to increase the time out period?

Aniket_Shinde1 · October 21, 2020, 7:48am

I am facing same issue while submitting sales invoice
where there are 10 line items or more and update stock is ticked.
Version
erpnext 12.12.1
frappe 12.10.2