Page MenuHomePhabricator
Create Task
Maniphest T53294

Overhaul internal profiling system
Closed, ResolvedPublic
Actions

Description

For a extreme example, consider this filter:
https://en.wikipedia.org/wiki/Special:AbuseFilter/473

How can it consumes 23296 conditions if the condition limit is set to 1000?

Why does that value changes every second?
(reloading the page a few times I got: 51172, then 3986, then 7859, 14690, and so on...)

This is very confusing for users trying to debug and optimize the existing filters...

See Also:
T47045: Condition limit outrageously high after filter is disabled
T43691: Abuse filter inconsistent matching between testing and real checking
T57459: Include "condition limit consumed" column in AbuseFilter list

Original comment by Dragons flight on gerrit/201104

The AbuseFilter internal stats collection has been plagued by several bugs
for its entire history. The most prominent bug is caused by a race
condition where competing Apache instances can corrupt the data in
memcache. This is due to distributing stat data across multiple memcache
entries. Other stat corruption is associated with editing filters or
filter runs that abort due to reaching the condition limit.

The modifications here overhaul the stats system to solve these problems.
In particular, all per filter profile data is now hosted in an array
that is stored in memcache as a block so that the different stats
remain consistent. The restructuring also lays the groundwork for future
enhancements to the internal AbuseFilter profiling.

Details

Reference
bz51294
SubjectRepoBranchLines +/-
Merge global profiling keysmediawiki/extensions/AbuseFiltermaster+83 -63
Move per-filter matches profiling to per-filter datamediawiki/extensions/AbuseFiltermaster+27 -39
Store per-filter profiling in a single keymediawiki/extensions/AbuseFiltermaster+41 -30
Mostly unbreak profiling of number of conditions used by filtersmediawiki/extensions/AbuseFiltermaster+9 -7
Customize query in gerrit

Related Objects
Search...

Event Timeline

• bzimport raised the priority of this task from to High.Nov 22 2014, 1:52 AM
• bzimport added a project: AbuseFilter.
• bzimport set Reference to bz51294.
• bzimport added a subscriber: Unknown Object (MLST).
He7d3r created this task.Jul 13 2013, 4:14 PM
He7d3r added a comment.Jul 13 2013, 4:19 PM

I don't know if this is a problem, but I noticed the function getFilterProfile uses three keys:
wfMemcKey( 'abusefilter', 'profile', $filter, 'count' );
wfMemcKey( 'abusefilter', 'profile', $filter, 'total' );
wfMemcKey( 'abusefilter', 'profile-conds', 'total' );

But the resetFilterProfile only resets the first two. Shouldn't it also reset the key profile-conds?

[1] https://git.wikimedia.org/blob/mediawiki%2Fextensions%2FAbuseFilter.git/HEAD/AbuseFilter.class.php#L535

He7d3r added a comment.Jul 13 2013, 7:00 PM

See also:
https://en.wikipedia.org/wiki/Wikipedia_talk:Edit_filter?oldid=564103784#Request_for_Interpretation

Aklapper added a comment.Jul 15 2013, 11:16 AM

(In reply to comment #0)

For a extreme example, consider this filter:
https://en.wikipedia.org/wiki/Special:AbuseFilter/473

How can it consumes 23296 conditions if the condition limit is set to 1000?

Where exactly can I see that (position in the UI)?

He7d3r added a comment.Jul 15 2013, 11:48 AM

There is a line like this:

Statistics: Of the last 147 actions, this filter has matched 4 (2.72%). On average, its run time is 1.77 ms, and it consumes 13,105 conditions of the condition limit.

(the text comes from [[MediaWiki:abusefilter-edit-status]])

He7d3r added a comment.Jul 15 2013, 1:02 PM

It really doesn't known what a "limit" is: I just saw it saying filter 473 consumes 112,686 conditions (!)

Ciencia_Al_Poder added a comment.Aug 16 2013, 1:13 PM

See also:
https://www.mediawiki.org/wiki/Extension:AbuseFilter/Rules_format#Conditions

(added and documented by Helder)

• werdna unsubscribed.Dec 10 2014, 5:18 PM
Se4598 mentioned this in T87862: Show AbuseFilter average run time and used conditions in main table.Jan 29 2015, 7:16 PM
Dragons_flight subscribed.Feb 25 2015, 12:39 AM

This is really three separate bugs that all lead to per filter stats corruption:

  1. Failure to reset properly when a filter is edited.
  2. Failure to count properly when evaluation is aborted due to the condition limit being reached.
  3. A race condition that causes near simultaneous instances of the AbuseFilter to corrupt each others stats.

The third problem is the dominant one for the highly active wikis and can lead to really silly results. Both per filter condition counts and run times are affected, though the nonsensical condition counts are more noticeable.

I am nearly done with a patch that addresses this bug.

Dragons_flight mentioned this in T90754: Allow tracking of max run time / conditions consumed in AbuseFilter.Feb 25 2015, 6:38 PM
gerritbot subscribed.Apr 1 2015, 4:54 AM

Change 201104 had a related patch set uploaded (by Dragons flight):
Overhaul AbuseFilter internal profiling system

https://gerrit.wikimedia.org/r/201104

gerritbot added a project: Patch-For-Review.Apr 1 2015, 4:54 AM
matej_suchanek assigned this task to Dragons_flight.Jun 9 2015, 3:37 PM
matej_suchanek updated the task description. (Show Details)
matej_suchanek set Security to None.
Ciencia_Al_Poder mentioned this in T101648: Remove average run time and consumed conditions to make editing faster.Jun 9 2015, 7:07 PM
matej_suchanek mentioned this in T57459: Include "condition limit consumed" column in AbuseFilter list.Jun 12 2015, 12:37 PM
He7d3r updated the task description. (Show Details)Jan 6 2016, 9:31 PM
He7d3r removed a subscriber: • wikibugs-l-list.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJan 6 2016, 9:31 PM
Glaisher merged a task: T132191: The number of conditions used being reported is absolutely bonkers.Apr 8 2016, 4:27 PM
Glaisher added a subscriber: matmarex.
matmarex added a subscriber: • werdna.Apr 8 2016, 5:44 PM
In T53294#1064524, @Dragons_flight wrote:
  1. A race condition that causes near simultaneous instances of the AbuseFilter to corrupt each others stats.

The third problem is the dominant one for the highly active wikis and can lead to really silly results.

I don't think this can reasonably account for the reported values being wrong by a factor of ten or more.

I'm pretty sure that the number of conditions is counted globally, for all filters together, then treated it as if it was the per-filter number, which obviously results in off-the-wall values. I wonder what @werdna was smoking when committing rSVN52738. ;)

Glaisher subscribed.Apr 8 2016, 5:48 PM
gerritbot added a comment.Apr 8 2016, 5:51 PM

Change 282399 had a related patch set uploaded (by Bartosz Dziewoński):
Mostly unbreak profiling of number of conditions used by filters

https://gerrit.wikimedia.org/r/282399

Dragons_flight added a comment.Apr 8 2016, 7:57 PM
In T53294#2191188, @matmarex wrote:
In T53294#1064524, @Dragons_flight wrote:
  1. A race condition that causes near simultaneous instances of the AbuseFilter to corrupt each others stats.

The third problem is the dominant one for the highly active wikis and can lead to really silly results.

I don't think this can reasonably account for the reported values being wrong by a factor of ten or more.

I'm pretty sure that the number of conditions is counted globally, for all filters together, then treated it as if it was the per-filter number, which obviously results in off-the-wall values. I wonder what @werdna was smoking when committing rSVN52738. ;)

The race condition can give rise to very large errors. The condition counts and times are all stored as ratios, e.g. (total time elapsed) / (number of runs recorded). Because the numerator and denominator are in separate variables they are retrieved and saved to memcache separately. Under race conditions it is possible for one instance to update and save the numerator while a different instance is overwriting the denominator, leading to possible states that are out of sync. This is especially severe is one of the instances in the process of reseting the variables. If the denominator gets reset to zero but the numerator gets stuck somewhere else, the ratio blows up leading to large errors.

That's not saying there aren't other profiling errors. It is a mess actually, but getting to reports like 100,000 conditions exhausted is mostly caused by the fact the memcache numerators and denominators can get out of sync with each other.

Most of the memcache calls need to be eliminated for both practical and performance reasons and replaced with a small number of calls using structured data.

gerritbot added a comment.Apr 11 2016, 12:56 PM

Change 282399 merged by jenkins-bot:
Mostly unbreak profiling of number of conditions used by filters

https://gerrit.wikimedia.org/r/282399

ReleaseTaggerBot added a project: MW-1.27-release (WMF-deploy-2016-04-12_(1.27.0-wmf.21)).Apr 11 2016, 1:00 PM
matmarex added a comment.Apr 11 2016, 1:03 PM
In T53294#2191587, @Dragons_flight wrote:

If the denominator gets reset to zero but the numerator gets stuck somewhere else, the ratio blows up leading to large errors.

Hmm, I didn't think of this. That is more plausible.

matmarex removed a project: Patch-For-Review.Apr 11 2016, 1:03 PM
He7d3r mentioned this in T47045: Condition limit outrageously high after filter is disabled.Apr 12 2016, 6:31 PM
He7d3r mentioned this in T43691: Abuse filter inconsistent matching between testing and real checking.Oct 17 2016, 1:55 PM
Liuxinyu970226 subscribed.Nov 27 2016, 9:07 AM
Samwalton9-WMF subscribed.Nov 28 2016, 10:26 AM

What's the status of this? As far as I'm aware resource/condition tracking was simply removed altogether. Would it make sense to re-title this task to "re-implement resource tracking"?

He7d3r added a comment.Nov 28 2016, 11:22 AM

It is still available. See $wgAbuseFilterConditionLimit and T132189.

Samwalton9-WMF added a comment.Nov 28 2016, 11:24 AM

Ah, interesting. It seems then, that it takes too much computational power to leave this running in its current implementation?

Liuxinyu970226 added a project: Community-Wishlist-Survey-2016.Jan 1 2017, 2:56 AM
Liuxinyu970226 removed a project: Community-Wishlist-Survey-2016.Jan 2 2017, 12:50 AM
• TBolliger subscribed.Mar 16 2017, 11:28 PM
Daimona closed this task as Resolved.Mar 25 2018, 12:08 PM
Daimona subscribed.

There are enough reasons to close this:

  • Many wikis don't use such profiling anymore (and it has been changed since the creation of this task)
  • I checked many filters on en.wiki, and every of them reports sane values for used conditions
  • https://gerrit.wikimedia.org/r/282399 actually solved the issue
Liuxinyu970226 unsubscribed.Mar 26 2018, 3:33 AM
Daimona reopened this task as Open.Apr 4 2018, 3:21 PM

Reopening. The problem itself is resolved, but we're still waiting for Dragons_flight's patch to give a final fix to profiling system.

Daimona renamed this task from Condition limit is broken: consumes 100,000+ conditions limit is set to 1000 to Overhaul internal profiling system .Apr 4 2018, 3:22 PM
Daimona lowered the priority of this task from High to Medium.
Daimona added a parent task: T191039: Re-enable filter profiling on every wiki.
Daimona added a subtask: T87862: Show AbuseFilter average run time and used conditions in main table.Apr 4 2018, 3:25 PM
matmarex unsubscribed.Apr 5 2018, 5:15 PM
Daimona added a project: Patch-For-Review.Apr 24 2018, 4:28 PM
Daimona claimed this task.Oct 21 2018, 12:17 PM

Claiming as I took over the patch.

Huji mentioned this in T208842: Create a front end for making unit tests for filters.Nov 6 2018, 10:17 PM
Daimona added a comment.Jan 30 2019, 7:38 PM

Of note, I just discovered that ContentTranslation calls checkAllFilters while users are editing, in order -I think- to provide real-time feedback. But checkAllFilters has a call to recordStats, and this means that every time CX checks filters, it increases profiling data. This will be fixed in https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/AbuseFilter/+/487163/.

gerritbot added a comment.Feb 10 2019, 10:04 AM

Change 489443 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Store per-filter profiling in a single key

https://gerrit.wikimedia.org/r/489443

He7d3r added a comment.Feb 10 2019, 10:11 AM
In T53294#4918840, @Daimona wrote:

Of note, I just discovered that ContentTranslation calls checkAllFilters while users are editing, in order -I think- to provide real-time feedback. But checkAllFilters has a call to recordStats, and this means that every time CX checks filters, it increases profiling data. This will be fixed in https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/AbuseFilter/+/487163/.

See also

gerritbot added a comment.Feb 10 2019, 10:59 AM

Change 489445 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Move per-filter matches profiling to per-filter data

https://gerrit.wikimedia.org/r/489445

Daimona updated the task description. (Show Details)Feb 10 2019, 6:15 PM
Samwalton9-WMF unsubscribed.Feb 11 2019, 10:14 AM
gerritbot added a comment.Mar 23 2019, 1:39 PM

Change 489443 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Store per-filter profiling in a single key

https://gerrit.wikimedia.org/r/489443

gerritbot added a comment.Mar 23 2019, 1:39 PM

Change 489445 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Move per-filter matches profiling to per-filter data

https://gerrit.wikimedia.org/r/489445

gerritbot added a comment.Mar 23 2019, 1:39 PM

Change 201104 had a related patch set uploaded (by Daimona Eaytoy; owner: Dragons flight):
[mediawiki/extensions/AbuseFilter@master] Merge global profiling keys

https://gerrit.wikimedia.org/r/201104

Krinkle added a project: Performance-Team (Radar).Aug 2 2019, 10:58 PM
Krinkle moved this task from Limbo to Watching on the Performance-Team (Radar) board.
gerritbot added a comment.Aug 3 2019, 10:43 PM

Change 489443 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Store per-filter profiling in a single key

https://gerrit.wikimedia.org/r/489443

ReleaseTaggerBot added a project: MW-1.34-notes (1.34.0-wmf.17; 2019-08-06).Aug 3 2019, 11:00 PM
gerritbot added a comment.Aug 4 2019, 4:07 PM

Change 489445 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Move per-filter matches profiling to per-filter data

https://gerrit.wikimedia.org/r/489445

gerritbot added a comment.Aug 4 2019, 6:40 PM

Change 201104 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Merge global profiling keys

https://gerrit.wikimedia.org/r/201104

Daimona closed this task as Resolved.Aug 4 2019, 9:27 PM
Daimona removed a project: Patch-For-Review.
Krinkle mentioned this in T156095: Re-enable AbuseFilterCachingParser once we are sure it's safe.Aug 4 2019, 9:30 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL