Query execution timeout for certain Special:Contributions queries
Closed, DuplicatePublicPRODUCTION ERROR
Actions

Description

Error

mwversion: 1.38.0-wmf.24
reqId: 05b13bdc-8dfd-4c8e-9da1-1f5148de683a
Find reqId in Logstash

normalized_message

[{reqId}] {exception_url}   Wikimedia\Rdbms\DBQueryError: Error 1969: Query execution was interrupted (max_statement_time exceeded) (db1096:3316)
Function: IndexPager::buildQueryInfo (contributions page unfiltered)
Query: SET STATEMENT max_statement_time=30 [query redacted]

exception.trace

from /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/Database.php(1655)
#0 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/Database.php(1639): Wikimedia\Rdbms\Database->getQueryException(string, integer, string, string)
#1 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/Database.php(1613): Wikimedia\Rdbms\Database->getQueryExceptionAndLog(string, integer, string, string)
#2 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/Database.php(1207): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
#3 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/Database.php(1859): Wikimedia\Rdbms\Database->query(string, string, integer)
#4 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/DBConnRef.php(69): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
#5 /srv/mediawiki/php-1.38.0-wmf.24/includes/libs/rdbms/database/DBConnRef.php(319): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#6 /srv/mediawiki/php-1.38.0-wmf.24/includes/specials/pagers/ContribsPager.php(303): Wikimedia\Rdbms\DBConnRef->select(array, array, array, string, array, array)
#7 /srv/mediawiki/php-1.38.0-wmf.24/includes/pager/IndexPager.php(276): ContribsPager->reallyDoQuery(string, integer, boolean)
#8 /srv/mediawiki/php-1.38.0-wmf.24/includes/pager/IndexPager.php(778): IndexPager->doQuery()
#9 /srv/mediawiki/php-1.38.0-wmf.24/includes/specials/SpecialContributions.php(330): IndexPager->getNumRows()
#10 /srv/mediawiki/php-1.38.0-wmf.24/includes/poolcounter/PoolCounterWorkViaCallback.php(74): SpecialContributions->{closure}()
#11 /srv/mediawiki/php-1.38.0-wmf.24/includes/poolcounter/PoolCounterWork.php(162): PoolCounterWorkViaCallback->doWork()
#12 /srv/mediawiki/php-1.38.0-wmf.24/includes/specials/SpecialContributions.php(355): PoolCounterWork->execute()
#13 /srv/mediawiki/php-1.38.0-wmf.24/includes/specialpage/SpecialPage.php(671): SpecialContributions->execute(NULL)
#14 /srv/mediawiki/php-1.38.0-wmf.24/includes/specialpage/SpecialPageFactory.php(1378): SpecialPage->run(NULL)
#15 /srv/mediawiki/php-1.38.0-wmf.24/includes/MediaWiki.php(315): MediaWiki\SpecialPage\SpecialPageFactory->executePath(string, RequestContext)
#16 /srv/mediawiki/php-1.38.0-wmf.24/includes/MediaWiki.php(910): MediaWiki->performRequest()
#17 /srv/mediawiki/php-1.38.0-wmf.24/includes/MediaWiki.php(564): MediaWiki->main()
#18 /srv/mediawiki/php-1.38.0-wmf.24/index.php(53): MediaWiki->run()
#19 /srv/mediawiki/php-1.38.0-wmf.24/index.php(46): wfIndexMain()
#20 /srv/mediawiki/w/index.php(3): require(string)
#21 {main}

Impact

User facing error messages for these URLs.

Notes

I'm seeing what looks like a number of variations on this in 1.38.0-wmf.24 (T300200), at least for Special:RecentChanges, Special:Contributions, and Special:Watchlist. Fairly low rate.

I think this is new, trying to get a handle on that before deciding if it warrants a rollback.

Details

Request URL: https://fr.wikipedia.org/w/index.php?title=*&offset=*&target=*&namespace=*&tagfilter=*&start=*&end=*

Related Objects

Mentioned In: T312815: DBPerformance: Expectation readQueryTime <= 5 not met (from ApiQueryUserContribs)
T303089: Consistent fatal timeout when visiting Special:Log default view for some users
Mentioned Here: T303089: Consistent fatal timeout when visiting Special:Log default view for some users
P21857 Special:Log go boom
T297708: Set max execution time for several expensive mediawiki actions
T300200: 1.38.0-wmf.24 deployment blockers

Event Timeline

brennen created this task.Mar 3 2022, 10:22 PM

Restricted Application added a project: Growth-Team. · View Herald TranscriptMar 3 2022, 10:22 PM

Restricted Application added a subscriber: Aklapper. · View Herald Transcript

...or did a log format just change slightly or something and these are more or less typical, but unexpectedly leaking into the mediawiki-new-errors dashboard?

After digging a bit more in logs, I think this is a false alarm. Rate of these looks pretty constant for the last 3 weeks. Filtering on mediawiki-new-errors may need tweaked.

Some discussion just now in #wikimedia-operations - seems likely to be a result of (or at least related to?) T297708.

brennen reopened this task as Open.Mar 5 2022, 12:05 AM

• MZMcBride subscribed.Mar 5 2022, 12:13 AM

Visiting https://en.wikipedia.org/wiki/Special:Log/MZMcBride seems to trigger this error consistently. That query is

P21857 Special:Log go boom

1	SET
2	STATEMENT max_statement_time = 30 FOR
3	SELECT
4	/! STRAIGHT_JOIN /
5	log_id,
6	log_type,
7	log_action,
8	log_timestamp,
9	log_namespace,
10	log_title,
11	log_params,
12	log_deleted,
13	user_id,
14	user_name,
15	user_editcount,
16	log_actor,
17	logging_actor.actor_user AS `log_user`,
18	logging_actor.actor_name AS `log_user_text`,
19	comment_log_comment.comment_text AS `log_comment_text`,
20	comment_log_comment.comment_data AS `log_comment_data`,
21	comment_log_comment.comment_id AS `log_comment_cid`,
22	(
23	SELECT
24	GROUP_CONCAT(ctd_name SEPARATOR ',')
25	FROM
26	`change_tag`
27	JOIN `change_tag_def` ON ((ct_tag_id = ctd_id))
28	WHERE
29	ct_log_id = log_id
30	) AS `ts_tags`
31	FROM
32	`logging`
33	JOIN `actor` `logging_actor` ON ((actor_id = log_actor))
34	LEFT JOIN `user` ON ((user_id = logging_actor.actor_user))
35	JOIN `comment` `comment_log_comment` ON (
36	(comment_log_comment.comment_id = log_comment_id)
37	)
38	WHERE
39	(
40	log_type NOT IN (
41	'spamblacklist',
42	'titleblacklist',
43	'urlshortener',
44	'abusefilter',
45	'abusefilterprivatedetails',
46	'oath',
47	'suppress'
48	)
49	)
50	AND (log_type != 'review')
51	AND (log_type != 'thanks')
52	AND (log_type != 'patrol')
53	AND (log_type != 'tag')
54	AND log_actor = 24276
55	AND ((log_deleted & 4) = 0)
56	ORDER BY
57	log_timestamp DESC
58	LIMIT
59	51

• MZMcBride mentioned this in T303089: Consistent fatal timeout when visiting Special:Log default view for some users.Mar 5 2022, 1:38 AM

Zabe subscribed.Mar 5 2022, 10:41 AM

In T303010#7754401, @brennen wrote:

Some discussion just now in #wikimedia-operations - seems likely to be a result of (or at least related to?) T297708.

Tagging DBA per the above.

Growth-Team is on here because Watchlist and RecentChanges are tagged, but it's not related to any changes we've made and I assume that people who worked on T297708 will address this task eventually. Moving this to Triaged on our team's board accordingly.

Krinkle renamed this task from Wikimedia\Rdbms\DBQueryError: Error 1969: Query execution was interrupted (max_statement_time exceeded) (db1096:3316) Function: [function] to Query execution timeout for certain Special:Contributions queries.Mar 14 2022, 4:45 PM

The original report was for a specific Special:Contributions query. This one to be exact:

https://fr.wikipedia.org/wiki/Special:Contributions/2A04%3ACEC0%3A0%3A0%3A0%3A0%3A0%3A0%2F32?offset=20220303191106

which is a custom query for a /32 CIDR IP-range. I am unable to reproduce this particular timeout though, even when I increase the size to 500 results and move several pages backward and forward in time, it seems quite snappy at the moment.

I've rescoped this task such as to not be generally about all timeouts in any situation on any special page, but slightly more specific. More details would be useful. It might be that this one is not deterministic/common enough to be worth having a task for.

Some of the later comments were about Special:Log timing out even for the default uncustomised query that we promote in the user interface. That seems like a more urgent issue and is tracked at T303089 now.

Krinkle moved this task from Untriaged to Mar 2022 on the Wikimedia-production-error board.Mar 14 2022, 4:49 PM

Zabe merged a task: T304967: DB error when viewing IP range contribs.Mar 29 2022, 3:55 PM

Zabe added subscribers: MBH, Base.

Umherirrender merged a task: T305675: IPv6 CIDR range not working when viewing the next page in special:contributions.Apr 8 2022, 7:55 PM

Umherirrender added subscribers: Jerrykim306, Stang, TheresNoTime, revi.

Izno moved this task from To triage to Special:Contributions / Special:DeletedContributions on the MediaWiki-Special-pages board.Apr 24 2022, 12:38 AM

brennen moved this task from Backlog to Logs/Train on the User-brennen board.Apr 25 2022, 10:28 PM

Malarz_pl subscribed.May 2 2022, 11:40 AM

TheresNoTime mentioned this in T312815: DBPerformance: Expectation readQueryTime <= 5 not met (from ApiQueryUserContribs).Jul 11 2022, 11:19 PM

Umherirrender added a project: Wikimedia-Slow-DB-Query.Sep 7 2022, 10:11 PM

Krinkle edited projects, added Unstewarded-production-error; removed Platform Engineering.Aug 18 2023, 7:35 PM

Krinkle unsubscribed.