[MediaWiki-commits] [Gerrit] mediawiki...AbuseFilter[master]: Add slow filters debug data to the logs.
jenkins-bot has submitted this change and it was merged. (
https://gerrit.wikimedia.org/r/380621 )
Change subject: Add slow filters debug data to the logs.
..
Add slow filters debug data to the logs.
When $wgAbuseFilterRuntimeProfile is true, all filters taking
longer than $wgAbuseFilterRuntimeLimit will be logged for
later analysis
Bug: T174205
Change-Id: Id81833afa8421476a6cee47eb3393acdb3a38d65
---
M AbuseFilter.php
M extension.json
M includes/AbuseFilter.class.php
3 files changed, 51 insertions(+), 14 deletions(-)
Approvals:
jenkins-bot: Verified
Kaldari: Looks good to me, approved
diff --git a/AbuseFilter.php b/AbuseFilter.php
index 7f13eaf..58c410b 100644
--- a/AbuseFilter.php
+++ b/AbuseFilter.php
@@ -122,3 +122,8 @@
* Whether to record runtime metrics for all filters combined.
*/
$wgAbuseFilterRuntimeProfile = false;
+
+/**
+ * Runtime in milliseconds before a filter is considered slow.
+ */
+$wgAbuseFilterSlowFilterRuntimeLimit = 500;
diff --git a/extension.json b/extension.json
index a043b6c..dbda826 100644
--- a/extension.json
+++ b/extension.json
@@ -249,7 +249,8 @@
},
"AbuseFilterLogIPMaxAge": 7776000,
"AbuseFilterProfile": false,
- "AbuseFilterRuntimeProfile": false
+ "AbuseFilterRuntimeProfile": false,
+ "AbuseFilterSlowFilterRuntimeLimit": 500
},
"load_composer_autoloader": true,
"manifest_version": 1
diff --git a/includes/AbuseFilter.class.php b/includes/AbuseFilter.class.php
index 3ce5cdb..2d1face 100644
--- a/includes/AbuseFilter.class.php
+++ b/includes/AbuseFilter.class.php
@@ -450,10 +450,11 @@
*
* @param AbuseFilterVariableHolder $vars
* @param string $group The filter's group (as defined in
$wgAbuseFilterValidGroups)
+* @param Title|null $title
*
* @return bool[] Map of (integer filter ID => bool)
*/
- public static function checkAllFilters( $vars, $group = 'default' ) {
+ public static function checkAllFilters( $vars, $group = 'default',
Title $title = null ) {
global $wgAbuseFilterCentralDB, $wgAbuseFilterIsCentral;
// Fetch from the database.
@@ -472,7 +473,7 @@
);
foreach ( $res as $row ) {
- $filter_matched[$row->af_id] = self::checkFilter( $row,
$vars, true );
+ $filter_matched[$row->af_id] = self::checkFilter( $row,
$vars, $title );
}
if ( $wgAbuseFilterCentralDB && !$wgAbuseFilterIsCentral ) {
@@ -510,7 +511,7 @@
foreach ( $res as $row ) {
$filter_matched['global-' . $row->af_id] =
- self::checkFilter( $row, $vars, true,
'global-' );
+ self::checkFilter( $row, $vars, $title,
'global-' );
}
}
@@ -524,17 +525,17 @@
* @static
* @param stdClass $row
* @param AbuseFilterVariableHolder $vars
-* @param bool $profile
+* @param Title|null $title
* @param string $prefix
* @return bool
*/
- public static function checkFilter( $row, $vars, $profile = false,
$prefix = '' ) {
- global $wgAbuseFilterProfile;
+ public static function checkFilter( $row, $vars, Title $title = null,
$prefix = '' ) {
+ global $wgAbuseFilterProfile, $wgAbuseFilterRuntimeProfile,
$wgAbuseFilterSlowFilterRuntimeLimit;
$filterID = $prefix . $row->af_id;
$startConds = $startTime = null;
- if ( $profile && $wgAbuseFilterProfile ) {
+ if ( $wgAbuseFilterProfile || $wgAbuseFilterRuntimeProfile ) {
$startConds = self::$condCount;
$startTime = microtime( true );
}
@@ -558,16 +559,46 @@
$result = false;
}
- if ( $profile && $wgAbuseFilterProfile ) {
- $endTime = microtime( true );
- $endConds = self::$condCount;
+ $timeTaken = microtime( true ) - $startTime;
+ $condsUsed = self::$condCount - $startConds;
- $timeTaken = $endTime - $startTime;
- $condsUsed = $endConds - $startConds;
+ if ( $wgAbuseFilterProfile ) {
self::recordProfilingResult( $row->af_id, $timeTaken,
$condsUsed );
}
+ $runtime = $timeTaken * 1000;
+ if ( $wgAbuseFilterRuntimeProfile && $runtime >
$wgAbuseFilterSlowFilterRuntimeLimit ) {
+ self::recordSlowFilter( $filterID, $runtime,
$condsUsed, $result, $title );
+ }
+
[MediaWiki-commits] [Gerrit] mediawiki...AbuseFilter[master]: Add slow filters debug data to the logs.
Dmaza has uploaded a new change for review. (
https://gerrit.wikimedia.org/r/380621 )
Change subject: Add slow filters debug data to the logs.
..
Add slow filters debug data to the logs.
When $wgAbuseFilterRuntimeProfile is true, all filters taking
longer than $wgAbuseFilterRuntimeLimit will be logged for
later analysis
Bug: T174205
Change-Id: Id81833afa8421476a6cee47eb3393acdb3a38d65
---
M AbuseFilter.php
M extension.json
M includes/AbuseFilter.class.php
3 files changed, 39 insertions(+), 9 deletions(-)
git pull ssh://gerrit.wikimedia.org:29418/mediawiki/extensions/AbuseFilter
refs/changes/21/380621/1
diff --git a/AbuseFilter.php b/AbuseFilter.php
index 7f13eaf..6746897 100644
--- a/AbuseFilter.php
+++ b/AbuseFilter.php
@@ -122,3 +122,8 @@
* Whether to record runtime metrics for all filters combined.
*/
$wgAbuseFilterRuntimeProfile = false;
+
+/**
+ * Runtime in miliseconds before a filter is considered slow.
+ */
+$wgAbuseFilterRuntimeLimit = 100;
diff --git a/extension.json b/extension.json
index a043b6c..a183d64 100644
--- a/extension.json
+++ b/extension.json
@@ -249,7 +249,8 @@
},
"AbuseFilterLogIPMaxAge": 7776000,
"AbuseFilterProfile": false,
- "AbuseFilterRuntimeProfile": false
+ "AbuseFilterRuntimeProfile": false,
+ "AbuseFilterRuntimeLimit": 100
},
"load_composer_autoloader": true,
"manifest_version": 1
diff --git a/includes/AbuseFilter.class.php b/includes/AbuseFilter.class.php
index 3ce5cdb..0a09ef7 100644
--- a/includes/AbuseFilter.class.php
+++ b/includes/AbuseFilter.class.php
@@ -529,12 +529,12 @@
* @return bool
*/
public static function checkFilter( $row, $vars, $profile = false,
$prefix = '' ) {
- global $wgAbuseFilterProfile;
+ global $wgAbuseFilterProfile, $wgAbuseFilterRuntimeProfile,
$wgAbuseFilterRuntimeLimit;
$filterID = $prefix . $row->af_id;
$startConds = $startTime = null;
- if ( $profile && $wgAbuseFilterProfile ) {
+ if ( $profile && ( $wgAbuseFilterProfile ||
$wgAbuseFilterRuntimeProfile ) ) {
$startConds = self::$condCount;
$startTime = microtime( true );
}
@@ -558,19 +558,43 @@
$result = false;
}
- if ( $profile && $wgAbuseFilterProfile ) {
- $endTime = microtime( true );
- $endConds = self::$condCount;
+ if ( $profile ) {
+ $timeTaken = microtime( true ) - $startTime;
+ $condsUsed = self::$condCount - $startConds;
- $timeTaken = $endTime - $startTime;
- $condsUsed = $endConds - $startConds;
- self::recordProfilingResult( $row->af_id, $timeTaken,
$condsUsed );
+ if ( $wgAbuseFilterProfile ) {
+ self::recordProfilingResult( $row->af_id,
$timeTaken, $condsUsed );
+ }
+
+ $runtime = $timeTaken * 1000;
+ if ( $wgAbuseFilterRuntimeProfile && $runtime >
$wgAbuseFilterRuntimeLimit ) {
+ self::recordSlowFilter( $row->af_id, $runtime,
$condsUsed );
+ }
}
return $result;
}
/**
+* Logs slow filter's runtime data for later analysis
+*
+* @param int $filterId
+* @param float $runtime
+* @param int $totalConditions
+*/
+ private static function recordSlowFilter( $filterId, $runtime,
$totalConditions ) {
+ $logger = LoggerFactory::getInstance( 'AbuseFilterRuntime' );
+ $logger->info( 'Edit filter is taking too long',
+ [
+ 'wiki' => wfWikiID(),
+ 'filter_id' => $filterId,
+ 'runtime' => $runtime,
+ 'total_conditions' => $totalConditions
+ ]
+ );
+ }
+
+ /**
* @param int $filter
*/
public static function resetFilterProfile( $filter ) {
--
To view, visit https://gerrit.wikimedia.org/r/380621
To unsubscribe, visit https://gerrit.wikimedia.org/r/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: Id81833afa8421476a6cee47eb3393acdb3a38d65
Gerrit-PatchSet: 1
Gerrit-Project: mediawiki/extensions/AbuseFilter
Gerrit-Branch: master
Gerrit-Owner: Dmaza
___
MediaWiki-commits mailing list
MediaWiki-commits@lists.wikimedia.org
https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
