Page MenuHomePhabricator
Create Task
Maniphest T127772

MWSession redis key retrieved 8-9 times per page request
Closed, ResolvedPublic
Actions

Description

MediaWiki is hitting redis for session data multiple times in a single page request.

Here's how I'm seeing this. I picked a codfw application server, since they are not getting any traffic, except PyBal health-checks, which hit Special:BlankPage on enwiki. I then run tcpdump looking for traffic with a destination port of 6379:

curl 'http://localhost/wiki/S%C3%A3o_Paulo' -s \
  -H 'host: pt.wikipedia.org' \
  -H 'X-Forwarded-Proto: https' \
  -H 'WMF-Last-Access=12-Feb-2016; optin=beta; centralauth_LoggedOut=XXX; GeoIP=US:CA:San_Francisco:37.79:-122.39:v4; forceHTTPS=true; centralauth_User=Ori+Livneh; centralauth_Token=XXX; centralauth_Session=XXX'

(where XXX are valid values copied from my browser, which I have redacted here.)

I see the following:

$ sudo tcpdump -i eth0 -s 65535 -A -ttt port 6379 | grep -B2 'ptwiki:'
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes


GET
$49
ptwiki:MWSession:fg6...(redacted)...k44
--
GET
$49
ptwiki:MWSession:fg6...(redacted)...k44
--
GET
$49
ptwiki:MWSession:fg6...(redacted)...k44
--
GET
$49
ptwiki:MWSession:fg6...(redacted)...k44
--
GET
$49
ptwiki:MWSession:fg6...(redacted)...k44
--
SETEX
$49
ptwiki:MWSession:fg6...(redacted)...k44
--
SETEX
$49
ptwiki:MWSession:fg6...(redacted)...k44
--
SETEX
$49
ptwiki:MWSession:fg6...(redacted)...k44
--
SETEX
$49
ptwiki:MWSession:fg6...(redacted)...k44

If I issue the request again, I see another 9 redis ops, but the key is different:

--
GET
$49
ptwiki:MWSession:jvf...(redacted)...1hj
--
GET
$49
ptwiki:MWSession:jvf...(redacted)...1hj
--
GET
$49
ptwiki:MWSession:jvf...(redacted)...1hj
--
GET
$49
ptwiki:MWSession:jvf...(redacted)...1hj
--
GET
$49
ptwiki:MWSession:jvf...(redacted)...1hj
--
SETEX
$49
ptwiki:MWSession:jvf...(redacted)...1hj
--
SETEX
$49
ptwiki:MWSession:jvf...(redacted)...1hj
--
SETEX
$49
ptwiki:MWSession:jvf...(redacted)...1hj
--
SETEX
$49
ptwiki:MWSession:jvf...(redacted)...1hj

The key changes on every request.

You can see that this is related to the recent auth work by looking at the ops/sec graphs for the session redis hosts on Ganglia:

graph (1).png (373×747 px, 27 KB)

Details

ProjectBranchLines +/-Subject
mediawiki/extensions/CentralAuthwmf/1.27.0-wmf.14+18 -9Reduce memcache traffic for central session storage
mediawiki/extensions/CentralAuthmaster+18 -9Reduce memcache traffic for central session storage
mediawiki/corewmf/1.27.0-wmf.13+32 -5CachedBagOStuff: cache backend misses
mediawiki/corewmf/1.27.0-wmf.14+32 -5CachedBagOStuff: cache backend misses
mediawiki/coremaster+32 -5CachedBagOStuff: cache backend misses
Customize query in gerrit

Related Objects
Search...

Event Timeline

ori created this task.Feb 22 2016, 11:08 PM
ori mentioned this in T126700: Severe save latency regression.
ori added a comment.Feb 22 2016, 11:42 PM

I hacked debug logging statements into RedisBagOStuff::{doGet,set} and repeated the request. Here are the backtraces for all the redis gets/sets in the page request mentioned in the task description:

-----
Key: global:ChronologyProtector:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 2] BagOStuff->get() (includes/db/ChronologyProtector.php:199)
[ 3] ChronologyProtector->initPositions() (includes/db/ChronologyProtector.php:94)
[ 4] ChronologyProtector->initLB() (includes/db/loadbalancer/LBFactoryMulti.php:242)
[ 5] LBFactoryMulti->getMainLB() (includes/GlobalFunctions.php:3220)
[ 6] wfGetLB (includes/GlobalFunctions.php:3210)
[ 7] wfGetDB (includes/user/User.php:750)
[ 8] User::idFromName() (extensions/CentralAuth/includes/CentralAuthUser.php:1761)
[ 9] CentralAuthUser->canAuthenticate() (extensions/CentralAuth/includes/CentralAuthUser.php:1803)
[10] CentralAuthUser->authenticateWithToken() (extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php:174)
[11] CentralAuthSessionProvider->provideSessionInfo() (includes/session/SessionManager.php:616)
[12] MediaWiki\Session\SessionManager->getSessionInfoForRequest() (includes/session/SessionManager.php:185)
[13] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[14] WebRequest->getSession() (includes/session/SessionManager.php:123)
[15] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[16] include (includes/WebStart.php:156)
[17] include (index.php:40)
[18] include (/srv/mediawiki/w/index.php:3)
-----
Key: ptwiki:MWSession:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/CachedBagOStuff.php:54)
[ 2] CachedBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 3] BagOStuff->get() (includes/session/SessionManager.php:1033)
[ 4] MediaWiki\Session\SessionManager->generateSessionId() (includes/session/SessionInfo.php:145)
[ 5] MediaWiki\Session\SessionInfo->__construct() (extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php:193)
[ 6] CentralAuthSessionProvider->provideSessionInfo() (includes/session/SessionManager.php:616)
[ 7] MediaWiki\Session\SessionManager->getSessionInfoForRequest() (includes/session/SessionManager.php:185)
[ 8] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[ 9] WebRequest->getSession() (includes/session/SessionManager.php:123)
[10] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[11] include (includes/WebStart.php:156)
[12] include (index.php:40)
[13] include (/srv/mediawiki/w/index.php:3)
-----
Key: ptwiki:MWSession:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/CachedBagOStuff.php:54)
[ 2] CachedBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 3] BagOStuff->get() (includes/session/SessionManager.php:672)
[ 4] MediaWiki\Session\SessionManager->loadSessionInfoFromStore() (includes/session/SessionManager.php:635)
[ 5] MediaWiki\Session\SessionManager->getSessionInfoForRequest() (includes/session/SessionManager.php:185)
[ 6] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[ 7] WebRequest->getSession() (includes/session/SessionManager.php:123)
[ 8] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[ 9] include (includes/WebStart.php:156)
[10] include (index.php:40)
[11] include (/srv/mediawiki/w/index.php:3)
-----
Key: ptwiki:MWSession:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/CachedBagOStuff.php:54)
[ 2] CachedBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 3] BagOStuff->get() (includes/session/SessionBackend.php:133)
[ 4] MediaWiki\Session\SessionBackend->__construct() (includes/session/SessionManager.php:959)
[ 5] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[ 6] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[ 7] WebRequest->getSession() (includes/session/SessionManager.php:123)
[ 8] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[ 9] include (includes/WebStart.php:156)
[10] include (index.php:40)
[11] include (/srv/mediawiki/w/index.php:3)
-----
Key: centralauth:session:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 2] BagOStuff->get() (extensions/CentralAuth/includes/CentralAuthUtils.php:204)
[ 3] CentralAuthUtils::setCentralSession() (extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php:308)
[ 4] CentralAuthSessionProvider->persistSession() (includes/session/SessionBackend.php:637)
[ 5] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 6] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 7] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 8] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[ 9] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[10] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[11] WebRequest->getSession() (includes/session/SessionManager.php:123)
[12] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[13] include (includes/WebStart.php:156)
[14] include (index.php:40)
[15] include (/srv/mediawiki/w/index.php:3)
-----
Key: centralauth:session:(redacted)
[ 1] RedisBagOStuff->set() (extensions/CentralAuth/includes/CentralAuthUtils.php:210)
[ 2] CentralAuthUtils::setCentralSession() (extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php:308)
[ 3] CentralAuthSessionProvider->persistSession() (includes/session/SessionBackend.php:637)
[ 4] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 5] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 6] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 7] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[ 8] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[ 9] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[10] WebRequest->getSession() (includes/session/SessionManager.php:123)
[11] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[12] include (includes/WebStart.php:156)
[13] include (index.php:40)
[14] include (/srv/mediawiki/w/index.php:3)
-----
Key: ptwiki:MWSession:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/CachedBagOStuff.php:54)
[ 2] CachedBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 3] BagOStuff->get() (includes/session/SessionManager.php:208)
[ 4] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[ 5] WebRequest->getSession() (includes/session/SessionManager.php:123)
[ 6] MediaWiki\Session\SessionManager::getGlobalSession() (includes/session/SessionBackend.php:701)
[ 7] MediaWiki\Session\SessionBackend->checkPHPSession() (includes/session/SessionBackend.php:640)
[ 8] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 9] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[10] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[11] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[12] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[13] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[14] WebRequest->getSession() (includes/session/SessionManager.php:123)
[15] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[16] include (includes/WebStart.php:156)
[17] include (index.php:40)
[18] include (/srv/mediawiki/w/index.php:3)
-----
Key: ptwiki:MWSession:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/CachedBagOStuff.php:54)
[ 2] CachedBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 3] BagOStuff->get() (includes/session/SessionManager.php:249)
[ 4] MediaWiki\Session\SessionManager->getEmptySessionInternal() (includes/session/SessionManager.php:218)
[ 5] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[ 6] WebRequest->getSession() (includes/session/SessionManager.php:123)
[ 7] MediaWiki\Session\SessionManager::getGlobalSession() (includes/session/SessionBackend.php:701)
[ 8] MediaWiki\Session\SessionBackend->checkPHPSession() (includes/session/SessionBackend.php:640)
[ 9] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[10] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[11] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[12] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[13] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[14] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[15] WebRequest->getSession() (includes/session/SessionManager.php:123)
[16] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[17] include (includes/WebStart.php:156)
[18] include (index.php:40)
[19] include (/srv/mediawiki/w/index.php:3)
-----
Key: centralauth:session:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 2] BagOStuff->get() (extensions/CentralAuth/includes/CentralAuthUtils.php:164)
[ 3] CentralAuthUtils::getCentralSessionById() (extensions/CentralAuth/includes/CentralAuthUtils.php:150)
[ 4] CentralAuthUtils::getCentralSession() (extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php:300)
[ 5] CentralAuthSessionProvider->persistSession() (includes/session/SessionBackend.php:637)
[ 6] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 7] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 8] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 9] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[10] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:299)
[11] MediaWiki\Session\SessionManager->getEmptySessionInternal() (includes/session/SessionManager.php:218)
[12] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[13] WebRequest->getSession() (includes/session/SessionManager.php:123)
[14] MediaWiki\Session\SessionManager::getGlobalSession() (includes/session/SessionBackend.php:701)
[15] MediaWiki\Session\SessionBackend->checkPHPSession() (includes/session/SessionBackend.php:640)
[16] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[17] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[18] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[19] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[20] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[21] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[22] WebRequest->getSession() (includes/session/SessionManager.php:123)
[23] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[24] include (includes/WebStart.php:156)
[25] include (index.php:40)
[26] include (/srv/mediawiki/w/index.php:3)
-----
Key: centralauth:session:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 2] BagOStuff->get() (extensions/CentralAuth/includes/CentralAuthUtils.php:204)
[ 3] CentralAuthUtils::setCentralSession() (extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php:308)
[ 4] CentralAuthSessionProvider->persistSession() (includes/session/SessionBackend.php:637)
[ 5] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 6] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 7] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 8] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[ 9] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:299)
[10] MediaWiki\Session\SessionManager->getEmptySessionInternal() (includes/session/SessionManager.php:218)
[11] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[12] WebRequest->getSession() (includes/session/SessionManager.php:123)
[13] MediaWiki\Session\SessionManager::getGlobalSession() (includes/session/SessionBackend.php:701)
[14] MediaWiki\Session\SessionBackend->checkPHPSession() (includes/session/SessionBackend.php:640)
[15] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[16] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[17] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[18] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[19] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[20] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[21] WebRequest->getSession() (includes/session/SessionManager.php:123)
[22] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[23] include (includes/WebStart.php:156)
[24] include (index.php:40)
[25] include (/srv/mediawiki/w/index.php:3)
-----
Key: centralauth:session:(redacted)
[ 1] RedisBagOStuff->set() (extensions/CentralAuth/includes/CentralAuthUtils.php:210)
[ 2] CentralAuthUtils::setCentralSession() (extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php:308)
[ 3] CentralAuthSessionProvider->persistSession() (includes/session/SessionBackend.php:637)
[ 4] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 5] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 6] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 7] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[ 8] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:299)
[ 9] MediaWiki\Session\SessionManager->getEmptySessionInternal() (includes/session/SessionManager.php:218)
[10] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[11] WebRequest->getSession() (includes/session/SessionManager.php:123)
[12] MediaWiki\Session\SessionManager::getGlobalSession() (includes/session/SessionBackend.php:701)
[13] MediaWiki\Session\SessionBackend->checkPHPSession() (includes/session/SessionBackend.php:640)
[14] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[15] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[16] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[17] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[18] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[19] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[20] WebRequest->getSession() (includes/session/SessionManager.php:123)
[21] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[22] include (includes/WebStart.php:156)
[23] include (index.php:40)
[24] include (/srv/mediawiki/w/index.php:3)
-----
Key: centralauth:session:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 2] BagOStuff->get() (extensions/CentralAuth/includes/CentralAuthUtils.php:164)
[ 3] CentralAuthUtils::getCentralSessionById() (extensions/CentralAuth/includes/CentralAuthUtils.php:150)
[ 4] CentralAuthUtils::getCentralSession() (extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php:300)
[ 5] CentralAuthSessionProvider->persistSession() (includes/session/SessionBackend.php:637)
[ 6] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 7] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 8] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 9] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[10] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:299)
[11] MediaWiki\Session\SessionManager->getEmptySessionInternal() (includes/session/SessionManager.php:218)
[12] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[13] WebRequest->getSession() (includes/session/SessionManager.php:123)
[14] MediaWiki\Session\SessionManager::getGlobalSession() (includes/session/SessionBackend.php:701)
[15] MediaWiki\Session\SessionBackend->checkPHPSession() (includes/session/SessionBackend.php:640)
[16] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[17] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[18] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[19] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[20] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[21] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[22] WebRequest->getSession() (includes/session/SessionManager.php:123)
[23] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[24] include (includes/WebStart.php:156)
[25] include (index.php:40)
[26] include (/srv/mediawiki/w/index.php:3)
-----
Key: centralauth:session:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 2] BagOStuff->get() (extensions/CentralAuth/includes/CentralAuthUtils.php:204)
[ 3] CentralAuthUtils::setCentralSession() (extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php:308)
[ 4] CentralAuthSessionProvider->persistSession() (includes/session/SessionBackend.php:637)
[ 5] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 6] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 7] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 8] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[ 9] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:299)
[10] MediaWiki\Session\SessionManager->getEmptySessionInternal() (includes/session/SessionManager.php:218)
[11] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[12] WebRequest->getSession() (includes/session/SessionManager.php:123)
[13] MediaWiki\Session\SessionManager::getGlobalSession() (includes/session/SessionBackend.php:701)
[14] MediaWiki\Session\SessionBackend->checkPHPSession() (includes/session/SessionBackend.php:640)
[15] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[16] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[17] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[18] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[19] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[20] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[21] WebRequest->getSession() (includes/session/SessionManager.php:123)
[22] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[23] include (includes/WebStart.php:156)
[24] include (index.php:40)
[25] include (/srv/mediawiki/w/index.php:3)
-----
Key: centralauth:session:(redacted)
[ 1] RedisBagOStuff->set() (extensions/CentralAuth/includes/CentralAuthUtils.php:210)
[ 2] CentralAuthUtils::setCentralSession() (extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php:308)
[ 3] CentralAuthSessionProvider->persistSession() (includes/session/SessionBackend.php:637)
[ 4] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 5] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 6] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 7] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[ 8] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:299)
[ 9] MediaWiki\Session\SessionManager->getEmptySessionInternal() (includes/session/SessionManager.php:218)
[10] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[11] WebRequest->getSession() (includes/session/SessionManager.php:123)
[12] MediaWiki\Session\SessionManager::getGlobalSession() (includes/session/SessionBackend.php:701)
[13] MediaWiki\Session\SessionBackend->checkPHPSession() (includes/session/SessionBackend.php:640)
[14] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[15] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[16] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[17] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[18] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[19] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[20] WebRequest->getSession() (includes/session/SessionManager.php:123)
[21] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[22] include (includes/WebStart.php:156)
[23] include (index.php:40)
[24] include (/srv/mediawiki/w/index.php:3)
-----
Key: ptwiki:MWSession:(redacted)
[ 1] RedisBagOStuff->set() (includes/libs/objectcache/CachedBagOStuff.php:65)
[ 2] CachedBagOStuff->set() (includes/session/SessionBackend.php:680)
[ 3] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 4] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 5] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 6] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[ 7] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:299)
[ 8] MediaWiki\Session\SessionManager->getEmptySessionInternal() (includes/session/SessionManager.php:218)
[ 9] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[10] WebRequest->getSession() (includes/session/SessionManager.php:123)
[11] MediaWiki\Session\SessionManager::getGlobalSession() (includes/session/SessionBackend.php:701)
[12] MediaWiki\Session\SessionBackend->checkPHPSession() (includes/session/SessionBackend.php:640)
[13] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[14] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[15] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[16] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[17] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:190)
[18] MediaWiki\Session\SessionManager->getSessionForRequest() (includes/WebRequest.php:664)
[19] WebRequest->getSession() (includes/session/SessionManager.php:123)
[20] MediaWiki\Session\SessionManager::getGlobalSession() (includes/Setup.php:712)
[21] include (includes/WebStart.php:156)
[22] include (index.php:40)
[23] include (/srv/mediawiki/w/index.php:3)
-----
Key: SessionManager-ip:(redacted)
[ 1] RedisBagOStuff->doGet() (includes/libs/objectcache/CachedBagOStuff.php:54)
[ 2] CachedBagOStuff->doGet() (includes/libs/objectcache/BagOStuff.php:147)
[ 3] BagOStuff->get() (includes/session/SessionManager.php:1120)
[ 4] MediaWiki\Session\SessionManager->checkIpLimits() (includes/Setup.php:812)
[ 5] include (includes/WebStart.php:156)
[ 6] include (index.php:40)
[ 7] include (/srv/mediawiki/w/index.php:3)
-----
Key: ptwiki:MWSession:(redacted)
[ 1] RedisBagOStuff->set() (includes/libs/objectcache/CachedBagOStuff.php:65)
[ 2] CachedBagOStuff->set() (includes/session/SessionBackend.php:680)
[ 3] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 4] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 5] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 6] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[ 7] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:211)
[ 8] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[ 9] WebRequest->getSession() (includes/user/User.php:1174)
[10] User->loadFromSession() (includes/user/User.php:384)
[11] User->load() (includes/user/User.php:5087)
[12] User->loadOptions() (includes/user/User.php:2705)
[13] User->getOption() (includes/context/RequestContext.php:368)
[14] RequestContext->getLanguage() (includes/Message.php:650)
[15] Message->setContext() (includes/context/RequestContext.php:462)
[16] RequestContext->msg() (includes/context/ContextSource.php:186)
[17] ContextSource->msg() (includes/OutputPage.php:1000)
[18] OutputPage->setPageTitle() (includes/page/Article.php:504)
[19] Article->view() (includes/actions/ViewAction.php:44)
[20] ViewAction->show() (includes/MediaWiki.php:501)
[21] MediaWiki->performAction() (includes/MediaWiki.php:286)
[22] MediaWiki->performRequest() (includes/MediaWiki.php:736)
[23] MediaWiki->main() (includes/MediaWiki.php:517)
[24] MediaWiki->run() (index.php:43)
[25] include (/srv/mediawiki/w/index.php:3)
-----
Key: ptwiki:MWSession:(redacted)
[ 1] RedisBagOStuff->set() (includes/libs/objectcache/CachedBagOStuff.php:65)
[ 2] CachedBagOStuff->set() (includes/session/SessionBackend.php:680)
[ 3] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 4] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 5] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 6] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[ 7] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:211)
[ 8] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[ 9] WebRequest->getSession() (includes/user/User.php:3083)
[10] User->getRights() (includes/user/User.php:3351)
[11] User->isAllowed() (extensions/FlaggedRevs/backend/FlaggedRevs.hooks.php:991)
[12] FlaggedRevsHooks::setSessionKey() (includes/Hooks.php:195)
[13] Hooks::run() (includes/user/User.php:388)
[14] User->load() (includes/user/User.php:5087)
[15] User->loadOptions() (includes/user/User.php:2705)
[16] User->getOption() (includes/context/RequestContext.php:368)
[17] RequestContext->getLanguage() (includes/Message.php:650)
[18] Message->setContext() (includes/context/RequestContext.php:462)
[19] RequestContext->msg() (includes/context/ContextSource.php:186)
[20] ContextSource->msg() (includes/OutputPage.php:1000)
[21] OutputPage->setPageTitle() (includes/page/Article.php:504)
[22] Article->view() (includes/actions/ViewAction.php:44)
[23] ViewAction->show() (includes/MediaWiki.php:501)
[24] MediaWiki->performAction() (includes/MediaWiki.php:286)
[25] MediaWiki->performRequest() (includes/MediaWiki.php:736)
[26] MediaWiki->main() (includes/MediaWiki.php:517)
[27] MediaWiki->run() (index.php:43)
[28] include (/srv/mediawiki/w/index.php:3)
-----
Key: ptwiki:MWSession:(redacted)
[ 1] RedisBagOStuff->set() (includes/libs/objectcache/CachedBagOStuff.php:65)
[ 2] CachedBagOStuff->set() (includes/session/SessionBackend.php:680)
[ 3] MediaWiki\Session\SessionBackend->save() (includes/session/SessionBackend.php:558)
[ 4] Closure$MediaWiki\Session\SessionBackend::delaySave (includes/libs/ScopedCallback.php:74)
[ 5] ScopedCallback->__destruct() (includes/libs/ScopedCallback.php:54)
[ 6] ScopedCallback::consume() (includes/session/SessionManager.php:980)
[ 7] MediaWiki\Session\SessionManager->getSessionFromInfo() (includes/session/SessionManager.php:211)
[ 8] MediaWiki\Session\SessionManager->getSessionById() (includes/WebRequest.php:658)
[ 9] WebRequest->getSession() (includes/user/User.php:4180)
[10] User->getEditTokenObject() (includes/user/User.php:4195)
[11] User->getEditToken() (includes/resourceloader/ResourceLoaderUserTokensModule.php:48)
[12] ResourceLoaderUserTokensModule->contextUserTokens() (includes/resourceloader/ResourceLoaderUserTokensModule.php:66)
[13] ResourceLoaderUserTokensModule->getScript() (includes/resourceloader/ResourceLoaderModule.php:576)
[14] ResourceLoaderModule->buildContent() (includes/resourceloader/ResourceLoaderModule.php:544)
[15] ResourceLoaderModule->getModuleContent() (includes/resourceloader/ResourceLoader.php:976)
[16] ResourceLoader->makeModuleResponse() (includes/OutputPage.php:2897)
[17] OutputPage->makeResourceLoaderLink() (includes/OutputPage.php:3044)
[18] OutputPage->getInlineHeadScripts() (includes/OutputPage.php:2711)
[19] OutputPage->headElement() (includes/skins/SkinTemplate.php:465)
[20] SkinTemplate->prepareQuickTemplate() (includes/skins/SkinTemplate.php:240)
[21] SkinTemplate->outputPage() (includes/OutputPage.php:2351)
[22] OutputPage->output() (includes/MediaWiki.php:744)
[23] MediaWiki->main() (includes/MediaWiki.php:517)
[24] MediaWiki->run() (index.php:43)
[25] include (/srv/mediawiki/w/index.php:3)
bd808 added a comment.Feb 22 2016, 11:53 PM

This looks a lot like what we attempted to fix with the introduction of an in process cache in rMWfcdd643a46d8: SessionManager: Don't save non-persisted sessions to backend storage and rMW25dbd91513f1: Clean up after Ie161e0f.

Looking at CachedBagOStuff I see that it doesn't locally cache backend misses. Could that be causing the additional backend queries?

bd808 added a comment.Feb 23 2016, 12:09 AM

The centralauth:session fetches are the same issue as T127236: No in-process cache for CentralAuthUser which has been patched in master with rECAUc52bb45d5306: Cache CentralAuthUsers more aggressively.

Paladox added a comment.Feb 23 2016, 12:12 AM

Would back porting the CentralAuth patch onto the wmf 14 branch fix the problem.

ori added a comment.Feb 23 2016, 12:25 AM
In T127772#2053555, @bd808 wrote:

Looking at CachedBagOStuff I see that it doesn't locally cache backend misses. Could that be causing the additional backend queries?

AFAIK, redis is now replicated to CODFW, but to be completely sure I repeated the experiment on a depooled app server in EQIAD. These are the GETs:

MISS: global:ChronologyProtector:0b7..(redacted)..3a4
MISS: ptwiki:MWSession:lnq..(redacted)..r5l
MISS: ptwiki:MWSession:lnq..(redacted)..r5l
MISS: ptwiki:MWSession:lnq..(redacted)..r5l
MISS: centralauth:session:fd8..(redacted)..778
MISS: ptwiki:MWSession:lnq..(redacted)..r5l
MISS: ptwiki:MWSession:lnq..(redacted)..r5l
HIT: centralauth:session:fd8..(redacted)..778
HIT: centralauth:session:fd8..(redacted)..778
HIT: centralauth:session:fd8..(redacted)..778
HIT: centralauth:session:fd8..(redacted)..778
HIT: SessionManager-ip:37d..(redacted)..cc5

Repeating the request:

MISS: global:ChronologyProtector:0b7..(redacted)..3a4
MISS: ptwiki:MWSession:h74..(redacted)..4ec
MISS: ptwiki:MWSession:h74..(redacted)..4ec
MISS: ptwiki:MWSession:h74..(redacted)..4ec
MISS: centralauth:session:46c..(redacted)..6ed
MISS: ptwiki:MWSession:h74..(redacted)..4ec
MISS: ptwiki:MWSession:h74..(redacted)..4ec
HIT: centralauth:session:46c..(redacted)..6ed
HIT: centralauth:session:46c..(redacted)..6ed
HIT: centralauth:session:46c..(redacted)..6ed
HIT: centralauth:session:46c..(redacted)..6ed
HIT: SessionManager-ip:37d..(redacted)..cc5

So, it looks like you are right -- the repeat GETs for MWSession are due to the miss not getting cached. But then: why is it consistently a miss, and why does it change on every request?

Krinkle added a comment.Feb 23 2016, 12:28 AM
In T127772#2053555, @bd808 wrote:

Looking at CachedBagOStuff I see that it doesn't locally cache backend misses.

We shouldn't have multiple code paths using cache keys as a public API and all independently request this information. Rather, there should be one point responsible for fetching this key and other code paths can retrieve the information from that class (which can store it in a member variable once loaded). It's imho an anti-pattern to use generic layers in e.g. BagOStuff for this purpose.

ori added a comment.Feb 23 2016, 1:01 AM

FWIW, I amended my script to use a persistent cookie jar, to rule out the possibility that the churn in session keys was caused by me not obeying Set-Cookie headers. The behavior is the same.

Tgr added a comment.Feb 23 2016, 1:10 AM

Sessionmanager-ip is temporary logging code with its own cache, can be disregarded. Apart from that one thing to improve is that SessionManager::generateSessionId checks whether the id is already taken, which is pointless. That's probably an extra ping even for unpersisted anonymous sessions.

gerritbot added a subscriber: gerritbot.Feb 23 2016, 1:46 AM

Change 272653 had a related patch set uploaded (by BryanDavis):
CachedBagOStuff: cache backend misses

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

gerritbot added a project: Patch-For-Review.Feb 23 2016, 1:46 AM
Anomie added a comment.Feb 23 2016, 2:30 AM

Thanks, Ori.

In T127772#2053648, @bd808 wrote:

The centralauth:session fetches are the same issue as T127236: No in-process cache for CentralAuthUser which has been patched in master with rECAUc52bb45d5306: Cache CentralAuthUsers more aggressively.

I should look into that, actually. IIRC T127236 would be centralauth-user fetches, not centralauth:session.

Chances are we can throw a CachedBagOStuff in there easily enough, that one does use a BagOStuff.

In T127772#2053678, @ori wrote:

But then: why is it consistently a miss, and why does it change on every request?

It'll be a miss until something saves into it. I don't know why you're seeing it 8 times when I only saw it twice (once for the "ping" Gergő points out later and once for the first actual load) in my testing both locally and on mw1017, but I suppose it probably doesn't matter much.

The change each request is expected: a request without any active session will create a new empty session with a new key, but if nothing causes it to be persisted then obviously it can't know to use that key again for a later request. We could, maybe, delay the creation of the key in this case until something actually needs it. If saving one redis fetch would be worth the added code complexity and the time it takes to write and test it, let me know and I'll look into it.

In T127772#2053772, @Tgr wrote:

Apart from that one thing to improve is that SessionManager::generateSessionId checks whether the id is already taken, which is pointless. That's probably an extra ping even for unpersisted anonymous sessions.

Not if the negative caching works. The "ping" will cache the negative just like any other fetch would.

And it does save things in the extremely rare chance that it does manage to pick an already-used key.

Tgr added a comment.Feb 23 2016, 3:09 AM
In T127772#2053970, @Anomie wrote:

And it does save things in the extremely rare chance that it does manage to pick an already-used key.

The chance of picking a used key is 16^-32 * <number of sessions> * <frequency> which is something like 10^-30 per second (give or take a few zeros). Per Wikipedia, the chance of cosmic radiation flipping a bit in CPU memory is something like 10^-15 per second, making some wild guesstimates of how often would that be just the right bit to cause a fatal session-related error like an authentication that should fail succeeding, maybe 10^-25 per second. So the id collision check is not making any dent in the probability of things going south for completely random reasons (which is a probability far, far too low to bother with anyway).

gerritbot added a comment.Feb 23 2016, 3:03 PM

Change 272653 merged by jenkins-bot:
CachedBagOStuff: cache backend misses

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

gerritbot added a comment.Feb 23 2016, 3:25 PM

Change 272733 had a related patch set uploaded (by BryanDavis):
CachedBagOStuff: cache backend misses

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

gerritbot added a comment.Feb 23 2016, 3:26 PM

Change 272734 had a related patch set uploaded (by BryanDavis):
CachedBagOStuff: cache backend misses

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

ReleaseTaggerBot added projects: MW-1.27-release-notes, MW-1.27-release (WMF-deploy-2016-03-01_(1.27.0-wmf.15)).Feb 23 2016, 4:00 PM
gerritbot added a comment.Feb 23 2016, 5:50 PM

Change 272776 had a related patch set uploaded (by Anomie):
Reduce memcache traffic for central session storage

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

gerritbot added a comment.Feb 23 2016, 8:34 PM

Change 272734 merged by jenkins-bot:
CachedBagOStuff: cache backend misses

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

gerritbot added a comment.Feb 23 2016, 8:34 PM

Change 272733 merged by jenkins-bot:
CachedBagOStuff: cache backend misses

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

ReleaseTaggerBot added projects: MW-1.27-release (WMF-deploy-2016-02-09_(1.27.0-wmf.13)), MW-1.27-release (WMF-deploy-2016-02-16_(1.27.0-wmf.14)).Feb 23 2016, 9:00 PM
gerritbot added a comment.Feb 23 2016, 10:13 PM

Change 272893 had a related patch set uploaded (by Anomie):
User::isSafeToLoad() should return false if MW_NO_SESSION

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

gerritbot added a comment.Feb 25 2016, 10:04 PM

Change 273375 had a related patch set uploaded (by Ori.livneh):
Reduce memcache traffic for central session storage

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

gerritbot added a comment.Feb 25 2016, 10:08 PM

Change 272776 merged by jenkins-bot:
Reduce memcache traffic for central session storage

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

gerritbot added a comment.Feb 25 2016, 10:20 PM

Change 273375 merged by jenkins-bot:
Reduce memcache traffic for central session storage

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

Krinkle removed projects: MW-1.27-release (WMF-deploy-2016-02-16_(1.27.0-wmf.14)), MW-1.27-release (WMF-deploy-2016-02-09_(1.27.0-wmf.13)).Feb 29 2016, 7:45 PM
Krinkle moved this task from Inbox to Next: Goal-oriented on the Performance-Team board.Feb 29 2016, 7:55 PM
hashar removed a subscriber: hashar.Feb 29 2016, 7:58 PM
ori closed this task as Resolved.Mar 1 2016, 10:03 PM
ori assigned this task to Anomie.

I confirmed that session data is now retrieved at most once per request.
This was fixed by @Anomie in rECAU961241fbdc91: Reduce memcache traffic for central session storage and @Tgr in rMW9c733318107e: Cache user data in memory.

ori added a parent task: T128543: Hunt down duplicate memcached gets.Mar 2 2016, 12:59 AM
• Fjalapeno edited projects, added Product-Infrastructure-Team-Backlog; removed Reading-Infrastructure-Team-Old (Don't use).Jun 7 2017, 2:56 PM
Aklapper removed a subscriber: Anomie.Oct 16 2020, 5:40 PM
Content licensed under Creative Commons Attribution-ShareAlike 3.0 (CC-BY-SA) unless otherwise noted; code licensed under GNU General Public License (GPL) or 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