[OJS-3.4.0-4] Statistic problem

Hi @bozana

MYSQL-8.0.28

After the rollback of the last patch, log files 20240206 and 20240505 are processed normally but log file 20240208 is stuck.

20240208 The log file is stuck in the processing folder again. I have tried manually retrying as suggested [OJS-3.4.0-4] Statistic problem - #59 by bozana and noticed that the MYSQL process and query handler is showing up as waiting for handler commit. It looks like this till the end. Finally, the log file 20240208 resides in the processing folder.

Here I am attaching the screenshot of MYSQL processing.

Screenshot 2024-02-09 100741

Hi @shantanusingh

Phew… I do not know why is this happening… :frowning:

Maybe this post can help: https://forums.percona.com/t/percona-8-statement-hangs-with-waiting-for-handler-commit-state/13832/7?
I.e. to investigate more about innodb_flush_log_at_trx_commit, innodb_log_file_size, innodb_log_buffer_size and innodb_log_files_in_group ?
Or maybe it is also something other on your system/server configuration/properties…

:frowning:

Hi @bozana

I have set the MYSQL .cnf file.

innodb_buffer_pool_size = 5G
innodb_log_buffer_size = 2G
innodb_log_file_size = 2G
innodb_log_files_in_group = 4
innodb_flush_log_at_trx_commit = 2 or 0

For 2 days it continued normally as before but on the third day, this process could not be completed. 20240212 The log file is stuck in the process folder.

I have set the maximum execution of PHP to 600 seconds. Below is the timeout of MYSQL, any suggestions regarding these settings?

interactive_timeout = 1800
wait_timeout = 1800

Hmm, looks like the queries are having progress (i.e. the SQL is not the same and the value at the time column is small).

If you use SHOW FULL processlist the whole SQL will be shown, then it might be easier to see if there’s progress or if the query is deadlocked.

Best,
Jonas Raoni

Hi @jonasraoni thanks for replying and stay with me to solve the problem.

The last one is 20240212 log file which is stuck in the processing folder and this type of problem has happened many times. I tried 20240212 in the morning but it didn’t work.

Now I have tried tracking the query as suggested, but the log file was processed and stored, but the error was reported in the failed jobs (admin section) below. I have retried the failed task from the admin section and it is completed.

After some time all MYSQL queries disappeared, I am unable to track through CLI. Can you suggest how to identify the deadlocked query?

PDOException: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction in /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php:570
Stack trace:
#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(570): PDOStatement->execute()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(753): Illuminate\Database\Connection->Illuminate\Database\{closure}()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(720): Illuminate\Database\Connection->runQueryCallback()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(577): Illuminate\Database\Connection->run()
#4 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(522): Illuminate\Database\Connection->affectingStatement()
#5 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(3552): Illuminate\Database\Connection->delete()
#6 /ojs/lib/pkp/classes/statistics/PKPTemporaryTotalsDAO.php(184): Illuminate\Database\Query\Builder->delete()
#7 /ojs/jobs/statistics/CompileUsageStatsFromTemporaryRecords.php(110): PKP\statistics\PKPTemporaryTotalsDAO->deleteCounterSubmissionDailyByLoadId()
#8 /ojs/jobs/statistics/CompileUsageStatsFromTemporaryRecords.php(55): APP\jobs\statistics\CompileUsageStatsFromTemporaryRecords->compileMetrics()
#9 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): APP\jobs\statistics\CompileUsageStatsFromTemporaryRecords->handle()
#10 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Util.php(41): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#11 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#12 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#13 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Container.php(661): Illuminate\Container\BoundMethod::call()
#14 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(128): Illuminate\Container\Container->call()
#15 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}()
#16 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#17 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(132): Illuminate\Pipeline\Pipeline->then()
#18 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(124): Illuminate\Bus\Dispatcher->dispatchNow()
#19 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Queue\CallQueuedHandler->Illuminate\Queue\{closure}()
#20 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#21 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(126): Illuminate\Pipeline\Pipeline->then()
#22 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(70): Illuminate\Queue\CallQueuedHandler->dispatchThroughMiddleware()
#23 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(98): Illuminate\Queue\CallQueuedHandler->call()
#24 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(425): Illuminate\Queue\Jobs\Job->fire()
#25 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#26 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#27 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(104): Illuminate\Queue\Worker->runNextJob()
#28 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#29 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(128): PKP\queue\JobRunner->processJobs()
#30 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#31 {main}

Next Illuminate\Database\QueryException: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction (SQL: delete from `metrics_counter_submission_daily` where `load_id` = usage_events_20240212.log or `date` = DATE(20240212)) in /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php:760
Stack trace:
#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(720): Illuminate\Database\Connection->runQueryCallback()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(577): Illuminate\Database\Connection->run()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(522): Illuminate\Database\Connection->affectingStatement()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(3552): Illuminate\Database\Connection->delete()
#4 /ojs/lib/pkp/classes/statistics/PKPTemporaryTotalsDAO.php(184): Illuminate\Database\Query\Builder->delete()
#5 /ojs/jobs/statistics/CompileUsageStatsFromTemporaryRecords.php(110): PKP\statistics\PKPTemporaryTotalsDAO->deleteCounterSubmissionDailyByLoadId()
#6 /ojs/jobs/statistics/CompileUsageStatsFromTemporaryRecords.php(55): APP\jobs\statistics\CompileUsageStatsFromTemporaryRecords->compileMetrics()
#7 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): APP\jobs\statistics\CompileUsageStatsFromTemporaryRecords->handle()
#8 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Util.php(41): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#9 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#10 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#11 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Container.php(661): Illuminate\Container\BoundMethod::call()
#12 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(128): Illuminate\Container\Container->call()
#13 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}()
#14 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#15 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(132): Illuminate\Pipeline\Pipeline->then()
#16 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(124): Illuminate\Bus\Dispatcher->dispatchNow()
#17 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Queue\CallQueuedHandler->Illuminate\Queue\{closure}()
#18 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#19 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(126): Illuminate\Pipeline\Pipeline->then()
#20 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(70): Illuminate\Queue\CallQueuedHandler->dispatchThroughMiddleware()
#21 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(98): Illuminate\Queue\CallQueuedHandler->call()
#22 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(425): Illuminate\Queue\Jobs\Job->fire()
#23 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#24 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#25 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(104): Illuminate\Queue\Worker->runNextJob()
#26 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#27 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(128): PKP\queue\JobRunner->processJobs()
#28 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#29 {main}

#0 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(720): Illuminate\Database\Connection->runQueryCallback()
#1 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(577): Illuminate\Database\Connection->run()
#2 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php(522): Illuminate\Database\Connection->affectingStatement()
#3 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(3552): Illuminate\Database\Connection->delete()
#4 /ojs/lib/pkp/classes/statistics/PKPTemporaryTotalsDAO.php(184): Illuminate\Database\Query\Builder->delete()
#5 /ojs/jobs/statistics/CompileUsageStatsFromTemporaryRecords.php(110): PKP\statistics\PKPTemporaryTotalsDAO->deleteCounterSubmissionDailyByLoadId()
#6 /ojs/jobs/statistics/CompileUsageStatsFromTemporaryRecords.php(55): APP\jobs\statistics\CompileUsageStatsFromTemporaryRecords->compileMetrics()
#7 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): APP\jobs\statistics\CompileUsageStatsFromTemporaryRecords->handle()
#8 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Util.php(41): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#9 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#10 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#11 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Container/Container.php(661): Illuminate\Container\BoundMethod::call()
#12 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(128): Illuminate\Container\Container->call()
#13 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}()
#14 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#15 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(132): Illuminate\Pipeline\Pipeline->then()
#16 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(124): Illuminate\Bus\Dispatcher->dispatchNow()
#17 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(141): Illuminate\Queue\CallQueuedHandler->Illuminate\Queue\{closure}()
#18 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(116): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#19 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(126): Illuminate\Pipeline\Pipeline->then()
#20 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(70): Illuminate\Queue\CallQueuedHandler->dispatchThroughMiddleware()
#21 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(98): Illuminate\Queue\CallQueuedHandler->call()
#22 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(425): Illuminate\Queue\Jobs\Job->fire()
#23 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(375): Illuminate\Queue\Worker->process()
#24 /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(326): Illuminate\Queue\Worker->runJob()
#25 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(104): Illuminate\Queue\Worker->runNextJob()
#26 /ojs/lib/pkp/classes/queue/JobRunner.php(220): PKP\core\PKPQueueProvider->runJobInQueue()
#27 /ojs/lib/pkp/classes/core/PKPQueueProvider.php(128): PKP\queue\JobRunner->processJobs()
#28 [internal function]: PKP\core\PKPQueueProvider->PKP\core\{closure}()
#29 {main}

Hi @shantanusingh and @jonasraoni,

According to the error log, this delete line is problematic: pkp-lib/classes/statistics/PKPTemporaryTotalsDAO.php at stable-3_4_0 · pkp/pkp-lib · GitHub. Hmmm… :thinking:

Deadlocks can happen, and the fix is to retry. But if this is happening too often or always at the same place, then there’s something to be improved.

@bozana As we’re barely using transactions/locks in the code, the only thing that comes to my mind are two (possibly long) processes trying to access/update the same set of rows at the same time, but no idea why it’s happening, this table seems to be updated just inside the job :thinking:

@shantanusingh you might run SHOW ENGINE INNODB STATUS and send us the output. According to the MySQL manual there should be more information about the last deadlock that happened (e.g. queries that were involved), it should make it easier for us to detect the source of the issue.

Also, is your journal scaled (N servers running OJS with a shared database?) or did you setup the supervisor to run more than 1 worker?

Best,
Jonas Raoni

Hi @jonasraoni @bozana

We are running 1 OMP-3.4 (https://ebook.icar.org.in) and 2 OJS-3.4 (https://epatrika.icar.org.in small website and https://epubs.icar.org.in is main website) applications on one server.

I’ve tried running the 20240213 log file manually but it’s stuck in the processing folder and won’t complete. After that I checked SHOW ENGINE INNODB STATUS\G; But it is only showing the deadlocked query 2024-02-13 19:45:09.

After running the SHOW ENGINE INNODB STATUS\G; some of the deadlock MySQL query found.

mysql> SHOW ENGINE INNODB STATUS\G;
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2024-02-14 11:28:18 139799579436800 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 42 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 84546 srv_active, 0 srv_shutdown, 9536 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1216822
OS WAIT ARRAY INFO: signal count 5012520
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2024-02-13 19:45:09 139798652098304
*** (1) TRANSACTION:
TRANSACTION 228444376, ACTIVE 0 sec inserting
mysql tables in use 2, locked 2
LOCK WAIT 18 lock struct(s), heap size 1128, 464 row lock(s), undo log entries 2
MySQL thread id 105598, OS thread handle 139791671899904, query id 172605935 localhost epubs executing
INSERT INTO metrics_counter_submission_daily (load_id, context_id, submission_id, date, metric_investigations, metric_investigations_unique, metric_requests, metric_requests_unique)
            SELECT * FROM (SELECT load_id, context_id, submission_id, DATE(date) as date, count(*) as metric, 0 as metric_investigations_unique, 0 as metric_requests, 0 as metric_requests_unique
                FROM usage_stats_total_temporary_records
                WHERE load_id = 'usage_events_20240212.log' AND submission_id IS NOT NULL
                GROUP BY load_id, context_id, submission_id, DATE(date)) AS t

                ON DUPLICATE KEY UPDATE metric_investigations = metric

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 2236 page no 112 n bits 392 index msd_context_id_submission_id of table `ojs_hindi`.`metrics_counter_submission_daily` trx id 228444376 lock_mode X locks rec but not gap
Record lock, heap no 319 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 8000000000000002; asc         ;;
 1: len 8; hex 800000000000007c; asc        |;;
 2: len 8; hex 0000000000002045; asc        E;;


*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2236 page no 19 n bits 624 index msd_context_id_submission_id of table `ojs_hindi`.`metrics_counter_submission_daily` trx id 228444376 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 170 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 8000000000000002; asc         ;;
 1: len 8; hex 800000000000000b; asc         ;;
 2: len 8; hex 000000000000068f; asc         ;;


*** (2) TRANSACTION:
TRANSACTION 228444375, ACTIVE 0 sec fetching rows
mysql tables in use 2, locked 2
LOCK WAIT 41 lock struct(s), heap size 8312, 1004 row lock(s), undo log entries 23
MySQL thread id 105600, OS thread handle 139799578380032, query id 172605687 localhost epubs executing
insert into `metrics_counter_submission_monthly` (`context_id`, `submission_id`, `month`, `metric_investigations`, `metric_investigations_unique`, `metric_requests`, `metric_requests_unique`) select csd.context_id, csd.submission_id, CAST(DATE_FORMAT(csd.date, '%Y%m') AS UNSIGNED) as csdmonth, SUM(csd.metric_investigations), SUM(csd.metric_investigations_unique), SUM(csd.metric_requests), SUM(csd.metric_requests_unique) from `metrics_counter_submission_daily` as `csd` where CAST(DATE_FORMAT(csd.date, '%Y%m') AS UNSIGNED) = '202402' group by csd.context_id, csd.submission_id, csdmonth

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 2236 page no 19 n bits 624 index msd_context_id_submission_id of table `ojs_hindi`.`metrics_counter_submission_daily` trx id 228444375 lock mode S
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 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 8000000000000002; asc         ;;
 1: len 8; hex 8000000000000008; asc         ;;
 2: len 8; hex 000000000000000c; asc         ;;
.
.
.
.
Record lock, heap no 540 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 8000000000000002; asc         ;;
 1: len 8; hex 8000000000000017; asc         ;;
 2: len 8; hex 00000000000013c8; asc         ;;


*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2236 page no 112 n bits 392 index msd_context_id_submission_id of table `ojs_hindi`.`metrics_counter_submission_daily` trx id 228444375 lock mode S waiting
Record lock, heap no 319 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 8000000000000002; asc         ;;
 1: len 8; hex 800000000000007c; asc        |;;
 2: len 8; hex 0000000000002045; asc        E;;

*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 228714523
Purge done for trx's n:o < 228714519 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421275375804416, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421275375803608, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421275375802800, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421275375801992, 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: complete io for buf page (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: 66
2344075 OS file reads, 3491691 OS file writes, 1680191 OS fsyncs
4.60 reads/s, 16384 avg bytes/read, 95.99 writes/s, 31.97 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 3, free list len 22056, seg size 22060, 25143 merges
merged operations:
 insert 74246, delete mark 220699, delete 41660
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 1328213, node heap has 8368 buffer(s)
Hash table size 1328213, node heap has 535 buffer(s)
Hash table size 1328213, node heap has 1085 buffer(s)
Hash table size 1328213, node heap has 31463 buffer(s)
Hash table size 1328213, node heap has 3228 buffer(s)
Hash table size 1328213, node heap has 1034 buffer(s)
Hash table size 1328213, node heap has 2573 buffer(s)
Hash table size 1328213, node heap has 1193 buffer(s)
51193.09 hash searches/s, 8234.80 non-hash searches/s
---
LOG
---
Log sequence number          342758059817
Log buffer assigned up to    342758059817
Log buffer completed up to   342758059817
Log written up to            342758059817
Log flushed up to            342758059152
Added dirty pages up to      342758059817
Pages flushed up to          342755188885
Last checkpoint at           342755188885
1600086 log i/o's done, 37.58 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 4213490
Buffer pool size   327652
Free buffers       8190
Database pages     269983
Old database pages 99497
Modified db pages  840
Pending reads      0
Pending writes: LRU 0, flush list 6, single page 0
Pages made young 2185139, not young 263086187
51.82 youngs/s, 303.86 non-youngs/s
Pages read 2343201, created 7966, written 1171273
4.60 reads/s, 0.02 creates/s, 44.66 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 1 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 269983, unzip_LRU len: 0
I/O sum[19040]:cur[416], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   40955
Free buffers       1021
Database pages     33751
Old database pages 12438
Modified db pages  89
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 286919, not young 33058654
7.02 youngs/s, 49.75 non-youngs/s
Pages read 292924, created 896, written 170449
0.68 reads/s, 0.00 creates/s, 6.53 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 2 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 33751, unzip_LRU len: 0
I/O sum[2380]:cur[52], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   40957
Free buffers       1024
Database pages     33764
Old database pages 12443
Modified db pages  28
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 257183, not young 32368240
3.99 youngs/s, 21.26 non-youngs/s
Pages read 286700, created 1058, written 127135
0.68 reads/s, 0.02 creates/s, 6.60 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 1 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 33764, unzip_LRU len: 0
I/O sum[2380]:cur[52], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   40956
Free buffers       1024
Database pages     33745
Old database pages 12436
Modified db pages  96
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 263850, not young 30477894
2.23 youngs/s, 33.83 non-youngs/s
Pages read 286452, created 960, written 165394
0.45 reads/s, 0.00 creates/s, 6.48 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 1 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 33745, unzip_LRU len: 0
I/O sum[2380]:cur[52], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   40957
Free buffers       1025
Database pages     33733
Old database pages 12432
Modified db pages  32
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 274666, not young 32876917
2.77 youngs/s, 20.04 non-youngs/s
Pages read 294618, created 962, written 125202
0.47 reads/s, 0.00 creates/s, 6.13 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 1 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 33733, unzip_LRU len: 0
I/O sum[2380]:cur[52], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   40958
Free buffers       1025
Database pages     33736
Old database pages 12433
Modified db pages  23
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 231297, not young 33203431
2.75 youngs/s, 20.11 non-youngs/s
Pages read 291880, created 997, written 124842
0.49 reads/s, 0.00 creates/s, 5.61 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 1 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 33736, unzip_LRU len: 0
I/O sum[2380]:cur[52], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   40957
Free buffers       1024
Database pages     33734
Old database pages 12432
Modified db pages  82
Pending reads      0
Pending writes: LRU 0, flush list 6, single page 0
Pages made young 284152, not young 34037183
5.05 youngs/s, 88.49 non-youngs/s
Pages read 298993, created 1273, written 135248
0.66 reads/s, 0.00 creates/s, 4.98 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 3 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 33734, unzip_LRU len: 0
I/O sum[2380]:cur[52], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   40957
Free buffers       1024
Database pages     33781
Old database pages 12449
Modified db pages  266
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 300232, not young 32882331
4.70 youngs/s, 30.09 non-youngs/s
Pages read 297156, created 999, written 161894
0.42 reads/s, 0.00 creates/s, 4.37 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: 33781, unzip_LRU len: 0
I/O sum[2380]:cur[52], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   40955
Free buffers       1023
Database pages     33739
Old database pages 12434
Modified db pages  224
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 286840, not young 34181537
23.30 youngs/s, 40.29 non-youngs/s
Pages read 294478, created 821, written 161109
0.75 reads/s, 0.00 creates/s, 3.95 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 1 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 33739, unzip_LRU len: 0
I/O sum[2380]:cur[52], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=22020, Main thread ID=139791756936960 , state=sleeping
Number of rows inserted 376500, updated 78032, deleted 335785, read 22152340335
2.29 inserts/s, 1.21 updates/s, 33.17 deletes/s, 166003.69 reads/s
Number of system rows inserted 0, updated 317, deleted 0, read 130551
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.00 sec)

ERROR:
No query specified

mysql>
{
    "uuid": "77de35ce-1d8d-49f7-ab1c-cd2902426cf8",
    "displayName": "APP\\jobs\\statistics\\CompileUsageStatsFromTemporaryRecords",
    "job": "Illuminate\\Queue\\CallQueuedHandler@call",
    "maxTries": 1,
    "maxExceptions": 3,
    "failOnTimeout": true,
    "backoff": "5",
    "timeout": 60,
    "retryUntil": null,
    "data": {
        "commandName": "APP\\jobs\\statistics\\CompileUsageStatsFromTemporaryRecords",
        "command": "O:57:\"APP\\jobs\\statistics\\CompileUsageStatsFromTemporaryRecords\":3:{s:9:\"\u0000*\u0000loadId\";s:25:\"usage_events_20240212.log\";s:10:\"connection\";s:8:\"database\";s:5:\"queue\";s:5:\"queue\";}"
    }
}


{
    "message": "SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction (SQL: \n            INSERT INTO metrics_counter_submission_daily (load_id, context_id, submission_id, date, metric_investigations, metric_investigations_unique, metric_requests, metric_requests_unique)\n            SELECT * FROM (SELECT load_id, context_id, submission_id, DATE(date) as date, count(*) as metric, 0 as metric_investigations_unique, 0 as metric_requests, 0 as metric_requests_unique\n                FROM usage_stats_total_temporary_records\n                WHERE load_id = usage_events_20240212.log AND submission_id IS NOT NULL\n                GROUP BY load_id, context_id, submission_id, DATE(date)) AS t\n            \n                ON DUPLICATE KEY UPDATE metric_investigations = metric;\n            )",
    "code": "40001",
    "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Database\/Connection.php",
    "line": 760,
    "trace": [
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Database\/Connection.php",
            "line": 720,
            "function": "runQueryCallback",
            "class": "Illuminate\\Database\\Connection",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Database\/Connection.php",
            "line": 546,
            "function": "run",
            "class": "Illuminate\\Database\\Connection",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Database\/DatabaseManager.php",
            "line": 469,
            "function": "statement",
            "class": "Illuminate\\Database\\Connection",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Support\/Facades\/Facade.php",
            "line": 338,
            "function": "__call",
            "class": "Illuminate\\Database\\DatabaseManager",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/classes\/statistics\/PKPTemporaryTotalsDAO.php",
            "line": 241,
            "function": "__callStatic",
            "class": "Illuminate\\Support\\Facades\\Facade",
            "type": "::"
        },
        {
            "file": "\/ojshindi\/jobs\/statistics\/CompileUsageStatsFromTemporaryRecords.php",
            "line": 111,
            "function": "compileCounterSubmissionDailyMetrics",
            "class": "PKP\\statistics\\PKPTemporaryTotalsDAO",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/jobs\/statistics\/CompileUsageStatsFromTemporaryRecords.php",
            "line": 55,
            "function": "compileMetrics",
            "class": "APP\\jobs\\statistics\\CompileUsageStatsFromTemporaryRecords",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Container\/BoundMethod.php",
            "line": 36,
            "function": "handle",
            "class": "APP\\jobs\\statistics\\CompileUsageStatsFromTemporaryRecords",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Container\/Util.php",
            "line": 41,
            "function": "Illuminate\\Container\\{closure}",
            "class": "Illuminate\\Container\\BoundMethod",
            "type": "::"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Container\/BoundMethod.php",
            "line": 93,
            "function": "unwrapIfClosure",
            "class": "Illuminate\\Container\\Util",
            "type": "::"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Container\/BoundMethod.php",
            "line": 37,
            "function": "callBoundMethod",
            "class": "Illuminate\\Container\\BoundMethod",
            "type": "::"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Container\/Container.php",
            "line": 661,
            "function": "call",
            "class": "Illuminate\\Container\\BoundMethod",
            "type": "::"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Bus\/Dispatcher.php",
            "line": 128,
            "function": "call",
            "class": "Illuminate\\Container\\Container",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Pipeline\/Pipeline.php",
            "line": 141,
            "function": "Illuminate\\Bus\\{closure}",
            "class": "Illuminate\\Bus\\Dispatcher",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Pipeline\/Pipeline.php",
            "line": 116,
            "function": "Illuminate\\Pipeline\\{closure}",
            "class": "Illuminate\\Pipeline\\Pipeline",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Bus\/Dispatcher.php",
            "line": 132,
            "function": "then",
            "class": "Illuminate\\Pipeline\\Pipeline",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/CallQueuedHandler.php",
            "line": 124,
            "function": "dispatchNow",
            "class": "Illuminate\\Bus\\Dispatcher",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Pipeline\/Pipeline.php",
            "line": 141,
            "function": "Illuminate\\Queue\\{closure}",
            "class": "Illuminate\\Queue\\CallQueuedHandler",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Pipeline\/Pipeline.php",
            "line": 116,
            "function": "Illuminate\\Pipeline\\{closure}",
            "class": "Illuminate\\Pipeline\\Pipeline",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/CallQueuedHandler.php",
            "line": 126,
            "function": "then",
            "class": "Illuminate\\Pipeline\\Pipeline",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/CallQueuedHandler.php",
            "line": 70,
            "function": "dispatchThroughMiddleware",
            "class": "Illuminate\\Queue\\CallQueuedHandler",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/Jobs\/Job.php",
            "line": 98,
            "function": "call",
            "class": "Illuminate\\Queue\\CallQueuedHandler",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/Worker.php",
            "line": 425,
            "function": "fire",
            "class": "Illuminate\\Queue\\Jobs\\Job",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/Worker.php",
            "line": 375,
            "function": "process",
            "class": "Illuminate\\Queue\\Worker",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/Worker.php",
            "line": 326,
            "function": "runJob",
            "class": "Illuminate\\Queue\\Worker",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/classes\/core\/PKPQueueProvider.php",
            "line": 104,
            "function": "runNextJob",
            "class": "Illuminate\\Queue\\Worker",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/classes\/queue\/JobRunner.php",
            "line": 220,
            "function": "runJobInQueue",
            "class": "PKP\\core\\PKPQueueProvider",
            "type": "->"
        },
        {
            "file": "\/ojshindi\/lib\/pkp\/classes\/core\/PKPQueueProvider.php",
            "line": 128,
            "function": "processJobs",
            "class": "PKP\\queue\\JobRunner",
            "type": "->"
        },
        {
            "function": "PKP\\core\\{closure}",
            "class": "PKP\\core\\PKPQueueProvider",
            "type": "->"
        }
    ]
}

Hi, @jonasraoni I checked the failed jobs today and found some deadlock issues in the admin section. same like [OJS-3.4.0-4] Statistic problem - #65 by shantanusingh.

Next Illuminate\Database\QueryException: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction (SQL: delete from metrics_counter_submission_daily where load_id = usage_events_20240213.log or date = DATE(20240213)) in /ojs/lib/pkp/lib/vendor/laravel/framework/src/Illuminate/Database/Connection.php:760

I ran SHOW ENGINE INNODB STATUS\G; today.

mysql> SHOW ENGINE INNODB STATUS\G;
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2024-02-15 09:10:31 139799044835072 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 42 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 153497 srv_active, 0 srv_shutdown, 18685 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2017244
OS WAIT ARRAY INFO: signal count 9146754
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------------------
LATEST FOREIGN KEY ERROR
------------------------
2024-02-14 16:12:56 139799043778304 Transaction:
TRANSACTION 228836194, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
5 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 1
MySQL thread id 272351, OS thread handle 139799043778304, query id 305132693 localhost epubs update
insert into `submission_search_object_keywords` (`keyword_id`, `object_id`, `pos`) values (19721, 918768, 0), (23229, 918768, 1), (21630, 918768, 2), (19167, 918768, 3), (35450, 918768, 4), (20285, 918768, 5), (19682, 918768, 6)
Foreign key constraint fails for table `ojs4`.`submission_search_object_keywords`:
,
  CONSTRAINT `submission_search_object_keywords_object_id_foreign` FOREIGN KEY (`object_id`) REFERENCES `submission_search_objects` (`object_id`) ON DELETE CASCADE
Trying to add in child table, in index submission_search_object_keywords_unique tuple:
DATA TUPLE: 3 fields;
 0: len 8; hex 80000000000e04f0; asc         ;;
 1: len 4; hex 80000000; asc     ;;
 2: len 8; hex 0000000002a75b1c; asc       [ ;;

But in parent table `ojs4`.`submission_search_objects`, in index PRIMARY,
the closest match we can find is record:
PHYSICAL RECORD: n_fields 6; compact format; info bits 32
 0: len 8; hex 80000000000e04f1; asc         ;;
 1: len 6; hex 00000da3c360; asc      `;;
 2: len 7; hex 01000001342b51; asc     4+Q;;
 3: len 8; hex 8000000000024413; asc       D ;;
 4: len 4; hex 80000004; asc     ;;
 5: SQL NULL;

------------------------
LATEST DETECTED DEADLOCK
------------------------
2024-02-14 17:12:45 139798652098304
*** (1) TRANSACTION:
TRANSACTION 228884828, ACTIVE 1 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 3 row lock(s)
MySQL thread id 282259, OS thread handle 139791587858176, query id 311114910 localhost epubs updating
delete from `metrics_counter_submission_daily` where `load_id` = 'usage_events_20240213.log' or `date` = DATE(20240213)

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 3126 page no 10 n bits 248 index PRIMARY of table `ojs4`.`metrics_counter_submission_daily` trx id 228884828 lock_mode X
Record lock, heap no 2 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000001; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e42eca; asc      . ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000002; asc         ;;
 5: len 8; hex 8000000000018fad; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000004; asc     ;;
 8: len 4; hex 80000004; asc     ;;
 9: len 4; hex 80000004; asc     ;;
 10: len 4; hex 80000004; asc     ;;

Record lock, heap no 3 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000002; asc         ;;
 1: len 6; hex 00000ba59d11; asc       ;;
 2: len 7; hex 01000004442e7d; asc     D.};;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000029; asc        );;
 5: len 8; hex 8000000000019b7d; asc        };;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000001; asc     ;;
 8: len 4; hex 80000001; asc     ;;
 9: len 4; hex 80000000; asc     ;;
 10: len 4; hex 80000000; asc     ;;


*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3126 page no 10 n bits 248 index PRIMARY of table `ojs4`.`metrics_counter_submission_daily` trx id 228884828 lock_mode X waiting
Record lock, heap no 4 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000003; asc         ;;
 1: len 6; hex 00000ba59d11; asc       ;;
 2: len 7; hex 01000004442ea4; asc     D. ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 800000000000decb; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000001; asc     ;;
 8: len 4; hex 80000001; asc     ;;
 9: len 4; hex 80000000; asc     ;;
 10: len 4; hex 80000000; asc     ;;


*** (2) TRANSACTION:
TRANSACTION 228884803, ACTIVE 4 sec fetching rows
mysql tables in use 2, locked 2
LOCK WAIT 1082 lock struct(s), heap size 139384, 105777 row lock(s), undo log entries 6686
MySQL thread id 282260, OS thread handle 139791668729600, query id 311111664 localhost epubs executing
insert into `metrics_counter_submission_monthly` (`context_id`, `submission_id`, `month`, `metric_investigations`, `metric_investigations_unique`, `metric_requests`, `metric_requests_unique`) select csd.context_id, csd.submission_id, CAST(DATE_FORMAT(csd.date, '%Y%m') AS UNSIGNED) as csdmonth, SUM(csd.metric_investigations), SUM(csd.metric_investigations_unique), SUM(csd.metric_requests), SUM(csd.metric_requests_unique) from `metrics_counter_submission_daily` as `csd` where CAST(DATE_FORMAT(csd.date, '%Y%m') AS UNSIGNED) = '202402' group by csd.context_id, csd.submission_id, csdmonth

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 3126 page no 10 n bits 248 index PRIMARY of table `ojs4`.`metrics_counter_submission_daily` trx id 228884803 lock mode S locks rec but not gap
Record lock, heap no 4 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000003; asc         ;;
 1: len 6; hex 00000ba59d11; asc       ;;
 2: len 7; hex 01000004442ea4; asc     D. ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 800000000000decb; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000001; asc     ;;
 8: len 4; hex 80000001; asc     ;;
 9: len 4; hex 80000000; asc     ;;
 10: len 4; hex 80000000; asc     ;;

Record lock, heap no 12 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 000000000000000b; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e42f62; asc      /b;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 800000000001a57e; asc        ~;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000001; asc     ;;
 8: len 4; hex 80000001; asc     ;;
 9: len 4; hex 80000001; asc     ;;
 10: len 4; hex 80000001; asc     ;;

Record lock, heap no 14 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 000000000000000d; asc         ;;
 1: len 6; hex 00000ba59d11; asc       ;;
 2: len 7; hex 01000004443025; asc     D0%;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 80000000000136d1; asc       6 ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000001; asc     ;;
 8: len 4; hex 80000001; asc     ;;
 9: len 4; hex 80000000; asc     ;;
 10: len 4; hex 80000000; asc     ;;

Record lock, heap no 18 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000011; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e43046; asc      0F;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 80000000000226c3; asc       & ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 8000001c; asc     ;;
 8: len 4; hex 80000014; asc     ;;
 9: len 4; hex 80000008; asc     ;;
 10: len 4; hex 80000007; asc     ;;

Record lock, heap no 24 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000017; asc         ;;
 1: len 6; hex 00000ba59d11; asc       ;;
 2: len 7; hex 010000044431a7; asc     D1 ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000002; asc         ;;
 5: len 8; hex 8000000000010cfc; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000001; asc     ;;
 8: len 4; hex 80000001; asc     ;;
 9: len 4; hex 80000000; asc     ;;
 10: len 4; hex 80000000; asc     ;;

Record lock, heap no 26 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000019; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e42ffa; asc      / ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000002; asc         ;;
 5: len 8; hex 8000000000009203; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000001; asc     ;;
 8: len 4; hex 80000001; asc     ;;
 9: len 4; hex 80000001; asc     ;;
 10: len 4; hex 80000001; asc     ;;

Record lock, heap no 28 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 000000000000001b; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e4306c; asc      0l;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 800000000001b342; asc        B;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 8000000c; asc     ;;
 8: len 4; hex 80000009; asc     ;;
 9: len 4; hex 80000009; asc     ;;
 10: len 4; hex 80000009; asc     ;;

Record lock, heap no 29 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 000000000000001c; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e43092; asc      0 ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 80000000000225b7; asc       % ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000004; asc     ;;
 8: len 4; hex 80000003; asc     ;;
 9: len 4; hex 80000003; asc     ;;
 10: len 4; hex 80000002; asc     ;;

Record lock, heap no 30 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 000000000000001d; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e430b8; asc      0 ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 80000000000223d5; asc       # ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000005; asc     ;;
 8: len 4; hex 80000003; asc     ;;
 9: len 4; hex 80000004; asc     ;;
 10: len 4; hex 80000003; asc     ;;

Record lock, heap no 31 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 000000000000001e; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e430de; asc      0 ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 80000000000224c4; asc       $ ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000004; asc     ;;
 8: len 4; hex 80000004; asc     ;;
 9: len 4; hex 80000003; asc     ;;
 10: len 4; hex 80000003; asc     ;;

Record lock, heap no 32 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 000000000000001f; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e43104; asc      1 ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 8000000000022a91; asc       * ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000004; asc     ;;
 8: len 4; hex 80000004; asc     ;;
 9: len 4; hex 80000003; asc     ;;
 10: len 4; hex 80000003; asc     ;;

Record lock, heap no 33 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000020; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e4312a; asc      1*;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 8000000000022853; asc       (S;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000002; asc     ;;
 8: len 4; hex 80000002; asc     ;;
 9: len 4; hex 80000002; asc     ;;
 10: len 4; hex 80000002; asc     ;;

Record lock, heap no 34 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000021; asc        !;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e43150; asc      1P;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 800000000001e4c7; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000004; asc     ;;
 8: len 4; hex 80000003; asc     ;;
 9: len 4; hex 80000003; asc     ;;
 10: len 4; hex 80000003; asc     ;;

Record lock, heap no 36 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000023; asc        #;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e4319c; asc      1 ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 80000000000224cc; asc       $ ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000003; asc     ;;
 8: len 4; hex 80000003; asc     ;;
 9: len 4; hex 80000003; asc     ;;
 10: len 4; hex 80000003; asc     ;;

Record lock, heap no 37 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000024; asc        $;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e431c2; asc      1 ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 800000000002274c; asc       'L;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000003; asc     ;;
 8: len 4; hex 80000003; asc     ;;
 9: len 4; hex 80000002; asc     ;;
 10: len 4; hex 80000002; asc     ;;

Record lock, heap no 40 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000027; asc        ';;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e43234; asc      24;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 80000000000208bf; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000002; asc     ;;
 8: len 4; hex 80000002; asc     ;;
 9: len 4; hex 80000002; asc     ;;
 10: len 4; hex 80000002; asc     ;;

Record lock, heap no 41 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000028; asc        (;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e4325a; asc      2Z;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 8000000000020392; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000003; asc     ;;
 8: len 4; hex 80000003; asc     ;;
 9: len 4; hex 80000003; asc     ;;
 10: len 4; hex 80000003; asc     ;;

Record lock, heap no 44 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 000000000000002b; asc        +;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e432cc; asc      2 ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 8000000000021db9; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000002; asc     ;;
 8: len 4; hex 80000002; asc     ;;
 9: len 4; hex 80000002; asc     ;;
 10: len 4; hex 80000002; asc     ;;

Record lock, heap no 47 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 000000000000002e; asc        .;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e4333e; asc      3>;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 800000000002275a; asc       'Z;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000007; asc     ;;
 8: len 4; hex 80000006; asc     ;;
 9: len 4; hex 80000004; asc     ;;
 10: len 4; hex 80000004; asc     ;;

Record lock, heap no 50 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000031; asc        1;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e433b0; asc      3 ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 8000000000022331; asc       #1;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000001; asc     ;;
 8: len 4; hex 80000001; asc     ;;
 9: len 4; hex 80000001; asc     ;;
 10: len 4; hex 80000001; asc     ;;

Record lock, heap no 62 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 000000000000003d; asc        =;;
 1: len 6; hex 00000ba59d11; asc       ;;
 2: len 7; hex 01000004443727; asc     D7';;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 8000000000013565; asc       5e;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000001; asc     ;;
 8: len 4; hex 80000001; asc     ;;
 9: len 4; hex 80000000; asc     ;;
 10: len 4; hex 80000000; asc     ;;

Record lock, heap no 71 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000046; asc        F;;
 1: len 6; hex 00000ba59d11; asc       ;;
 2: len 7; hex 0100000444387e; asc     D8~;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 80000000000197a2; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000001; asc     ;;
 8: len 4; hex 80000001; asc     ;;
 9: len 4; hex 80000000; asc     ;;
 10: len 4; hex 80000000; asc     ;;

Record lock, heap no 72 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000047; asc        G;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e4365c; asc      6\;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000001; asc         ;;
 5: len 8; hex 800000000002064b; asc        K;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000003; asc     ;;
 8: len 4; hex 80000002; asc     ;;
 9: len 4; hex 80000002; asc     ;;
 10: len 4; hex 80000002; asc     ;;


*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3126 page no 10 n bits 248 index PRIMARY of table `ojs4`.`metrics_counter_submission_daily` trx id 228884803 lock mode S locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 11; compact format; info bits 0
 0: len 8; hex 0000000000000001; asc         ;;
 1: len 6; hex 00000ba59d16; asc       ;;
 2: len 7; hex 02000000e42eca; asc      . ;;
 3: len 25; hex 75736167655f6576656e74735f32303233313230322e6c6f67; asc usage_events_20231202.log;;
 4: len 8; hex 8000000000000002; asc         ;;
 5: len 8; hex 8000000000018fad; asc         ;;
 6: len 3; hex 8fcf82; asc    ;;
 7: len 4; hex 80000004; asc     ;;
 8: len 4; hex 80000004; asc     ;;
 9: len 4; hex 80000004; asc     ;;
 10: len 4; hex 80000004; asc     ;;

*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 229115257
Purge done for trx's n:o < 229115219 undo n:o < 0 state: running but idle
History list length 18
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421275375806840, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421275375806032, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421275375805224, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421275375804416, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421275375802800, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421275375801992, 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: 150
4215147 OS file reads, 6126992 OS file writes, 2967347 OS fsyncs
51.90 reads/s, 16384 avg bytes/read, 618.54 writes/s, 55.73 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 3, free list len 22056, seg size 22060, 50793 merges
merged operations:
 insert 138942, delete mark 492250, delete 128428
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 1328213, node heap has 8389 buffer(s)
Hash table size 1328213, node heap has 512 buffer(s)
Hash table size 1328213, node heap has 1073 buffer(s)
Hash table size 1328213, node heap has 29274 buffer(s)
Hash table size 1328213, node heap has 3429 buffer(s)
Hash table size 1328213, node heap has 906 buffer(s)
Hash table size 1328213, node heap has 2168 buffer(s)
Hash table size 1328213, node heap has 926 buffer(s)
133473.82 hash searches/s, 15006.43 non-hash searches/s
---
LOG
---
Log sequence number          343146038884
Log buffer assigned up to    343146038884
Log buffer completed up to   343146038884
Log written up to            343146038884
Log flushed up to            343146038884
Added dirty pages up to      343146038884
Pages flushed up to          343102027474
Last checkpoint at           343102017886
2815006 log i/o's done, 496.67 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 4213490
Buffer pool size   327652
Free buffers       8225
Database pages     272750
Old database pages 100520
Modified db pages  9925
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 3684016, not young 394933226
36.40 youngs/s, 5636.99 non-youngs/s
Pages read 4214276, created 13768, written 2030714
51.89 reads/s, 4.21 creates/s, 92.90 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 13 / 1000
Pages read ahead 3.97/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 272750, unzip_LRU len: 0
I/O sum[54368]:cur[320], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   40955
Free buffers       1024
Database pages     34124
Old database pages 12576
Modified db pages  1000
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 475327, not young 50046932
1.66 youngs/s, 440.23 non-youngs/s
Pages read 527067, created 1364, written 302173
6.94 reads/s, 0.56 creates/s, 11.61 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 8 / 1000
Pages read ahead 0.56/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 34124, unzip_LRU len: 0
I/O sum[6796]:cur[40], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   40957
Free buffers       1033
Database pages     34116
Old database pages 12573
Modified db pages  1297
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 441893, not young 48453673
6.33 youngs/s, 30.68 non-youngs/s
Pages read 516375, created 1927, written 217241
4.14 reads/s, 0.23 creates/s, 11.61 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: 34116, unzip_LRU len: 0
I/O sum[6796]:cur[40], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   40956
Free buffers       1040
Database pages     34061
Old database pages 12553
Modified db pages  1411
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 446395, not young 46082486
4.84 youngs/s, 111.22 non-youngs/s
Pages read 516026, created 1805, written 288239
4.49 reads/s, 0.00 creates/s, 11.61 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 2 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 34061, unzip_LRU len: 0
I/O sum[6796]:cur[40], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   40957
Free buffers       1024
Database pages     34086
Old database pages 12562
Modified db pages  1420
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 460357, not young 49518918
4.81 youngs/s, 900.98 non-youngs/s
Pages read 530648, created 1808, written 217480
6.10 reads/s, 0.86 creates/s, 11.61 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 17 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 34086, unzip_LRU len: 0
I/O sum[6796]:cur[40], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   40958
Free buffers       1025
Database pages     34115
Old database pages 12573
Modified db pages  1357
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 406126, not young 49082962
7.03 youngs/s, 766.34 non-youngs/s
Pages read 524642, created 1633, written 215017
6.61 reads/s, 0.02 creates/s, 11.61 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 14 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 34115, unzip_LRU len: 0
I/O sum[6796]:cur[40], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   40957
Free buffers       1028
Database pages     34062
Old database pages 12553
Modified db pages  1237
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 475734, not young 51519749
3.48 youngs/s, 1333.29 non-youngs/s
Pages read 536045, created 2156, written 235285
8.43 reads/s, 1.03 creates/s, 11.61 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 26 / 1000
Pages read ahead 0.58/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 34062, unzip_LRU len: 0
I/O sum[6796]:cur[40], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   40957
Free buffers       1025
Database pages     34103
Old database pages 12569
Modified db pages  1319
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 495900, not young 49772154
2.73 youngs/s, 853.80 non-youngs/s
Pages read 536148, created 1654, written 280883
7.24 reads/s, 0.00 creates/s, 11.61 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 11 / 1000
Pages read ahead 1.50/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 34103, unzip_LRU len: 0
I/O sum[6796]:cur[40], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   40955
Free buffers       1026
Database pages     34083
Old database pages 12561
Modified db pages  884
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 482284, not young 50456352
5.51 youngs/s, 1200.45 non-youngs/s
Pages read 527325, created 1421, written 274396
7.94 reads/s, 1.50 creates/s, 11.61 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 23 / 1000
Pages read ahead 1.33/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 34083, unzip_LRU len: 0
I/O sum[6796]:cur[40], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=22020, Main thread ID=139791756936960 , state=sleeping
Number of rows inserted 688266, updated 132233, deleted 596489, read 36820488024
1.93 inserts/s, 58.09 updates/s, 491.63 deletes/s, 313536.92 reads/s
Number of system rows inserted 0, updated 317, deleted 0, read 213105
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.10 sec)

ERROR:
No query specified

mysql>

Thanks for the help! I see there’s information about the 2 transactions that were locking each other, so I’ll let @bozana continue, she has more knowledge about this part of the application, and I’ll be mostly away until next week :slight_smile:

As you’re having an intermittent issue with deadlocks, I think it’s worth to investigate and come up with a solution.

@bozana, I guess these tables are accessed only by the jobs, right? It would be good to understand why these operations are running in parallel, I think jobs can’t be executed in parallel unless you have N+1 workers (I think @shantanusingh didn’t setup more than one).
Anyway, as running N+1 workers should be possible, two things that you can try is:

  • Retry the operation (3x is a good number). One of the deadlocked transactions will die, but the other will work! Then there’s a good change that retrying after some time (perhaps sleeping for some msecs with usleep() will be enough).
  • Decrease the number of rows (the less time a transaction/operation runs, the more difficult is to get a deadlock).

Best,
Jonas Raoni

Hi @shantanusingh and @jonasraoni

To be honest I do not understand what is happening there. Can one of you tell me what two operations are running in parallel? Or are there always different once? – I do not understand that fully that MySQL output.
And yes, these temporary usage stats tables are accessed only by jobs. However the metrics_* statistics tables can be accessed for reading by e.g. statistics report page. The metrics_* statistics tables are filled/written only by jobs.
@shantanusingh still have the OJS version where there are two not chained jobs responsible for stats processing: ojs/jobs/statistics/CompileUsageStatsFromTemporaryRecords.php at 3_4_0-4 · pkp/ojs · GitHub and pkp-lib/jobs/statistics/CompileMonthlyMetrics.php at 3_4_0-4 · pkp/pkp-lib · GitHub. He uses the build-in job runner i.e. each job is processed in a request. And each operation in a job should be run sequentially, s. e.g. the function ojs/jobs/statistics/CompileUsageStatsFromTemporaryRecords.php at 3_4_0-4 · pkp/ojs · GitHub.
So where is this conflict happening and how?

EDIT:
And actually, this delete operation (e.g. delete from metrics_counter_submission_dailywhereload_id= 'usage_events_20240213.log' ordate = DATE(20240213)) should not actually do anything because a new log file is being processed and there are no entries with that day yet. So why is it locking the table for so long? Or what is happening?

Why do I see in that last MySQL output usage_events_20231202.log everywhere? I do not know what does it mean… Is it causing the problems?

@shantanusingh, do you try to re-process usage_events_20231202.log as well?
As I remember usage_events_20231202.log was making another problem (with foreign keys, right?) that you still need to investigate. Please copy it somewhere else till you/we have some time to investigate that step by step.
And it would be best to only have one file to process – so that we know what is happening – that means all the other files from processing/ or stage/ folder should be copied somewhere else, till we figure out what is happening…

p.s. Unfortunately I will also be away from 20.2. till 1.3. and will not be able to help in that time…

Hi @shantanusingh

I’ve just read about deadlocks and what those MySQL outputs mean. It seems the process from the old file usage_events_20231202.log is holding the table locked.
Either it stayed since then? :open_mouth:
Or have you tried to re-process that file again?
And, as I said, please try to process only one file at time, and first when that file finished try with others!!!

Hi @bozana @jonasraoni

I have re-run the usage_events_20231202.log and it is complete. After that I ran use_events_20240215.log but still the task was not completed and log file stuck in the processing folder.

Many log files were not completed but were archived in December 2023. And when I tried to process them again, none of them except 20231202 completed and got stuck in the processing folder.

I will retry to clear December 2023 after 1-2 days may be it work.

{
    "uuid": "1db6dc40-2c0c-4442-8c5e-e5e89f299835",
    "displayName": "PKP\\jobs\\statistics\\CompileMonthlyMetrics",
    "job": "Illuminate\\Queue\\CallQueuedHandler@call",
    "maxTries": 1,
    "maxExceptions": 3,
    "failOnTimeout": true,
    "backoff": "5",
    "timeout": 60,
    "retryUntil": null,
    "data": {
        "commandName": "PKP\\jobs\\statistics\\CompileMonthlyMetrics",
        "command": "O:41:\"PKP\\jobs\\statistics\\CompileMonthlyMetrics\":4:{s:8:\"\u0000*\u0000month\";s:6:\"202312\";s:7:\"\u0000*\u0000site\";O:13:\"PKP\\site\\Site\":6:{s:5:\"_data\";a:19:{s:8:\"redirect\";i:0;s:13:\"primaryLocale\";s:2:\"en\";s:17:\"minPasswordLength\";i:6;s:16:\"installedLocales\";a:1:{i:0;s:2:\"en\";}s:16:\"supportedLocales\";a:1:{i:0;s:2:\"en\";}s:12:\"contactEmail\";a:1:{s:2:\"en\";s:25:\"support.epubs@icar.gov.in\";}s:11:\"contactName\";a:1:{s:2:\"en\";s:37:\"Indian Agricultural Research Journals\";}s:7:\"sidebar\";a:3:{i:0;s:27:\"AnnouncementFeedBlockPlugin\";i:1;s:8:\"director\";i:2;s:9:\"technical\";}s:10:\"styleSheet\";a:2:{s:10:\"uploadName\";s:14:\"styleSheet.css\";s:12:\"dateUploaded\";s:19:\"2022-09-23 09:29:53\";}s:15:\"themePluginPath\";s:7:\"default\";s:5:\"title\";a:1:{s:2:\"en\";s:37:\"Indian Agricultural Research Journals\";}s:17:\"compressStatsLogs\";b:0;s:19:\"enableGeoUsageStats\";s:7:\"country\";s:19:\"keepDailyUsageStats\";b:1;s:27:\"enableInstitutionUsageStats\";b:0;s:16:\"isSushiApiPublic\";b:1;s:19:\"isSiteSushiPlatform\";b:0;s:18:\"counterR5StartDate\";s:10:\"2023-12-01\";s:12:\"uniqueSiteId\";s:13:\"540ac7edb7229\";}s:20:\"_hasLoadableAdapters\";b:0;s:27:\"_metadataExtractionAdapters\";a:0:{}s:25:\"_extractionAdaptersLoaded\";b:0;s:26:\"_metadataInjectionAdapters\";a:0:{}s:24:\"_injectionAdaptersLoaded\";b:0;}s:10:\"connection\";s:8:\"database\";s:5:\"queue\";s:5:\"queue\";}"
    }
}


{
    "message": "SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction (SQL: insert into `metrics_counter_submission_monthly` (`context_id`, `submission_id`, `month`, `metric_investigations`, `metric_investigations_unique`, `metric_requests`, `metric_requests_unique`) select csd.context_id, csd.submission_id, CAST(DATE_FORMAT(csd.date, '%Y%m') AS UNSIGNED) as csdmonth, SUM(csd.metric_investigations), SUM(csd.metric_investigations_unique), SUM(csd.metric_requests), SUM(csd.metric_requests_unique) from `metrics_counter_submission_daily` as `csd` where CAST(DATE_FORMAT(csd.date, '%Y%m') AS UNSIGNED) = 202312 group by csd.context_id, csd.submission_id, csdmonth)",
    "code": "40001",
    "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Database\/Connection.php",
    "line": 760,
    "trace": [
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Database\/Connection.php",
            "line": 720,
            "function": "runQueryCallback",
            "class": "Illuminate\\Database\\Connection",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Database\/Connection.php",
            "line": 577,
            "function": "run",
            "class": "Illuminate\\Database\\Connection",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Database\/Query\/Builder.php",
            "line": 3340,
            "function": "affectingStatement",
            "class": "Illuminate\\Database\\Connection",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/classes\/services\/queryBuilders\/PKPStatsSushiQueryBuilder.php",
            "line": 222,
            "function": "insertUsing",
            "class": "Illuminate\\Database\\Query\\Builder",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/classes\/services\/PKPStatsSushiService.php",
            "line": 106,
            "function": "addMonthlyMetrics",
            "class": "PKP\\services\\queryBuilders\\PKPStatsSushiQueryBuilder",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/jobs\/statistics\/CompileMonthlyMetrics.php",
            "line": 66,
            "function": "addMonthlyMetrics",
            "class": "PKP\\services\\PKPStatsSushiService",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Container\/BoundMethod.php",
            "line": 36,
            "function": "handle",
            "class": "PKP\\jobs\\statistics\\CompileMonthlyMetrics",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Container\/Util.php",
            "line": 41,
            "function": "Illuminate\\Container\\{closure}",
            "class": "Illuminate\\Container\\BoundMethod",
            "type": "::"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Container\/BoundMethod.php",
            "line": 93,
            "function": "unwrapIfClosure",
            "class": "Illuminate\\Container\\Util",
            "type": "::"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Container\/BoundMethod.php",
            "line": 37,
            "function": "callBoundMethod",
            "class": "Illuminate\\Container\\BoundMethod",
            "type": "::"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Container\/Container.php",
            "line": 661,
            "function": "call",
            "class": "Illuminate\\Container\\BoundMethod",
            "type": "::"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Bus\/Dispatcher.php",
            "line": 128,
            "function": "call",
            "class": "Illuminate\\Container\\Container",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Pipeline\/Pipeline.php",
            "line": 141,
            "function": "Illuminate\\Bus\\{closure}",
            "class": "Illuminate\\Bus\\Dispatcher",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Pipeline\/Pipeline.php",
            "line": 116,
            "function": "Illuminate\\Pipeline\\{closure}",
            "class": "Illuminate\\Pipeline\\Pipeline",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Bus\/Dispatcher.php",
            "line": 132,
            "function": "then",
            "class": "Illuminate\\Pipeline\\Pipeline",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/CallQueuedHandler.php",
            "line": 124,
            "function": "dispatchNow",
            "class": "Illuminate\\Bus\\Dispatcher",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Pipeline\/Pipeline.php",
            "line": 141,
            "function": "Illuminate\\Queue\\{closure}",
            "class": "Illuminate\\Queue\\CallQueuedHandler",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Pipeline\/Pipeline.php",
            "line": 116,
            "function": "Illuminate\\Pipeline\\{closure}",
            "class": "Illuminate\\Pipeline\\Pipeline",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/CallQueuedHandler.php",
            "line": 126,
            "function": "then",
            "class": "Illuminate\\Pipeline\\Pipeline",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/CallQueuedHandler.php",
            "line": 70,
            "function": "dispatchThroughMiddleware",
            "class": "Illuminate\\Queue\\CallQueuedHandler",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/Jobs\/Job.php",
            "line": 98,
            "function": "call",
            "class": "Illuminate\\Queue\\CallQueuedHandler",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/Worker.php",
            "line": 425,
            "function": "fire",
            "class": "Illuminate\\Queue\\Jobs\\Job",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/Worker.php",
            "line": 375,
            "function": "process",
            "class": "Illuminate\\Queue\\Worker",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/lib\/vendor\/laravel\/framework\/src\/Illuminate\/Queue\/Worker.php",
            "line": 326,
            "function": "runJob",
            "class": "Illuminate\\Queue\\Worker",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/classes\/core\/PKPQueueProvider.php",
            "line": 104,
            "function": "runNextJob",
            "class": "Illuminate\\Queue\\Worker",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/classes\/queue\/JobRunner.php",
            "line": 220,
            "function": "runJobInQueue",
            "class": "PKP\\core\\PKPQueueProvider",
            "type": "->"
        },
        {
            "file": "\/ojs\/lib\/pkp\/classes\/core\/PKPQueueProvider.php",
            "line": 128,
            "function": "processJobs",
            "class": "PKP\\queue\\JobRunner",
            "type": "->"
        },
        {
            "function": "PKP\\core\\{closure}",
            "class": "PKP\\core\\PKPQueueProvider",
            "type": "->"
        }
    ]

Hi @shantanusingh,

Do you have those MySQL outputs (SHOW ENGINE INNODB STATUS) for that last log file processing? – To know what exactly is leading to the deal lock. Earlier outputs have always shown that the processing of the log file usage_events_20231202.log was locking the table.

Because you have the OJS version where two jobs (that can be run in parallel) – CompileUsageStatsFromTemporaryRecords and CompileMonthlyMetrics – are run for a log file processing, it could eventually be that these two jobs create the dead lock.
In the latest changes/fixes I have made (s. Use jobs chain for usage stats log files processing · Issue #9664 · pkp/pkp-lib · GitHub) all jobs are run in a chain – one after another – they cannot be run in parallel. That should take care of this possible case. But I am not sure if you can apply those patches – there are a lot. You would need to apply all these:
You would need the one that you reverted (pkp/pkp-lib#9679 allow processing of the log files from the last month · pkp/pkp-lib@d0862af · GitHub).

Butut then also:
in lib/pkp:

in ojs:

Or to wait for the next 3.4.0.5 release :-\

Hi @bozana thanks for your support and guidance.

I have cleared the log file of December 2023 and the image below is showing the statistics of 01 December 2023. But on 20231212 I am getting failed jobs, error is mentioned below.

“message”: “SQLSTATE[23000]: Integrity constraint violation: 1452 Cannot add or update a child row: a foreign key constraint fails (ojs4.metrics_submission, CONSTRAINT metrics_submission_representation_id_foreign FOREIGN KEY (representation_id) REFERENCES publication_galleys (galley_id) ON DELETE CASCADE) (SQL: insert into metrics_submission (load_id, context_id, submission_id, representation_id, submission_file_id, file_type, assoc_type, date, metric) select load_id, context_id, submission_id, representation_id, submission_file_id, file_type, assoc_type, DATE(date) as date, count(*) as metric from usage_stats_total_temporary_records where load_id = usage_events_20231212.log and assoc_type = 515 group by load_id, context_id, submission_id, representation_id, submission_file_id, file_type, assoc_type, DATE(date))”,
“code”: “23000”,

I have tried to re-run the stuck log file of 15-17 February 2024 in the Processing and Stage folder. I have tried splitting the log file from 35 MB into smaller file size around 15-15 MB and re-run and 99% of the log file gets processed successfully.

I have run SHOW ENGINE INNODB STATUS and got some lock logs 20231208 and 20231212. I have re-run that date log file and the process completed successfully. 20231202 Log file locking table is not visible for that day after re-run the log file.

Let’s see what happens in the next 3-4 days. If there is any problem then I will try patching as per your suggestion ([OJS-3.4.0-4] Statistic problem - #76 by bozana). :slightly_smiling_face:

Hi!

I see @bozana will be away, so I’ll check if I can come up with a generic fix for the whole application.

Best,
Jonas Raoni

1 Like

Hi @jonasraoni

I have cleared the previous failed jobs and after that, it runs fine for two days and then the next day it gets stuck in the processing folder. I have tried several times to fix the logs but the same problem occurs again (stuck after 2 days).

I’ve tried my best but I don’t know what’s going on.

Hi!

Today I spent some time trying to come up with a generic solution to retry all queries in the application. And it’s possible, but as it will require too many workarounds, the code won’t be approved :eyes:

So, let’s try to first increase the number of retries for the jobs (if you add .diff to the end of the links, GitHub will generate a diff file):
OJS Used default number of retries (3x) · jonasraoni/ojs@87944be · GitHub
/lib/pkp Used default number of retries (3x) · jonasraoni/pkp-lib@062f9b8 · GitHub

Maybe it will be enough! If not, I can add deadlock measures to this part of the code.

Best,
Jonas Raoni