Translate job execution time seems to have significantly increase
Closed, ResolvedPublicBUG REPORT
Actions

Description

For several weeks, I have noticed a huge delay with Translate jobs on Meta-Wiki.

Reproduction steps:

Edit a translatable page, mark the new version for translation, and observe the time for FuzzyBot to update translation pages.
Edit a translation unit (e.g. using Tux interface) and observe the time for the edit to affect the translation page.

What happens?:

It can take more than 120 seconds (e.g. mark action log, FuzzyBot edit).
It can take more than 60 seconds (e.g. unit edit, final page edit).

I did not immediately report this issue, because I thought it was due to a temporary server overload. But since it has been lasting for several weeks, it is not “temporary”.

I think this issue appears in August, but I am not sure. I am only sure I did not notice it in April.

Is there a way to get a job performance graph for 6 last months, in order to check whether this is actually a regression?

Details

	Subject	Repo	Branch	Lines +/-
	Update Translate job names	operations/deployment-charts	master	+2 -2

Customize query in gerrit

Related Objects
Search...

Status	Subtype	Assigned	Task
Open		None	T182943 Move namespaced extensions to use PSR-4 autoloading
Open		None	T278278 Adopt PSR-4 namespaces in WMF-deployed extensions/skins
Open		None	T193166 Adopt PSR-4 namespaces in Translate and modernize code
Resolved		Wangombe	T312006 Move classes under tag folder to namespace
Resolved	BUG REPORT	Nikerabbit	T318484 Translate job execution time seems to have significantly increase

Event Timeline

Pols12 created this task.Sep 24 2022, 7:39 PM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 24 2022, 7:39 PM

Not sure about the correct job, but some metrics are at https://grafana.wikimedia.org/d/CbmStnlGk/jobqueue-job?orgId=1&var-dc=eqiad%20prometheus%2Fk8s&var-job=MessageUpdateJob&from=now-90d&to=now

Increase in execution time for MessageUpdateJob do look suspicious, but it shouldn't affect case #2. https://grafana.wikimedia.org/d/CbmStnlGk/jobqueue-job?orgId=1&var-dc=eqiad%20prometheus%2Fk8s&var-job=RenderTranslationPageJob&from=now-90d&to=now looks okay with average being ~1.5 seconds (though many outliers given the p99 graph).

The changes for MessageUpdateJob seem to have started around August 15-16th, which could correspond to 1.39.0-wmf.25. We did some small maintenance for Translate jobs in that branch https://www.mediawiki.org/wiki/MediaWiki_1.39/wmf.25#Translate but nothing there should cause a performance regression.

For investigation.

Nikerabbit triaged this task as High priority.Sep 26 2022, 11:13 AM

Nikerabbit moved this task from Quarter Backlog to Priority: Localization infrastructure on the Language-Team (Language-2022-July-September) board.

The graph was showing times for TTMServerMessageUpdateJob in addition to MessageUpdateJob. This increase makes there makes sense and is known and doesn't affect FuzzyBot. The graph shows no change for MessageUpdateJob.

Looking at the first example in Logstash reqId:9b010468-b15c-4128-80fd-b24b9bf83305, I see that the page was marked around Sep 23, 2022 @ 19:37:55.685 and first log entry from the 'UpdateTranslatablePageJob` is at Sep 23, 2022 @ 19:39:08.748. That job spawned RenderTranslationPageJob which finished at Sep 23, 2022 @ 19:40:20.998.

This seems to indicate the delay was in the JobQueue. This graph seems to confirm it: https://grafana.wikimedia.org/d/CbmStnlGk/jobqueue-job?orgId=1&var-dc=eqiad%20prometheus%2Fk8s&var-job=UpdateTranslatablePageJob&from=now-90d&to=now&viewPanel=5: average delay is about minute.

Now, given we changed these job names recently, this seems a regression from that, given the old names are still used in https://gerrit.wikimedia.org/g/operations/deployment-charts/+/d5052e6d8bb1b89393b993e9b59762fe5db8bcb1/helmfile.d/services/changeprop-jobqueue/values.yaml#107. I believe if we update those names, we should be back to previous delays.

Change 835589 had a related patch set uploaded (by Nikerabbit; author: Nikerabbit):

[operations/deployment-charts@master] Update Translate job names

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

gerritbot added a project: Patch-For-Review.Sep 27 2022, 11:43 AM

Nikerabbit moved this task from In Progress to In Review on the Language-Team (Language-2022-July-September) board.Sep 27 2022, 11:44 AM

Nikerabbit added a parent task: T312006: Move classes under tag folder to namespace.

For comparison, the jobs with the old name had <1s delay before the change: https://grafana.wikimedia.org/d/CbmStnlGk/jobqueue-job?orgId=1&var-dc=eqiad%20prometheus%2Fk8s&var-job=TranslationsUpdateJob&from=now-90d&to=now&viewPanel=5

In T318484#8264297, @Nikerabbit wrote:

Now, given we changed these job names recently, this seems a regression from that, given the old names are still used in https://gerrit.wikimedia.org/g/operations/deployment-charts/+/d5052e6d8bb1b89393b993e9b59762fe5db8bcb1/helmfile.d/services/changeprop-jobqueue/values.yaml#107. I believe if we update those names, we should be back to previous delays.

You've already got the right fix in that review, good stuff! Just to confirm - when the job names changed they no longer had the concurrency rules or a dedicated worker applied to them, and so they fell into the low_traffic jobs bucket which has much more contested concurrency and less guarantees, hence slower times.

Change 835589 merged by jenkins-bot:

[operations/deployment-charts@master] Update Translate job names

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

Maintenance_bot removed a project: Patch-For-Review.Sep 29 2022, 12:30 PM