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

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.

In T174205#3602981, @dmaza wrote:

@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: Were you able to figure out how to access these logs?

I think I found it: https://logstash.wikimedia.org/app/kibana#/dashboard/941a0560-b9b2-11e7-a3f7-cb9288bcae84?_g=h@44136fa&_a=h@57ffae5

@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.