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 );
+ }
+
return $result;
+ }
+
+ /**
+ * Logs slow filter's runtime data for later analysis
+ *
+ * @param string $filterId
+ * @param float $runtime
+ * @param int $totalConditions
+ * @param Title|null $title
+ */
+ private static function recordSlowFilter(
+ $filterId, $runtime, $totalConditions, $matched, Title $title =
null
+ ) {
+ $title = $title ? $title->getPrefixedText() : '';
+
+ $logger = LoggerFactory::getInstance( 'AbuseFilterSlow' );
+ $logger->info(
+ 'Edit filter {filter_id} on {wiki} is taking longer
than expected',
+ [
+ 'wiki' => wfWikiID(),
+ 'filter_id' => $filterId,
+ 'title' => $title,
+ 'runtime' => $runtime,
+ 'matched' => $matched,
+ 'total_conditions' => $totalConditions
+ ]
+ );
}
/**
@@ -927,7 +958,7 @@
$statsd->increment(
'abusefilter.check-stash.hit' );
}
} else {
- $filter_matched = self::checkAllFilters( $vars, $group
);
+ $filter_matched = self::checkAllFilters( $vars, $group,
$title );
if ( $isForEdit && $mode !== 'stash' ) {
$logger->info( __METHOD__ . ": cache miss for
'$title' (key $stashKey)." );
$statsd->increment(
'abusefilter.check-stash.miss' );
--
To view, visit https://gerrit.wikimedia.org/r/380621
To unsubscribe, visit https://gerrit.wikimedia.org/r/settings
Gerrit-MessageType: merged
Gerrit-Change-Id: Id81833afa8421476a6cee47eb3393acdb3a38d65
Gerrit-PatchSet: 8
Gerrit-Project: mediawiki/extensions/AbuseFilter
Gerrit-Branch: master
Gerrit-Owner: Dmaza <dm...@wikimedia.org>
Gerrit-Reviewer: Dbarratt <dbarr...@wikimedia.org>
Gerrit-Reviewer: Dmaza <dm...@wikimedia.org>
Gerrit-Reviewer: Jackmcbarn <jackmcb...@gmail.com>
Gerrit-Reviewer: Kaldari <rkald...@wikimedia.org>
Gerrit-Reviewer: MaxSem <maxsem.w...@gmail.com>
Gerrit-Reviewer: MusikAnimal <musikani...@gmail.com>
Gerrit-Reviewer: Niharika29 <nko...@wikimedia.org>
Gerrit-Reviewer: Samwilson <s...@samwilson.id.au>
Gerrit-Reviewer: jenkins-bot <>
_______________________________________________
MediaWiki-commits mailing list
MediaWiki-commits@lists.wikimedia.org
https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
