[go: up one dir, main page]
Page MenuHomePhabricator
Create Task
Maniphest T306584

Commons Action API DB queries for logevents timeout (internal_api_error_DBQueryTimeoutError)
Open, Needs TriagePublicPRODUCTION ERROR
Actions

Description

request in JSON
{
	"action": "query",
	"format": "json",
	"maxlag": "5",
	"list": "logevents",
	"meta": "userinfo",
	"indexpageids": 1,
	"continue": "-||userinfo",
	"letype": "upload",
	"lestart": "2022-04-18T00:00:00.000Z",
	"leend": "2022-04-18T23:59:59.999Z",
	"ledir": "newer",
	"lenamespace": "6",
	"lelimit": "5000",
	"lecontinue": "20220418143831|323543786",
	"uiprop": "blockinfo|hasmsg"
}
Error
  • mwversion: 1.39.0-wmf.8 (a4aaf3c)
  • reqId: bf9acb80-f8bf-4600-b44c-6dab46ad4681
normalized_message
[{reqId}] {exception_url}   Wikimedia\Rdbms\DBQueryTimeoutError: A database query timeout has occurred. 
Query: SET STATEMENT max_statement_time=30 FOR SELECT  /*! STRAIGHT_JOIN */ log_id,log_type,log_action,log_timestamp,log_deleted,page_id,log_page,acto
exception.trace
from /srv/mediawiki/php-1.39.0-wmf.8/includes/libs/rdbms/database/Database.php(1775)
#0 /srv/mediawiki/php-1.39.0-wmf.8/includes/libs/rdbms/database/Database.php(1763): Wikimedia\Rdbms\Database->getQueryException(string, integer, string, string)
#1 /srv/mediawiki/php-1.39.0-wmf.8/includes/libs/rdbms/database/Database.php(1737): Wikimedia\Rdbms\Database->getQueryExceptionAndLog(string, integer, string, string)
#2 /srv/mediawiki/php-1.39.0-wmf.8/includes/libs/rdbms/database/Database.php(1217): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
#3 /srv/mediawiki/php-1.39.0-wmf.8/includes/libs/rdbms/database/Database.php(1983): Wikimedia\Rdbms\Database->query(string, string, integer)
#4 /srv/mediawiki/php-1.39.0-wmf.8/includes/libs/rdbms/querybuilder/SelectQueryBuilder.php(641): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
#5 /srv/mediawiki/php-1.39.0-wmf.8/includes/api/ApiQueryBase.php(427): Wikimedia\Rdbms\SelectQueryBuilder->fetchResultSet()
#6 /srv/mediawiki/php-1.39.0-wmf.8/includes/api/ApiQueryLogEvents.php(271): ApiQueryBase->select(string)
#7 /srv/mediawiki/php-1.39.0-wmf.8/includes/api/ApiQuery.php(631): ApiQueryLogEvents->execute()
#8 /srv/mediawiki/php-1.39.0-wmf.8/includes/api/ApiMain.php(1902): ApiQuery->execute()
#9 /srv/mediawiki/php-1.39.0-wmf.8/includes/api/ApiMain.php(874): ApiMain->executeAction()
#10 /srv/mediawiki/php-1.39.0-wmf.8/includes/api/ApiMain.php(845): ApiMain->executeActionWithErrorHandling()
#11 /srv/mediawiki/php-1.39.0-wmf.8/api.php(90): ApiMain->execute()
#12 /srv/mediawiki/php-1.39.0-wmf.8/api.php(45): wfApiMain()
#13 /srv/mediawiki/w/api.php(3): require(string)
#14 {main}
Impact

Since 2022-04-15 similar API queries have been timing out and returning error code internal_api_error_DBQueryTimeoutError.

Notes

Details

MediaWiki Version
1.39.0-wmf.8
Request URL
https://commons.wikimedia.org/w/api.php?action=query&format=json&maxlag=5&list=logevents&meta=userinfo&indexpageids=1&continue=-%7C%7Cuserinfo&letype=upload&lestart=2022-04-18T00%3A00%3A00.000Z&leend=2022-04-18T23%3A59%3A59.999Z&ledir=newer&lenamespace=6&lelimit=5000&lecontinue=20220418143831%7C323543786&uiprop=blockinfo%7Chasmsg

Related Objects

Event Timeline

JJMC89 created this task.Apr 21 2022, 1:25 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 21 2022, 1:25 AM
JJMC89 moved this task from Older to Untriaged on the Wikimedia-production-error board.Apr 21 2022, 3:08 AM
Zabe subscribed.Apr 21 2022, 7:22 AM
Zabe updated the task description. (Show Details)Apr 21 2022, 7:36 AM
Zabe set Release Version to 1.39.0-wmf.8.
Zabe set Phatality ID to ff6d54bf526de757711cc871c023a032e7045b59a595955ce915890b95451813.
Zabe unsubscribed.
Zabe subscribed.
Lucas_Werkmeister_WMDE subscribed.Apr 21 2022, 8:35 AM

Sounds like basically the same issue as T298845.

Lucas_Werkmeister_WMDE added a comment.Apr 21 2022, 8:44 AM

Full SQL query from logstash:

SET STATEMENT max_statement_time=30 FOR SELECT  /*! STRAIGHT_JOIN */ log_id,log_type,log_action,log_timestamp,log_deleted,page_id,log_page,actor_name,actor_user,log_namespace,log_title,log_params,comment_log_comment.comment_text AS `log_comment_text`,comment_log_comment.comment_data AS `log_comment_data`,comment_log_comment.comment_id AS `log_comment_cid`  FROM `logging` JOIN `actor` ON ((actor_id=log_actor)) LEFT JOIN `page` ON ((log_namespace=page_namespace) AND (log_title=page_title)) JOIN `comment` `comment_log_comment` ON ((comment_log_comment.comment_id = log_comment_id))   WHERE (log_type NOT IN ('spamblacklist','titleblacklist','urlshortener','abusefilterprivatedetails','oath','suppress')) AND log_type = 'upload' AND (log_timestamp>='20220418000000') AND (log_timestamp<='20220418235959') AND (log_timestamp > '20220418143831' OR (log_timestamp = '20220418143831' AND log_id >= 323543786)) AND log_namespace = 6 AND ((log_deleted & 1) != 1)  ORDER BY log_timestamp,log_id LIMIT 5001

Takes 58.9 seconds on the stats machines.

Umherirrender added a project: Wikimedia-Slow-DB-Query.Apr 21 2022, 9:56 AM
Umherirrender subscribed.

The query is affected by T297708.

Since https://gerrit.wikimedia.org/r/c/mediawiki/core/+/777448 some more database errors are reported as DBQueryTimeoutError and not longer as DBQueryError.

This query is for one specific log type, while T298845 is focused on the logs of one actor. Both query scenario has different index, but it could be a problem with the index as well (T303089)

Krinkle subscribed.Apr 21 2022, 3:18 PM

I note that this is reproducible even with a low limit (e.g. 50 instead of 5000). I also note that it involves relatively few conditions or complex features, not some rare edge case that we could perhaps argue isn't supported to always work at current resourcing (best effort, within timeout).

https://commons.wikimedia.org/w/api.php?action=query&format=json&maxlag=5&list=logevents&meta=userinfo&indexpageids=1&continue=-%7C%7Cuserinfo&letype=upload&lestart=2022-04-18T00%3A00%3A00.000Z&leend=2022-04-18T23%3A59%3A59.999Z&ledir=newer&lenamespace=6&lelimit=50&lecontinue=20220418143831%7C323543786&uiprop=blockinfo%7Chasmsg

Krinkle moved this task from Untriaged to Apr 2022 on the Wikimedia-production-error board.Apr 21 2022, 3:18 PM
Umherirrender added a comment.Apr 21 2022, 6:18 PM

A explain locally is using the index log_type_action (fields (log_type, log_action, log_timestamp)), it works better when forcing index log_type_time (fields (log_type, log_timestamp)), because log_action is not set by the WHERE conditions

Using upload/upload seems a bit faster:
https://commons.wikimedia.org/w/api.php?action=query&format=json&maxlag=5&list=logevents&meta=userinfo&indexpageids=1&continue=-%7C%7Cuserinfo&leaction=upload/upload&lestart=2022-04-18T00%3A00%3A00Z&leend=2022-04-18T23%3A59%3A59Z&ledir=newer&lenamespace=6&lelimit=max&lecontinue=20220418143831%7C323543786&uiprop=blockinfo%7Chasmsg

but has to be done with all possible types: upload/overwrite, upload/revert, upload/upload - https://commons.wikimedia.org/w/api.php?modules=query+logevents

Malarz_pl subscribed.May 2 2022, 11:40 AM
Umherirrender unsubscribed.Aug 31 2022, 8:00 PM
Yann subscribed.Aug 25 2024, 11:14 AM

While trying https://commons.wikimedia.org/wiki/Special:Log/Yann, I got

To avoid creating high database load, this query was aborted because the duration exceeded the limit. If you are reading many items at once, try doing multiple smaller operations instead.

[02bbda82-1d39-4863-a2f1-67e00e1be1f3] 2024-08-25 11:09:59: Fatal exception of type "Wikimedia\Rdbms\DBQueryTimeoutError"
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits