diff options
author | Thomas Steur <tsteur@users.noreply.github.com> | 2019-09-11 10:42:26 +0300 |
---|---|---|
committer | diosmosis <diosmosis@users.noreply.github.com> | 2019-09-11 10:42:26 +0300 |
commit | e31ec88c07621cf52283490e5ffc7935308d00d5 (patch) | |
tree | 86b52a7a21a4430cea823e45d4da35b397ef3968 | |
parent | a1cba093124040a6ea1b9695af9de3293c229723 (diff) |
Allow configuration of max execution time (#14858)
* allow configuration of max execution time
* trigger event when query time exceeded
* fix screenshot test
* added some tests and mention mariadb not supported
-rwxr-xr-x | config/global.ini.php | 6 | ||||
-rw-r--r-- | core/Updater/Migration/Db.php | 10 | ||||
-rw-r--r-- | plugins/CoreHome/templates/_dataTable.twig | 2 | ||||
-rw-r--r-- | plugins/Live/Controller.php | 10 | ||||
-rw-r--r-- | plugins/Live/Exception/MaxExecutionTimeExceededException.php | 14 | ||||
-rw-r--r-- | plugins/Live/Model.php | 125 | ||||
-rw-r--r-- | plugins/Live/lang/en.json | 4 | ||||
-rw-r--r-- | plugins/Live/templates/getLastVisitsStart.twig | 4 | ||||
-rw-r--r-- | plugins/Live/tests/Integration/ModelTest.php | 169 | ||||
-rw-r--r-- | tests/UI/expected-screenshots/UIIntegrationTest_admin_diagnostics_configfile.png | 4 |
10 files changed, 336 insertions, 12 deletions
diff --git a/config/global.ini.php b/config/global.ini.php index 74e3e306a9..e874b68b66 100755 --- a/config/global.ini.php +++ b/config/global.ini.php @@ -548,6 +548,12 @@ live_widget_visitor_count_last_minutes = 3 ; this limit can be adjusted by changing this value live_visitor_profile_max_visits_to_aggregate = 100 +; If configured, will abort a MySQL query after the configured amount of seconds and show an error in the UI to for +; example lower the date range or tweak the segment (if one is applied). Set it to -1 if the query time should not be +; limited. Note: This feature requires a recent MySQL version (5.7 or newer). Some MySQL forks like MariaDB might not +; support this feature which uses the MAX_EXECUTION_TIME hint. +live_query_max_execution_time = -1 + ; In "All Websites" dashboard, when looking at today's reports (or a date range including today), ; the page will automatically refresh every 5 minutes. Set to 0 to disable automatic refresh multisites_refresh_after_seconds = 300 diff --git a/core/Updater/Migration/Db.php b/core/Updater/Migration/Db.php index 2cda50accb..011dfd566b 100644 --- a/core/Updater/Migration/Db.php +++ b/core/Updater/Migration/Db.php @@ -67,4 +67,14 @@ abstract class Db extends Migration */ const ERROR_CODE_TABLE_NOT_EXISTS = 1146; + /** + * Query execution was interrupted, maximum statement execution time exceeded + */ + const ERROR_CODE_MAX_EXECUTION_TIME_EXCEEDED_QUERY_INTERRUPTED = 3024; + + /** + * Sort aborted: Query execution was interrupted, maximum statement execution time exceeded + */ + const ERROR_CODE_MAX_EXECUTION_TIME_EXCEEDED_SORT_ABORTED = 1028; + } diff --git a/plugins/CoreHome/templates/_dataTable.twig b/plugins/CoreHome/templates/_dataTable.twig index 3d8be6103d..29535d8bb8 100644 --- a/plugins/CoreHome/templates/_dataTable.twig +++ b/plugins/CoreHome/templates/_dataTable.twig @@ -47,7 +47,7 @@ <div class="dataTableWrapper"> {% if error is defined %} - {{ error.message }} + <div piwik-alert="danger">{{ error.message }}</div> {% else %} {% if properties.show_header_message is defined and properties.show_header_message is not empty %} <div class='datatableHeaderMessage'>{{ properties.show_header_message | raw }}</div> diff --git a/plugins/Live/Controller.php b/plugins/Live/Controller.php index 41829626fc..a7af05e8d3 100644 --- a/plugins/Live/Controller.php +++ b/plugins/Live/Controller.php @@ -88,8 +88,14 @@ class Controller extends \Piwik\Plugin\Controller $view = new View('@Live/getLastVisitsStart'); $view->idSite = (int) $this->idSite; - $api = new Request("method=Live.getLastVisitsDetails&idSite={$this->idSite}&filter_limit=10&format=original&serialize=0&disable_generic_filters=1"); - $visitors = $api->process(); + $error = ''; + try { + $api = new Request("method=Live.getLastVisitsDetails&idSite={$this->idSite}&filter_limit=10&format=original&serialize=0&disable_generic_filters=1"); + $visitors = $api->process(); + } catch (\Exception $e) { + $error = $e->getMessage(); + } + $view->error = $error; $view->visitors = $visitors; return $this->render($view); diff --git a/plugins/Live/Exception/MaxExecutionTimeExceededException.php b/plugins/Live/Exception/MaxExecutionTimeExceededException.php new file mode 100644 index 0000000000..26555dc313 --- /dev/null +++ b/plugins/Live/Exception/MaxExecutionTimeExceededException.php @@ -0,0 +1,14 @@ +<?php +/** + * Piwik - free/libre analytics platform + * + * @link https://matomo.org + * @license http://www.gnu.org/licenses/gpl-3.0.html GPL v3 or later + * + */ + +namespace Piwik\Plugins\Live\Exception; + +class MaxExecutionTimeExceededException extends \Exception +{ +} diff --git a/plugins/Live/Model.php b/plugins/Live/Model.php index 3a089aff5a..1ff5515d4f 100644 --- a/plugins/Live/Model.php +++ b/plugins/Live/Model.php @@ -12,14 +12,17 @@ namespace Piwik\Plugins\Live; use Exception; use Piwik\API\Request; use Piwik\Common; +use Piwik\Config; use Piwik\Container\StaticContainer; use Piwik\Date; use Piwik\Db; use Piwik\Period; use Piwik\Period\Range; use Piwik\Piwik; +use Piwik\Plugins\Live\Exception\MaxExecutionTimeExceededException; use Piwik\Segment; use Piwik\Site; +use Piwik\Updater\Migration\Db as DbMigration; class Model { @@ -73,14 +76,14 @@ class Model list($sql, $bind) = $this->makeLogVisitsQueryString($idSite, $queryRange[0], $queryRange[1], $segment, $updatedOffset, $updatedLimit, $visitorId, $minTimestamp, $filterSortOrder); - $visits = Db::getReader()->fetchAll($sql, $bind); + $visits = $this->executeLogVisitsQuery($sql, $bind, $segment, $dateStart, $dateEnd, $minTimestamp, $limit); if (!empty($offset) && empty($visits)) { // find out if there are any matches $updatedOffset = 0; list($sql, $bind) = $this->makeLogVisitsQueryString($idSite, $queryRange[0], $queryRange[1], $segment, $updatedOffset, $updatedLimit, $visitorId, $minTimestamp, $filterSortOrder); - $visits = Db::getReader()->fetchAll($sql, $bind); + $visits = $this->executeLogVisitsQuery($sql, $bind, $segment, $dateStart, $dateEnd, $minTimestamp, $limit); if (!empty($visits)) { // found out the number of visits that we skipped in this query $offset = $offset - count($visits); @@ -112,6 +115,102 @@ class Model return $foundVisits; } + private function executeLogVisitsQuery($sql, $bind, $segment, $dateStart, $dateEnd, $minTimestamp, $limit) + { + $readerDb = Db::getReader(); + try { + $visits = $readerDb->fetchAll($sql, $bind); + } catch (Exception $e) { + $this->handleMaxExecutionTimeError($readerDb, $e, $sql, $bind, $segment, $dateStart, $dateEnd, $minTimestamp, $limit); + throw $e; + } + return $visits; + } + + /** + * @param \Piwik\Tracker\Db|\Piwik\Db\AdapterInterface|\Piwik\Db $readerDb + * @param Exception $e + * @param $sql + * @param array $bind + * @param $segment + * @param $dateStart + * @param $dateEnd + * @param $minTimestamp + * @param $limit + * + * @throws MaxExecutionTimeExceededException + */ + public function handleMaxExecutionTimeError($readerDb, $e, $sql, $bind, $segment, $dateStart, $dateEnd, $minTimestamp, $limit) + { + // we also need to check for the 'maximum statement execution time exceeded' text as the query might be + // aborted at different stages and we can't really know all the possible codes at which it may be aborted etc + $isMaxExecutionTimeError = $readerDb->isErrNo($e, DbMigration::ERROR_CODE_MAX_EXECUTION_TIME_EXCEEDED_QUERY_INTERRUPTED) + || $readerDb->isErrNo($e, DbMigration::ERROR_CODE_MAX_EXECUTION_TIME_EXCEEDED_SORT_ABORTED) + || strpos($e->getMessage(), 'maximum statement execution time exceeded') !== false; + + if ($isMaxExecutionTimeError) { + $message = ''; + + if ($this->isLookingAtMoreThanOneDay($dateStart, $dateEnd, $minTimestamp)) { + $message .= ' ' . Piwik::translate('Live_QueryMaxExecutionTimeExceededReasonDateRange'); + } + + if (!empty($segment)) { + $message .= ' ' . Piwik::translate('Live_QueryMaxExecutionTimeExceededReasonSegment'); + } + + $limitThatCannotBeSelectedInUiButOnlyApi = 550; + if ($limit > $limitThatCannotBeSelectedInUiButOnlyApi) { + $message .= ' ' . Piwik::translate('Live_QueryMaxExecutionTimeExceededLimit'); + } + + if (empty($message)) { + $message .= ' ' . Piwik::translate('Live_QueryMaxExecutionTimeExceededReasonUnknown'); + } + + $message = Piwik::translate('Live_QueryMaxExecutionTimeExceeded') . ' ' . $message; + + $params = array( + 'sql' => $sql, 'bind' => $bind, 'segment' => $segment, 'limit' => $limit + ); + + /** + * @ignore + * @internal + */ + Piwik::postEvent('Live.queryMaxExecutionTimeExceeded', array($params)); + throw new MaxExecutionTimeExceededException($message); + } + } + + /** + * @param Date|null $dateStart + * @param Date|null $dateEnd + * @param int|null $minTimestamp + * @return bool + * @throws Exception + */ + public function isLookingAtMoreThanOneDay($dateStart, $dateEnd, $minTimestamp) + { + if (!$dateStart) { + if (!$minTimestamp) { + return true; + } else { + $dateStart = Date::factory($minTimestamp); + } + } + + if (!$dateEnd) { + $dateEnd = Date::now(); + } + + if ($dateEnd->subHour(36)->isEarlier($dateStart)) { + return false; + } + + return true; + } + public function splitDatesIntoMultipleQueries($dateStart, $dateEnd, $limit, $offset) { $virtualDateEnd = $dateEnd; @@ -391,11 +490,18 @@ class Model $innerQuery = $segment->getSelectQuery($select, $from, $where, $whereBind, $orderBy, $groupBy, $innerLimit, $offset); $bind = $innerQuery['bind']; + + $maxExecutionTimeHint = $this->getMaxExecutionTimeMySQLHint(); + if ($visitorId) { + // for now let's not apply when looking for a specific visitor + $maxExecutionTimeHint = ''; + } + // Group by idvisit so that a given visit appears only once, useful when for example: // 1) when a visitor converts 2 goals // 2) when an Action Segment is used, the inner query will return one row per action, but we want one row per visit $sql = " - SELECT sub.* FROM ( + SELECT $maxExecutionTimeHint sub.* FROM ( " . $innerQuery['sql'] . " ) AS sub GROUP BY sub.idvisit @@ -407,6 +513,19 @@ class Model return array($sql, $bind); } + private function getMaxExecutionTimeMySQLHint() + { + $general = Config::getInstance()->General; + $maxExecutionTime = $general['live_query_max_execution_time']; + $maxExecutionTimeHint = ''; + if (is_numeric($maxExecutionTime) && $maxExecutionTime > 0) { + $timeInMs = $maxExecutionTime * 1000; + $timeInMs = (int) $timeInMs; + $maxExecutionTimeHint = ' /*+ MAX_EXECUTION_TIME('.$timeInMs.') */ '; + } + return $maxExecutionTimeHint; + } + /** * @param $idSite * @return Site diff --git a/plugins/Live/lang/en.json b/plugins/Live/lang/en.json index 62d85f3a0e..f346c7557e 100644 --- a/plugins/Live/lang/en.json +++ b/plugins/Live/lang/en.json @@ -36,6 +36,10 @@ "ToggleActions": "Toggle visibility of all actions", "TopVisitedPages": "Top visited pages", "VisitsLog": "Visits Log", + "QueryMaxExecutionTimeExceeded": "The query took too long to execute.", + "QueryMaxExecutionTimeExceededReasonDateRange": "This can happen if the selected date range is too large. Please try to select a smaller date range.", + "QueryMaxExecutionTimeExceededReasonSegment": "This can happen if the selected segment doesn't match any visit. Please try to check your selected segment.", + "QueryMaxExecutionTimeExceededReasonUnknown": "Please try again. If it happens repeatedly, please get in touch with the administrator or support.", "VisitorLog": "Visits Log", "VisitorLogDocumentation": "This table shows the latest visits within the selected date range. You can see when a visitor's last visit occurred by hovering over the date of a visit. %1$s If the date range includes today, you can see your visitors real time! %2$s The data displayed here is always live, regardless of whether and how often you are using the archiving cron job.", "VisitorLogNoDataMessagePurged": "Likely the data has been purged because the regular deletion of old raw data is enabled and the date for this report is more than %s days old. A super user can change this setting by going to Administration => Privacy.", diff --git a/plugins/Live/templates/getLastVisitsStart.twig b/plugins/Live/templates/getLastVisitsStart.twig index 04969679f3..c0a380a501 100644 --- a/plugins/Live/templates/getLastVisitsStart.twig +++ b/plugins/Live/templates/getLastVisitsStart.twig @@ -1,6 +1,9 @@ {# some users view thousands of pages which can crash the browser viewing Live! #} {% set maxPagesDisplayedByVisitor=100 %} +{% if error is not empty %} +<div piwik-alert="danger">{{ error }}</div> +{% else %} <ul id="visitsLive"> {% for visitor in visitors.getRows() %} <li id="{{ visitor.getColumn('idVisit') }}" class="visit"> @@ -128,3 +131,4 @@ $(function () { }); }); </script> +{% endif %}
\ No newline at end of file diff --git a/plugins/Live/tests/Integration/ModelTest.php b/plugins/Live/tests/Integration/ModelTest.php index 2132c9434d..ac27bdf2a8 100644 --- a/plugins/Live/tests/Integration/ModelTest.php +++ b/plugins/Live/tests/Integration/ModelTest.php @@ -9,8 +9,11 @@ namespace Piwik\Plugins\Live\tests\Integration; use Piwik\Common; +use Piwik\Config; use Piwik\Date; +use Piwik\Db; use Piwik\Piwik; +use Piwik\Plugins\Live\Exception\MaxExecutionTimeExceededException; use Piwik\Plugins\Live\Model; use Piwik\Tests\Framework\Fixture; use Piwik\Tests\Framework\Mock\FakeAccess; @@ -68,6 +71,60 @@ class ModelTest extends IntegrationTestCase return $validDates; } + public function test_handleMaxExecutionTimeError_doesNotThrowExceptionWhenNotExceededTime() + { + $db = Db::get(); + $e = new \Exception('foo bar baz'); + $sql = 'SELECT 1'; + $bind = array(); + $segment = ''; + $dateStart = Date::now()->subDay(1); + $dateEnd = Date::now(); + $minTimestamp = 1; + $limit = 50; + $model = new Model(); + $model->handleMaxExecutionTimeError($db, $e, $sql, $bind, $segment, $dateStart, $dateEnd, $minTimestamp, $limit); + $this->assertTrue(true); + } + + /** + * @expectedException \Piwik\Plugins\Live\Exception\MaxExecutionTimeExceededException + * @expectedExceptionMessage Live_QueryMaxExecutionTimeExceeded Live_QueryMaxExecutionTimeExceededReasonUnknown + */ + public function test_handleMaxExecutionTimeError_whenTimeIsExceeded_noReasonFound() + { + $db = Db::get(); + $e = new \Exception('[3024] Query execution was interrupted, maximum statement execution time exceeded'); + $sql = 'SELECT 1'; + $bind = array(); + $segment = ''; + $dateStart = Date::now()->subDay(1); + $dateEnd = Date::now(); + $minTimestamp = null; + $limit = 50; + $model = new Model(); + $model->handleMaxExecutionTimeError($db, $e, $sql, $bind, $segment, $dateStart, $dateEnd, $minTimestamp, $limit); + } + + /** + * @expectedException \Piwik\Plugins\Live\Exception\MaxExecutionTimeExceededException + * @expectedExceptionMessage Live_QueryMaxExecutionTimeExceeded Live_QueryMaxExecutionTimeExceededReasonDateRange Live_QueryMaxExecutionTimeExceededReasonSegment Live_QueryMaxExecutionTimeExceededLimit + */ + public function test_handleMaxExecutionTimeError_whenTimeIsExceeded_manyReasonsFound() + { + $db = Db::get(); + $e = new \Exception('Query execution was interrupted, maximum statement execution time exceeded'); + $sql = 'SELECT 1'; + $bind = array(); + $segment = 'userId>=1'; + $dateStart = Date::now()->subDay(10); + $dateEnd = Date::now(); + $minTimestamp = null; + $limit = 5000; + $model = new Model(); + $model->handleMaxExecutionTimeError($db, $e, $sql, $bind, $segment, $dateStart, $dateEnd, $minTimestamp, $limit); + } + public function test_getStandAndEndDate() { $model = new Model(); @@ -77,6 +134,54 @@ class ModelTest extends IntegrationTestCase $this->assertEquals('2019-01-01 00:00:00', $dateEnd->getDatetime()); } + public function test_isLookingAtMoreThanOneDay_whenNoDateSet() + { + $model = new Model(); + $this->assertTrue($model->isLookingAtMoreThanOneDay(null, null, null)); + } + + public function test_isLookingAtMoreThanOneDay_whenNoStartDateSet() + { + $model = new Model(); + $this->assertTrue($model->isLookingAtMoreThanOneDay(null, Date::now(), null)); + } + + public function test_isLookingAtMoreThanOneDay_whenNoStartDateSetAndMinTimestampIsOld() + { + $model = new Model(); + $this->assertTrue($model->isLookingAtMoreThanOneDay(null, Date::now(), Date::now()->subDay(5)->getTimestamp())); + } + + public function test_isLookingAtMoreThanOneDay_whenNoStartDateSetButMinTimestampIsRecent() + { + $model = new Model(); + $this->assertFalse($model->isLookingAtMoreThanOneDay(null, Date::now(), Date::now()->subHour(5)->getTimestamp())); + } + + public function test_isLookingAtMoreThanOneDay_whenNoEndDateIsSet_StartDateIsOld() + { + $model = new Model(); + $this->assertTrue($model->isLookingAtMoreThanOneDay(Date::now()->subDay(5), null, null)); + } + + public function test_isLookingAtMoreThanOneDay_whenNoEndDateIsSet_StartDateIsRecent() + { + $model = new Model(); + $this->assertFalse($model->isLookingAtMoreThanOneDay(Date::now()->subHour(5), null, null)); + } + + public function test_isLookingAtMoreThanOneDay_whenStartAndEndDateIsSet_onlyOneDay() + { + $model = new Model(); + $this->assertFalse($model->isLookingAtMoreThanOneDay(Date::yesterday()->subDay(1), Date::yesterday(), null)); + } + + public function test_isLookingAtMoreThanOneDay_whenStartAndEndDateIsSet_moreThanOneDay() + { + $model = new Model(); + $this->assertTrue($model->isLookingAtMoreThanOneDay(Date::yesterday()->subDay(2), Date::yesterday(), null)); + } + public function test_makeLogVisitsQueryString() { $model = new Model(); @@ -92,7 +197,7 @@ class ModelTest extends IntegrationTestCase $minTimestamp = false, $filterSortOrder = false ); - $expectedSql = ' SELECT sub.* FROM + $expectedSql = ' SELECT sub.* FROM ( SELECT log_visit.* FROM ' . Common::prefixTable('log_visit') . ' AS log_visit @@ -134,7 +239,7 @@ class ModelTest extends IntegrationTestCase $minTimestamp = false, $filterSortOrder = false ); - $expectedSql = ' SELECT sub.* FROM + $expectedSql = ' SELECT sub.* FROM ( SELECT log_visit.* FROM ' . Common::prefixTable('log_visit') . ' AS log_visit @@ -175,7 +280,7 @@ class ModelTest extends IntegrationTestCase $minTimestamp = false, $filterSortOrder = false ); - $expectedSql = ' SELECT sub.* FROM + $expectedSql = ' SELECT sub.* FROM ( SELECT log_visit.* FROM ' . Common::prefixTable('log_visit') . ' AS log_visit @@ -214,7 +319,7 @@ class ModelTest extends IntegrationTestCase $minTimestamp = false, $filterSortOrder = false ); - $expectedSql = ' SELECT sub.* FROM + $expectedSql = ' SELECT sub.* FROM ( SELECT log_inner.* @@ -248,6 +353,62 @@ class ModelTest extends IntegrationTestCase $this->assertEquals(SegmentTest::removeExtraWhiteSpaces($expectedBind), SegmentTest::removeExtraWhiteSpaces($bind)); } + public function test_makeLogVisitsQueryString_addsMaxExecutionHintIfConfigured() + { + $config = Config::getInstance(); + $general = $config->General; + $general['live_query_max_execution_time'] = 30; + $config->General = $general; + + $model = new Model(); + list($dateStart, $dateEnd) = $model->getStartAndEndDate($idSite = 1, 'month', '2010-01-01'); + list($sql, $bind) = $model->makeLogVisitsQueryString( + $idSite = 1, + $dateStart, + $dateEnd, + $segment = false, + $offset = 0, + $limit = 100, + $visitorId = false, + $minTimestamp = false, + $filterSortOrder = false + ); + $expectedSql = 'SELECT /*+ MAX_EXECUTION_TIME(30000) */ sub.* FROM ('; + + $general['live_query_max_execution_time'] = -1; + $config->General = $general; + + $this->assertStringStartsWith($expectedSql, trim($sql)); + } + + public function test_makeLogVisitsQueryString_doesNotAddsMaxExecutionHintForVisitorIds() + { + $config = Config::getInstance(); + $general = $config->General; + $general['live_query_max_execution_time'] = 30; + $config->General = $general; + + $model = new Model(); + list($dateStart, $dateEnd) = $model->getStartAndEndDate($idSite = 1, 'month', '2010-01-01'); + list($sql, $bind) = $model->makeLogVisitsQueryString( + $idSite = 1, + $dateStart, + $dateEnd, + $segment = false, + $offset = 0, + $limit = 100, + $visitorId = '1234567812345678', + $minTimestamp = false, + $filterSortOrder = false + ); + $expectedSql = 'SELECT sub.* FROM ('; + + $general['live_query_max_execution_time'] = -1; + $config->General = $general; + + $this->assertStringStartsWith($expectedSql, trim($sql)); + } + public function test_splitDatesIntoMultipleQueries_notMoreThanADayUsesOnlyOneQuery() { $dates = $this->splitDatesIntoMultipleQueries('2010-01-01 00:00:00', '2010-01-02 00:00:00', $limit = 5, $offset = 0); diff --git a/tests/UI/expected-screenshots/UIIntegrationTest_admin_diagnostics_configfile.png b/tests/UI/expected-screenshots/UIIntegrationTest_admin_diagnostics_configfile.png index 5b077378e8..b433b89813 100644 --- a/tests/UI/expected-screenshots/UIIntegrationTest_admin_diagnostics_configfile.png +++ b/tests/UI/expected-screenshots/UIIntegrationTest_admin_diagnostics_configfile.png @@ -1,3 +1,3 @@ version https://git-lfs.github.com/spec/v1 -oid sha256:51c4781efd832067a5919d6e103abb1bc96ae478df8c5a1ca155357832aa6494 -size 4329802 +oid sha256:3b7d0e8060f94d0e53447a61cdba1e94903890a55aa8788b8de6d5610e03e8de +size 4330295 |