Page MenuHomePhabricator

deeptest Jenkins jobs became slower than they used to
Closed, ResolvedPublic

Description

While looking at the Zuul status page I noticed the Pywikibot deeptest jobs had been running for an hour which is way slower than their usual ~ 15 minutes.

The two changes got +2ed today:

The jobs have been running for 35 minutes and are still running.

From our Grafana dashboard tracking the duration of jobs ( https://grafana.wikimedia.org/d/ccaceff0-9ca6-4c89-9c4b-9138003439bf/zuul-job-prometheus?orgId=1&from=now-30d&to=now&timezone=utc&var-pipeline=$__all&var-job=pywikibot-core-tox-deeptest-py39&var-job=pywikibot-core-tox-deeptest-py314&var-status=SUCCESS&viewPanel=panel-5 ) here is the duration of successful py39/py314 deeptest jobs over 30 days:

pywikibot_deeptest_30days.png (836×589 px, 53 KB)

I do not know the reason, but it should be investigated. I would assume new tests have recently been added or maybe the queries are throttled more than they used to be?

Details

Event Timeline

@hashar: I guess there were a lot of wait cycles due to maxlag retries (see T421642) and some API timeouts for log events have been observed over the last few days.

There are up to 5 retries, and the wait time depends on the lag value returned in the error response, multiplied by the cycle counter. This can add a significant amount of time to the overall runtime.

I don't think new tests are necessarily the cause. Usually the tests still needs about 13 minutes:
https://gerrit.wikimedia.org/r/c/pywikibot/core/+/1324359

Here is a test which needs ~40 minutes and there were 40 "Maximum retries attempted due to maxlag without success."

You will see other peaks if you extend the timeline to 90 days, for example.

Some ideas:

  • increase config.maxlag parameter for deeptests (default is 5 as suggested in https://www.mediawiki.org/wiki/Manual:Maxlag_parameter); we have 90 instead of 5 for doctests.
  • decrease wait cycles (currently 5 times)
  • adaptive retry escalation: increase maxlag parameter with every wait cycle

Change #1324377 had a related patch set uploaded (by Xqt; author: Xqt):

[pywikibot/core@master] maxlag: Remove minimum retry limit from wait cycle

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

Change #1324377 merged by JJMC89:

[pywikibot/core@master] maxlag: Remove minimum retry limit from wait cycle

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

@Xqt thank you for the detailed reply!

I did not look up further than 30 days and went to file this task to raise awareness of a potential regression/code issue that would have made the suite way slower than expected :-] Feel free to mark this task resolved if there is nothing to act on.

Xqt claimed this task.

See comment above

@Xqt there was another report filed about the CiviCRM build suddenly timing out, that was due to a faulty setting on the Ceph file backend. And while investigating I found that the newer hosts on WMCS are way slower than other. Thus when a build is scheduled on a slow host, the job takes longer. See T434024#12195653 and following comments/tasks.

I did not dig further at the time you filed the task because I assumed the deeptest to naturally have a wide dispredancy of runtime duration. It is entirely possible that some of the slow deeptest happened to have run on the slow WMCS hosts.

Thus essentially it does not just affect pywikibot, it is an infrastructure problem and it is being looked at.