Page MenuHomePhabricator
Create Task
Maniphest T346967

Fetching AbuseFilter's FilterUser involves query that takes more than 5 seconds
Closed, ResolvedPublic
Actions

Description

message
Expectation (readQueryTime <= 5) by MediaWiki::restInPeace not met (actual: 5.4763600826263) in trx #cf8136e1e4:
SELECT user_password FROM `user` WHERE user_name = 'X' LIMIT N
trace
from /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/TransactionProfiler.php(525)
#0 /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/TransactionProfiler.php(334): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated(string, Wikimedia\Rdbms\GeneralizedSql, double, string, string)
#1 /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/database/TransactionManager.php(615): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion(Wikimedia\Rdbms\GeneralizedSql, double, boolean, integer, string, string)
#2 /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/database/Database.php(859): Wikimedia\Rdbms\TransactionManager->recordQueryCompletion(Wikimedia\Rdbms\GeneralizedSql, double, boolean, integer, string)
#3 /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/database/Database.php(749): Wikimedia\Rdbms\Database->attemptQuery(Wikimedia\Rdbms\Query, string, boolean)
#4 /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/database/Database.php(670): Wikimedia\Rdbms\Database->executeQuery(Wikimedia\Rdbms\Query, string, integer)
#5 /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/database/Database.php(1383): Wikimedia\Rdbms\Database->query(Wikimedia\Rdbms\Query, string)
#6 /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/database/Database.php(1392): Wikimedia\Rdbms\Database->select(array, array, array, string, array, array)
#7 /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/database/DBConnRef.php(119): Wikimedia\Rdbms\Database->selectRow(array, array, array, string, array, array)
#8 /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/database/DBConnRef.php(369): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#9 /srv/mediawiki/php-1.41.0-wmf.26/includes/libs/rdbms/querybuilder/SelectQueryBuilder.php(741): Wikimedia\Rdbms\DBConnRef->selectRow(array, array, array, string, array, array)
#10 /srv/mediawiki/php-1.41.0-wmf.26/includes/auth/LocalPasswordPrimaryAuthenticationProvider.php(171): Wikimedia\Rdbms\SelectQueryBuilder->fetchRow()
#11 /srv/mediawiki/php-1.41.0-wmf.26/includes/auth/AuthManager.php(923): MediaWiki\Auth\LocalPasswordPrimaryAuthenticationProvider->testUserCanAuthenticate(string)
#12 /srv/mediawiki/php-1.41.0-wmf.26/includes/user/User.php(2346): MediaWiki\Auth\AuthManager->userCanAuthenticate(string)
#13 /srv/mediawiki/php-1.41.0-wmf.26/includes/user/User.php(882): User->isSystemUser()
#14 /srv/mediawiki/php-1.41.0-wmf.26/extensions/AbuseFilter/includes/FilterUser.php(57): User::newSystemUser(string, array)
#15 /srv/mediawiki/php-1.41.0-wmf.26/extensions/AbuseFilter/includes/FilterUser.php(48): MediaWiki\Extension\AbuseFilter\FilterUser->getUser()
#16 /srv/mediawiki/php-1.41.0-wmf.26/extensions/AbuseFilter/includes/Hooks/Handlers/CheckUserHandler.php(48): MediaWiki\Extension\AbuseFilter\FilterUser->getUserIdentity()
#17 /srv/mediawiki/php-1.41.0-wmf.26/includes/HookContainer/HookContainer.php(161): MediaWiki\Extension\AbuseFilter\Hooks\Handlers\CheckUserHandler->onCheckUserInsertChangesRow(string, string, array, MediaWiki\User\UserIdentityValue, RecentChange)
#18 /srv/mediawiki/php-1.41.0-wmf.26/extensions/CheckUser/src/Hook/HookRunner.php(60): MediaWiki\HookContainer\HookContainer->run(string, array)
#19 /srv/mediawiki/php-1.41.0-wmf.26/extensions/CheckUser/src/Hooks.php(406): MediaWiki\CheckUser\Hook\HookRunner->onCheckUserInsertChangesRow(string, string, array, MediaWiki\User\UserIdentityValue, RecentChange)
#20 /srv/mediawiki/php-1.41.0-wmf.26/extensions/CheckUser/src/Hooks.php(207): MediaWiki\CheckUser\Hooks::insertIntoCuChangesTable(array, string, MediaWiki\User\UserIdentityValue, RecentChange)
#21 /srv/mediawiki/php-1.41.0-wmf.26/extensions/CheckUser/src/Hooks.php(890): MediaWiki\CheckUser\Hooks::updateCheckUserData(RecentChange)
#22 /srv/mediawiki/php-1.41.0-wmf.26/includes/HookContainer/HookContainer.php(161): MediaWiki\CheckUser\Hooks->onRecentChange_save(RecentChange)
#23 /srv/mediawiki/php-1.41.0-wmf.26/includes/HookContainer/HookRunner.php(3213): MediaWiki\HookContainer\HookContainer->run(string, array)
#24 /srv/mediawiki/php-1.41.0-wmf.26/includes/changes/RecentChange.php(476): MediaWiki\HookContainer\HookRunner->onRecentChange_save(RecentChange)
#25 /srv/mediawiki/php-1.41.0-wmf.26/includes/changes/RecentChange.php(761): RecentChange->save()
#26 /srv/mediawiki/php-1.41.0-wmf.26/includes/deferred/MWCallableUpdate.php(40): RecentChange::{closure}()
#27 /srv/mediawiki/php-1.41.0-wmf.26/includes/deferred/DeferredUpdates.php(463): MWCallableUpdate->doUpdate()
#28 /srv/mediawiki/php-1.41.0-wmf.26/includes/deferred/DeferredUpdates.php(192): DeferredUpdates::attemptUpdate(MWCallableUpdate)
#29 /srv/mediawiki/php-1.41.0-wmf.26/includes/deferred/DeferredUpdates.php(276): DeferredUpdates::run(MWCallableUpdate)
#30 /srv/mediawiki/php-1.41.0-wmf.26/includes/deferred/DeferredUpdatesScope.php(267): DeferredUpdates::{closure}(MWCallableUpdate, integer)
#31 /srv/mediawiki/php-1.41.0-wmf.26/includes/deferred/DeferredUpdatesScope.php(196): DeferredUpdatesScope->processStageQueue(integer, integer, Closure)
#32 /srv/mediawiki/php-1.41.0-wmf.26/includes/deferred/DeferredUpdates.php(295): DeferredUpdatesScope->processUpdates(integer, Closure)
#33 /srv/mediawiki/php-1.41.0-wmf.26/includes/MediaWiki.php(1152): DeferredUpdates::doUpdates()
#34 /srv/mediawiki/php-1.41.0-wmf.26/includes/MediaWiki.php(870): MediaWiki->restInPeace()
#35 /srv/mediawiki/php-1.41.0-wmf.26/api.php(130): MediaWiki->doPostOutputShutdown()
#36 /srv/mediawiki/php-1.41.0-wmf.26/api.php(48): wfApiMain()
#37 /srv/mediawiki/w/api.php(3): require(string)
#38 {main}
Notes

The AbuseFilter extension gets the FilterUser, but for some reason the query that checks if the FilterUser can authenticate takes more than 5 seconds to run.

Details

SubjectRepoBranchLines +/-
Don't attempt to steal or create the FilterUser in CheckUserHandlermediawiki/extensions/AbuseFiltermaster+83 -46
Customize query in gerrit

Related Objects

Event Timeline

Dreamy_Jazz created this task.Sep 20 2023, 6:01 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 20 2023, 6:01 PM
Dreamy_Jazz renamed this task from Fetching user_password from user table to test if user can authenticate takes more than 5 seconds causing TransactionProfiler warning to Fetching AbuseFilter's FilterUser involves query that takes more than 5 seconds.Sep 20 2023, 6:02 PM
matej_suchanek mentioned this in T355412: AbuseFilter call to User::newSystemUser on frwiki causing slow DB queries.Jan 19 2024, 5:08 PM
Dreamy_Jazz merged a task: T355412: AbuseFilter call to User::newSystemUser on frwiki causing slow DB queries.Jan 19 2024, 5:16 PM
Dreamy_Jazz added a subscriber: matej_suchanek.
Dreamy_Jazz mentioned this in T356275: Creation of AbuseFilter system user causes deadlock in User::newSystemUser for RevisionSlider patches in CI.Jan 31 2024, 5:37 PM
gerritbot added a comment.Jan 31 2024, 6:54 PM

Change 994797 had a related patch set uploaded (by Dreamy Jazz; author: Dreamy Jazz):

[mediawiki/extensions/AbuseFilter@master] Don't attempt to steal or create system user in CheckUserHandler

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

gerritbot added a project: Patch-For-Review.Jan 31 2024, 6:54 PM
Dreamy_Jazz claimed this task.Jan 31 2024, 7:35 PM
Tgr subscribed.Feb 1 2024, 3:39 AM

LocalPasswordPrimaryAuthenticationProvider->testUserCanAuthenticate() is a primary key lookup, so probably some sort of lock contention.

gerritbot added a comment.Feb 1 2024, 11:26 PM

Change 994797 merged by jenkins-bot:

[mediawiki/extensions/AbuseFilter@master] Don't attempt to steal or create the FilterUser in CheckUserHandler

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

Dreamy_Jazz closed this task as Resolved.Feb 1 2024, 11:40 PM

This specific occurrence of slow queries when calling User::newSystemUser should be fixed as that is no longer called after the associated patch. As such closing this as resolved. I will check logstash after this reaches wikis next week.

ReleaseTaggerBot added a project: MW-1.42-notes (1.42.0-wmf.17; 2024-02-06).Feb 2 2024, 3:00 AM
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