| Urbanecm_WMF | |
| Sep 26 2024, 5:05 PM |
| F57560066: query.txt | |
| Sep 26 2024, 7:57 PM |
| F57560036: image.png | |
| Sep 26 2024, 7:39 PM |
[{reqId}] {exception_url} Wikimedia\RequestTimeout\RequestTimeoutException: The maximum execution time of {limit} seconds was exceededIt is not possible to see who s mentored by a given long-term mentor.
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Resolved | Urbanecm_WMF | T376124 Removing a mentor from the list of mentors does not always reassign newcomers | |||
| Resolved | PRODUCTION ERROR | Urbanecm_WMF | T375784 Getting a full list of mentors timeouts for long-term mentors (Wikimedia\RequestTimeout\RequestTimeoutException: The maximum execution time of {limit} seconds was exceeded) |
> $start = microtime(true); $res = \MediaWiki\MediaWikiServices::getInstance()->get('GrowthExperimentsMentorStore')->getMenteesByMentor(User::newFromName('Nick_Moyes'), 'primary'); $end = microtime(true);
= 1727370895.2964
> $end - $start
= 75.591993093491
>Apparently, just getting the list of mentees takes a good 75 seconds. For another mentor, Blaze_Wolf (T330071#10165865), the situation is even worse (82 seconds):
Psy Shell v0.12.3 (PHP 7.4.33 — cli) by Justin Hileman
> $start = microtime(true); $res = \MediaWiki\MediaWikiServices::getInstance()->get('GrowthExperimentsMentorStore')->getMenteesByMentor(User::newFromName('Blaze_Wolf'), 'primary'); $end = microtime(true); $end - $start;
= 82.123007059097
>Both times are well over what can finish within a single webrequest. It is also a significant portion of the time allowance for jobs (200 seconds), and quite possibly (one of the) root cause(s) for T354222: reassignMenteesJob is not able to finish in time when a mentor has too many mentees assigned.
A significant part of this appears to be taken by UserSelectQueryBuilder, see callgraph.
Change #1076016 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[mediawiki/extensions/GrowthExperiments@master] DatabaseMentorStore: Cast user IDs to integers before looking them up
Base query used by UserSelectQueryBuilder:
I found that a significant portion of the delay is caused by typing – $ids is an array of strings, not integers. Once that is fixed, the same logic runs within few seconds – verified via mwdebug. Moving to sprint for Code Review.
@Urbanecm_WMF not that the images are not publicly visible (and also not to me), is that intentional?
I'm curious: how did you find out that this was the cause?
Not intentional, I forgot to explicitly attach them to this task to ensure visibility. T310833 strikes yet again. Fixed, thanks for the note!
I'm curious: how did you find out that this was the cause?
At first, I measured the duration of individual steps DatabaseMentorStore::getMenteesByMentor() does. I did that via a lot of shell.php/eval.php fiddling (T375784#10180969 shows the general pattern I used). This led me to the conclusion that the majority of the time is used by UserSelectQueryBuilder.
Then, I used eval.php with the --d 2 parameter to get the actual SQL query UserSelectQueryBuilder uses (dumped in T375784#10181095). I ran it at one of the replicas, verifying the query itself takes the most time.
Once I opened the query, I realised the IDs are strings (not integers). Since I previously worked on a performance problem with exactly this cause, this was the first thing I checked (I executed the query again, this time with numerical IDs, and it finished much faster [seconds rather than more than a minute]). If interested, more details about the other performance problem can be found in a Techblog post I wrote about it.
Change #1076016 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@master] DatabaseMentorStore: Cast user IDs to integers before looking them up
Change #1076969 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[mediawiki/extensions/GrowthExperiments@wmf/1.43.0-wmf.24] DatabaseMentorStore: Cast user IDs to integers before looking them up
I'll probably backport this later today to all wikis, so we can observe the effect. But functionally, this should be fixed now.
Change #1076969 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@wmf/1.43.0-wmf.24] DatabaseMentorStore: Cast user IDs to integers before looking them up
Mentioned in SAL (#wikimedia-operations) [2024-10-01T08:39:45Z] <urbanecm@deploy2002> Started scap sync-world: Backport for [[gerrit:1076969|DatabaseMentorStore: Cast user IDs to integers before looking them up (T375784)]]
Mentioned in SAL (#wikimedia-operations) [2024-10-01T08:46:43Z] <urbanecm@deploy2002> Finished scap sync-world: Backport for [[gerrit:1076969|DatabaseMentorStore: Cast user IDs to integers before looking them up (T375784)]] (duration: 06m 58s)
I can now successfully download Nick's mentees:
urbanecm@wmf3345 ~ % time curl -s 'https://en.wikipedia.org/w/api.php?action=query&format=xml&gemmmentor=Nick_Moyes&list=growthmentormentee' > /dev/null curl -s > /dev/null 0.04s user 0.04s system 0% cpu 11.435 total urbanecm@wmf3345 ~ %
Still takes a considerable amount of time, but significantly less than a minute. Hopefully this would also help with the other mentorship-related timeouts.
Checked for wmf.24 - no recent errors (the last timestamp Sep 30, 2024 @ 09:18:26.971 ( logstash link) . Will check it on Oct 04/2024.
Just noting that with one of the original examples resolved in another task, an example with >25000 mentees IS completing on a basic api fetch: https://en.wikipedia.org/w/api.php?action=query&format=jsonfm&list=growthmentormentee&formatversion=2&gemmmentor=Dreamyshade
Thank you, @Xaosflux! After re-checking for the error on logstash link - all seems to be normal.