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(a)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
--
| Bjoern Kahl +++ Siegburg +++ Germany |
| "googlelogin@-my-domain-" +++
www.bjoern-kahl.de |
| Languages: German, English, Ancient Latin (a bit :-)) |