[BUG] ocsreport not respond .httpd blocked #1573

bud4 · 2023-10-31T11:00:34Z

OCS Inventory version
Version : 2.12.0
Distribution: CentOS Stream 8
db : MariaDB Server version 10.3.28-MariaDB

Describe the bug
not response from ocs-report url. httpd active.

To Reproduce
after days of correct functioning the web interface was no longer responsive

Log file (optional)
php error log 👍
[31-Oct-2023 10:05:16.379791] DEBUG: pid 1160, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 0 active children, 6 spare children, 6 running children. Spawning rate 1
[31-Oct-2023 10:05:17.380960] DEBUG: pid 1160, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 0 active children, 6 spare children, 6 running children. Spawning rate 1
[31-Oct-2023 10:05:18.382152] DEBUG: pid 1160, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 0 active children, 6 spare children, 6 running children. Spawning rate 1
[31-Oct-2023 10:05:19.383501] DEBUG: pid 1160, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 0 active children, 6 spare children, 6 running children. Spawning rate 1
[31-Oct-2023 10:05:20.384605] DEBUG: pid 1160, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 0 active children, 6 spare children, 6 running children. Spawning rate 1
[31-Oct-2023 10:05:21.385790] DEBUG: pid 1160, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 0 active children, 6 spare children, 6 running children. Spawning rate 1
[31-Oct-2023 10:05:22.387177] DEBUG: pid 1160, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 0 active children, 6 spare children, 6 running children. Spawning rate 1
[31-Oct-2023 10:05:23.388323] DEBUG: pid 1160, fpm_pctl_perform_idle_server_maintenance(), line 382: [pool www] currently 0 active children, 6 spare children, 6 running children. Spawning rate 1

ystemctl status httpd.service
● httpd.service - The Apache HTTP Server
Loaded: loaded (/etc/systemd/system/httpd.service; enabled; vendor preset: disabled)
Drop-In: /etc/systemd/system/httpd.service.d
└─php-fpm.conf
Active: failed (Result: timeout) since Tue 2023-10-31 09:26:08 CET; 55s ago
Docs: man:httpd.service(8)
Main PID: 95862 (code=killed, signal=KILL)
Status: "Total requests: 121028; Idle/Busy workers 62/38;Requests/sec: 0.0527; Bytes served/sec: 4.2KB/sec"

ott 31 09:26:08 ocs systemd[1]: httpd.service: Killing process 220174 (/usr/sbin/httpd) with signal SIGKILL.
ott 31 09:26:08 ocs systemd[1]: httpd.service: Killing process 224181 (/usr/sbin/httpd) with signal SIGKILL.
ott 31 09:26:08 ocs systemd[1]: httpd.service: Killing process 261371 (/usr/sbin/httpd) with signal SIGKILL.
ott 31 09:26:08 ocs systemd[1]: httpd.service: Killing process 268158 (/usr/sbin/httpd) with signal SIGKILL.
ott 31 09:26:08 ocs systemd[1]: httpd.service: Killing process 276534 (/usr/sbin/httpd) with signal SIGKILL.
ott 31 09:26:08 ocs systemd[1]: httpd.service: Killing process 279842 (/usr/sbin/httpd) with signal SIGKILL.
ott 31 09:26:08 ocs systemd[1]: httpd.service: Killing process 282647 (/usr/sbin/httpd) with signal SIGKILL.
ott 31 09:26:08 ocs systemd[1]: httpd.service: Killing process 301189 (/usr/sbin/httpd) with signal SIGKILL.
ott 31 09:26:08 ocs systemd[1]: httpd.service: Failed with result 'timeout'.
ott 31 09:26:08 ocs systemd[1]: Stopped The Apache HTTP Server.
bug.zip

Lea9250 · 2023-12-11T13:58:01Z

Hi @bud4,

The line "Lock wait timeout exceeded" in your error_log refers to a SQL delete statement made upon update of an inventory section. Would you be able to check the SQL process list while this is happening, see which queries are slowing the database ?
Depending on how many assets the OCS server is handling, this could also be a sign that the server needs more resources or that apache or php-fpm are not properly configured.

Regards,
Léa

bud4 · 2024-01-22T13:38:13Z

Unfortunately the problem is recurring very often.
the vm has 10 cores and 10 giga of ram. It has many more resources than a server with loads and services that are critical for us. I attach logs and report below some output of sql commands to investigate the active operations in the database. I think it's a Race condition.
show engine innodb status;
`
ATEST DETECTED DEADLOCK

2024-01-22 12:35:01 0x7f82649cf700
*** (1) TRANSACTION:
TRANSACTION 19789548, ACTIVE 12 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 7 lock struct(s), heap size 1128, 5 row lock(s), undo log entries 2
MySQL thread id 24215, OS thread handle 140198191974144, query id 108510918 localhost ocs_user Updating
UPDATE devices SET TVALUE='NOTIFIED', COMMENTS='Mon Jan 22 12:34:49 2024' WHERE NAME='DOWNLOAD' AND HARDWARE_ID='36773' AND TVALUE IS NULL
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 154 page no 633 n bits 1216 index HARDWARE_ID of table ocs_db.devices trx id 19789548 lock_mode X waiting
Record lock, heap no 890 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 80008fa5; asc ;;
1: len 4; hex 8000eaca; asc ;;

*** (2) TRANSACTION:
TRANSACTION 19789494, ACTIVE 61 sec fetching rows
mysql tables in use 3, locked 3
179 lock struct(s), heap size 24696, 4988 row lock(s), undo log entries 1
MySQL thread id 24208, OS thread handle 140198010484480, query id 108499186 localhost ocs_user Updating
UPDATE devices SET TVALUE='SUCCESS', COMMENTS='Mon Jan 22 12:34:00 2024'
WHERE NAME="DOWNLOAD"
AND HARDWARE_ID='36773'
AND IVALUE='24'
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 154 page no 633 n bits 1216 index HARDWARE_ID of table ocs_db.devices trx id 19789494 lock_mode X
Record lock, heap no 890 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 80008fa5; asc ;;
1: len 4; hex 8000eaca; asc ;;

Record lock, heap no 892 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 80008fa5; asc ;;
1: len 4; hex 8000eacb; asc ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 154 page no 633 n bits 1216 index HARDWARE_ID of table ocs_db.devices trx id 19789494 lock_mode X waiting
Record lock, heap no 979 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 80008fa5; asc ;;
1: len 4; hex 8000eacd; asc ;;

*** WE ROLL BACK TRANSACTION (1)

TRANSACTIONS

Trx id counter 19796604
Purge done for trx's n:o < 19796604 undo n:o < 0 state: running
History list length 3081
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421673163255920, not started
0 lock struct(s), heap size 1128, 0 row lock(s)

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] , aio writes: [0, 0, 0, 0] ,
ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
3323244729 OS file reads, 14179126 OS file writes, 5208945 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 102, seg size 104, 489285 merges
merged operations:
insert 379397, delete mark 815391, delete 24069
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 34673, node heap has 62 buffer(s)
Hash table size 34673, node heap has 6 buffer(s)
Hash table size 34673, node heap has 39 buffer(s)
Hash table size 34673, node heap has 44 buffer(s)
Hash table size 34673, node heap has 69 buffer(s)
Hash table size 34673, node heap has 227 buffer(s)
Hash table size 34673, node heap has 24 buffer(s)
Hash table size 34673, node heap has 19 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s

LOG

Log sequence number 1588962893936
Log flushed up to 1588962893936
Pages flushed up to 1588962893936
Last checkpoint at 1588962893927
0 pending log flushes, 0 pending chkp writes
952265 log i/o's done, 0.00 log i/o's/second

BUFFER POOL AND MEMORY

Total large memory allocated 170590208
Dictionary memory allocated 354960
Buffer pool size 8191
Free buffers 1
Database pages 7700
Old database pages 2823
Modified db pages 0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 8431285, not young 130339903074
0.00 youngs/s, 0.00 non-youngs/s
Pages read 3323244829, created 1233588, written 11962162
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: 7700, 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
0 read views open inside InnoDB
Process ID=2336, Main thread ID=140197913687808, state: sleeping
Number of rows inserted 57829599, updated 615424, deleted 55541086, read 149834543298
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

END OF INNODB MONITOR OUTPUT

`
+--------+------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

http_error_log.log
php-error.log
mariadb.log

bud4 · 2024-01-31T10:18:12Z

the problem repeats frequently I have to restart the server very often

=====================================
2024-01-31 11:03:13 0x7fe480931700 INNODB MONITOR OUTPUT

Per second averages calculated from the last 31 seconds

BACKGROUND THREAD

srv_master_thread loops: 283991 srv_active, 0 srv_shutdown, 470927 srv_idle
srv_master_thread log flush and writes: 754916

SEMAPHORES

OS WAIT ARRAY INFO: reservation count 2393393
OS WAIT ARRAY INFO: signal count 4304043
RW-shared spins 7650435, rounds 83095040, OS waits 687393
RW-excl spins 4661219, rounds 18651086, OS waits 144420
RW-sx spins 514292, rounds 7954907, OS waits 132610
Spin rounds per wait: 10.86 RW-shared, 4.00 RW-excl, 15.47 RW-sx

LATEST DETECTED DEADLOCK

2024-01-31 09:29:38 0x7fe480a5d700
*** (1) TRANSACTION:
TRANSACTION 20137662, ACTIVE 12 sec updating or deleting
mysql tables in use 1, locked 1
LOCK WAIT 15 lock struct(s), heap size 1128, 37 row lock(s), undo log entries 6
MySQL thread id 18699, OS thread handle 140619388237568, query id 88049305 localhost ocs_user Updating
UPDATE devices SET HARDWARE_ID='38617' WHERE HARDWARE_ID='38467'
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 154 page no 637 n bits 720 index HARDWARE_ID of table ocs_db.devices trx id 20137662 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) TRANSACTION:
TRANSACTION 20137611, ACTIVE 39 sec updating or deleting
mysql tables in use 1, locked 1
18 lock struct(s), heap size 1128, 38 row lock(s), undo log entries 6
MySQL thread id 18693, OS thread handle 140619387623168, query id 88036261 localhost ocs_user Updating
UPDATE devices SET HARDWARE_ID='38615' WHERE HARDWARE_ID='38426'
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 154 page no 637 n bits 720 index HARDWARE_ID of table ocs_db.devices trx id 20137611 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 341 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000ea97; asc ;;

Record lock, heap no 342 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000ea98; asc ;;

Record lock, heap no 343 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000eb48; asc H;;

Record lock, heap no 344 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000eb49; asc I;;

Record lock, heap no 345 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000eb4a; asc J;;

Record lock, heap no 346 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000eb4b; asc K;;

Record lock, heap no 347 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000ec01; asc ;;

Record lock, heap no 348 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000ec02; asc ;;

Record lock, heap no 349 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000ec03; asc ;;

Record lock, heap no 350 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000ec04; asc ;;

Record lock, heap no 351 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000ed3b; asc ;;;

Record lock, heap no 352 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000ed3c; asc <;;

Record lock, heap no 353 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000ed3d; asc =;;

Record lock, heap no 354 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000961a; asc ;;
1: len 4; hex 8000ed3e; asc >;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 154 page no 637 n bits 720 index HARDWARE_ID of table ocs_db.devices trx id 20137611 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;

*** WE ROLL BACK TRANSACTION (1)

TRANSACTIONS

Trx id counter 20145228
Purge done for trx's n:o < 20118020 undo n:o < 0 state: running but idle
History list length 13142
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 422094358480632, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422094358476448, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 20145215, ACTIVE 13 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 18 lock struct(s), heap size 1128, 213 row lock(s), undo log entries 1
MySQL thread id 19596, OS thread handle 140619399317248, query id 89645333 localhost ocs_user Updating
DELETE FROM driverslist WHERE HARDWARE_ID='13755'
Trx read view will not see trx with id >= 20145214, sees < 20145163
------- TRX HAS BEEN WAITING 12 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 542 page no 86 n bits 152 index PRIMARY of table ocs_db.driverslist trx id 20145215 lock_mode X waiting
Record lock, heap no 18 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 4; hex 8002fe87; asc ;;
1: len 4; hex 80004c82; asc L ;;
2: len 6; hex 000000000000; asc ;;
3: len 7; hex 80000000000000; asc ;;
4: len 10; hex 5052494e545155455545; asc PRINTQUEUE;;
5: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
6: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
7: len 9; hex 4d6963726f736f6674; asc Microsoft;;
8: len 12; hex 31302e302e31393034312e31; asc 10.0.19041.1;;
9: len 10; hex 323030362f30362f3231; asc 2006/06/21;;
10: len 14; hex 7072696e7471756575652e696e66; asc printqueue.inf;;
11: len 22; hex 4d6963726f736f6674205072696e7420746f20504446; asc Microsoft Print to PDF;;
12: len 4; hex 5665726f; asc Vero;;
13: len 30; hex 5357445c5052494e54454e554d5c7b46443133374545302d433632312d34; asc SWD\PRINTENUM{FD137EE0-C621-4; (total 52 bytes);

---TRANSACTION 422094358430424, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 20145210, ACTIVE 18 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 13 lock struct(s), heap size 1128, 217 row lock(s), undo log entries 1
MySQL thread id 19592, OS thread handle 140619400238848, query id 89643983 localhost ocs_user Updating
DELETE FROM driverslist WHERE HARDWARE_ID='37008'
Trx read view will not see trx with id >= 20145210, sees < 20145163
------- TRX HAS BEEN WAITING 17 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 542 page no 86 n bits 152 index PRIMARY of table ocs_db.driverslist trx id 20145210 lock_mode X waiting
Record lock, heap no 18 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 4; hex 8002fe87; asc ;;
1: len 4; hex 80004c82; asc L ;;
2: len 6; hex 000000000000; asc ;;
3: len 7; hex 80000000000000; asc ;;
4: len 10; hex 5052494e545155455545; asc PRINTQUEUE;;
5: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
6: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
7: len 9; hex 4d6963726f736f6674; asc Microsoft;;
8: len 12; hex 31302e302e31393034312e31; asc 10.0.19041.1;;
9: len 10; hex 323030362f30362f3231; asc 2006/06/21;;
10: len 14; hex 7072696e7471756575652e696e66; asc printqueue.inf;;
11: len 22; hex 4d6963726f736f6674205072696e7420746f20504446; asc Microsoft Print to PDF;;
12: len 4; hex 5665726f; asc Vero;;
13: len 30; hex 5357445c5052494e54454e554d5c7b46443133374545302d433632312d34; asc SWD\PRINTENUM{FD137EE0-C621-4; (total 52 bytes);

---TRANSACTION 20145203, ACTIVE 27 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 16 lock struct(s), heap size 1128, 203 row lock(s), undo log entries 1
MySQL thread id 19591, OS thread handle 140619391616768, query id 89641656 localhost ocs_user Updating
DELETE FROM driverslist WHERE HARDWARE_ID='18257'
Trx read view will not see trx with id >= 20145202, sees < 20145080
------- TRX HAS BEEN WAITING 25 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 542 page no 86 n bits 152 index PRIMARY of table ocs_db.driverslist trx id 20145203 lock_mode X waiting
Record lock, heap no 18 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 4; hex 8002fe87; asc ;;
1: len 4; hex 80004c82; asc L ;;
2: len 6; hex 000000000000; asc ;;
3: len 7; hex 80000000000000; asc ;;
4: len 10; hex 5052494e545155455545; asc PRINTQUEUE;;
5: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
6: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
7: len 9; hex 4d6963726f736f6674; asc Microsoft;;
8: len 12; hex 31302e302e31393034312e31; asc 10.0.19041.1;;
9: len 10; hex 323030362f30362f3231; asc 2006/06/21;;
10: len 14; hex 7072696e7471756575652e696e66; asc printqueue.inf;;
11: len 22; hex 4d6963726f736f6674205072696e7420746f20504446; asc Microsoft Print to PDF;;
12: len 4; hex 5665726f; asc Vero;;
13: len 30; hex 5357445c5052494e54454e554d5c7b46443133374545302d433632312d34; asc SWD\PRINTENUM{FD137EE0-C621-4; (total 52 bytes);

---TRANSACTION 20145200, ACTIVE 30 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 14 lock struct(s), heap size 1128, 365 row lock(s), undo log entries 1
MySQL thread id 19590, OS thread handle 140619391923968, query id 89640728 localhost ocs_user Updating
DELETE FROM driverslist WHERE HARDWARE_ID='20507'
Trx read view will not see trx with id >= 20145200, sees < 20145080
------- TRX HAS BEEN WAITING 28 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 542 page no 86 n bits 152 index PRIMARY of table ocs_db.driverslist trx id 20145200 lock_mode X waiting
Record lock, heap no 18 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 4; hex 8002fe87; asc ;;
1: len 4; hex 80004c82; asc L ;;
2: len 6; hex 000000000000; asc ;;
3: len 7; hex 80000000000000; asc ;;
4: len 10; hex 5052494e545155455545; asc PRINTQUEUE;;
5: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
6: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
7: len 9; hex 4d6963726f736f6674; asc Microsoft;;
8: len 12; hex 31302e302e31393034312e31; asc 10.0.19041.1;;
9: len 10; hex 323030362f30362f3231; asc 2006/06/21;;
10: len 14; hex 7072696e7471756575652e696e66; asc printqueue.inf;;
11: len 22; hex 4d6963726f736f6674205072696e7420746f20504446; asc Microsoft Print to PDF;;
12: len 4; hex 5665726f; asc Vero;;
13: len 30; hex 5357445c5052494e54454e554d5c7b46443133374545302d433632312d34; asc SWD\PRINTENUM{FD137EE0-C621-4; (total 52 bytes);

---TRANSACTION 20145199, ACTIVE 35 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 15 lock struct(s), heap size 1128, 228 row lock(s), undo log entries 1
MySQL thread id 19589, OS thread handle 140619387008768, query id 89639151 localhost ocs_user Updating
DELETE FROM driverslist WHERE HARDWARE_ID='28268'
Trx read view will not see trx with id >= 20145197, sees < 20145080
------- TRX HAS BEEN WAITING 35 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 542 page no 86 n bits 152 index PRIMARY of table ocs_db.driverslist trx id 20145199 lock_mode X waiting
Record lock, heap no 18 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 4; hex 8002fe87; asc ;;
1: len 4; hex 80004c82; asc L ;;
2: len 6; hex 000000000000; asc ;;
3: len 7; hex 80000000000000; asc ;;
4: len 10; hex 5052494e545155455545; asc PRINTQUEUE;;
5: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
6: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
7: len 9; hex 4d6963726f736f6674; asc Microsoft;;
8: len 12; hex 31302e302e31393034312e31; asc 10.0.19041.1;;
9: len 10; hex 323030362f30362f3231; asc 2006/06/21;;
10: len 14; hex 7072696e7471756575652e696e66; asc printqueue.inf;;
11: len 22; hex 4d6963726f736f6674205072696e7420746f20504446; asc Microsoft Print to PDF;;
12: len 4; hex 5665726f; asc Vero;;
13: len 30; hex 5357445c5052494e54454e554d5c7b46443133374545302d433632312d34; asc SWD\PRINTENUM{FD137EE0-C621-4; (total 52 bytes);

---TRANSACTION 422094358417872, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 20145214, ACTIVE 13 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 13 lock struct(s), heap size 1128, 104 row lock(s), undo log entries 1
MySQL thread id 19586, OS thread handle 140619386701568, query id 89645268 localhost ocs_user Updating
DELETE FROM driverslist WHERE HARDWARE_ID='32921'
Trx read view will not see trx with id >= 20145214, sees < 20145163
------- TRX HAS BEEN WAITING 12 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 542 page no 86 n bits 152 index PRIMARY of table ocs_db.driverslist trx id 20145214 lock_mode X waiting
Record lock, heap no 18 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 4; hex 8002fe87; asc ;;
1: len 4; hex 80004c82; asc L ;;
2: len 6; hex 000000000000; asc ;;
3: len 7; hex 80000000000000; asc ;;
4: len 10; hex 5052494e545155455545; asc PRINTQUEUE;;
5: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
6: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
7: len 9; hex 4d6963726f736f6674; asc Microsoft;;
8: len 12; hex 31302e302e31393034312e31; asc 10.0.19041.1;;
9: len 10; hex 323030362f30362f3231; asc 2006/06/21;;
10: len 14; hex 7072696e7471756575652e696e66; asc printqueue.inf;;
11: len 22; hex 4d6963726f736f6674205072696e7420746f20504446; asc Microsoft Print to PDF;;
12: len 4; hex 5665726f; asc Vero;;
13: len 30; hex 5357445c5052494e54454e554d5c7b46443133374545302d433632312d34; asc SWD\PRINTENUM{FD137EE0-C621-4; (total 52 bytes);

---TRANSACTION 20145221, ACTIVE 11 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 19 lock struct(s), heap size 1128, 197 row lock(s), undo log entries 1
MySQL thread id 19585, OS thread handle 140619392538368, query id 89646005 localhost ocs_user Updating
DELETE FROM driverslist WHERE HARDWARE_ID='9699'
Trx read view will not see trx with id >= 20145221, sees < 20145179
------- TRX HAS BEEN WAITING 10 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 542 page no 86 n bits 152 index PRIMARY of table ocs_db.driverslist trx id 20145221 lock_mode X waiting
Record lock, heap no 18 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 4; hex 8002fe87; asc ;;
1: len 4; hex 80004c82; asc L ;;
2: len 6; hex 000000000000; asc ;;
3: len 7; hex 80000000000000; asc ;;
4: len 10; hex 5052494e545155455545; asc PRINTQUEUE;;
5: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
6: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
7: len 9; hex 4d6963726f736f6674; asc Microsoft;;
8: len 12; hex 31302e302e31393034312e31; asc 10.0.19041.1;;
9: len 10; hex 323030362f30362f3231; asc 2006/06/21;;
10: len 14; hex 7072696e7471756575652e696e66; asc printqueue.inf;;
11: len 22; hex 4d6963726f736f6674205072696e7420746f20504446; asc Microsoft Print to PDF;;
12: len 4; hex 5665726f; asc Vero;;
13: len 30; hex 5357445c5052494e54454e554d5c7b46443133374545302d433632312d34; asc SWD\PRINTENUM{FD137EE0-C621-4; (total 52 bytes);

---TRANSACTION 20145209, ACTIVE 24 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 14 lock struct(s), heap size 1128, 213 row lock(s), undo log entries 1
MySQL thread id 19582, OS thread handle 140619391002368, query id 89642628 localhost ocs_user Updating
DELETE FROM driverslist WHERE HARDWARE_ID='32860'
Trx read view will not see trx with id >= 20145209, sees < 20145163
------- TRX HAS BEEN WAITING 23 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 542 page no 86 n bits 152 index PRIMARY of table ocs_db.driverslist trx id 20145209 lock_mode X waiting
Record lock, heap no 18 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 4; hex 8002fe87; asc ;;
1: len 4; hex 80004c82; asc L ;;
2: len 6; hex 000000000000; asc ;;
3: len 7; hex 80000000000000; asc ;;
4: len 10; hex 5052494e545155455545; asc PRINTQUEUE;;
5: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
6: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
7: len 9; hex 4d6963726f736f6674; asc Microsoft;;
8: len 12; hex 31302e302e31393034312e31; asc 10.0.19041.1;;
9: len 10; hex 323030362f30362f3231; asc 2006/06/21;;
10: len 14; hex 7072696e7471756575652e696e66; asc printqueue.inf;;
11: len 22; hex 4d6963726f736f6674205072696e7420746f20504446; asc Microsoft Print to PDF;;
12: len 4; hex 5665726f; asc Vero;;
13: len 30; hex 5357445c5052494e54454e554d5c7b46443133374545302d433632312d34; asc SWD\PRINTENUM{FD137EE0-C621-4; (total 52 bytes);

---TRANSACTION 20145196, ACTIVE 37 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 20 lock struct(s), heap size 3488, 201 row lock(s), undo log entries 1
MySQL thread id 19581, OS thread handle 140619389159168, query id 89638390 localhost ocs_user Updating
DELETE FROM driverslist WHERE HARDWARE_ID='11316'
Trx read view will not see trx with id >= 20145196, sees < 20145080
------- TRX HAS BEEN WAITING 36 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 542 page no 86 n bits 152 index PRIMARY of table ocs_db.driverslist trx id 20145196 lock_mode X waiting
Record lock, heap no 18 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 4; hex 8002fe87; asc ;;
1: len 4; hex 80004c82; asc L ;;
2: len 6; hex 000000000000; asc ;;
3: len 7; hex 80000000000000; asc ;;
4: len 10; hex 5052494e545155455545; asc PRINTQUEUE;;
5: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
6: len 17; hex 4c6f63616c205072696e74205175657565; asc Local Print Queue;;
7: len 9; hex 4d6963726f736f6674; asc Microsoft;;
8: len 12; hex 31302e302e31393034312e31; asc 10.0.19041.1;;
9: len 10; hex 323030362f30362f3231; asc 2006/06/21;;
10: len 14; hex 7072696e7471756575652e696e66; asc printqueue.inf;;
11: len 22; hex 4d6963726f736f6674205072696e7420746f20504446; asc Microsoft Print to PDF;;
12: len 4; hex 5665726f; asc Vero;;
13: len 30; hex 5357445c5052494e54454e554d5c7b46443133374545302d433632312d34; asc SWD\PRINTENUM{FD137EE0-C621-4; (total 52 bytes);

---TRANSACTION 422094358468080, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 20145179, ACTIVE 60 sec fetching rows
mysql tables in use 1, locked 1
85224 lock struct(s), heap size 9117816, 4557787 row lock(s), undo log entries 2109
MySQL thread id 19510, OS thread handle 140619398702848, query id 89647206 localhost ocs_user Updating
DELETE FROM winupdatestate WHERE HARDWARE_ID='21011'
Trx read view will not see trx with id >= 20145179, sees < 20145080
---TRANSACTION 422094358426240, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422094358451344, ACTIVE 16492 sec
0 lock struct(s), heap size 1128, 0 row lock(s)
MySQL thread id 16827, OS thread handle 140619401160448, query id 84714462 localhost ocs_user
Trx read view will not see trx with id >= 20120722, sees < 20120722
---TRANSACTION 422094358447160, ACTIVE 26612 sec
0 lock struct(s), heap size 1128, 0 row lock(s)
MySQL thread id 16826, OS thread handle 140619397474048, query id 84022353 localhost ocs_user
Trx read view will not see trx with id >= 20118402, sees < 20118388
---TRANSACTION 422094358438792, ACTIVE 26428 sec
0 lock struct(s), heap size 1128, 0 row lock(s)
MySQL thread id 16817, OS thread handle 140619390387968, query id 84034050 localhost ocs_user
Trx read view will not see trx with id >= 20118437, sees < 20118432
---TRANSACTION 422094358434608, ACTIVE 27065 sec
0 lock struct(s), heap size 1128, 0 row lock(s)
MySQL thread id 16788, OS thread handle 140619400853248, query id 83986919 localhost ocs_user
Trx read view will not see trx with id >= 20118284, sees < 20118284
---TRANSACTION 422094358422056, ACTIVE 28086 sec
0 lock struct(s), heap size 1128, 0 row lock(s)
MySQL thread id 16787, OS thread handle 140619390695168, query id 83938117 localhost ocs_user
Trx read view will not see trx with id >= 20118019, sees < 20118019

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] , aio writes: [0, 0, 0, 0] ,
ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
2663998713 OS file reads, 11967238 OS file writes, 4207497 OS fsyncs
1 pending reads, 0 pending writes
7262.64 reads/s, 16384 avg bytes/read, 19.74 writes/s, 8.32 fsyncs/s

INSERT BUFFER AND ADAPTIVE HASH INDEX

Ibuf: size 1, free list len 102, seg size 104, 443165 merges
merged operations:
insert 325805, delete mark 740393, delete 54277
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 34673, node heap has 7 buffer(s)
Hash table size 34673, node heap has 6 buffer(s)
Hash table size 34673, node heap has 6 buffer(s)
Hash table size 34673, node heap has 6 buffer(s)
Hash table size 34673, node heap has 1 buffer(s)
Hash table size 34673, node heap has 4 buffer(s)
Hash table size 34673, node heap has 73 buffer(s)
Hash table size 34673, node heap has 3 buffer(s)
1908.00 hash searches/s, 1148.83 non-hash searches/s

LOG

Log sequence number 1621236554771
Log flushed up to 1621236548821
Pages flushed up to 1621236548821
Last checkpoint at 1621236396865
0 pending log flushes, 0 pending chkp writes
774760 log i/o's done, 1.81 log i/o's/second

BUFFER POOL AND MEMORY

Total large memory allocated 170590208
Dictionary memory allocated 354960
Buffer pool size 8191
Free buffers 0
Database pages 7525
Old database pages 2776
Modified db pages 3
Percent of dirty pages(LRU & free pages): 0.040
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 5978932, not young 111307236325
3.29 youngs/s, 226253.19 non-youngs/s
Pages read 2663998948, created 1026257, written 10239923
7265.64 reads/s, 0.84 creates/s, 16.00 writes/s
Buffer pool hit rate 970 / 1000, young-making rate 0 / 1000 not 905 / 1000
Pages read ahead 647.14/s, evicted without access 108.45/s, Random read ahead 0.00/s
LRU len: 7525, unzip_LRU len: 0
I/O sum[337607]:cur[7721], unzip sum[0]:cur[0]

ROW OPERATIONS

0 queries inside InnoDB, 0 queries in queue
15 read views open inside InnoDB
Process ID=1293, Main thread ID=140618806310656, state: sleeping
Number of rows inserted 47557023, updated 488158, deleted 46161681, read 127359664848
92.45 inserts/s, 0.42 updates/s, 91.55 deletes/s, 277471.47 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

END OF INNODB MONITOR OUTPUT

|
1 row in set (0.105 sec)

MariaDB [(none)]>
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

bud4 · 2024-02-05T10:37:18Z

the problem persists seems to be inherent to these sql operations:

DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/local/share/perl5/Apache/Ocsinventory/Server/Duplicate.pm line 268.
can't find ANONSUB's 'anon9' entry.
DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/local/share/perl5/Apache/Ocsinventory/Server/Inventory/Update.pm line 102.
can't find ANONSUB's 'anon39' entry.
can't find ANONSUB's 'anon13' entry.
DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/local/share/perl5/Apache/Ocsinventory/Server/Inventory/Update.pm line 102.

bud4 · 2024-02-13T11:49:10Z

the problem persists
``

DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/local/share/perl5/Apache/Ocsinventory/Server/Inventory/Update.pm line 102.
DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/local/share/perl5/Apache/Ocsinventory/Server/Inventory/Update.pm line 102.
DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/local/share/perl5/Apache/Ocsinventory/Server/Inventory/Update.pm line 102.
can't find ANONSUB's 'anon19' entry.
DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/local/share/perl5/Apache/Ocsinventory/Server/Inventory/Update.pm line 102.
DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/local/share/perl5/Apache/Ocsinventory/Server/Inventory/Update.pm line 102.
DBD::mysql::db do failed: Lock wait timeout exceeded; try restarting transaction at /usr/local/share/perl5/Apache/Ocsinventory/Server/Inventory/Update.pm line 102.
``

gillesdubois · 2024-02-14T08:16:48Z

Hi,

To be honest, I installed OCS where asset number went above 50k / 100k assets and everytime I encountered this issue was due to mariadb configuration.

In some rare case, it can be due to looping agents. On big instances we recommend to setup a third party system to filter / drop to recurrent request in order to keep the service quality up.

To get more information on the lock itself you need to enable verbose loggin on mariadb and not OCS Inventory which won't provide anything related to the "why" of the locks.

On big instances, the tmpdir variable may sometimes link to a partition / directory that doesn't allow enough space and slow the mariadb instance over time.

Could you also tell me how many assets are you inventorying on your instance ?
If you exceed 10k assets, having a full supported version using our professional services would be a good idea :)

Regards,
Gilles DUBOIS.

bud4 added bug need approval labels Oct 31, 2023

bud4 assigned charleneauger, damienbelliard, gillesdubois and RudyLaurent Oct 31, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[BUG] ocsreport not respond .httpd blocked #1573

[BUG] ocsreport not respond .httpd blocked #1573

bud4 commented Oct 31, 2023

Lea9250 commented Dec 11, 2023

bud4 commented Jan 22, 2024 •

edited

bud4 commented Jan 31, 2024

bud4 commented Feb 5, 2024

bud4 commented Feb 13, 2024

gillesdubois commented Feb 14, 2024

[BUG] ocsreport not respond .httpd blocked #1573

[BUG] ocsreport not respond .httpd blocked #1573

Comments

bud4 commented Oct 31, 2023

Lea9250 commented Dec 11, 2023

bud4 commented Jan 22, 2024 • edited

*** WE ROLL BACK TRANSACTION (1)

TRANSACTIONS

Trx id counter 19796604 Purge done for trx's n:o < 19796604 undo n:o < 0 state: running History list length 3081 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421673163255920, not started 0 lock struct(s), heap size 1128, 0 row lock(s)

FILE I/O

INSERT BUFFER AND ADAPTIVE HASH INDEX

LOG

Log sequence number 1588962893936 Log flushed up to 1588962893936 Pages flushed up to 1588962893936 Last checkpoint at 1588962893927 0 pending log flushes, 0 pending chkp writes 952265 log i/o's done, 0.00 log i/o's/second

BUFFER POOL AND MEMORY

ROW OPERATIONS

END OF INNODB MONITOR OUTPUT

bud4 commented Jan 31, 2024

the problem repeats frequently I have to restart the server very often

===================================== 2024-01-31 11:03:13 0x7fe480931700 INNODB MONITOR OUTPUT

Per second averages calculated from the last 31 seconds

BACKGROUND THREAD

srv_master_thread loops: 283991 srv_active, 0 srv_shutdown, 470927 srv_idle srv_master_thread log flush and writes: 754916

SEMAPHORES

LATEST DETECTED DEADLOCK

*** WE ROLL BACK TRANSACTION (1)

TRANSACTIONS

FILE I/O

INSERT BUFFER AND ADAPTIVE HASH INDEX

LOG

Log sequence number 1621236554771 Log flushed up to 1621236548821 Pages flushed up to 1621236548821 Last checkpoint at 1621236396865 0 pending log flushes, 0 pending chkp writes 774760 log i/o's done, 1.81 log i/o's/second

BUFFER POOL AND MEMORY

ROW OPERATIONS

END OF INNODB MONITOR OUTPUT

bud4 commented Feb 5, 2024

bud4 commented Feb 13, 2024

gillesdubois commented Feb 14, 2024

bud4 commented Jan 22, 2024 •

edited

Trx id counter 19796604
Purge done for trx's n:o < 19796604 undo n:o < 0 state: running
History list length 3081
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421673163255920, not started
0 lock struct(s), heap size 1128, 0 row lock(s)

Log sequence number 1588962893936
Log flushed up to 1588962893936
Pages flushed up to 1588962893936
Last checkpoint at 1588962893927
0 pending log flushes, 0 pending chkp writes
952265 log i/o's done, 0.00 log i/o's/second

=====================================
2024-01-31 11:03:13 0x7fe480931700 INNODB MONITOR OUTPUT

srv_master_thread loops: 283991 srv_active, 0 srv_shutdown, 470927 srv_idle
srv_master_thread log flush and writes: 754916

Log sequence number 1621236554771
Log flushed up to 1621236548821
Pages flushed up to 1621236548821
Last checkpoint at 1621236396865
0 pending log flushes, 0 pending chkp writes
774760 log i/o's done, 1.81 log i/o's/second