Cron archive run performance / errors

Support & Bugs
1

Hi!

I’m running a piwik instance, spread over 3 hosts (2 webserver, 1 db server), with about 100 active websites. Tracking is done via log-import, so no javascript tracking. For quite some time now, I see performance issues with the archive cron, for 2 larger websites. The cron archive run takes over 16 hours for just 1 website, and even after this time the run doesn’t finish correctly. Other sites process just fine in just a few seconds to a few minutes. Below is a log of a failed run. This occurs every day. During an archive run, the database is idle. The cron php process is constantly at 100% and uses a huge amount of memory (8GB or more for site id 8). The site has around 16M pageviews per week. PHP mem_limit has been set to -1 (unlimited), mysql max_allowed packet is set to 1G and wait_timeout is set to 999999. Still, the ‘mysql server has gone away’ error occurs. Is there anything I can do to succesfully create reports for these 2 sites?

DEBUG SitesManager[2015-02-27 23:00:01] Db::fetchAll() executing SQL: SELECT idsite FROM piwik_site
DEBUG CoreConsole[2015-02-27 23:00:01] Db::fetchAll() executing SQL: SELECT DATABASE()
DEBUG CoreConsole[2015-02-27 23:00:01] Db::fetchAll() executing SQL: SELECT option_value, option_name FROM piwik_option WHERE autoload = 1
DEBUG CoreConsole[2015-02-27 23:00:01] Db::fetchOne() executing SQL: SELECT option_value FROM piwik_option WHERE option_name = ?
DEBUG CoreConsole[2015-02-27 23:00:01] Loaded plugins: CorePluginsAdmin, CoreAdminHome, CoreHome, CoreVisualizations, Proxy, API, Widgetize, Transitions, LanguagesManager, Actions, Dashboard, MultiSites, Referrers, UserSettings, DevicesDetection, SEO, Events, UserCountry, VisitsSummary, VisitFrequency, VisitTime, VisitorInterest, ExampleAPI, Provider, Login, UsersManager, SitesManager, Installation, CoreUpdater, CoreConsole, ScheduledReports, UserCountryMap, Live, CustomVariables, PrivacyManager, ImageGraph, Annotations, MobileMessaging, Overlay, SegmentEditor, Insights, ZenMode, LeftMenu, Morpheus, Contents, BulkTracking, Resolution, DevicePlugins, BotTracker, PasswordPolicy, UserGroups
DEBUG SitesManager[2015-02-27 23:00:02] Db::fetchAll() executing SQL: SELECT idsite FROM piwik_site
DEBUG UserGroups[2015-02-27 23:00:02] Db::fetchOne() executing SQL: SELECT count(ug.id)
FROM piwik_user as u
INNER JOIN piwik_users_to_groups as utg on utg.login = u.login
INNER JOIN piwik_user_groups as ug on ug.id = utg.group_id
WHERE u.login = ? AND ug.superadmin = 1
DEBUG UserGroups[2015-02-27 23:00:02] Db::fetchAll() executing SQL: SELECT uga.idsite, uga.access
FROM piwik_user_groups_access as uga
LEFT JOIN piwik_users_to_groups as utg on utg.group_id = uga.group_id
WHERE utg.login = ?
GROUP BY uga.idsite
DEBUG LanguagesManager[2015-02-27 23:00:02] Db::fetchOne() executing SQL: SELECT language FROM piwik_user_language WHERE login = ?
DEBUG UsersManager[2015-02-27 23:00:02] Db::query() executing SQL: INSERT INTO piwik_option (option_name, option_value, autoload) VALUES (?, ?, ?) ON DUPLICATE KEY UPDATE option_value = ?
DEBUG SitesManager[2015-02-27 23:00:02] Db::fetchAll() executing SQL: SELECT idsite FROM piwik_site
DEBUG CoreConsole[2015-02-27 23:00:02] Db::fetchOne() executing SQL: SELECT option_value FROM piwik_option WHERE option_name = ?
INFO CoreConsole[2015-02-27 23:00:02] ---------------------------
INFO CoreConsole[2015-02-27 23:00:02] INIT
INFO CoreConsole[2015-02-27 23:00:02] Piwik is installed at: http://************/index.php
INFO CoreConsole[2015-02-27 23:00:02] Running Piwik 2.10.0 as Super User
INFO CoreConsole[2015-02-27 23:00:02] ---------------------------
INFO CoreConsole[2015-02-27 23:00:02] NOTES
INFO CoreConsole[2015-02-27 23:00:02] - Reports for today will be processed at most every 150 seconds. You can change this value in Piwik UI > Settings > General Settings.
INFO CoreConsole[2015-02-27 23:00:02] - Reports for the current week/month/year will be refreshed at most every 3600 seconds.
INFO CoreConsole[2015-02-27 23:00:02] - Archiving was last executed without error 4 hours 12 min ago
DEBUG CoreConsole[2015-02-27 23:00:02] Db::query() executing SQL: INSERT INTO piwik_option (option_name, option_value, autoload) VALUES (?, ?, ?) ON DUPLICATE KEY UPDATE option_value = ?
DEBUG SitesManager[2015-02-27 23:00:02] Db::fetchAll() executing SQL: SELECT idsite FROM piwik_site
DEBUG CoreConsole[2015-02-27 23:00:02] Db::fetchAll() executing SQL: SELECT option_name, option_value FROM piwik_option WHERE option_name LIKE ?
INFO CoreConsole[2015-02-27 23:00:02] - Will process 1 websites (–force-idsites)
INFO CoreConsole[2015-02-27 23:00:02] ---------------------------
INFO CoreConsole[2015-02-27 23:00:02] START
INFO CoreConsole[2015-02-27 23:00:02] Starting Piwik reports archiving…
DEBUG CoreConsole[2015-02-27 23:00:02] Db::fetchOne() executing SQL: SELECT option_value FROM piwik_option WHERE option_name = ?
DEBUG CoreConsole[2015-02-27 23:00:02] Db::fetchOne() executing SQL: SELECT option_value FROM piwik_option WHERE option_name = ?
DEBUG CoreConsole[2015-02-27 23:00:02] Db::fetchOne() executing SQL: SELECT option_value FROM piwik_option WHERE option_name = ?
DEBUG CoreConsole[2015-02-27 23:00:02] Db::query() executing SQL: INSERT INTO piwik_option (option_name, option_value, autoload) VALUES (?, ?, ?) ON DUPLICATE KEY UPDATE option_value = ?
DEBUG CoreConsole[2015-02-27 23:00:02] Db::fetchOne() executing SQL: SELECT option_value FROM piwik_option WHERE option_name = ?
DEBUG CoreConsole[2015-02-27 23:00:02] Db::query() executing SQL: INSERT INTO piwik_option (option_name, option_value, autoload) VALUES (?, ?, ?) ON DUPLICATE KEY UPDATE option_value = ?
INFO CoreConsole[2015-02-27 23:22:11] Archived website id = 8, period = day, 1181694 visits in last last52 days, 3 visits today, Time elapsed: 1329.078s
INFO CoreConsole[2015-02-27 23:47:38] Archived website id = 8, period = week, 2555358 visits in last last53 weeks, 183372 visits this week, Time elapsed: 1526.879s
INFO CoreConsole[2015-02-28 07:30:56] Archived website id = 8, period = month, 0 visits in last last52 months, 0 visits this month, Time elapsed: 27797.503s
INFO CoreConsole[2015-02-28 15:12:19] Archived website id = 8, period = year, 0 visits in last last7 years, 0 visits this year, Time elapsed: 27682.980s
DEBUG UsersManager[2015-02-28 15:12:19] Db::fetchAll() executing SQL: SELECT option_name, option_value FROM piwik_option WHERE option_name LIKE ?
WARNING UsersManager[2015-02-28 15:12:19] /export/www/piwik/html/libs/Zend/Db/Statement/Pdo.php(228): Warning - PDOStatement::execute(): MySQL server has gone away - Piwik 2.10.0 - Please report this message in the Piwik forums: http://forum.piwik.org (please do a search first as it might have been reported already)
WARNING UsersManager[2015-02-28 15:12:19] /export/www/piwik/html/libs/Zend/Db/Statement/Pdo.php(228): Warning - PDOStatement::execute(): Error reading result set’s header - Piwik 2.10.0 - Please report this message in the Piwik forums: http://forum.piwik.org (please do a search first as it might have been reported already)

2

Eventually, a cause for this behaviour was found: the problem is we import all bot visits, even for the larger sites. Since these bots visit all pages on the site, this causes the ‘log_link_visit_action’ table to have a very large amount of records (currently around 30 million with 5 days of log data). The 2 sites in question also have a lot (60.000+) of pages that are all tracked separately. This in turn causes the archive process to fail and take huge amounts of time, eventually timing out. The solution is to disable importing bot visits, which reduces the amount of records in the link_visit_action table and brings archive processing back to normality… So it was a combination of importing bot visits for sites with 10’s of thousands of pages that broke things.