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 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>: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> 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>/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>: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>
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> <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> <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