Dear All,
I need some help tracking down a DB deadlock on a single-server, "private" Wiki installation running latest MediaWiki download from http://www.mediawiki.org/wiki/Download
I have been referred to this mailing list from #mediawiki at irc.freenode.org, thanks for the pointer!
Installed versions: -------------------
- MediaWiki: 1.23.2
- VisualEditor from Git, branch REL1_23, ID 9883566
- Parsoid from Git, branch REL1_23, ID 8da3673
- parsoid service from Git, branch master, ID df35443
- mysql: 5.5.35, Debian wheezy package
- apache: 2.2.22, Debian wheezy package
- PHP: 5.4.4, Debian wheezy package
- OS: Linux 3.2.0-4-686-pae #1 SMP Debian 3.2.57-3 i686 GNU/Linux
MediaWiki, Parsoid (nodejs) service and mysql database are all on the same server. Setup followed the instructions on https://www.mediawiki.org/wiki/Parsoid/Setup
Problem description: --------------------
Logging in, reading and editing using the standard (not visual) edit works fine.
Clicking "Edit", which starts the visual editor, results in no reaction at all for approx 5 seconds, then the page goes dim and a progress indicator appears at the top right corner.
After another approx. 100 seconds, the page returns to normal state as if opened or reading.
Directly accessing the Parsoid service, here running on port 8000, promptly delivers the page.
Preliminary investigation: --------------------------
Enabling debugging in LocalSettings.php and tweaking wfDebugTimer() to get absolute millisecond timestamps and client address/port info in the log file showed the following sequences of activities (anonymized log files available if needed):
Summarized:
- client request page by calling "GET /wiki/api.php?format=json&action=visualeditor&paction=parse..."
- MediaWiki starts processing and class the Parsoid service with "GET /testwiki/TestPage?oldid=4053 HTTP/1.0"
- Parsoid service calls "GET /wiki/api.php?format=json&action=query&prop=revisions&..."
- call from Parsoid server into MediaWiki API deadlocks with client call into API.
The question is why is it deadlocking and how to prevent the deadlock.
Detailed activities analysis:
- (1) client accesses "GET /wiki/api.php?format=json&action=visualeditor&paction=parse..."
- (2) MediaWiki starts some session bookkeeping, including opening a DB transaction with "BEGIN" and performing several queries in the transaction.
- (3) MediaWiki/1.23.2 calls the parsoid service with "GET /testwiki/TestPage?oldid=4053 HTTP/1.0"
- (4) Parsoid/0.1 calls "GET /wiki/api.php?format=json&action=query&prop=revisions&..."
- (5) MediaWiki starts processing (in a new apache/PHP slave) and opens a new DB transaction with "BEGIN" performing the same initial "UPDATE `wiki_user` SET user_touched ..." query as first query in the transaction as in step (2).
- (6) approx. 40 seconds pass
- (7) Parsoid service drops connection from (4) to MediaWiki (TCP FIN packet observed by tcpdump while capturing the on-wire conversation between MediaWiki and the client / the Parsiod service)
- (8) Parsoid/0.1 calls again "GET /wiki/api.php?format=json&action=query&prop=revisions&..." from a new connection (client port number changed)
- (9) MediaWiki starts processing (in a new apache/PHP slave) and opens a new DB transaction with "BEGIN" performing the same initial "UPDATE `wiki_user` SET user_touched ..." query as first query in the transaction as in step (2) and (5).
- (10) approx. 10 seconds pass
- (11) MediaWiki receives a "SQL ERROR: Lock wait timeout exceeded; try restarting transaction" relating to transaction from step (5)
- (12) MediaWiki attempts a ROLLBACK of (5) and tries to send a "HTTP 500" (content captured by tcpdump) but the connection is already dead.
- (13) approx. 30 seconds pass
- (14) Parsoid service drops connection from (8) to MediaWiki (TCP FIN packet observed by tcpdump while capturing the on-wire conversation between MediaWiki and the client / the Parsiod service)
- (15) Parsoid/0.1 calls again "GET /wiki/api.php?format=json&action=query&prop=revisions&..." from a new connection (client port number changed)
- (16) MediaWiki starts processing (in a new apache/PHP slave) and opens a new DB transaction with "BEGIN" performing the same initial "UPDATE `wiki_user` SET user_touched ..." query as first query in the transaction as in step (2), (5) and (9).
- (17) approx. 10 seconds pass
- (18) MediaWiki receives a "SQL ERROR: Lock wait timeout exceeded; try restarting transaction" relating to transaction from step (9)
- (19) MediaWiki attempts a ROLLBACK of (9) and tries to send a "HTTP 500" (content captured by tcpdump) but the connection is already dead.
- (20) approx. 10 seconds pass
- (21) MediaWiki closes the connection to the Parsoid service from step (3), without any data exchange after receiving the initial "GET /testwiki/TestPage?oldid=4053 HTTP/1.0"
- (22) MediaWiki performs a DB "COMMIT" in the original client session from step (2), after 104 seconds.
- (23) MediaWiki continues processing the session from step (16), at least in part executing the same set of queries as in step (2).
- (24) MediaWiki performs a DB "COMMIT" in the Parsoid client session from step (15), after 20 seconds.
- (25) MediaWiki sends a "HTTP 200" with a JSON body to the Parsoid service as answer to request from step (15).
- (26) Parsoid service logs messages "starting parsing", a parse tree and "completed parsing in 101234 ms". (Note: It is unclear when in the range (21) to (26) these messages are logged, but I think this position "(26)" is most logical.) At earlier times, Parsoid logs the two messages "Failed API request, 8 retries remaining." and "Failed API request, 7 retries remaining." and not precisely known time steps, probably between (7)/(8) and (14)/(15), respectively.
Question: ---------
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?
Best regards
Björn
On 08/10/2014 04:10 PM, Bjoern Kahl wrote:
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?
In case this is a private wiki:
Did you set $wgSessionsInObjectCache = true;
following the instructions at https://www.mediawiki.org/wiki/Extension:VisualEditor#Linking_with_Parsoid_i... ?
Gabriel
Am 10.08.14 um 20:52 schrieb Gabriel Wicke:
On 08/10/2014 04:10 PM, Bjoern Kahl wrote:
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?
In case this is a private wiki:
Did you set $wgSessionsInObjectCache = true;
following the instructions at https://www.mediawiki.org/wiki/Extension:VisualEditor#Linking_with_Parsoid_i... ?
Yes, I have (and had) "$wgSessionsInObjectCache = true;" in my LocalSettings.php
I have just disabled it (set to false) to counter-check, and it does produce a different sequence of activities. On a first glance, it seems to stop earlier, but in the end process and answer three calls from Parsoid instead of zero.
I'll have a closer look tomorrow, for today it's to late (1 in the morning (1 CEST / 23 UTC))
Thanks
Björn
What seems like a deadlock may in fact be parsoid timing out while trying to connect to your local wiki's API end point. We have had some users report problems of this sort which were caused by their firewall or access control setup. You might want to verify that the API end point for your local wiki is configured correctly, and that you can successfully connect to it from the machine Parsoid is running on. --scott
On Sun, Aug 10, 2014 at 11:56 PM, Bjoern Kahl mls@bjoern-kahl.de wrote:
Am 10.08.14 um 20:52 schrieb Gabriel Wicke:
On 08/10/2014 04:10 PM, Bjoern Kahl wrote:
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?
In case this is a private wiki:
Did you set $wgSessionsInObjectCache = true;
following the instructions at https://www.mediawiki.org/wiki/Extension:VisualEditor#Linking_with_Parsoid_i... ?
Yes, I have (and had) "$wgSessionsInObjectCache = true;" in my LocalSettings.php
I have just disabled it (set to false) to counter-check, and it does produce a different sequence of activities. On a first glance, it seems to stop earlier, but in the end process and answer three calls from Parsoid instead of zero.
I'll have a closer look tomorrow, for today it's to late (1 in the morning (1 CEST / 23 UTC))
Thanks
Björn-- | Bjoern Kahl +++ Siegburg +++ Germany | | "googlelogin@-my-domain-" +++ www.bjoern-kahl.de | | Languages: German, English, Ancient Latin (a bit :-)) |
Wikitech-l mailing list Wikitech-l@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/wikitech-l
Dear Scott,
Am 11.08.14 um 05:36 schrieb C. Scott Ananian:
What seems like a deadlock may in fact be parsoid timing out while trying to connect to your local wiki's API end point. We have had some users report problems of this sort which were caused by their firewall or access control setup. You might want to verify that the API end point for your local wiki is configured correctly, and that you can successfully connect to it from the machine Parsoid is running on.
thanks for the input, but all services (Wiki (apache2), mysql and Parsoid) are running on the same machine.
Additionally, I used "tcpdumd -A ..." to capture the conversation between the Wiki (i.e. /wiki/api.php) and the Parsoid service, see detailed transcript in my original report, steps (3) to (7), and so verified that they can and do communicate. Logs available if needed.
Parsoid times out, but not due to a failed TCP connection.
@All: I am happy to provide any addition information regarding my setup and steps tried that you consider useful.
Best regards
Björn
On Sun, Aug 10, 2014 at 11:56 PM, Bjoern Kahl mls@bjoern-kahl.de wrote:
Am 10.08.14 um 20:52 schrieb Gabriel Wicke:
On 08/10/2014 04:10 PM, Bjoern Kahl wrote:
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?
In case this is a private wiki:
Did you set $wgSessionsInObjectCache = true;
following the instructions at https://www.mediawiki.org/wiki/Extension:VisualEditor#Linking_with_Parsoid_i...
?
Yes, I have (and had) "$wgSessionsInObjectCache = true;" in my LocalSettings.php
I have just disabled it (set to false) to counter-check, and it does produce a different sequence of activities. On a first glance, it seems to stop earlier, but in the end process and answer three calls from Parsoid instead of zero.
I'll have a closer look tomorrow, for today it's to late (1 in the morning (1 CEST / 23 UTC))
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.
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. --scott
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
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)%3E: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)%3E 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)%3E/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)%3E: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)%3E
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)%3E <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)%3E <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
Am 13.08.14 um 16:54 schrieb Arlo Breault:
Is this happening for all pages on the wiki, or just for this “TestPage”?
It happens on all pages.
I created the TestPage to rule out problems with complex WikiText. The "TestPage" is quite simple: only 35 lines, 83 words and 1493 characters according to the "wc" tool. Just a bit of unformatted text and a bulleted list created with the asterisk. No sections, no headlines, no tables, no text styles, nothing special.
Best regards
Björn
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)%3E: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)%3E 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)%3E/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)%3E: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)%3E
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)%3E <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)%3E <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')
On Tue, Aug 12, 2014 at 12:48 AM, Bjoern Kahl mls@bjoern-kahl.de wrote:
- require_once ( 'extensions/BibTex/bibtex.php' );
- require_once ( 'extensions/MathJax/MathJax.php' );
- require_once('extensions/WikiEditor/WikiEditor.php');
- require_once('extensions/UserMerge/UserMerge.php');
- require_once("$IP/extensions/LastUserLogin/LastUserLogin.php");
Could you try to temporarily disable these extensions (either all at once or one by one) and see if it fixes the problem? The last two in particular look like they might be responsible for the 'UPDATE `wiki_user` SET user_touched' transaction which appears to be causing the deadlock. --scott
Am 13.08.14 um 18:20 schrieb C. Scott Ananian:
On Tue, Aug 12, 2014 at 12:48 AM, Bjoern Kahl mls@bjoern-kahl.de wrote:
- require_once ( 'extensions/BibTex/bibtex.php' );
- require_once ( 'extensions/MathJax/MathJax.php' );
- require_once('extensions/WikiEditor/WikiEditor.php');
- require_once('extensions/UserMerge/UserMerge.php');
- require_once("$IP/extensions/LastUserLogin/LastUserLogin.php");
Could you try to temporarily disable these extensions (either all at once or one by one) and see if it fixes the problem? The last two in particular look like they might be responsible for the 'UPDATE `wiki_user` SET user_touched' transaction which appears to be causing the deadlock.
I disabled all extensions listed above: No change in behavior, still deadlocks.
By change I found that the whole site deadlocks, i.e. Trying to access another wiki page in a new browser tab, while visual editor tries to load in another, also stalls until the visual editor times out (105 seconds). Not really surprising, looking at the traces, but I'd thought I mention it anyway.
Best regards
Björn
wikitech-l@lists.wikimedia.org