Page MenuHomePhabricator

ERR_READ_TIMEOUT Error shown in editing long pages on Arabic Wikipedia or other wikis with linkprefix enabled
Closed, ResolvedPublic

Description

When editing many pages on Arabic Wikipedia especially the long pages , it show the attached error after clicking on the save button .


Version: 1.22.0
Severity: major
Platform: PC

Details

Reference
bz52865

Event Timeline

bzimport raised the priority of this task from to High.Nov 22 2014, 1:46 AM
bzimport set Reference to bz52865.

the error shown when tring to save the page

Attached:

Thanks for taking the time to report this!
Can you please provide an exact example with exact steps that somebody else could reproduce? Also see https://www.mediawiki.org/wiki/How_to_report_a_bug

Reedy added a comment.Aug 15 2013, 8:53 PM

(In reply to comment #1)

Created attachment 13100 [details]
the error shown when tring to save the page

Please post images in higher resolution/quality! It's very hard to read anything from that. Or, at least, copy paste the text under the grey line

Looks like a squid ERROR_CANNOT_FORWARD, but can't tell which squid(s) this may be

Attached:

moh.alhemaly wrote:

I Can not upload image to bugzilla, but this is url to it. https://www.dropbox.com/s/j8sj0q6peuaqduu/Capture.PNG

(In reply to comment #3)

(In reply to comment #1)

Created attachment 13100 [details]
the error shown when tring to save the page

Please post images in higher resolution/quality! It's very hard to read
anything from that. Or, at least, copy paste the text under the grey line
Looks like a squid ERROR_CANNOT_FORWARD, but can't tell which squid(s) this
may
be

Attached:

Created attachment 13124
Same screenshot

Attaching it to Bugzilla. The file is small enough that "Add attachment" works for me.

Attached:

emara / Mohamed:
Is this still reproducible? If yes, can you provide a link to one page where this problem can be seen?

(In reply to comment #3)

Looks like a squid ERROR_CANNOT_FORWARD, but can't tell which squid(s)

cp1003.eqiad.wmnet

moh.alhemaly wrote:

All Articles That Exceeded Level Of 130 bytes be hard edit. this is some of this articles in this page try to make any edit on any of it.
http://ar.wikipedia.org/wiki/خاص:صفحات_طويلة

mahfouz.saif.elyazal wrote:

You can try to reproduce it with the article about Islam. And Here is the link:
http://ar.wikipedia.org/wiki/%D8%A5%D8%B3%D9%84%D8%A7%D9%85

I tried to remove the following line that inserts a picture that is no longer available on wikicommons:

[[ملف:Babri rearview.jpg|تصغير|[[مسجد بابري|مسجد بابور]] في ولاية [[أوتار براديش]] [[الهند|بالهند]]، معبد هندوسي سابق استحال مسجدًا في عهد [[إمبراطورية مغول الهند|الأباطرة المغول]] ثم هدمه هندوس متعصبون سنة 1992.]]

and what I got was the following message about indicates a time out when passing data through the squid proxy:

Request: POST http://ar.wikipedia.org/w/index.php?title=%D8%A5%D8%B3%D9%84%D8%A7%D9%85&action=submit, from 196.205.190.140 via cp1001.eqiad.wmnet (squid/2.7.STABLE9) to 10.64.0.141 (10.64.0.141)
Error: ERR_READ_TIMEOUT, errno [No Error] at Fri, 23 Aug 2013 21:16:10 GMT

I was all ready to say something about complex templates and try using lua, but...

I tried the ?forceprofile option to the url, and had some interesting results:

100.00% 15.629602 1 - -total
99.64% 15.572851 1 - MediaWiki::main
97.16% 15.185047 1 - MediaWiki::performRequest
96.96% 15.154744 1 - MediaWiki::performAction
96.95% 15.153300 1 - Article::view
95.98% 15.001263 1 - PoolCounter_Client::acquireForAnyone

2.39% 0.373406      1 - OutputPage::output

Which seems wrong, so maybe something is wrong with Pool counter config?

(In reply to comment #9)

I was all ready to say something about complex templates and try using lua,
but...
I tried the ?forceprofile option to the url, and had some interesting
results:
100.00% 15.629602 1 - -total
99.64% 15.572851 1 - MediaWiki::main
97.16% 15.185047 1 - MediaWiki::performRequest
96.96% 15.154744 1 - MediaWiki::performAction
96.95% 15.153300 1 - Article::view
95.98% 15.001263 1 - PoolCounter_Client::acquireForAnyone

2.39% 0.373406      1 - OutputPage::output

Which seems wrong, so maybe something is wrong with Pool counter config?

Actually, that's probably just because i was visiting a pretty busy page, and maybe someone else had started rendering it in the time between my browser following the redirect from ?action=purge to the real page. Anyhow, ignore what i said above.

Problem is probably really complicated templates that need to be optimized (The templates take so long to render, that the page times out). Using lua for templates will probably result in a big speed boost.

Actually, it doesn't seem to be templates at all. I imported مصر into my local wiki, and it renders fine normally but if I change languages/messages/MessagesEn.php to set $linkPrefixExtension = true it takes a very long time. Profiling reports that the Parser::replaceInternalLinks2-prefixhandling block is called 4706 times for a total of 106165.145 microseconds out of 132266.461 total (which includes 15696.702 for the profiling itself).

The first few lines (anything showing over 1000ms):

Profiling data
Name Calls Total Each % Mem
-total 1 132266.461 132266.461 100.000% 323763776 ( 132266.461 - 132266.461) [0]
MediaWiki::main 1 115995.312 115995.312 87.698% 13945556 ( 115995.312 - 115995.312) [268332]
MediaWiki::performRequest 1 115837.514 115837.514 87.579% 12745446 ( 115837.514 - 115837.514) [268222]
MediaWiki::performAction 1 115823.683 115823.683 87.568% 12697952 ( 115823.683 - 115823.683) [268206]
EditPage::edit 1 115808.503 115808.503 87.557% 12649757 ( 115808.503 - 115808.503) [268201]
EditPage::edit-business-end 1 115766.022 115766.022 87.525% 11256750 ( 115766.022 - 115766.022) [268145]
EditPage::internalAttemptSave 1 115747.799 115747.799 87.511% 11182295 ( 115747.799 - 115747.799) [268129]
Parser::parse-WikitextContent::getParserOutput 2 115167.148 57583.574 87.072% 13425467 ( 56434.734 - 58732.414) [266237]
Parser::parse 2 115167.075 57583.537 87.072% 13425420 ( 56434.693 - 58732.382) [266239]
Parser::internalParse 148 115002.805 777.046 86.948% 14639358 ( -0.996 - 58070.885) [274670]
Parser::replaceInternalLinks2 162 108406.350 669.175 81.961% 6822086 ( -0.523 - 53980.376) [113950]
Parser::replaceInternalLinks2-prefixhandling 4706 106165.145 22.560 80.266% 33810552 ( 0.007 - 53.399) [0]
WikiPage::doEditContent 1 59102.591 59102.591 44.684% 1548990 ( 59102.591 - 59102.591) [130799]
hook: EditFilterMerged 1 56601.482 56601.482 42.794% 8906536 ( 56601.482 - 56601.482) [137251]
SpamBlacklistHooks::filterMerged 1 56596.141 56596.141 42.789% 8842893 ( 56596.141 - 56596.141) [137245]
wfSpamBlacklistFilter 1 56595.163 56595.163 42.789% 8874261 ( 56595.163 - 56595.163) [137244]
PPFrame_DOM::expand 70146 33645.483 0.480 25.438% 191341780 ( -16.119 - 3612.935) [670872]
Parser::braceSubstitution 3494 25838.918 7.395 19.536% 57848685 ( -11.287 - 1489.913) [562083]
-overhead-total 268417 15696.702 0.058 11.867% 306957152 ( 15696.702 - 15696.702) [268417]
Parser::braceSubstitution-pfunc 3318 7621.249 2.297 5.762% 38034801 ( -3.205 - 1487.452) [171241]
Parser::callParserFunction 2120 7528.970 3.551 5.692% 23275438 ( -3.172 - 1487.474) [169121]
Parser::replaceVariables 2420 6139.509 2.537 4.642% 12914606 ( -0.106 - 3618.133) [140412]
Parser::callParserFunction-pfunc-invoke 46 4144.569 90.099 3.133% 4856509 ( 0.535 - 1487.506) [76583]
ScribuntoHooks::invokeHook 46 4143.728 90.081 3.133% 4960986 ( 0.536 - 1487.503) [76537]
Parser::argSubstitution 16214 3890.259 0.240 2.941% 19615137 ( -2.044 - 1471.886) [75288]
Parser::callParserFunction-pfunc-switch 242 1752.245 7.241 1.325% 11973858 ( 0.036 - 349.141) [28369]
-overhead-internal 268417 1238.141 0.005 0.936% 85896720 ( 0.003 - 7.089) [0]
Parser::callParserFunction-pfunc-if 1556 1011.190 0.650 0.765% 3275860 ( -3.145 - 293.022) [52459]

tin:~$ mwscript eval.php --wiki=arwiki

return wfMessage( 'linkprefix' )->inContentLanguage()->text()

/^(.*?)([a-zA-Z\x80-\xff]+)$/sD

Not that bad, just that it gets called on each line of the text :/

Is this problem something that only recently started happening (e.g. in the past month) or is it a longer running problem?

mahfouz.saif.elyazal wrote:

(In reply to comment #13)

Is this problem something that only recently started happening (e.g. in the
past month) or is it a longer running problem?

No, it is a longer running problem. And it usually happens with long articles.

Change 81368 had a related patch set uploaded by Anomie:
Improve linkprefix regular expressions

https://gerrit.wikimedia.org/r/81368

Hi Alolita, could you find someone on your team to finish off? Brad has taken this as far as his expertise and time will allow. Thanks!

TomerA added a comment.Oct 7 2013, 9:34 AM

Bip? Is there anything new with this?

(In reply to comment #17)

Bip? Is there anything new with this?

Current status of code review is that the patch needs associated tests.

Parser::replaceInternalLinks2-prefixhandling block is called 4706 times for a
total of 106165.145 microseconds out of 132266.461 total (which includes
15696.702 for the profiling itself).

You mean 106165.145 milliseconds, not microseconds.

Change 91425 had a related patch set uploaded by Anomie:
Remove linkprefix message, add $linkPrefixCharset

https://gerrit.wikimedia.org/r/91425

mahfouz.saif.elyazal wrote:

How can we create tests for the patch? A link to a guide would be highly appreciated.

Ijon added a comment.Oct 24 2013, 2:25 AM

Hi there. So, this is a serious issue hampering actual page editing on a major Wikipedia. Can we get a timeline on when the patch could go live? Who is in charge of writing those tests?

(In reply to comment #22)

Hi there. So, this is a serious issue hampering actual page editing on a
major
Wikipedia. Can we get a timeline on when the patch could go live? Who is in
charge of writing those tests?

Tim and Brad are working on getting this resolved ASAP; fuzz testing is in progress as you can see in the changeset above. This is known to be a high priority issue, but it's also an area of the code where new subtle errors can easily be introduced, so suffice it to say that it's assigned, prioritized highly, and a fix will be deployed when we're confident that it resolves this issue without introducing new ones.

The testing is done to my satisfaction. The fix will be deployed today or tomorrow.

Ijon added a comment.Oct 24 2013, 2:47 AM

Oh, fantastic news, thanks!

mahfouz.saif.elyazal wrote:

Thanks Guys! Kindly post an announcement on the wiki community portal when you're done with the deployment process.

Change 81368 merged by jenkins-bot:
Improve linkprefix regular expressions

https://gerrit.wikimedia.org/r/81368

Change 91584 had a related patch set uploaded by Tim Starling:
Improve linkprefix regular expressions (MFM to 1.22wmf21)

https://gerrit.wikimedia.org/r/91584

Change 91584 merged by jenkins-bot:
Improve linkprefix regular expressions (MFM to 1.22wmf21)

https://gerrit.wikimedia.org/r/91584

Change 91587 had a related patch set uploaded by Tim Starling:
Improve linkprefix regular expressions (MFM to 1.22wmf22)

https://gerrit.wikimedia.org/r/91587

Change 91587 merged by jenkins-bot:
Improve linkprefix regular expressions (MFM to 1.22wmf22)

https://gerrit.wikimedia.org/r/91587

Fixed and deployed to all wikis.

Thank you all for your work.