Page MenuHomePhabricator

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

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:

Event Timeline

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)

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?

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

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?

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.

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.

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.

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

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

Thanks, Ori.

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.

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.

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.

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).

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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.