Closed eramirezprotec closed 4 years ago
tsteur
commented
4 years ago seeing here https://github.com/matomo-org/matomo/issues/6398#issuecomment-388370992 reports to invalidate are mentioned as well. Might be the same. How often do you see this error per day? Are you also using the log importer? Is there any chance you could enable mysql error log so we can get more information about the deadlock?
pardvm
commented
4 years ago @tsteur, I've able to relate this problem with this other: #15267 In that issue, you sugested to have a sleep between the launch of each cron archiver. We did it indeed but it doens't seems to work.
Do you have another idea on how to get several archivers synchronized in order only one site is processed?
tsteur
commented
4 years ago @pardvm have you tried to increase the sleep to say one minute (assuming you launch them hourly)? And I suppose the sleep is executed correctly with different sleep intervals for each archiver? Looking at the code this should work. Let me know if this doesn't work or if you confirm it's set up like this. I suppose we could in general also add some random minor sleep interval at the beginning of the script just to avoid these issues in general. @pardvm as a result of this do you also see deadlocks?
pardvm
commented
4 years ago @tsteur, We've increased the sleep to 30s and, yes: each archiver is launched 30s after the previous.
I'll keep observing and I'll come back here with the results.
pardvm
commented
4 years ago @tsteur, We haven't observed the deadlock since last modification regarding the sleep: cross fingers! Thanks
tsteur
commented
4 years ago Awesome @pardvm fingers crossed. Let me know if they come back otherwise.
@eramirezprotec might be worth a try as well in case you're starting multiple archivers at the same time?
I will keep this issue open to at least at a tiny random sleep at the beginning of the archive script to prevent this issue a bit better.
@diosmosis @mattab thinking to add some sleep to the beginning of the archiver script in CoreArchiver.php command.
// we randomly sleep up to half a second in case multiple archivers are being launched at the same time.
// this can prevent deadlocks see https://github.com/matomo-org/matomo/issues/15545 although ideally we should
// sleep here a bit longer to better avoid this.
usleep(Common::getRandomInt(0, 500000));For example. This would randomly sleep between 0 and 0.5seconds. From above we can see though that this might not be enough and we'd need to sleep randomly maybe between 0 and 10 or 0 and 30 seconds to minimise this issue. Not sure that's an issue? It might still not fully prevent any race conditions there but at least it be less likely. Fixing the actual race conditions be tricky. Would prefer not adding a new parameter just for that as it then doesn't work out of the box.
Alternatively, we could have an FAQ describing this behaviour and would also need to add a sleep for that example: https://github.com/matomo-org/matomo/issues/4903#issuecomment-48314857
However, FAQs may not be viewed so if it worked out of the box it be even better. Thought there maybe was an FAQ already but couldn't find it. On https://matomo.org/docs/setup-auto-archiving/ it doesn't describe it. So as part of this guide it could be maybe mentioned how to launch multiple archivers with the sleep instead of changing the code.
pardvm
commented
4 years ago @tsteur, It just have ocurred again!... All day was fine but... it is still here (though randomly) What a pity indeed.
P.S.- F.Y.I. @eramirezprotec is a colleague at work and we both are trying to figure this problem out
pardvm
commented
4 years ago @tsteur, @eramirezprotec For your information, bellow is the complete stack trace of the last occurrence of the problem:
ERROR [2020-02-14 02:09:00] 2191 Got invalid response from API request: ?module=API&method=API.get&idSite=92&period=day&date=last15&format=php&trigger=archivephp. Response was 'a:2:{s:6:"result";s:5:"error";s:7:"message";s:11640:"SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction
#0 /data/httpd-pwk-2.4.25/htdocs/analytics/libs/Zend/Db/Statement.php(300): Zend_Db_Statement_Pdo->_execute(Array)
#1 /data/httpd-pwk-2.4.25/htdocs/analytics/libs/Zend/Db/Adapter/Abstract.php(479): Zend_Db_Statement->execute(Array)
#2 /data/httpd-pwk-2.4.25/htdocs/analytics/libs/Zend/Db/Adapter/Pdo/Abstract.php(238): Zend_Db_Adapter_Abstract->query('DELETE FROM `pi...', Array)
#3 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Db/Adapter/Pdo/Mysql.php(309): Zend_Db_Adapter_Pdo_Abstract->query('DELETE FROM `pi...', Array)
#4 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Db.php(276): Piwik\Db\Adapter\Pdo\Mysql->query('DELETE FROM `pi...', Array)
#5 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Option.php(235): Piwik\Db::query('DELETE FROM `pi...', Array)
#6 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Option.php(94): Piwik\Option->deleteNameLike('report_to_inval...', NULL)
#7 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Archive/ArchiveInvalidator.php(194): Piwik\Option::deleteLike('report_to_inval...')
#8 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Archive/ArchiveInvalidator.php(268): Piwik\Archive\ArchiveInvalidator->forgetRememberedArchivedReportsToInvalidate(92,Object(Piwik\Date))
#9 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Archive.php(508): Piwik\Archive\ArchiveInvalidator->markArchivesAsInvalidated(Array, Array, false)
#10 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Archive.php(641): Piwik\Archive->invalidatedReportsIfNeeded()
#11 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Archive.php(620): Piwik\Archive->cacheArchiveIdsAfterLaunching(Array, Array)
#12 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Archive.php(549): Piwik\Archive->getArchiveIds(Array)
#13 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Archive.php(303): Piwik\Archive->get(Array, 'numeric')
#14 /data/httpd-pwk-2.4.25/htdocs/analytics/plugins/VisitsSummary/API.php(47): Piwik\Archive->getDataTableFromNumeric(Array)
#15 [internal function]: Piwik\Plugins\VisitsSummary\API->get(92, 'day', 'last15', false, Array)
#16 /data/httpd-pwk-2.4.25/htdocs/analytics/core/API/Proxy.php(237): call_user_func_array(Array, Array)
#17 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Context.php(28): Piwik\API\Proxy->Piwik\API\{closure}()
#18 /data/httpd-pwk-2.4.25/htdocs/analytics/core/API/Proxy.php(328): Piwik\Context::executeWithQueryParameters(Array, Object(Closure))
#19 /data/httpd-pwk-2.4.25/htdocs/analytics/plugins/API/API.php(435): Piwik\API\Proxy->call('\Piwik\Plugins\...', 'get', Array)
#20 [internal function]: Piwik\Plugins\API\API->get(92, 'day', 'last15', false, Array)
#21 /data/httpd-pwk-2.4.25/htdocs/analytics/core/API/Proxy.php(237): call_user_func_array(Array, Array)
#22 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Context.php(28): Piwik\API\Proxy->Piwik\API\{closure}()
#23 /data/httpd-pwk-2.4.25/htdocs/analytics/core/API/Proxy.php(328): Piwik\Context::executeWithQueryParameters(Array, Object(Closure))
#24 /data/httpd-pwk-2.4.25/htdocs/analytics/core/API/Request.php(265): Piwik\API\Proxy->call('\Piwik\Plugins\...', 'get', Array)
#25 /data/httpd-pwk-2.4.25/htdocs/analytics/plugins/API/Controller.php(41): Piwik\API\Request->process()
#26 [internal function]: Piwik\Plugins\API\Controller->index()
#27 /data/httpd-pwk-2.4.25/htdocs/analytics/core/FrontController.php(589): call_user_func_array(Array, Array)
#28 /data/httpd-pwk-2.4.25/htdocs/analytics/core/FrontController.php(165): Piwik\FrontController->doDispatch('API', false, Array)
#29 /data/httpd-pwk-2.4.25/htdocs/analytics/core/dispatch.php(34): Piwik\FrontController->dispatch()
#30 /data/httpd-pwk-2.4.25/htdocs/analytics/index.php(27): require_once('/data/httpd-pwk...')
#31 /data/httpd-pwk-2.4.25/htdocs/analytics/core/CliMulti/RequestCommand.php(79): require_once('/data/httpd-pwk...')
#32 /data/httpd-pwk-2.4.25/htdocs/analytics/vendor/symfony/console/Symfony/Component/Console/Command/Command.php(257): Piwik\CliMulti\RequestCommand->execute(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#33 /data/httpd-pwk-2.4.25/htdocs/analytics/vendor/symfony/console/Symfony/Component/Console/Application.php(874): Symfony\Component\Console\Command\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#34 /data/httpd-pwk-2.4.25/htdocs/analytics/vendor/symfony/console/Symfony/Component/Console/Application.php(195): Symfony\Component\Console\Application->doRunCommand(Object(Piwik\CliMulti\RequestCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#35 [internal function]: Symfony\Component\Console\Application->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#36 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Console.php(125): call_user_func(Array, Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#37 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Access.php(644): Piwik\Console->Piwik\{closure}()
#38 /data/httpd-pwk-2.4.25/htdocs/analytics/core/Console.php(126): Piwik\Access::doAsSuperUser(Object(Closure))
#39 /data/httpd-pwk-2.4.25/htdocs/analytics/vendor/symfony/console/Symfony/Component/Console/Application.php(126): Piwik\Console->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#40 /data/httpd-pwk-2.4.25/htdocs/analytics/console(27): Symfony\Component\Console\Application->run()
#41 {main}, caused by: SQLSTATE[40001]: Serialization faI wonder if it's related to something I've seen yesterday where we do a lot of deletes there on the option and the general cache https://github.com/matomo-org/matomo/blob/3.13.2/core/Archive/ArchiveInvalidator.php#L178-L195
As a result some other requests might try to insert/update these option entries while another one is trying to delete it etc. As above is in a for loop there could be such edge conditions maybe.
@pardvm when this happens it be great - if you can - shortly afterwards execute on the database this query
SHOW ENGINE INNODB STATUSThis would maybe let us better understand which lock it was waiting for.
If that's not easily possible, you could set the log level to debug temporarily in config/config.ini.php but this could have side effects that you see a lot of messages in the Matomo UI. You would probably want to change this line from Log::debug to Log::warn in https://github.com/matomo-org/matomo/blob/3.13.2/core/Db.php#L813
And also make sure to add a logging to file see https://matomo.org/faq/troubleshooting/faq_115/
If that's not easily possible, you could temporarily maybe change the above line to throw new Exception("Encountered deadlock: " . print_r($deadlockInfo, true));
tsteur
commented
4 years ago Hope this helps. And thanks for your help troubleshooting this
pardvm
commented
4 years ago @tsteur ,
Pff!!. It would be very difficult to be awake when the error occurs again. However, I'll try the SHOW ENGINE INNODB STATUS command as soon I can.
Also, I'll evalute doing the temporary change in the code to flush $deadlockInfo
Thanks a lot for your support
pardvm
commented
4 years ago @tsteur,
Find attached in innodb-status.txt the last result for show engine innodb status after the dead-lock occured.
Hope this could help. Let me know about anything I can do to help
tsteur
commented
4 years ago @pardvm thanks very much for this.
The lock in here seems actually bit different and not for that particular case:
MySQL thread id 2891310, OS thread handle 140646037559040, query id 925132939 minfor16 10.0.3.116 piwik updating UPDATE piwik_log_visit SET idvisitor = ..., visit_last_action_time = '2020-02-17 09:10:31', visit_exit_idaction_name = '10708013', visit_exit_idaction_url = '17443', visit_total_actions = visit_total_actions + 1 , visit_total_interactions = visit_total_interactions + 1 , visit_total_time = '85' WHERE idsite = '13' AND idvisit = '1226508397' *** WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 955 page no 3893779 n bits 136 index PRIMARY of table
piwik.piwik_log_visittrx id 1425206090 lock_mode X locks rec but not gap waiting Record lock, heap no 37 PHYSICAL RECORD: n_fields 79; compact format; info bits 0
pardvm
commented
4 years ago @tsteur, I've been able to capture another deadlock. For your reference, please, find attached corresponding information: innodb-status-20-02.txt
Marc-Whiteman
commented
4 years ago We are seeing the same error while running ver 3.13.1:
------------------------
LATEST DETECTED DEADLOCK
------------------------
2020-02-20 11:10:11 0x7feae7fff700
*** (1) TRANSACTION:
TRANSACTION 1436045592, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 62 row lock(s)
MySQL thread id 3730831, OS thread handle 140647735736064, query id 1169747052 minfor15.mas.local 10.0.3.39 piwik updating
DELETE FROM `piwik_option` WHERE option_name LIKE 'report_to_invalidate_90_2020-02-20%'
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 872 page no 71 n bits 280 index PRIMARY of table `piwik`.`piwik_option` trx id 1436045592 lock_mode X waiting
Record lock, heap no 184 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 30; hex 7265706f72745f746f5f696e76616c69646174655f375f323032302d3032; asc report_to_invalidate_7_2020-02; (total 38 bytes);
1: len 6; hex 00005598505f; asc U P_;;
2: len 7; hex a30007951d0132; asc 2;;
3: len 1; hex 31; asc 1;;
4: len 1; hex 80; asc ;;@Marc-Whiteman, As far I have been able to discover, the efects of that deadlock are not "visible" to the operators accessing Matomo dashboards (I gues that it is due to the fact that the problem arises during invalidation process of a previous archive during the current day. Can you also confirm that?
tsteur
commented
4 years ago Cheers for this input. This helps me understand things better. Created https://github.com/matomo-org/matomo/pull/15603 which hopefully fixes it. Feel free to give it a try already if you can. Hoping this can make it into the release on Monday/Tuesday if not it'll be in 3.13.4 I reckon. If you could give us feedback if that helps that be great.
copying some info from the txt in here.
*** (1) TRANSACTION:
TRANSACTION 1436045592, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 62 row lock(s)
DELETE FROM `piwik_option` WHERE option_name LIKE 'report_to_invalidate_90_2020-02-20%'
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 872 page no 71 n bits 280 index PRIMARY of table `piwik`.`piwik_option` trx id 1436045592 lock_mode X waiting
Record lock, heap no 184 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 30; hex 7265706f72745f746f5f696e76616c69646174655f375f323032302d3032; asc report_to_invalidate_7_2020-02; (total 38 bytes);
*** (2) TRANSACTION:
TRANSACTION 1436045407, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
76 lock struct(s), heap size 8400, 93 row lock(s), undo log entries 151
MySQL thread id 3730828, OS thread handle 140646891386624, query id 1169747207 minfor16 10.0.3.116 piwik update
INSERT IGNORE INTO `piwik_option` (option_name, option_value, autoload) VALUES ('report_to_invalidate_58_2020-02-20_5626', '1', '0')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 872 page no 71 n bits 280 index PRIMARY of table `piwik`.`piwik_option` trx id 1436045407 lock_mode X locks rec but not gap
Record lock, heap no 184 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 30; hex 7265706f72745f746f5f696e76616c69646174655f375f323032302d3032; asc report_to_invalidate_7_2020-02; (total 38 bytes);
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 872 page no 71 n bits 280 index PRIMARY of table `piwik`.`piwik_option` trx id 1436045407 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 175 PHYSICAL RECORD: n_fields 5; compact format; info bits 0This should be hopefully fixed. Let us know if it still happens with the latest release and I'll reopen.
pardvm
commented
4 years ago @tsteur, Just to inform you that, after apply the patch, all seemed to go well but last night another deadlock occured. Following the trace with call stack. Let's hope it helps: ``ERROR [2020-02-28 23:13:42] 23355 Got invalid response from API request: ?module=API&method=API.get&idSite=87&period=day&date=last2&format=php&trigger=archivephp. Response was 'a:2:{s:6:"result";s:5:"error";s:7:"message";s:13686:"SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction
ERROR [2020-02-28 23:13:42] 23355 Empty or invalid response '' for website id 87, Time elapsed: 9.851s, skipping``
tsteur
commented
4 years ago Sorry about that @pardvm By the looks might be a different deadlock issue now maybe.
If someone could ideally send us a deadlock information like last time from show engine innodb status that be great 👍
tsteur
commented
4 years ago We actually had this issue yesterday as well:
LATEST DETECTED DEADLOCK
------------------------
2020-03-01 15:43:35 0x2adf4e24f700
*** (1) TRANSACTION:
TRANSACTION 23816213114, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 7 lock struct(s), heap size 1136, 4 row lock(s), undo log entries 4
MySQL thread id 932399233, OS thread handle 47049637373696, query id 10134440470 10.10.10.10 mc_example update
INSERT IGNORE INTO `option` (option_name, option_value, autoload) VALUES ('report_to_invalidate_3_2020-03-01_10264', '1', '0')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 317015 page no 80 n bits 0 index PRIMARY of table `foo_example`.`option` trx id 23816213114 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 167 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len=30; bufptr=0x2ad14a50e633; hex= 7265706f72745f746f5f696e76616c69646174655f335f323032302d3033; asc report_to_invalidate_3_2020-03; (total 39 bytes);
1: len=6; bufptr=0x2ad14a50e65a; hex= 00058b8e91ae; asc ;;
2: len=7; bufptr=0x2ad14a50e660; hex= b700201ae40122; asc ";;
3: len=1; bufptr=0x2ad14a50e667; hex= 31; asc 1;;
4: len=1; bufptr=0x2ad14a50e668; hex= 80; asc ;;
*** (2) TRANSACTION:
TRANSACTION 23816212998, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 8 lock struct(s), heap size 1136, 5 row lock(s), undo log entries 4
MySQL thread id 932399201, OS thread handle 47037265245952, query id 10134440168 10.10.10.10 mc_example update
INSERT IGNORE INTO `option` (option_name, option_value, autoload) VALUES ('report_to_invalidate_3_2020-03-01_10280', '1', '0')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 317015 page no 80 n bits 0 index PRIMARY of table `foo_example`.`option` trx id 23816212998 lock_mode X locks gap before rec
Record lock, heap no 167 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len=30; bufptr=0x2ad14a50e633; hex= 7265706f72745f746f5f696e76616c69646174655f335f323032302d3033; asc report_to_invalidate_3_2020-03; (total 39 bytes);
1: len=6; bufptr=0x2ad14a50e65a; hex= 00058b8e91ae; asc ;;
2: len=7; bufptr=0x2ad14a50e660; hex= b700201ae40122; asc ";;
3: len=1; bufptr=0x2ad14a50e667; hex= 31; asc 1;;
4: len=1; bufptr=0x2ad14a50e668; hex= 80; asc ;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 317015 page no 80 n bits 0 index PRIMARY of table `foo_example`.`option` trx id 23816212998 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 167 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len=30; bufptr=0x2ad14a50e633; hex= 7265706f72745f746f5f696e76616c69646174655f335f323032302d3033; asc report_to_invalidate_3_2020-03; (total 39 bytes);
1: len=6; bufptr=0x2ad14a50e65a; hex= 00058b8e91ae; asc ;;
2: len=7; bufptr=0x2ad14a50e660; hex= b700201ae40122; asc ";;
3: len=1; bufptr=0x2ad14a50e667; hex= 31; asc 1;;
4: len=1; bufptr=0x2ad14a50e668; hex= 80; asc ;;Not sure you still need it, but...
LATEST DETECTED DEADLOCK
------------------------
2020-03-02 12:01:10 0x7f56f7a6e700
*** (1) TRANSACTION:
TRANSACTION 97395463, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 24 lock struct(s), heap size 3520, 31 row lock(s), undo log entries 50
MySQL thread id 683001, OS thread handle 140011706545920, query id 294788873 mtm-private-app3.aimediagroup.com 192.168.227.110 matomo Update
INSERT IGNORE INTO `matomo_option` (option_name, option_value, autoload) VALUES ('report_to_invalidate_3_2020-03-02_6794', '1', '0')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 197 page no 34 n bits 232 index PRIMARY of table `matomo`.`matomo_option` trx id 97395463 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 147 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 30; hex 7265706f72745f746f5f696e76616c69646174655f345f323032302d3033; asc report_to_invalidate_4_2020-03; (total 38 bytes);
1: len 6; hex 000000000000; asc ;;
2: len 7; hex 80000000000000; asc ;;
3: len 1; hex 31; asc 1;;
4: len 1; hex 80; asc ;;
*** (2) TRANSACTION:
TRANSACTION 97395467, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
22 lock struct(s), heap size 3520, 26 row lock(s), undo log entries 53
MySQL thread id 683006, OS thread handle 140011498825472, query id 294788907 mtm-private-app3.aimediagroup.com 192.168.227.110 matomo Update
INSERT IGNORE INTO `matomo_option` (option_name, option_value, autoload) VALUES ('report_to_invalidate_106_2020-03-02_6088', '1', '0')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 197 page no 34 n bits 232 index PRIMARY of table `matomo`.`matomo_option` trx id 97395467 lock_mode X locks gap before rec
Record lock, heap no 147 PHYSICAL RECORD: n_fields 5; compact format; info bits 0We discussed yesterday that it may help to prefix these invalidate report key with random characters so they might reserve a different index gap.
Like report_to_invalidate_3_2020-03-02_6794 and report_to_invalidate_106_2020-03-02_6088 is quite similar and maybe the problem is that it locks the same index gap and thus running into a deadlock. The idea was if we can generate a random string like [a-Z0-9]{4} and prefix this, then they are more likely trying to lock different gaps. We have no idea though if that would work. A problem I found with this solution is that we basically need to query where option_name like %_report_to_invalidate_% in tracker and archiver which means there may be full table scans to get these values. Archiver might not be as important but whenever we write the general cache it would do full table scans and currently we're recreating that cache quite often (hopefully fixed soon). Not sure if this be an issue? The table typically contains less than 1000 entries (but may contain 10K or 30K or 100K entries depending on the number of users, saved attributes, etc). Not sure if this be an issue? @mattab I reckon this be fine?
So the goal of this issue be to prefix these values with a random 4 character prefix. With values from a-zA-Z0-9.
tsteur
commented
4 years ago As it's contained all in ArchiveInvalidator class this might be easy to do and can then see how often deadlocks still happen
tsteur
commented
4 years ago fyi not really seeing a reduction in the number of deadlocks since applying #15666 but it's hard to say as we don't get many anyway. Further improvement should be the archive refactoring to avoid this issue mostly in the first place by no longer executing these queries for today tracking requests.
tsteur
commented
4 years ago Moving this issue for now to 3.13.5 as #15666 in combination with the archive refactoring might fix the issue. Be good to hear once 3.13.4 is released whether this works.
tsteur
commented
4 years ago With the recent 3.13.5 patches we haven't seen any deadlocks yet. Closing this for now. Let me know should this still be an issue after 3.13.5
lato333
commented
1 year ago Hello,
I am also using the log import script (/misc/log-analytics/import_logs.py) and experiencing this issue on the latest matomo version (4.15.1).
Command:
/usr/bin/python ./misc/log-analytics/import_logs.py --recorders 5 --url=<url> --enable-static --enable-http-redirects --idsite=<id> --token-auth <token> <filename>
------------------------
LATEST DETECTED DEADLOCK
------------------------
2023-10-17 08:00:02 0x7f444c3bb640
*** (1) TRANSACTION:
TRANSACTION 3992030563, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 2
MariaDB thread id 395363, OS thread handle 139931313485376, query id 288849097 localhost 127.0.0.1 matomo Update
INSERT IGNORE INTO `matomo_option` (option_name, option_value, autoload) VALUES ('6vS3_report_to_invalidate_14_2023-10-16_446883', '1', '0')
*** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1074179 page no 168 n bits 168 index PRIMARY of table `matomo`.`matomo_option` trx id 3992030563 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 111 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 19; hex 626162656c5f64656661756c745265706f7274; asc babel_defaultReport;;
1: len 6; hex 000040ca503d; asc @ P=;;
2: len 7; hex 7f0018002a1fb9; asc * ;;
3: len 10; hex 4d756c74695369746573; asc MultiSites;;
4: len 1; hex 80; asc ;;
*** CONFLICTING WITH:
RECORD LOCKS space id 1074179 page no 168 n bits 168 index PRIMARY of table `matomo`.`matomo_option` trx id 3992030562 lock_mode X locks gap before rec
Record lock, heap no 111 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 19; hex 626162656c5f64656661756c745265706f7274; asc babel_defaultReport;;
1: len 6; hex 000040ca503d; asc @ P=;;
2: len 7; hex 7f0018002a1fb9; asc * ;;
3: len 10; hex 4d756c74695369746573; asc MultiSites;;
4: len 1; hex 80; asc ;;
RECORD LOCKS space id 1074179 page no 168 n bits 168 index PRIMARY of table `matomo`.`matomo_option` trx id 3992030563 lock_mode X locks gap before rec
Record lock, heap no 111 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 19; hex 626162656c5f64656661756c745265706f7274; asc babel_defaultReport;;
1: len 6; hex 000040ca503d; asc @ P=;;
2: len 7; hex 7f0018002a1fb9; asc * ;;
3: len 10; hex 4d756c74695369746573; asc MultiSites;;
4: len 1; hex 80; asc ;;
*** (2) TRANSACTION:
TRANSACTION 3992030562, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 2
MariaDB thread id 395365, OS thread handle 139931779741248, query id 288849096 localhost 127.0.0.1 matomo Update
INSERT IGNORE INTO `matomo_option` (option_name, option_value, autoload) VALUES ('6jWh_report_to_invalidate_14_2023-10-16_449908', '1', '0')
*** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1074179 page no 168 n bits 168 index PRIMARY of table `matomo`.`matomo_option` trx id 3992030562 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 111 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 19; hex 626162656c5f64656661756c745265706f7274; asc babel_defaultReport;;
1: len 6; hex 000040ca503d; asc @ P=;;
2: len 7; hex 7f0018002a1fb9; asc * ;;
3: len 10; hex 4d756c74695369746573; asc MultiSites;;
4: len 1; hex 80; asc ;;
*** CONFLICTING WITH:
RECORD LOCKS space id 1074179 page no 168 n bits 168 index PRIMARY of table `matomo`.`matomo_option` trx id 3992030562 lock_mode X locks gap before rec
Record lock, heap no 111 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 19; hex 626162656c5f64656661756c745265706f7274; asc babel_defaultReport;;
1: len 6; hex 000040ca503d; asc @ P=;;
2: len 7; hex 7f0018002a1fb9; asc * ;;
3: len 10; hex 4d756c74695369746573; asc MultiSites;;
4: len 1; hex 80; asc ;;
RECORD LOCKS space id 1074179 page no 168 n bits 168 index PRIMARY of table `matomo`.`matomo_option` trx id 3992030563 lock_mode X locks gap before rec
Record lock, heap no 111 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 19; hex 626162656c5f64656661756c745265706f7274; asc babel_defaultReport;;
1: len 6; hex 000040ca503d; asc @ P=;;
2: len 7; hex 7f0018002a1fb9; asc * ;;
3: len 10; hex 4d756c74695369746573; asc MultiSites;;
4: len 1; hex 80; asc ;;
Any ideas how to resolve this?
Thanks!
Hi!
I'm getting this error every day since I updated Matomo to version 3.13.1:
INFO [2020-02-09 04:07:32] 9595 Failed to invalidate archived reports: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transactionI found some tickets about the deadlock situation but none of them speak about the deadlock happening when trying to invalidate archived reports.
Thank you very much.