Page MenuHomePhabricator

Expectation (readQueryTime <= 5) by MediaWiki\Api\ApiMain::setRequestExpectations not met (actual: {actualSeconds}) in trx #{trxId}:{query}
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error
  • mwversion: 1.45.0-wmf.8
  • timestamp: 2025-07-08T22:14:00.733Z
  • phpversion: 8.1.32
  • reqId: e60317e2-d5d3-40b0-a760-57c3a8dbd5a3
  • Find reqId in Logstash
normalized_message
Expectation (readQueryTime <= 5) by MediaWiki\Api\ApiMain::setRequestExpectations not met (actual: {actualSeconds}) in trx #{trxId}:
{query}
FrameLocationCall
from/srv/mediawiki/php-1.45.0-wmf.8/includes/libs/rdbms/TransactionProfiler.php(558)
#0/srv/mediawiki/php-1.45.0-wmf.8/includes/libs/rdbms/TransactionProfiler.php(363)Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated(string, Wikimedia\Rdbms\GeneralizedSql, float, string, string)
#1/srv/mediawiki/php-1.45.0-wmf.8/includes/libs/rdbms/database/TransactionManager.php(574)Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion(Wikimedia\Rdbms\GeneralizedSql, float, bool, int, string, string)
#2/srv/mediawiki/php-1.45.0-wmf.8/includes/libs/rdbms/database/Database.php(858)Wikimedia\Rdbms\TransactionManager->recordQueryCompletion(Wikimedia\Rdbms\GeneralizedSql, float, bool, int, string)
#3/srv/mediawiki/php-1.45.0-wmf.8/includes/libs/rdbms/database/Database.php(711)Wikimedia\Rdbms\Database->attemptQuery(Wikimedia\Rdbms\Query, string, bool)
#4/srv/mediawiki/php-1.45.0-wmf.8/includes/libs/rdbms/database/Database.php(638)Wikimedia\Rdbms\Database->executeQuery(Wikimedia\Rdbms\Query, string, int)
#5/srv/mediawiki/php-1.45.0-wmf.8/includes/libs/rdbms/database/Database.php(1367)Wikimedia\Rdbms\Database->query(Wikimedia\Rdbms\Query, string)
#6/srv/mediawiki/php-1.45.0-wmf.8/includes/libs/rdbms/database/DBConnRef.php(127)Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
#7/srv/mediawiki/php-1.45.0-wmf.8/includes/libs/rdbms/database/DBConnRef.php(351)Wikimedia\Rdbms\DBConnRef->__call(string, array)
#8/srv/mediawiki/php-1.45.0-wmf.8/includes/libs/rdbms/querybuilder/SelectQueryBuilder.php(762)Wikimedia\Rdbms\DBConnRef->select(array, array, array, string, array, array)
#9/srv/mediawiki/php-1.45.0-wmf.8/includes/api/ApiQueryBase.php(419)Wikimedia\Rdbms\SelectQueryBuilder->fetchResultSet()
#10/srv/mediawiki/php-1.45.0-wmf.8/includes/api/ApiQueryCategoryMembers.php(242)MediaWiki\Api\ApiQueryBase->select(string)
#11/srv/mediawiki/php-1.45.0-wmf.8/includes/api/ApiQueryCategoryMembers.php(63)MediaWiki\Api\ApiQueryCategoryMembers->run(MediaWiki\Api\ApiPageSet)
#12/srv/mediawiki/php-1.45.0-wmf.8/includes/api/ApiPageSet.php(287)MediaWiki\Api\ApiQueryCategoryMembers->executeGenerator(MediaWiki\Api\ApiPageSet)
#13/srv/mediawiki/php-1.45.0-wmf.8/includes/api/ApiPageSet.php(250)MediaWiki\Api\ApiPageSet->executeInternal(bool)
#14/srv/mediawiki/php-1.45.0-wmf.8/includes/api/ApiQuery.php(722)MediaWiki\Api\ApiPageSet->execute()
#15/srv/mediawiki/php-1.45.0-wmf.8/includes/api/ApiMain.php(2016)MediaWiki\Api\ApiQuery->execute()
#16/srv/mediawiki/php-1.45.0-wmf.8/includes/api/ApiMain.php(954)MediaWiki\Api\ApiMain->executeAction()
#17/srv/mediawiki/php-1.45.0-wmf.8/includes/api/ApiMain.php(925)MediaWiki\Api\ApiMain->executeActionWithErrorHandling()
#18/srv/mediawiki/php-1.45.0-wmf.8/includes/api/ApiEntryPoint.php(152)MediaWiki\Api\ApiMain->execute()
#19/srv/mediawiki/php-1.45.0-wmf.8/includes/MediaWikiEntryPoint.php(198)MediaWiki\Api\ApiEntryPoint->execute()
#20/srv/mediawiki/php-1.45.0-wmf.8/api.php(44)MediaWiki\MediaWikiEntryPoint->run()
#21/srv/mediawiki/w/api.php(3)require(string)
#22{main}
Impact
Notes
wikiadmin2023@10.64.0.43(itwiki)> explain SELECT  page_namespace,page_title,page_id,page_content_model,page_is_redirect,page_is_new,page_latest,page_touched,page_len,cl_from,cl_sortkey,cl_type,cl_timestamp  FROM `page`,`categorylinks` FORCE INDEX (cl_timestamp) JOIN `linktarget` ON ((cl_target_id = lt_id ))   WHERE lt_namespace = 14 AND lt_title = 'Cancellazioni_consensuali_prorogate_del_2_luglio_2025' AND (cl_from=page_id)  ORDER BY cl_timestamp,cl_from LIMIT 101  ;
+------+-------------+---------------+--------+----------------------------+--------------------+---------+------------------------------+----------+-----------------------------+
| id   | select_type | table         | type   | possible_keys              | key                | key_len | ref                          | rows     | Extra                       |
+------+-------------+---------------+--------+----------------------------+--------------------+---------+------------------------------+----------+-----------------------------+
|    1 | SIMPLE      | linktarget    | const  | PRIMARY,lt_namespace_title | lt_namespace_title | 261     | const,const                  | 1        | Using index                 |
|    1 | SIMPLE      | categorylinks | ALL    | NULL                       | NULL               | NULL    | NULL                         | 23119354 | Using where; Using filesort |
|    1 | SIMPLE      | page          | eq_ref | PRIMARY                    | PRIMARY            | 4       | itwiki.categorylinks.cl_from | 1        |                             |
+------+-------------+---------------+--------+----------------------------+--------------------+---------+------------------------------+----------+-----------------------------+
3 rows in set (0.001 sec)

wikiadmin2023@10.64.0.43(itwiki)>

Details

Request URL
https://it.wikipedia.org/w/api.php?action=query&assertuser=*&clprop=*&format=*&gcmdir=*&gcmlimit=*&gcmnamespace=*&gcmsort=*&gcmtitle=*&generator=*&inprop=*&maxlag=*&prop=*
Related Changes in Gerrit:

Event Timeline

The join between page and categorylinks seems wrong.

wikiadmin2023@10.64.131.12(itwiki)> explain SELECT  page_namespace,page_title,page_id,page_content_model,page_is_redirect,page_is_new,page_latest,page_touched,page_len,cl_from,cl_sortkey,cl_type,cl_timestamp  FROM `page` join `categorylinks` on cl_from = page_id JOIN `linktarget` ON ((cl_target_id = lt_id ))   WHERE lt_namespace = 14 AND lt_title = 'Cancellazioni_consensuali_prorogate_del_2_luglio_2025' AND (cl_from=page_id)  ORDER BY cl_from LIMIT 101  ;
+------+-------------+---------------+--------+----------------------------+--------------------+---------+------------------------------+------+-----------------------------+
| id   | select_type | table         | type   | possible_keys              | key                | key_len | ref                          | rows | Extra                       |
+------+-------------+---------------+--------+----------------------------+--------------------+---------+------------------------------+------+-----------------------------+
|    1 | SIMPLE      | linktarget    | const  | PRIMARY,lt_namespace_title | lt_namespace_title | 261     | const,const                  | 1    | Using index                 |
|    1 | SIMPLE      | categorylinks | ref    | PRIMARY,cl_sortkey_id      | cl_sortkey_id      | 9       | const                        | 1    | Using where; Using filesort |
|    1 | SIMPLE      | page          | eq_ref | PRIMARY                    | PRIMARY            | 4       | itwiki.categorylinks.cl_from | 1    |                             |
+------+-------------+---------------+--------+----------------------------+--------------------+---------+------------------------------+------+-----------------------------+
3 rows in set (0.001 sec)

This could be fast

Even with cl_timestamp being forced in order, it is fast, at least in this case:

wikiadmin2023@10.64.131.12(itwiki)> explain SELECT  page_namespace,page_title,page_id,page_content_model,page_is_redirect,page_is_new,page_latest,page_touched,page_len,cl_from,cl_sortkey,cl_type,cl_timestamp  FROM `page` join `categorylinks` on cl_from = page_id JOIN `linktarget` ON ((cl_target_id = lt_id ))   WHERE lt_namespace = 14 AND lt_title = 'Cancellazioni_consensuali_prorogate_del_2_luglio_2025' AND (cl_from=page_id)  ORDER BY cl_timestamp,cl_from LIMIT 101  ;
+------+-------------+---------------+--------+----------------------------+--------------------+---------+------------------------------+------+-----------------------------+
| id   | select_type | table         | type   | possible_keys              | key                | key_len | ref                          | rows | Extra                       |
+------+-------------+---------------+--------+----------------------------+--------------------+---------+------------------------------+------+-----------------------------+
|    1 | SIMPLE      | linktarget    | const  | PRIMARY,lt_namespace_title | lt_namespace_title | 261     | const,const                  | 1    | Using index                 |
|    1 | SIMPLE      | categorylinks | ref    | PRIMARY,cl_sortkey_id      | cl_sortkey_id      | 9       | const                        | 1    | Using where; Using filesort |
|    1 | SIMPLE      | page          | eq_ref | PRIMARY                    | PRIMARY            | 4       | itwiki.categorylinks.cl_from | 1    |                             |
+------+-------------+---------------+--------+----------------------------+--------------------+---------+------------------------------+------+-----------------------------+
3 rows in set (0.001 sec)

Change #1167562 had a related patch set uploaded (by Zabe; author: Zabe):

[mediawiki/core@master] ApiQueryCategoryMembers: Try stop forcing index in read new code

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

Change #1167562 merged by jenkins-bot:

[mediawiki/core@master] ApiQueryCategoryMembers: Try stop forcing index in read new code

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

Change #1167573 had a related patch set uploaded (by Zabe; author: Zabe):

[mediawiki/core@wmf/1.45.0-wmf.8] ApiQueryCategoryMembers: Try stop forcing index in read new code

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

Change #1167574 had a related patch set uploaded (by Zabe; author: Zabe):

[mediawiki/core@wmf/1.45.0-wmf.9] ApiQueryCategoryMembers: Try stop forcing index in read new code

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

Change #1167574 merged by jenkins-bot:

[mediawiki/core@wmf/1.45.0-wmf.9] ApiQueryCategoryMembers: Try stop forcing index in read new code

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

Change #1167573 merged by jenkins-bot:

[mediawiki/core@wmf/1.45.0-wmf.8] ApiQueryCategoryMembers: Try stop forcing index in read new code

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

Mentioned in SAL (#wikimedia-operations) [2025-07-09T13:52:37Z] <zabe@deploy1003> Started scap sync-world: Backport for [[gerrit:1167574|ApiQueryCategoryMembers: Try stop forcing index in read new code (T399037)]], [[gerrit:1167573|ApiQueryCategoryMembers: Try stop forcing index in read new code (T399037)]], [[gerrit:1167570|Fix categorylinks read new code for excluding categories (T398861 T398939)]], [[gerrit:1167569|Fix categorylinks read new code for excluding categories (T39886

Mentioned in SAL (#wikimedia-operations) [2025-07-09T13:54:47Z] <zabe@deploy1003> zabe: Backport for [[gerrit:1167574|ApiQueryCategoryMembers: Try stop forcing index in read new code (T399037)]], [[gerrit:1167573|ApiQueryCategoryMembers: Try stop forcing index in read new code (T399037)]], [[gerrit:1167570|Fix categorylinks read new code for excluding categories (T398861 T398939)]], [[gerrit:1167569|Fix categorylinks read new code for excluding categories (T398861 T398939)]] synced

Mentioned in SAL (#wikimedia-operations) [2025-07-09T14:01:20Z] <zabe@deploy1003> Finished scap sync-world: Backport for [[gerrit:1167574|ApiQueryCategoryMembers: Try stop forcing index in read new code (T399037)]], [[gerrit:1167573|ApiQueryCategoryMembers: Try stop forcing index in read new code (T399037)]], [[gerrit:1167570|Fix categorylinks read new code for excluding categories (T398861 T398939)]], [[gerrit:1167569|Fix categorylinks read new code for excluding categories (T3988

Zabe claimed this task.

We should still consider adding a cl_timestamp_id index to categorylinks, but no longer forcing cl_timestamp did the job here as it seems (at least for the wikis which are currently set to read new).

Zabe moved this task from Triage to Done on the DBA board.