Is this happening for all pages on the wiki, or just for this “TestPage”?
On Monday, August 11, 2014 at 4:48 PM, Bjoern Kahl wrote: > > Dear Scott > dear All, > > Am 11.08.14 um 11:54 schrieb C. Scott Ananian: > > > What could cause this behavior and how should I configure my system to > > > prevent the deadlocks? If this is a Bug in either MediWiki or the > > > VisualEditor or Parsoid, how to further investigate and fix it? > > > Wikitech-l mailing list > > > Wikitech-l@lists.wikimedia.org (mailto:Wikitech-l@lists.wikimedia.org) > > > https://lists.wikimedia.org/mailman/listinfo/wikitech-l > > > > > > > > > Holding a database lock while a Parsoid query is made seems like a really > > bad idea. That seems like it could be a big in MediaWiki core. However, > > I'm running an almost identical setup on my machine (Debian/unstable rather > > than wheezy) as are most Parsoid developers (Ubuntu instead of Debian) and > > I've never seen this. > > > > > Honestly, I was surprised running into this problem and I am still not > sure where the culprit is. MediaWiki is used at so many places, it is > hard to believe in a locking bug, although possible. > > > > Perhaps I might suggest looking closely at the code which takes database > > locks, and why it is doing so? Perhaps more details on your db > > configuration would also be helpful, if you're not using Debian and > > MediaWiki defaults. > > > > > Here come more details: > > - Everything runs on a single server, single core. > > - System runs in 32 bit mode (although CPU is capable of 64 bit mode) > > - mySQL table type is InnoDB > > - no unusual mysql server options are in effect, as far as I remember > > - PHP is not using memcache or any other caching module > > - the Wiki is mostly idle, approx 30 users and highest ever concurrent > login count was 3 users. > > - All tests so far done with a copy where at most one user was active > at anytime (myself) > > - my LocalSettings.php might be a bit non-standard. Here some > settings that may or may not be relevant (in order of appearance > in LocalSettings.php): > > + $wgDBprefix = "wiki_"; > + $wgDBTableOptions = "ENGINE=InnoDB, DEFAULT CHARSET=binary"; > + $wgDBmysql5 = false; > + $wgMainCacheType = CACHE_NONE; > + $wgMemCachedServers = array(); > + $wgUseInstantCommons = false; > + $wgDefaultSkin = "vector"; > + $wgResourceLoaderMaxQueryLength = -1; > + $wgGroupPermissions['*']['createaccount'] = false; > + $wgGroupPermissions['*']['edit'] = false; > + $wgGroupPermissions['*']['read'] = false; > + require_once ( 'extensions/BibTex/bibtex.php' ); > + require_once ( 'extensions/MathJax/MathJax.php' ); > + $wgParserCacheType = CACHE_NONE; > + $wgTexvc = '/extensions/Math/math/texvc'; > + $wgUseTeX = true; > + require_once('extensions/WikiEditor/WikiEditor.php'); > + require_once "$IP/extensions/Parsoid/Parsoid.php"; > + require_once "$IP/extensions/VisualEditor/VisualEditor.php"; > + $wgDefaultUserOptions['visualeditor-enable'] = 1; > + $wgVisualEditorParsoidURL = 'http://<my.server.name > (http://my.server.name)>:8000'; > + $wgVisualEditorParsoidPrefix = 'testwiki'; > + $wgSessionsInObjectCache = true; > + $wgVisualEditorParsoidForwardCookies = true; > + require_once('extensions/UserMerge/UserMerge.php'); > + require_once("$IP/extensions/LastUserLogin/LastUserLogin.php"); > > - Also in LocalSettings.php, I have enabled debugging using: > > + $wgDebugLogFile = "</some/path/to>/mediawiki-debug-{$wgDBname}.log"; > + $wgShowSQLErrors = true; > + $wgShowDBErrorBacktrace = true; > + $wgDebugTimestamps = true; > + $wgDebugDumpSql = true; > > Are there other / better options to get a comprehensive trace of > what happens when? > > > - - - - Please find below an excerpt from the debug log - - - - > > Note: > I tweaked wfDebugTimer() to have absolute timestamps and to have > client address/port in order to relate debug log lines to tcpdump > logs from capturing the on-wire conversation between MediaWiki and > Parsoid service. > > Sorry for the overlong lines. > > If I should upload the log somewhere, please tell me where. > > > (1) client access to API for visual editor > > <client.ip>:55246 17:49:15.640 0.1347 1.5M Start request GET > /wiki/api.php?format=json&action=visualeditor&paction=parse&page=TestPage > HTTP HEADERS: > HOST: <my.server.name (http://my.server.name)> > X-REQUESTED-WITH: XMLHttpRequest > USER-AGENT: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) > AppleWebKit/534.59.10 (KHTML, like Gecko) Version/5.1.9 Safari/534.59.10 > ACCEPT: application/json, text/javascript, */*; q=0.01 > REFERER: http://<my.server.name > (http://my.server.name)>/wiki/index.php/TestPage?veaction=edit > ACCEPT-LANGUAGE: de-de > ACCEPT-ENCODING: gzip, deflate > COOKIE: wikiEditor-0-toolbar-section=advanced; > test_wiki__session=gt5evdjgg9ebdrkcg4i6c6gqc0; > test_wiki_UserName=TestUser; test_wiki_UserID=18; > PHPSESSID=ts0j9nug4oa0o2c4fka2ok5ei3 > CONNECTION: keep-alive > <client.ip>:55246 17:49:15.662 0.1566 1.5M [caches] main: > EmptyBagOStuff, message: SqlBagOStuff, parser: EmptyBagOStuff > <client.ip>:55246 17:49:15.730 0.2252 2.2M Connected to database 0 > at localhost > <client.ip>:55246 17:49:15.737 0.2318 2.2M Connected to database 0 > at localhost > <client.ip>:55246 17:49:15.738 0.2326 2.2M Query test (1) (slave): > SELECT /* SqlBagOStuff::getMulti */ keyname,value,exptime FROM > `wiki_objectcache` WHERE keyname = > 'test-wiki_:session:gt5evdjgg9ebdrkcg4i6c6gqc0' > <client.ip>:55246 17:49:15.837 0.3320 3.2M [caches] > LocalisationCache: using store LCStoreDB > <client.ip>:55246 17:49:15.924 0.4189 4.2M Unstubbing $wgParser on > call of $wgParser::setHook from wfBibtexExtension > <client.ip>:55246 17:49:15.990 0.4846 4.8M Parser: using > preprocessor: Preprocessor_DOM > <client.ip>:55246 17:49:15.997 0.4921 4.8M DatabaseBase::query: > Writes done: UPDATE `wiki_user` SET user_touched = '20140809154915' > WHERE user_id = 18 > > *** next line starts transaction *** > > <client.ip>:55246 17:49:15.998 0.4926 4.8M Query test (2) (slave): > BEGIN /* DatabaseBase::query (DatabaseBase::query) */ > <client.ip>:55246 17:49:15.998 0.4932 4.8M Query test (3) (slave): > UPDATE /* DatabaseBase::query */ `wiki_user` SET user_touched = > '20140809154915' WHERE user_id = 18 > <client.ip>:55246 17:49:20.242 4.7366 4.8M Fully initialised > <client.ip>:55246 17:49:20.298 4.7928 5.2M User: cache miss for user 18 > <client.ip>:55246 17:49:20.299 4.7937 5.2M Query test (4) (slave): > SELECT /* User::loadFromDatabase */ > user_id,user_name,user_real_name,user_password,user_newpassword,user_newpass_time,user_email,user_touched,user_token,user_email_authenticated,user_email_token,user_email_token_expires,user_password_expires,user_registration,user_editcount > FROM `wiki_user` WHERE user_id = '18' LIMIT 1 > <client.ip>:55246 17:49:20.305 4.8003 5.2M Query test (5) (slave): > SELECT /* User::loadGroups */ ug_group FROM `wiki_user_groups` > WHERE ug_user = '18' > <client.ip>:55246 17:49:20.315 4.8096 5.5M Query test (6) (slave): > SELECT /* LCStoreDB::get */ lc_value FROM `wiki_l10n_cache` WHERE > lc_lang = 'en' AND lc_key = 'deps' LIMIT 1 > <client.ip>:55246 17:49:20.317 4.8120 5.5M Query test (7) (slave): > SELECT /* LCStoreDB::get */ lc_value FROM `wiki_l10n_cache` WHERE > lc_lang = 'en' AND lc_key = 'list' LIMIT 1 > <client.ip>:55246 17:49:20.323 4.8181 6.0M Query test (8) (slave): > SELECT /* LCStoreDB::get */ lc_value FROM `wiki_l10n_cache` WHERE > lc_lang = 'en' AND lc_key = 'preload' LIMIT 1 > <client.ip>:55246 17:49:20.332 4.8275 6.0M Query test (9) (slave): > SELECT /* LCStoreDB::get */ lc_value FROM `wiki_l10n_cache` WHERE > lc_lang = 'en' AND lc_key = 'preload' LIMIT 1 > <client.ip>:55246 17:49:20.336 4.8310 6.0M User: loading options > for user 18 from database. > <client.ip>:55246 17:49:20.337 4.8318 6.0M Query test (10) (slave): > SELECT /* User::loadOptions */ up_property,up_value FROM > `wiki_user_properties` WHERE up_user = '18' > <client.ip>:55246 17:49:20.338 4.8330 6.0M User: logged in from session > <client.ip>:55246 17:49:20.356 4.8515 6.0M Query test (11) (slave): > SELECT /* LCStoreDB::get TestUser */ lc_value FROM `wiki_l10n_cache` > WHERE lc_lang = 'en' AND lc_key = 'namespaceGenderAliases' LIMIT 1 > <client.ip>:55246 17:49:20.358 4.8527 6.0M Query test (12) (slave): > SELECT /* LinkCache::addLinkObj TestUser */ > page_id,page_len,page_is_redirect,page_latest,page_content_model FROM > `wiki_page` WHERE page_namespace = '2' AND page_title = 'TestUser' > LIMIT 1 > <client.ip>:55246 17:49:20.367 4.8623 6.0M Query test (13) (slave): > SELECT /* Revision::fetchFromConds TestUser */ > rev_id,rev_page,rev_text_id,rev_timestamp,rev_comment,rev_user_text,rev_user,rev_minor_edit,rev_deleted,rev_len,rev_parent_id,rev_sha1,rev_content_format,rev_content_model,page_namespace,page_title,page_id,page_latest,page_is_redirect,page_len,user_name > FROM `wiki_revision` INNER JOIN `wiki_page` ON ((page_id = rev_page)) > LEFT JOIN `wiki_user` ON ((rev_user != 0) AND (user_id = rev_user)) > WHERE page_namespace = '2' AND page_title = 'TestUser' > > Note: no "COMMIT" here. Transaction will eventually be COMMITed after > timing out interaction with Parsoid service and aborting the > VisualEditor request (not part of this log excerpt). > > > (2) Mediawiki calling Parsoid service (from tcpdump, abridged) > > 17:49:20.387646 IP <server.ip>.37260 > <server.ip>.8000: Flags [S], seq > 3008505020, win 32792 > 17:49:20.387678 IP <server.ip>.8000 > <server.ip>.37260: Flags [S.], seq > 59446639, ack 3008505021, win 32768 > 17:49:20.387702 IP <server.ip>.37260 > <server.ip>.8000: Flags [.], ack > 1, win 2050 > 17:49:20.389966 IP <server.ip>.37260 > <server.ip>.8000: Flags [P.], seq > 1:387, ack 1, win 2050 > GET /testwiki/TestPage?oldid=4053 HTTP/1.0 > Host: <my.server.name (http://my.server.name)>:8000 > Accept: */* > Accept-Encoding: deflate, gzip^MCookie: > wikiEditor-0-toolbar-section=advanced; > test_wiki__session=gt5evdjgg9ebdrkcg4i6c6gqc0; > test_wiki_UserName=TestUser; test_wiki_UserID=18; > PHPSESSID=ts0j9nug4oa0o2c4fka2ok5ei3 > User-Agent: MediaWiki/1.23.2 > > > 17:49:20.390014 IP <server.ip>.8000 > <server.ip>.37260: Flags [.], ack > 387, win 2048 > > > (3a) Parsoid calling MediaWiki API (from tcpdump, abridged) > > > 17:49:20.412369 IP <server.ip>.43619 > <server.ip>.80: Flags [S], seq > 1070720780, win 32792 > 17:49:20.412402 IP <server.ip>.80 > <server.ip>.43619: Flags [S.], seq > 4074871095, ack 1070720781, win 32768 > 17:49:20.412427 IP <server.ip>.43619 > <server.ip>.80: Flags [.], ack 1, > win 2050 > 17:49:20.413214 IP <server.ip>.43619 > <server.ip>.80: Flags [P.], seq > 1:459, ack 1, win 2050 > GET > /wiki/api.php?format=json&action=query&prop=revisions&rvprop=content%7Cids%7Ctimestamp%7Cuser%7Cuserid%7Csize%7Csha1%7Ccontentmodel%7Ccomment&revids=4053 > HTTP/1.1 > User-Agent: Parsoid/0.1 > Connection: close > Cookie: wikiEditor-0-toolbar-section=advanced; > test_wiki__session=gt5evdjgg9ebdrkcg4i6c6gqc0; > test_wiki_UserName=TestUser; test_wiki_UserID=18; > PHPSESSID=ts0j9nug4oa0o2c4fka2ok5ei3 > host: <my.server.name (http://my.server.name)> > > > 17:49:20.413264 IP <server.ip>.80 > <server.ip>.43619: Flags [.], ack > 459, win 2048 > > > (3b) Parsoid calling MediaWiki API (from MediaWiki debug log) > > <server.ip>:43619 17:49:20.492 0.0759 1.5M Start request GET > /wiki/api.php?format=json&action=query&prop=revisions&rvprop=content%7Cids%7Ctimestamp%7Cuser%7Cuserid%7Csize%7Csha1%7Ccontentmodel%7Ccomment&revids=4053 > HTTP HEADERS: > USER-AGENT: Parsoid/0.1 > CONNECTION: close > COOKIE: wikiEditor-0-toolbar-section=advanced; > test_wiki__session=gt5evdjgg9ebdrkcg4i6c6gqc0; > test_wiki_UserName=TestUser; test_wiki_UserID=18; > PHPSESSID=ts0j9nug4oa0o2c4fka2ok5ei3 > HOST: <my.server.name (http://my.server.name)> > <server.ip>:43619 17:49:20.502 0.0859 1.5M [caches] main: > EmptyBagOStuff, message: SqlBagOStuff, parser: EmptyBagOStuff > <server.ip>:43619 17:49:20.538 0.1221 2.2M Connected to database 0 > at localhost > <server.ip>:43619 17:49:20.539 0.1234 2.2M Connected to database 0 > at localhost > <server.ip>:43619 17:49:20.540 0.1241 2.2M Query test (1) (slave): > SELECT /* SqlBagOStuff::getMulti */ keyname,value,exptime FROM > `wiki_objectcache` WHERE keyname = > 'test-wiki_:session:gt5evdjgg9ebdrkcg4i6c6gqc0' > <server.ip>:43619 17:49:20.594 0.1782 3.2M [caches] > LocalisationCache: using store LCStoreDB > <server.ip>:43619 17:49:20.640 0.2249 4.2M Unstubbing $wgParser on > call of $wgParser::setHook from wfBibtexExtension > <server.ip>:43619 17:49:20.672 0.2567 4.8M Parser: using > preprocessor: Preprocessor_DOM > <server.ip>:43619 17:49:20.676 0.2603 4.8M DatabaseBase::query: > Writes done: UPDATE `wiki_user` SET user_touched = '20140809154920' > WHERE user_id = 18 > <server.ip>:43619 17:49:20.676 0.2608 4.8M Query test (2) (slave): > BEGIN /* DatabaseBase::query (DatabaseBase::query) */ > <server.ip>:43619 17:49:20.677 0.2614 4.8M Query test (3) (slave): > UPDATE /* DatabaseBase::query */ `wiki_user` SET user_touched = > '20140809154920' WHERE user_id = 18 > > *** dead lock occurred *** > > (4) Parsoid timing out and recalling > > <server.ip>:43620 17:50:00.515 0.0757 1.5M Start request GET > /wiki/api.php?format=json&action=query&prop=revisions&rvprop=content%7Cids%7Ctimestamp%7Cuser%7Cuserid%7Csize%7Csha1%7Ccontentmodel%7Ccomment&revids=4053 > HTTP HEADERS: > USER-AGENT: Parsoid/0.1 > CONNECTION: close > COOKIE: wikiEditor-0-toolbar-section=advanced; > test_wiki__session=gt5evdjgg9ebdrkcg4i6c6gqc0; > test_wiki_UserName=TestUser; test_wiki_UserID=18; > PHPSESSID=ts0j9nug4oa0o2c4fka2ok5ei3 > HOST: <my.server.name (http://my.server.name)> > <server.ip>:43620 17:50:00.525 0.0854 1.5M [caches] main: > EmptyBagOStuff, message: SqlBagOStuff, parser: EmptyBagOStuff > <server.ip>:43620 17:50:00.559 0.1197 2.2M Connected to database 0 > at localhost > <server.ip>:43620 17:50:00.560 0.1209 2.2M Connected to database 0 > at localhost > <server.ip>:43620 17:50:00.561 0.1216 2.2M Query test (1) (slave): > SELECT /* SqlBagOStuff::getMulti */ keyname,value,exptime FROM > `wiki_objectcache` WHERE keyname = > 'test-wiki_:session:gt5evdjgg9ebdrkcg4i6c6gqc0' > <server.ip>:43620 17:50:00.612 0.1727 3.2M [caches] > LocalisationCache: using store LCStoreDB > <server.ip>:43620 17:50:00.657 0.2171 4.2M Unstubbing $wgParser on > call of $wgParser::setHook from wfBibtexExtension > <server.ip>:43620 17:50:00.687 0.2475 4.8M Parser: using > preprocessor: Preprocessor_DOM > <server.ip>:43620 17:50:00.691 0.2510 4.8M DatabaseBase::query: > Writes done: UPDATE `wiki_user` SET user_touched = '20140809155000' > WHERE user_id = 18 > <server.ip>:43620 17:50:00.691 0.2515 4.8M Query test (2) (slave): > BEGIN /* DatabaseBase::query (DatabaseBase::query) */ > <server.ip>:43620 17:50:00.692 0.2521 4.8M Query test (3) (slave): > UPDATE /* DatabaseBase::query */ `wiki_user` SET user_touched = > '20140809155000' WHERE user_id = 18 > > *** dead lock *** > > (5) MediaWiki timing out on lock acquisition > > <server.ip>:43619 17:50:11.927 51.5110 4.8M SQL ERROR: Lock wait > timeout exceeded; try restarting transaction (localhost) > <server.ip>:43619 17:50:11.937 51.5217 4.8M [Bug56269] Exception > thrown with an uncommited database transaction: [5640864b] > /wiki/api.php?format=json&action=query&prop=revisions&rvprop=content%7Cids%7Ctimestamp%7Cuser%7Cuserid%7Csize%7Csha1%7Ccontentmodel%7Ccomment&revids=4053 > Exception from line 1157 of > </some/path>/wiki/includes/db/Database.php: A database error has > occurred. Did you forget to run maintenance/update.php after upgrading? > See: https://www.mediawiki.org/wiki/Manual:Upgrading#Run_the_update_script > Query: UPDATE `wiki_user` SET user_touched = '20140809154920' WHERE > user_id = 18 > Function: DatabaseBase::query > Error: 1205 Lock wait timeout exceeded; try restarting transaction > (localhost) > > #0 </some/path>/wiki/includes/db/Database.php(1123): > DatabaseBase->reportQueryError('Lock wait timeo...', 1205, 'UPDATE > `wiki_us...', 'DatabaseBase::q...', false) > #1 </some/path>/wiki/extensions/LastUserLogin/LastUserLogin.php(64): > DatabaseBase->query('UPDATE `wiki_us...') > #2 [internal function]: wfUpdateUserTouched() > #3 </some/path>/wiki/includes/Setup.php(601): > call_user_func('wfUpdateUserTou...') > #4 </some/path>/wiki/includes/WebStart.php(156): > require_once('/var/www/virtua...') > #5 </some/path>/wiki/api.php(43): require('/var/www/virtua...') > #6 {main} > <server.ip>:43619 17:50:11.938 51.5224 4.8M Query test (4) (slave): > ROLLBACK /* LoadBalancer::rollbackMasterChanges */ > <server.ip>:43619 17:50:11.941 51.5257 4.8M DatabaseBase::query: > Writes done: REPLACE INTO `wiki_objectcache` (keyname,value,exptime) > VALUES ('test-wiki_:session:gt5evdjgg9ebdrkcg4i6c6gqc0','<binary data > removed>','20140809165011') > <server.ip>:43619 17:50:11.942 51.5262 4.8M Query test (5) (slave): > REPLACE /* SqlBagOStuff::set */ INTO `wiki_objectcache` > (keyname,value,exptime) VALUES > ('testtest-wiki_:session:gt5evdjgg9ebdrkcg4i6c6gqc0','<binary data > removed>','20140809165011') > > > > Best regards > > Björn > > -- > | Bjoern Kahl +++ Siegburg +++ Germany | > | "googlelogin@-my-domain-" +++ www.bjoern-kahl.de > (http://www.bjoern-kahl.de) | > | Languages: German, English, Ancient Latin (a bit :-)) | > > _______________________________________________ > Wikitech-l mailing list > Wikitech-l@lists.wikimedia.org (mailto:Wikitech-l@lists.wikimedia.org) > https://lists.wikimedia.org/mailman/listinfo/wikitech-l > > _______________________________________________ Wikitech-l mailing list Wikitech-l@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/wikitech-l
