Page MenuHomePhabricator

Log cases where abusefilter filters take over a certain amount of time to run
Closed, ResolvedPublic3 Story Points

Description

We should log cases where abusefilter filters take an extremely long time to run so that we can identify filters that may need to be optimized or that might require some improvements to the underlying code.

Event Timeline

kaldari created this task.Aug 25 2017, 8:52 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptAug 25 2017, 8:52 PM
He7d3r added a subscriber: He7d3r.Aug 30 2017, 5:19 PM
dbarratt set the point value for this task to 3.
dmaza added a subscriber: dmaza.Sep 1 2017, 1:55 PM

@TBolliger, @kaldari How many milliseconds are we gonna consider "too long" ?

dmaza claimed this task.Sep 1 2017, 1:58 PM

Having no idea the average speed of a filter, usability standards say anything over 0.1 seconds is too long. So, over 100 milliseconds?

Alternatively we could see the average speed and aim to measure the 10% slowest filters? or anything double the average?

@kaldari @MusikAnimal A few questions:

  1. Should I remove the old profiling logic? I remember conversations about it saying that it is useless 'cause it adds about ~1 sec to each edit. It is a lot of code and it is cluttering the extension. I see no reason to keep it.
  2. I propose to use the same flag $wgAbuseFilterRuntimeProfile to enable/disable this functionality, like we use for the data pushed to statsd. It is all runtime profiling in the end.
  3. I'm thinking on logging wikiId, filterId, totalRuntime, totalConditions to logstash. Do you agree?

If someone else needs to be tagged in this ticket, please tag them.

@MusikAnimal: Regarding the profiling, isn't it turned off on English Wikipedia, but enabled on other wikis? I can't remember.

Correct — the profiling is still enabled on other wikis: https://es.wikipedia.org/wiki/Especial:FiltroAntiAbusos/4

De las últimas acciones, este filtro ha coincidido con 0 (0,00%). En promedio, su tiempo de ejecución es de 0,27 ms, y consume 4 condiciones del límite de condiciones.

@kaldari @MusikAnimal A few questions:

  1. Should I remove the old profiling logic? I remember conversations about it saying that it is useless 'cause it adds about ~1 sec to each edit. It is a lot of code and it is cluttering the extension. I see no reason to keep it.
  2. I propose to use the same flag $wgAbuseFilterRuntimeProfile to enable/disable this functionality, like we use for the data pushed to statsd. It is all runtime profiling in the end.
  3. I'm thinking on logging wikiId, filterId, totalRuntime, totalConditions to logstash. Do you agree?

If someone else needs to be tagged in this ticket, please tag them.

Yup, other wikis are using the profiling, but I was told it's not so accurate. It does give a general idea of which filters are taking a long time compared to other filters, so still of some use I suppose. It'd be nice if we had better profiling that didn't slow down editing =P Then maybe enwiki could get it back! We miss it :'(

That being said, not sure if your opinion on whether to use $wgAbuseFilterRuntimeProfile changes. For now I'd probably leave things as-is, and one day we can revisit improving per-filter profiling.

Change 380621 had a related patch set uploaded (by Dmaza; owner: Dmaza):
[mediawiki/extensions/AbuseFilter@master] Add slow filters debug data to the logs.

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

Change 380621 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Add slow filters debug data to the logs.

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

dmaza closed this task as Resolved.Oct 12 2017, 11:14 PM
dmaza moved this task from Code Review to Done on the Anti-Harassment (AHT Sprint 7) board.

@dmaza: Were you able to figure out how to access these logs?

@dmaza: It seems to be recording about 1 hit per minute, which is pretty high. Let's try changing the threshold from 500 ms to 1000 ms so that we don't spam the logs.