Page MenuHomePhabricator

MessageCache absurdly slow with CACHE_NONE with wgReadOnly mode enabled
Closed, ResolvedPublic

Description

Author: amuenzeb

Description:
After upgrading from version 1.9.3 page delivery is incredibly slow (about 40s for each page). I think this is because of a timeout while mediawiki waits for the answer from a memcache server which is neither present nor configured.

This happens after upgrading from 1.9.3 as well as after upgrading from 1.10.2. Version 1.10.2 is working.

I also posted this on the mailing list.

Configuration:

  • Opensuse 10.2, kernel 2.6.18
  • mysql Ver 14.12 Distrib 5.0.26, for suse-linux-gnu (i686) using

readline 5.1

  • PHP 5.2.0 with Suhosin-Patch 0.9.6.1 (cli) (built: Jul 30 2007 15:36:02)

Copyright (c) 1997-2006 The PHP Group
Zend Engine v2.2.0, Copyright (c) 1998-2006 Zend Technologies

with Suhosin v0.9.10, (C) Copyright 2006, by Hardened-PHP Project
  • All tarfiles from mediawiki.org

Snippet from the logfile:

Start request
GET /php/mediawiki-testing/index.php5/Hauptseite
Host: XXXXXX
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.8.1.7) Gecko/20070914 Firefox/2.0.0.7
Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: de-de,de;q=0.8,en-us;q=0.5,en;q=0.3
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: wikidb_TEST_session=rFnqDOnk9nzgQQT8VTisQzD3_s7LcaQYzRpfsHR3frMVr52AKd3BAg9bxIqmUpi8; wikidb_TESTUserID=8iO9l82DarQdetA26Z6DZzuhV5Vt9xdWLY26P5jcxak.; wikidb_TESTUserName=sc6hRE5cFxTj3ed-oZ7jPKbpfETRx7QvGrh2tFcXyP4.
Cache-Control: max-age=0

Main cache: FakeMemCachedClient
Message cache: MediaWikiBagOStuff
Parser cache: MediaWikiBagOStuff
Unstubbing $wgParser on call of $wgParser->setHook from efSubpageList
Fully initialised
Unstubbing $wgContLang on call of $wgContLang->checkTitleEncoding from WebRequest::getGPCVal
Language::loadLocalisation(): got localisation for de from source
Language::loadLocalisation(): got localisation for en from source
Unstubbing $wgUser on call of $wgUser->isAllowed from Title::userCanRead
Unstubbing $wgLoadBalancer on call of $wgLoadBalancer->getConnection from wfGetDB
IP: XXX.XXX.XXX.XXX
Unstubbing $wgOut on call of $wgOut->setSquidMaxage from MediaWiki::performAction
Unstubbing $wgLang on call of $wgLang->getCode from User::getPageRenderingHash
Unstubbing $wgMessageCache on call of $wgMessageCache->loadAllMessages from User::getGroupName
MessageCache::load(): cache is empty
MessageCache::load(): loading all messages from DB
MemCached set error in MessageCache: restart memcached server!
OutputPage::checkLastModified: client did not send If-Modified-Since header
Article::tryFileCache(): not cacheable
Article::view using parser cache: yes
Trying parser cache wikidb_TESTING:pcache:idhash:1-0!1!0!!de!2!edit=0
Parser cache miss.
Saved in parser cache with key wikidb_TESTING:pcache:idhash:1-0!1!0!!de!2!edit=0 and timestamp 20071002105913
OutputPage::sendCacheControl: private caching; Tue, 02 Oct 2007 09:45:03 GMT **
20071002105913 23.028 /php/mediawiki-testing/index.php5/Hauptseite anon
Request ended normally


Version: 1.11.x
Severity: major
OS: Linux
Platform: PC

Details

Reference
bz11533

Event Timeline

bzimport raised the priority of this task from to Medium.Nov 21 2014, 9:58 PM
bzimport set Reference to bz11533.
bzimport added a subscriber: Unknown Object (MLST).

Main cache: FakeMemCachedClient
Message cache: MediaWikiBagOStuff
Parser cache: MediaWikiBagOStuff

That's using the local objectcache table for message cache storage.

The delay is from MessageCache::load() trying to ensure that it can properly save its data to the cache storage. It'll loop as long as the set() calls fail.

A quick peek at the code for SqlBagOStuff in includes/BagOStuff.php indicates that this should return a failure result only if the wiki is set in read-only mode; otherwise it always returns success, or else the entire system dies if there's a database error.

Can you confirm whether $wgReadOnly is set? That oughtn't to blow up the wiki like this, but if that's it that saves us some trouble tracking it down. :)

amuenzeb wrote:

You are right, $wgReadOnly is set. And (as I just tested) setting it to "false" resolves the performance problem.

Ok, that's a tacklable problem I think. :)

Changed summary to the more specific issue.

rey4 wrote:

I got bitten by this bug during an upgrade from MediaWiki 1.8.4 to 1.11.2. With the wgReadOnly flag turned on, the update script crawled along for hours (during the deleteDefaultMessages step) barely making any progress updating the database. After disabling wgReadOnly, the upgrade finished in less than a minute. It would be really great if this were fixed. The problem is just that the SqlBagOStuff::set method always returns false when wgReadOnly is enabled. This causes the MessageCache::load method to hang (for up to 30 seconds each time it is called), because it calls SqlBagOStuff::set in a loop, waiting for it not to return false.

$wgReadOnly is supposed to prevent any database writes, so that would prevent an updater script from working in the first place... unless it's broken horribly. :)

Replace includes/BagOStuff.php with this one to fix (MediaWiki 1.13.0)

Attached:

(In reply to comment #6)

Created an attachment (id=5179) [details]
Replace includes/BagOStuff.php with this one to fix (MediaWiki 1.13.0)

Please submit a diff

Please get this fixed, it's annoying :)

Oh, and... shouldn't update.php work in readonly mode? wouldn't it be nasty to have people editing while it's running?

denilsonsa wrote:

I had 1.11.1, then I enabled $wgReadOnly (because I was about to update my wiki).
Then I replaced the mediawiki files to 1.13.1 (preserving AdminSettings.php and LocalSettings.php).
Then I ran update.php from command-line. (which ignores $wgReadOnly)
Then I tried to access the wiki... and things were painfully slow. I mean, 1 minute or more to load any page.

Then I disabled $wgReadOnly, and everything was blazing fast again.

Can you please submit a diff patch, not the whole file? Thanks.

Fixed in r42796. Depressingly, this was a one-line fix. :)

Since read-only mode these days no longer actually enforces the "can't write anything to the DB" rule, just having read-only mode *not* disable cache writes fixes it nicely. Today's read-only mode is meant merely to prevent user-visible actions. (This of course means that it's insufficient for running on a database that's *actually* read-only, as some activity that causes background writes, such as the objectcache, would fail. But since we're already in that state, let's let things work in the common case, eh?)