@integrationtester opened this issue on October 7th 2014

so i use the tracking api.

my code separates actions into groups of 500-800 (depending on session length)

each group is put into a queue, and threads send these groups to piwik to be tracked.

currently 15 threads send these groups simultaneously.

why i do this: in my particular setup, i did some testing and around 500 was the sweet spot for piwik's ability to handle bulk tracks (less didn't decrease the time much, and more started increasing the time significantly)

i also noticed that the times it takes to track these hits doesn't seem to increase much if you have multiple bulk requests at the same time.

the problem: i recently upgraded from 2.2.2 to 2.7.0, and now when i run the same importer, i start getting error 500s from the tracker requests.

looking at the apache error logs, there seems to be deadlock issues:

[Tue Oct 07 13:00:01 2014] [error] [client 130.14.24.60] Error in Piwik (tracker): Error query: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction \t\t\t\t\t\t\t\tIn query: UPDATE piwikdev_log_visit SET idvisitor = ?, visit_total_time = ?, visit_last_action_time = ?, visit_exit_idaction_url = ?, visit_total_actions = visit_total_actions + 1 , custom_var_k1 = ?, custom_var_v1 = ? WHERE idsite = ? AND idvisit = ? \t\t\t\t\t\t\t\tParameters: array

@quba commented on October 7th 2014

I was able to reproduce this on my local machine while trying to import big log file (I guess it was Piwik 2.5).

@integrationtester commented on October 9th 2014

thanks for reproducing

@mattab commented on October 12th 2014

Thanks for the report, we should investigate this for sure.

@imoullet commented on November 7th 2014

Hello Same problem for me

Thanks for the future fix

@imoullet commented on November 13th 2014

Any news about that point . Every night my importlogs script fails because of that error. Please let me know urgently if there is a workaround for that . I am losing all my statistics since more than a week now.. !

Thanks

@mattab commented on November 13th 2014

do you guys get other errors in your web server log or mysql error log? I don't know what can cause this issue so far.

@imoullet commented on November 14th 2014

Nothing else tnat what jas been mentioned

In piwik output I have

Fatal error: Internal Server Error You can restart the import of "/var/tmp/stats/app/access_full" from the point it failed by specifying --skip=21056 on the command line.

And in apache log : [Thu Nov 13 04:08:18 2014] [error] [client 130.223.27.18] Error in Piwik (tracker): Error query: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction In query: UPDATE piwik_log_visit SET idvisitor = ?, visit_total_time = ?, visit_last_action_time = ?, visit_exit_idaction_url = ?, visit_total_actions = visit_total_actions + 1 WHERE idsite = ? AND idvisit = ? Parameters: array ( 0 => 'o\xf9\xfe\x18\xcc\x1e\x91\xc1', 1 => 187, 2 => '2014-11-12 15:57:00', 3 => 331274, 4 => 512, 5 => 18746028, )

Hote that's help

@zero-universe commented on November 20th 2014

I can also reproduce the error in 2.9.1.

I tried to import a logfile of the size of 60 MB.

This is the output of mysql.err (mariadb 5.5.34)

141120 15:22:20 *** (1) TRANSACTION: TRANSACTION 97983A, ACTIVE 1 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 6 lock struct(s), heap size 1248, 4 row lock(s), undo log entries 26 MySQL thread id 197643, OS thread handle 0x7f958fb85700, query id 37275520 piwik-db-server.tld piwik-server.tld piwik_basic Updating UPDATE piwik_log_visit SET idvisitor = '^SscD', visit_total_time = '1265', visit_last_action_time = '2014-10-08 17:57:21', visit_exit_idaction_url = '1607782', visit_total_a ctions = visit_total_actions + 1 WHERE idsite = '7' AND idvisit = '1300111' *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 1172 page no 2854 n bits 136 index PRIMARY of table piwik_basic.piwik_log_visit trx id 97983A lock_mode X locks rec but not gap waiting *** (2) TRANSACTION: TRANSACTION 979835, ACTIVE 1 sec starting index read, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 11 lock struct(s), heap size 1248, 10 row lock(s), undo log entries 175 MySQL thread id 197639, OS thread handle 0x7fabd81b4700, query id 37276630 piwik-db-server.tld piwik-server.tld piwik_basic Updating UPDATE piwik_log_visit SET idvisitor = '^So', visit_total_time = '1321', visit_last_action_time = '2014-10-08 18:02:39', visit_exit_idaction_url = '1607836', visit_t otal_actions = visit_total_actions + 1 WHERE idsite = '7' AND idvisit = '1300276' *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 1172 page no 2854 n bits 136 index PRIMARY of table piwik_basic.piwik_log_visit trx id 979835 lock_mode X locks rec but not gap *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 1172 page no 2855 n bits 144 index PRIMARY of table piwik_basic.piwik_log_visit trx id 979835 lock_mode X locks rec but not gap waiting *** WE ROLL BACK TRANSACTION (1) InnoDB: transactions deadlock detected, dumping detailed information.

@pietsch commented on November 25th 2014

I get the same error messages with Piwik 2.9.1 and Oracle's mysql-community-server-5.5.33 on openSUSE 12.2 (x86_64), and I seem to observe gaps in the imported data.

@pietsch commented on November 25th 2014

The error messages no longer appear when I change the (non-default) importer option --recorders=4 to --recorders=1 (or omit it). Of course this workaround slows down the import on a multi-core machine.

@zero-universe commented on November 26th 2014

My solution is to "downgrade" (reinstallation) to piwik 2.6.1. --recorders=24 is not a problem! Deadlocks are also gone !

@bratster commented on November 26th 2014

I have used a number of versions of PIWIK previously and am seeing this problem with 2.9.0.

Previously I have collected about 12 months worth of data and am running via BASh script to process through my archives, consolidate data into reasonable "chunks" and then upload with the python script...

Once I see the error on my main database, it then seems to repeat a lot. It is as if I have blocked the pipe and everything backs up. I have tried a number of things just to experiment to see if I can see a root cause: - I can take the same set of data, that fails to upload with this error and upload the same to a fresh new clean and empty database no problem whatsoever - I can retry loading to the main database and over time it will upload slowly and eventually - I can take other data to another machine in the network and upload from another instance of PIWIK pointing to the same dbase, at high speed

I conject that {for whatever reason} this is the dbase in a bad state, and all MySQL information about these kind of things suggests that its all about how the data is being pushed in, causing MySQL to "protect" its data (my words).

Furthermore pietsch's "fix" suggests that the database end of the connection has reached a state that can acceot data but (humanised word) "slow down" the rate of input....

So a question to PIWIK. Does the database just accept data when uploading with python OR does the php code and database together manipulate it in the upload session.

My current approach is to slow my rebuild right down and also to stop the continuing data collection from my live source... in otherwords I have one stream of data going into the database. My worry os that once a break occurs. That will be that and I will be back to uploading 20 records every 10 minutes or so.

zero-universe's suggestion is most wise at the moment....

What sort of information shall I collect to benefit this forum, assuming that I see the error once again?

Kev

@zero-universe commented on December 3rd 2014

any updates on this topic ?

@mattab commented on December 3rd 2014

@zero-universe nop

@rufinus commented on December 18th 2014

same here (v2.9.1), reducing recorders from 12 to 2 helped, but its only a temporary fix. i import hourly, and with only 2 threads it takes to much time. (115 req/sec instead of 280-350 req/sec)

@rojaro commented on December 29th 2014

Had to reduce recorders to 1 ... :-1:

@scukonick commented on January 12th 2015

The same affects me (2.9.1)

@mpiscaer commented on January 14th 2015

The same affects on version 2.10.0

@drhirn commented on January 16th 2015

Same here. Piwik 2.10.0 IIS8.5 PHP 5.4.24 MySQL 5.6.22

Reducing recorders to 1 helps

Error query: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction In query: UPDATE piwik_log_visit SET idvisitor = ?, visit_total_actions = visit_total_actions + 1 , visit_exit_idaction_url = ?, visit_total_time = ?, visit_last_action_time = ? WHERE idsite = ? AND idvisit = ?

@mddvul22 commented on February 5th 2015

We are also having this problem in this environment:

CentOS 7 Piwik 2.10.0 Apache 2.4.6 PHP 5.4.16 MariaDB 5.5.40

And like others here, reducing the number of recorders to 1 appears to have eliminated the problem.

@felicitus commented on February 7th 2015

+1 here.

Also had to reduce recorders to 1.

Debian Wheezy Piwik 2.10.0 Apache 2.2.22-13+deb7u4 PHP 5.4.36-0+deb7u3 MySQL 5.5.41-0+wheezy1

@medic123de commented on February 13th 2015

Hi, I wrote the transaction patch in 2.4.0. I will try to find a solution, I already have an Idea that different Data handling within piwik might be the problem.

As long as the analysis takes, please try to set "bulk_requests_use_transaction = 0" in config/global.ini That should improve the situation at the cost of speed, but not as much as "recorder = 1"

@OuestNeige commented on February 13th 2015

You are a genius! I could import without generating the error. Thank you.

@esapozhnikov commented on February 18th 2015

Any update on this issue?

I have also noticed that if you use MySQLi instead of PDO the deadlock errors go away but the number of records/sec drop significantly.

@mattab commented on February 18th 2015

I'm moving this to 2.12.0 and hopefully we can fix it there. Maybe @medic123de will have a solution for it :-)

@mattab commented on March 3rd 2015

FYI: this same issue is discussed in #7337 where it was identified that the deadlocks are caused by the archiving cron core:archive running at the same time which is causing those deadlocks.

@esapozhnikov commented on March 3rd 2015

@mattab I have also seen deadlocks caused by the import_logs.py script with no archive job running. I am not sure if the 2 issues are related as in the case of the archive job I am seeing the IOPS on our DB instance maxed out at over 2500 Write IOPS

@mddvul22 commented on March 4th 2015

I have seen deadlocks when imports were happening simulatenously with archiving. (Thanks for point that out.) But, like esapozhnikov mentions, I've also seen deadlocks when the import script was running and no archiving was happening.

@medic123de commented on March 5th 2015

@all can someone please verify, if import_logs.py from #7348 improves or fixes that issue?

@peterbo commented on March 5th 2015

@quba are you still able to reproduce the deadlock issue with the patched importer?

Other ways of fixing (or at least making deadlocks more unlikely) could be: - batch smaller commits in between. E.g. when a recorder bulk loads 1000 rows, the tracker could commit in 10 (20, 30, 40) row batches to reduce locks. - A generally accepted way for dealing with deadlocks is to simply retry a transaction

I would prefer a fix on the tracker's side because the import-log is not the only adapter for the bulk tracking API, and therefore should be bullet proof to use without knowledge of internals.

@mpiscaer commented on March 9th 2015

Looks like it has been resolved in #7348.

@peterbo commented on March 18th 2015

1) Could somebody check if this proof of concept bugfix would resolve the issue? I was not able to reproduce the error anymore with a 4G input file. This will not make deadlocks occur anymore but very likely will deal with the situation (release lock and try again after a short time).

Retrying is one of the best practices with a deadlock scenario, so this is a valid way to go. @medic123de @mattab @quba

2) It would be very interesting, if this PoC fix decreases speed significantly.

@mattab commented on March 19th 2015

here is diff without whitespace: https://github.com/peterbo/piwik/commit/ca4084a73560410c211309ee623d13bd617be6fe?w=1

Retrying sounds good to me, +1 for this approach

@cbay commented on April 4th 2015

@peterbo ca4084a doesn't solve the issue for me (I still have timeouts).

@mattab commented on April 9th 2015

Note there is a workaround available for this problem (as suggested by . In config/config.ini.php under [Tracker] add: bulk_requests_use_transaction=0

(another workaround is to set recorders to 1 but this config setting may be faster on your setup)

(edited Aug 26th 2016)

@hfrenzel commented on April 20th 2015

Setting bulk_requests_use_transaction=0 does not work. I'm getting the same deadlock. 2nd workaround worked, but takes very long to parse our logfiles (~75 rec/sec only)

@mddvul22 commented on June 24th 2015

I'm unclear on the status of this bug in Piwik. There appears to have been almost no action on this in two months. The last few posts seem to disagree regarding whether there is a fix for this. Any update?

@parruc commented on June 30th 2015

I dont thik it's solved @bryankwalton

If it can help I always get this Deadlock error on the same table (piwik_option table) when the logs import process tries to import data from logs.

The full error is:

2015/06/30 18:51:55 [error] 42998#0: *12755 FastCGI sent in stderr: "PHP message: Error in Piwik (tracker): Error query: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction                                 In query: INSERT INTO `piwik_option` (option_name, option_value, autoload)  VALUES (?, ?, ?)  ON DUPLICATE KEY UPDATE option_value = ?                                 Parameters: array (   0 => 'report_to_invalidate_2229_2015-06-25',   1 => '1',   2 => 0,   3 => '1', )" while reading response header from upstream, client: 127.0.0.1, server: piwik01.dsaw.unibo.it, request: "POST /piwik.php HTTP/1.0", upstream: "fastcgi://unix:/var/run/php5-fpm.sock:", host: "localhost"
@parruc commented on July 3rd 2015

Ok it's not a real solution but I'm avoiding potential data loss like this: and /var/www/piwik/libs/PiwikTracker/PiwikTracker.php:633

        $success = false;
        $count = 0;
        while(!$success) {
            try {
                $response = $this->sendRequest($this->getBaseUrl(), 'POST', $postData, $force = true);
                if ($response){
                    $success = true;
               }
            }
            catch(Exception $e){
                sleep(3);
                $count++;
                //error_log($url + " - " + $count, 3, "/var/log/piwik/test.log");
                // throw $e;
            }
        }

/var/www/piwik/libs/PiwikTracker/PiwikTracker.php:1384

            $success = false;
            $count = 0;
            while(!$success) {
                try {   
                        $response = file_get_contents($url, 0, $ctx);
                       if ($response){
                            $success = true;
                       }
                }
                catch(Exception $e){
                    sleep(3);
                    $count++;
                    //error_log($url + " - " + $count, 3, "/var/log/piwik/test.log");
                    //throw $e;
                }
            }

I know it's ugly but it works.

@esapozhnikov commented on July 13th 2015

@mattab

Any update on this issue, I though it will be fixed in 2.13 but I ma still getting deadlocks.

@phpdiddy commented on August 14th 2015

Just ran into this as well. Changing bulk_requests_use_transaction = 0 had no effect. No archiving is running during the time import is occurring. Latest 2.14.3 installed.

@piwikjapan commented on September 30th 2015

I wrote about it. See link http://forum.piwik.org/read.php?2,127070.

@luxpir commented on October 8th 2015

@piwikjapan Thanks for looking into that. Your last comment seems to have fixed it for me. At least log_import is working again, after some Mysql issues giving 500 errors:

The use of "--replay-tracking" and "--recorder-max-payload-size=200" did the trick - recorders were already at 1 and bulk_requests_use_transaction=0 had no effect.

@piwikjapan commented on November 17th 2015

I found a pattern of import_logs.py. http://forum.piwik.org/t/sql-error-and-what-i-did-seems-to-have-fixed-it/15632/4?u=piwikjapan

@mddvul22 commented on August 17th 2016

Since it seems that the solution is to not use a --recorders value greater than 1, and to add --replay-tracking and --recorder-max-payload-size, shouldn't this page be updated? It is still recommending that --recorder be set to the number of cores on the system.

@peterbo commented on August 25th 2016

Note that the workaround to set "bulk_requests_use_transaction=0" has to be set in the [Tracker] section, not as mentioned in https://github.com/piwik/piwik/issues/6398#issuecomment-91093146 in [General].

Powered by GitHub Issue Mirror