Page MenuHomePhabricator

User modules constantly invalidate their cache timestamp
Closed, ResolvedPublic

Description

The startup module requests is only for anonymous users and cookieless. It is requested directly from the html using a url that includes the relevant timestamp.

Yet, looking in the logs, we see quite a few definition updates (which afaik can only come from startup module requests) having a request context that includes a user name:

2015-04-02 08:43:36 mw1027 plwiki: ResourceLoaderModule::getDefinitionMtime: New definition for module ext.globalCssJs.user in context "en|ltr|monobook|Bsadowski1|||||scripts|"
2015-04-02 08:43:36 mw1022 commonswiki: ResourceLoaderModule::getDefinitionMtime: New definition for module ext.globalCssJs.user in context "fr|ltr|monobook|Linedwell|||||scripts|"
2015-04-02 08:44:49 mw1072 etwiki: ResourceLoaderModule::getDefinitionMtime: New definition for module user in context "et|ltr|vector|Kardulas||||||20150219T154650Z"
2015-04-02 08:45:54 mw1253 simplewiki: ResourceLoaderModule::getDefinitionMtime: New definition for module user in context "en-gb|ltr|vector|Thrasymedes|||||scripts|"
2015-04-02 08:45:55 mw1257 frwiki: ResourceLoaderModule::getDefinitionMtime: New definition for module user in context "fr|ltr|monobook|Prosopee|||||scripts|"
2015-04-02 08:45:57 mw1038 frwiki: ResourceLoaderModule::getDefinitionMtime: New definition for module user in context "fr|ltr|vector|Meixang||||||20150313T153236Z"
2015-04-02 08:46:41 mw1088 commonswiki: ResourceLoaderModule::getDefinitionMtime: New definition for module user in context "en|ltr|vector|El Grafo|||||scripts|"
2015-04-02 08:47:08 mw1081 hiwiki: ResourceLoaderModule::getDefinitionMtime: New definition for module ext.globalCssJs.user in context "hi|ltr|vector|Shrikarsan|||||scripts|"
2015-04-02 08:47:36 mw1219 dewiktionary: ResourceLoaderModule::getDefinitionMtime: New definition for module ext.globalCssJs.user in context "de|ltr|vector|Atamari|||||scripts|"
2015-04-02 08:47:57 mw1183 fawiki: ResourceLoaderModule::getDefinitionMtime: New definition for module user.groups in context "fa|rtl|vector|Far-gh||||||"
2015-04-02 08:48:07 mw1022 enwiki: ResourceLoaderModule::getDefinitionMtime: New definition for module user.groups in context "en|ltr|vector|MartinPoulter||||||"
2015-04-02 08:48:33 mw1107 fawiki: ResourceLoaderModule::getDefinitionMtime: New definition for module ext.globalCssJs.user in context "it|ltr|vector|Nastoshka|||||scripts|"
  • user
  • user.groups
  • ext.globalCssJs.user

See also:

Related Objects

Event Timeline

Krinkle created this task.Apr 2 2015, 8:49 AM
Krinkle raised the priority of this task from to Needs Triage.
Krinkle updated the task description. (Show Details)
Krinkle added subscribers: Krinkle, ori, Legoktm, Catrope.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 2 2015, 8:49 AM
Krinkle triaged this task as High priority.Apr 5 2015, 5:46 PM
Krinkle set Security to None.
Krinkle renamed this task from ResourceLoader timestamp for user modules should not be computed for logged-in users to User modules constantly invalidate their cache timestamp.Apr 10 2015, 5:24 PM
Krinkle added a comment.EditedApr 10 2015, 8:02 PM

I assume the reason these timestamps are computed from a startup module request. It seems these have a user name in their request context.

  • How come we have a user session in the startup module on bits.wikimedia.org?
  • Assuming that's not the case, where are they coming from?
  • Can we fix those sessions?

See also T44094: Startup manifest for logged-in users are minified and cause rapid objectcache growth.

Change 206433 had a related patch set uploaded (by Krinkle):
resourceloader: Add logging for T94810

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

Change 206436 had a related patch set uploaded (by Krinkle):
resourceloader: Add logging for T94810

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

Change 206437 had a related patch set uploaded (by Krinkle):
resourceloader: Add logging for T94810

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

Change 206433 merged by jenkins-bot:
resourceloader: Add logging for T94810

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

Change 206437 merged by jenkins-bot:
resourceloader: Add logging for T94810

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

Change 206436 merged by jenkins-bot:
resourceloader: Add logging for T94810

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

Krinkle claimed this task.Apr 28 2015, 5:24 PM
Krinkle moved this task from Accepted: Enhancement to Assigned on the MediaWiki-ResourceLoader board.
Krinkle removed a project: Patch-For-Review.
Krinkle removed a subscriber: gerritbot.
Jdforrester-WMF raised the priority of this task from High to Unbreak Now!.Apr 29 2015, 3:33 PM
Jdforrester-WMF added a project: Performance.
Krinkle added a comment.EditedApr 29 2015, 5:13 PM

I assume the reason these timestamps are computed from a startup module request. It seems these have a user name in their request context.

  • How come we have a user session in the startup module on bits.wikimedia.org?
  • Assuming that's not the case, where are they coming from?
  • Can we fix those sessions?

See also T44094: Startup manifest for logged-in users are minified and cause rapid objectcache growth.

None of the logged entries originate from bits.wikimedia.org/..modules=startup.. so that's good.

Raw samples:

2015-04-29 16:59:27 mw1042 wikidatawiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context "de|ltr|vector|.." from /wiki/Wikidata:Project_chat {"private":false}
.. Request with user parameter in context "sr|ltr|vector|.." from /wiki/File:Stevan_Kragujevic,_Slobodan_Penezic_Krcun.JPG {"private":false}
.. Request with user parameter in context "en|ltr|minerva.." from /w/load.php?debug=false&lang=en&modules=mobile.notifications%2Cusermodule&skin=minerva&user=..&* {"private":false}
.. Request with user parameter in context "ar|rtl|minerva.." from /w/load.php?debug=false&lang=ar&modules=mobile.notifications%2Cusermodule&skin=minerva&user=..&* {"private":false}
.. Request with user parameter in context "en|ltr|vector|.." from /wiki/File:State_law_reports.png {"private":false}
.. Request with user parameter in context "fr|ltr|vector|.." from /w/load.php?debug=false&lang=fr&modules=ext.globalCssJs.user&only=styles&skin=vector&user=..&* {"private":false}

Trend of past 24 hours:

$ grep 'getDefinitionMtime: Request with user' resourceloader.log | cut -d ' ' -f4- | sed 's/context "[^"]\+"/context/g' | sed 's/&user\=.\+$//g' | sort | uniq -c | sort -nr | head
   2018 enwiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context from /w/load.php?debug=false&lang=en&modules=mobile.notifications%2Cusermodule&skin=minerva
    281 jawiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context from /w/load.php?debug=false&lang=ja&modules=mobile.notifications%2Cusermodule&skin=minerva
    214 ruwiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context from /w/load.php?debug=false&lang=ru&modules=mobile.notifications%2Cusermodule&skin=minerva
    210 eswiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context from /w/load.php?debug=false&lang=es&modules=mobile.notifications%2Cusermodule&skin=minerva
    191 dewiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context from /w/load.php?debug=false&lang=de&modules=mobile.notifications%2Cusermodule&skin=minerva
    175 arwiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context from /w/load.php?debug=false&lang=ar&modules=mobile.notifications%2Cusermodule&skin=minerva
    153 itwiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context from /w/load.php?debug=false&lang=it&modules=mobile.notifications%2Cusermodule&skin=minerva
    146 frwiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context from /w/load.php?debug=false&lang=fr&modules=mobile.notifications%2Cusermodule&skin=minerva
    120 ptwiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context from /w/load.php?debug=false&lang=pt&modules=mobile.notifications%2Cusermodule&skin=minerva
     98 zhwiki resourceloader INFO: ResourceLoaderModule::getDefinitionMtime: Request with user parameter in context from /w/load.php?debug=false&lang=zh-tw&modules=mobile.notifications%2Cusermodule&skin=minerva

It's primarily:

  1. Desktop views from logged-in users

This makes sense as OutputPage has to generate urls to user-module requests and includes a version number. While not for the startup manifest, the path traverses the same ResourceLoaderModule::getModifiedTime path.

  1. Hardcoded requests from mobile to user-specific modules.

When handling requests for these hardcoded requests from OutputPage, like any other load request, ResourceLoader responds with a Last-Modified header. This is the max() of getModifiedTime of all modules being loaded in that patch. This header is a reflection of the server's current timestamps, regardless of the =version parameter in the url. And is especially important for unversioned requests, though that's not relevant here.

Hardcoded modules:

  • site
  • user
  • user.groups
  • ext.globalCssJs.user
  • mobile.usermodule (same as 'user', but without common.)

Like most other modules, WikiModules track their definition summary (which includes the page names). This definition varies over time when the user creates, deletes or restores their subpages (timestamp of wiki revisions is not sufficient). As such, this essentially results in upto total wikis * total logged-in users * total skins different definitions being tracked by ResourceLoader for these user modules.

Aside from things dropping out of memcached, these are most likely genuine cache misses. Either the user created/deleted one of the four associated script/style pages ({common,skin}.{js,css}), or the user visited this wiki/skin combo for the first time since we introduced the definition tracking.

This hash-to-timestamp mapping via memcached is suboptimal. We'd be better off replacing using hashes directly (see T94074). So that we don't need to track anything.

However that doesn't yet explain why mobile's requests specifically are so dominant here. There is likely something else going on.

Change 207661 had a related patch set uploaded (by Krinkle):
[WIP] resourceloader: Implement version hashes instead of timestamps

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

Krinkle moved this task from Tag to Doing on the Performance board.May 13 2015, 12:24 PM

rMWf37cee996ee9: resourceloader: Replace timestamp system with version hashing is way too large to be backported to REL1_25, and required a few extension updates too IIRC. Going to remove this as a 1.25 blocker.

Krinkle closed this task as Resolved.Jun 4 2015, 10:25 AM
Restricted Application added a subscriber: TerraCodes. · View Herald TranscriptAug 11 2016, 7:08 PM