Made some tweaks to the profiling; it can now be set to log only profiling data (without other debug junk), and to log it only when the total time spent > X seconds.
Currently logging to /apache/profile/en.profile on larousse. The first bit will be without any limit; then with 1.0 second limit, then with the title-parsing code filtered out (always fairly fast, but a lot of them, it ends up being useless noise), then with a 5.0 second limit.
I noticed also that the user_newtalk table didn't have any index on it, which may explain why a lot of newtalk check queries were fairly slow. I added indexes, but they're still sometimes oddly slow.
alter table user_newtalk add key(user_id), add key(user_ip);
Will try to process the data some in a bit...
-- brion vibber (brino @ pobox.com)
I'm seeing many slow queries on ipblocks as well as on user_newtalk. I don't think these are genuine, though; these are the first queries issued by a page load when the user object is being set up, so if the database as a whole is blocking us, that's where everything will wait.
-- brion vibber (brion @ pobox.com)
Anybody wanna look into optimizing OutputPage::replaceInternalLinks()? It's a known troublemaker; it's got a bit loop that could probably be much much more efficiently done.
Rendering pages with lots and lots of links gets *really* slow.
-- brion vibber (brion @ pobox.com)
20031001020630 0025.562 /wiki/List_of_Japan_related_topics anon at 0000.016 in 0000.001 ( 0.0%) - main-misc-setup at 0000.017 in 0000.079 ( 0.3%) - *** wfQuery("SELECT cur_id FROM cur WHERE cur_namespace=0 AND cur_title='List_of_Japan_relate...") at 0000.017 in 0000.080 ( 0.3%) - ** LinkCache::addLink-checkdatabase at 0000.097 in 0000.013 ( 0.1%) - ** wfQuery("SELECT cur_text,cur_timestamp,cur_user,cur_counter,cur_restrictions,cur_touched ...") at 0000.112 in 0000.005 ( 0.0%) - *** wfQuery("SELECT cur_id FROM cur WHERE cur_namespace=0 AND cur_title='List_of_Japan-relate...") at 0000.111 in 0000.006 ( 0.0%) - ** LinkCache::addLink-checkdatabase at 0000.117 in 0000.118 ( 0.5%) - ** wfQuery("SELECT cur_text,cur_timestamp,cur_user,cur_counter,cur_touched FROM cur WHERE cu...") at 0000.017 in 0000.218 ( 0.9%) - * Article::getContent at 0000.237 in 0003.250 (12.7%) - ** wfQuery("SELECT cur_id,cur_namespace,cur_title FROM cur,links WHERE cur_id=l_to AND...") at 0003.582 in 0000.013 ( 0.0%) - ** wfQuery("SELECT bl_to FROM brokenlinks WHERE bl_from='200203'...") at 0000.237 in 0003.358 (13.1%) - * LinkCache::preFill at 0003.597 in 0000.001 ( 0.0%) - *** OutputPage::removeHTMLtags at 0003.598 in 0000.002 ( 0.0%) - *** OutputPage:replaceVariables at 0003.634 in 0000.009 ( 0.0%) - *** OutputPage::doBlockLevels at 0003.657 in 0000.111 ( 0.4%) - *** OutputPage::replaceExternalLinks at 0003.768 in 0000.006 ( 0.0%) - **** OutputPage::replaceInternalLinks-setup at 0003.774 in 0016.715 (65.4%) - **** OutputPage::replaceInternalLinks-loop at 0003.768 in 0016.721 (65.4%) - *** OutputPage::replaceInternalLinks at 0003.597 in 0016.925 (66.2%) - ** OutputPage::doWikiPass2 at 0003.595 in 0016.928 (66.2%) - * OutputPage::addWikiText at 0000.017 in 0020.506 (80.2%) - Article::view at 0020.523 in 0000.000 ( 0.0%) - * OutputPage::output-headers at 0020.524 in 0000.000 ( 0.0%) - ** Skin::initPage at 0020.524 in 0000.009 ( 0.0%) - ** Skin::doBeforeContent at 0020.524 in 0000.010 ( 0.0%) - * OutputPage::output-middle at 0020.534 in 0004.993 (19.5%) - * OutputPage::output-bodytext at 0025.531 in 0000.001 ( 0.0%) - **** wfQuery("SELECT cur_id FROM cur WHERE cur_namespace=1 AND cur_title='List_of_Japan-relate...") at 0025.530 in 0000.002 ( 0.0%) - *** LinkCache::addLink-checkdatabase at 0025.552 in 0000.001 ( 0.0%) - ***** wfQuery("SELECT cur_id FROM cur WHERE cur_namespace=1 AND cur_title='List_of_Japan-relate...") at 0025.551 in 0000.002 ( 0.0%) - **** LinkCache::addLink-checkdatabase at 0025.543 in 0000.019 ( 0.1%) - *** Skin::quickBar at 0025.527 in 0000.035 ( 0.1%) - ** Skin::doAfterContent at 0025.527 in 0000.035 ( 0.1%) - * OutputPage::output-after at 0020.523 in 0005.039 (19.7%) - OutputPage::output
On Tue, Sep 30, 2003 at 07:13:49PM -0700, Brion Vibber wrote:
Anybody wanna look into optimizing OutputPage::replaceInternalLinks()? It's a known troublemaker; it's got a bit loop that could probably be much much more efficiently done.
Rendering pages with lots and lots of links gets *really* slow.
Can you measure how much time is spent in the Skin::makeLink subroutine that's called quite often during the loop?
Regards,
JeLuF
-- brion vibber (brion @ pobox.com)
20031001020630 0025.562 /wiki/List_of_Japan_related_topics anon at 0000.016 in 0000.001 ( 0.0%) - main-misc-setup at 0000.017 in 0000.079 ( 0.3%) - *** wfQuery("SELECT cur_id FROM cur WHERE cur_namespace=0 AND cur_title='List_of_Japan_relate...") at 0000.017 in 0000.080 ( 0.3%) - ** LinkCache::addLink-checkdatabase at 0000.097 in 0000.013 ( 0.1%) - ** wfQuery("SELECT cur_text,cur_timestamp,cur_user,cur_counter,cur_restrictions,cur_touched ...") at 0000.112 in 0000.005 ( 0.0%) - *** wfQuery("SELECT cur_id FROM cur WHERE cur_namespace=0 AND cur_title='List_of_Japan-relate...") at 0000.111 in 0000.006 ( 0.0%) - ** LinkCache::addLink-checkdatabase at 0000.117 in 0000.118 ( 0.5%) - ** wfQuery("SELECT cur_text,cur_timestamp,cur_user,cur_counter,cur_touched FROM cur WHERE cu...") at 0000.017 in 0000.218 ( 0.9%) - * Article::getContent at 0000.237 in 0003.250 (12.7%) - ** wfQuery("SELECT cur_id,cur_namespace,cur_title FROM cur,links WHERE cur_id=l_to AND...") at 0003.582 in 0000.013 ( 0.0%) - ** wfQuery("SELECT bl_to FROM brokenlinks WHERE bl_from='200203'...") at 0000.237 in 0003.358 (13.1%) - * LinkCache::preFill at 0003.597 in 0000.001 ( 0.0%) - *** OutputPage::removeHTMLtags at 0003.598 in 0000.002 ( 0.0%) - *** OutputPage:replaceVariables at 0003.634 in 0000.009 ( 0.0%) - *** OutputPage::doBlockLevels at 0003.657 in 0000.111 ( 0.4%) - *** OutputPage::replaceExternalLinks at 0003.768 in 0000.006 ( 0.0%) - **** OutputPage::replaceInternalLinks-setup at 0003.774 in 0016.715 (65.4%) - **** OutputPage::replaceInternalLinks-loop at 0003.768 in 0016.721 (65.4%) - *** OutputPage::replaceInternalLinks at 0003.597 in 0016.925 (66.2%) - ** OutputPage::doWikiPass2 at 0003.595 in 0016.928 (66.2%) - * OutputPage::addWikiText at 0000.017 in 0020.506 (80.2%) - Article::view at 0020.523 in 0000.000 ( 0.0%) - * OutputPage::output-headers at 0020.524 in 0000.000 ( 0.0%) - ** Skin::initPage at 0020.524 in 0000.009 ( 0.0%) - ** Skin::doBeforeContent at 0020.524 in 0000.010 ( 0.0%) - * OutputPage::output-middle at 0020.534 in 0004.993 (19.5%) - * OutputPage::output-bodytext at 0025.531 in 0000.001 ( 0.0%) - **** wfQuery("SELECT cur_id FROM cur WHERE cur_namespace=1 AND cur_title='List_of_Japan-relate...") at 0025.530 in 0000.002 ( 0.0%) - *** LinkCache::addLink-checkdatabase at 0025.552 in 0000.001 ( 0.0%) - ***** wfQuery("SELECT cur_id FROM cur WHERE cur_namespace=1 AND cur_title='List_of_Japan-relate...") at 0025.551 in 0000.002 ( 0.0%) - **** LinkCache::addLink-checkdatabase at 0025.543 in 0000.019 ( 0.1%) - *** Skin::quickBar at 0025.527 in 0000.035 ( 0.1%) - ** Skin::doAfterContent at 0025.527 in 0000.035 ( 0.1%) - * OutputPage::output-after at 0020.523 in 0005.039 (19.7%) - OutputPage::output
Wikitech-l mailing list Wikitech-l@Wikipedia.org http://mail.wikipedia.org/mailman/listinfo/wikitech-l
On Tue, 2003-09-30 at 21:59, Jens Frank wrote:
Can you measure how much time is spent in the Skin::makeLink subroutine that's called quite often during the loop?
For these inner functions, the millisecond resolution on the timer often isn't precise enough.
That page has 2548 links on it; 16.715 seconds in the replaceInternalLinks loop means about 6.5 milliseconds for each iteration, which does a number of string operations and regular expressions and eventually a makeLink. Each iteration does a string append, too, which is likely not that efficient.
Here's a quick overview of 200,000 lines of profiling data, recorded only for requests to www.wikipedia.org that took more than 5 seconds. Note that the actual writing out of page data is generally done in OutputPage::output; this should be more or less instantaneous, but we sometimes seem to be blocking on buffer flushes from the next layer up.
Columns are the number of calls, the total wallclock time spent in that function, and the mean wallclock time per call. Not all functions are profiled. Per-function time includes the time spent in any functions called by that function. Some "functions" are portions of functions. The recorded data span about 5 and a half hours.
1815 0.1 0.000 Skin::initPage 1885 1.8 0.001 OutputPage::output-headers 1630 1.7 0.001 OutputPage::replaceInternalLinks-setup 1630 3.2 0.002 OutputPage:replaceVariables 2846 31.3 0.011 main-misc-setup 1630 37.5 0.023 OutputPage::removeHTMLtags 1630 42.6 0.026 OutputPage::doBlockLevels 1803 101.8 0.056 Skin::doBeforeContent 1885 114.4 0.061 OutputPage::output-middle 57717 7682.8 0.133 LinkCache::addLink-checkdatabase 1630 244.2 0.150 OutputPage::replaceExternalLinks 101261 22135.9 0.219 wfQuery 1685 449.1 0.267 Skin::quickBar 1803 737.6 0.409 Skin::doAfterContent 981 539.3 0.550 LinkCache::preFill 1885 1313.6 0.697 OutputPage::output-after 1631 3956.1 2.426 OutputPage::replaceInternalLinks-loop 1631 3958.3 2.427 OutputPage::replaceInternalLinks 1631 4412.7 2.706 OutputPage::doWikiPass2 1990 6140.1 3.085 Article::getContent 1631 5165.5 3.167 OutputPage::addWikiText 52 174.4 3.354 Article::history 1885 8148.9 4.323 OutputPage::output-bodytext 1885 9579.6 5.082 OutputPage::output 1102 6530.4 5.926 Article::view
Code optimization efforts should look strongly at OutputPage::replaceInternalLinks and everything it calls. Article::getContent would mostly wait on the database to return data, it doesn't do much processing.
-- brion vibber (brion @ pobox.com)
Brion Vibber wrote:
On Tue, 2003-09-30 at 21:59, Jens Frank wrote:
Can you measure how much time is spent in the Skin::makeLink subroutine that's called quite often during the loop?
For these inner functions, the millisecond resolution on the timer often isn't precise enough.
This is clearly wrong. Even a one second resolution is often good enough, when you summarize the times for a large number of calls.
total_time = n_calls = 0; for (...loop...) { start = time(); do_call(); elapsed = time() - start; total_time += elapsed; n_calls ++; }
If the time in do_call() averages 14 ms, the chance is 1/70 that a boundary between two seconds should be passed during the call, and 1.0 should be added to total_time.
Still, an easier method is
start = time(); for(...loop...) { do_call(); } elapsed = time() - start; if (elapsed > 2 seconds) { write_warning("Too much total time spent in loop, rewrite it so it either uses fewer calls or faster calls"); }
A brave fighter can use a short sword, for he dares to go close to his enemy.
Brion Vibber wrote:
Anybody wanna look into optimizing OutputPage::replaceInternalLinks()? It's a known troublemaker; it's got a bit loop that could probably be much much more efficiently done.
Rendering pages with lots and lots of links gets *really* slow.
Is there a limit in the number of links that should be on a page? Some of these can probably be broken up into several shorter lists. Ec
On Tue, Sep 30, 2003 at 07:13:49PM -0700, Brion Vibber wrote:
Anybody wanna look into optimizing OutputPage::replaceInternalLinks()? It's a known troublemaker; it's got a bit loop that could probably be much much more efficiently done.
Rendering pages with lots and lots of links gets *really* slow.
Let's look at the loop:
foreach ( $a as $line ) { wfProfileIn( "$fname-loop" ); if ( preg_match( $e1, $line, $m ) ) { # page with alternate text
$text = $m[2]; $trail = $m[3];
} else if ( preg_match( $e2, $line, $m ) ) { # page with normal text
$text = ""; $trail = $m[2]; }
Exchange the two 'if'-clauses . "Page with normal text" is more frequent than "page with alternate text".
Some lines later:
if ( preg_match( "/^((?:i|x|[a-z]{2,3})(?:-[a-z0-9]+)?|[A-Za-z\x80-\xff]+) :(.*)$/", $link, $m ) ) {
A very complex regex to check for a colon and split the link if it does contain a colon. (Well, that's what I think it does, at least). Since this is case is seldom, too, it might be better to test for a colon first using strpos and do the split only if necessary. See http://jeluf.mine.nu/jf/y.php for a performance comparison.
Some lines later, inside some seldomly used branches in the namespace-links-block:
$s .= $sk->makeImageLink( $name, wfImageUrl( $name ), $text ); $s .= $trail;
Replace by a single $s .= $sk->makeImageLink( $name, wfImageUrl( $name ), $text ) . $trail;
See http://jeluf.mine.nu/jf/x.php for a performance comparison.
In Skin::makeLink, the namespace is computed again. This was already done in Outputpage::replaceInternalLinks, could we pass this information as a parameter instead of computing it again (sorry, no code, would have to set up an entire wikipedia to test it).
This are some changes in the 10%-range, nothing realy fundamental. For more changes, architecture would have to be changed to do more caching or preprocessing while saving articles.
Regards,
JeLuF
On Wed, 2003-10-01 at 14:59, Jens Frank wrote:
Exchange the two 'if'-clauses . "Page with normal text" is more frequent than "page with alternate text".
Better yet, let the regexp do the compare/jump. I've merged them to one; if there's no | it should be about as fast, and it only has to compile one regexp and zip through the title portion once.
if ( preg_match( "/^((?:i|x|[a-z]{2,3})(?:-[a-z0-9]+)?|[A-Za-z\\x80-\\xff]+):(.*)$/", $link, $m ) ) {
A very complex regex to check for a colon and split the link if it does contain a colon. (Well, that's what I think it does, at least). Since this is case is seldom, too, it might be better to test for a colon first using strpos and do the split only if necessary. See http://jeluf.mine.nu/jf/y.php for a performance comparison.
Wise. I've added this.
Some lines later, inside some seldomly used branches in the namespace-links-block:
Being seldom, I haven't touched these yet.
In Skin::makeLink, the namespace is computed again. This was already done in Outputpage::replaceInternalLinks, could we pass this information as a parameter instead of computing it again (sorry, no code, would have to set up an entire wikipedia to test it).
Much of the loop duplicates Title::secureAndSplit. It may make sense to rewrite the whole loop around these existing functions... or else duplicate the functionality but not the function call!
-- brion vibber (brion @ pobox.com)
On Wednesday 01 October 2003 04:13, Brion Vibber wrote:
Anybody wanna look into optimizing OutputPage::replaceInternalLinks()? It's a known troublemaker; it's got a bit loop that could probably be much much more efficiently done.
Why would not pages be rendered when saved and stored on disk as HTML, as they are typically saved once and viewed many times? As I understood, disk space is not a problem, but processor time is.
On Thu, 2003-10-02 at 04:16, Nikola Smolenski wrote:
On Wednesday 01 October 2003 04:13, Brion Vibber wrote:
Anybody wanna look into optimizing OutputPage::replaceInternalLinks()? It's a known troublemaker; it's got a bit loop that could probably be much much more efficiently done.
Why would not pages be rendered when saved and stored on disk as HTML, as they are typically saved once and viewed many times? As I understood, disk space is not a problem, but processor time is.
http://meta.wikipedia.org/wiki/File_cache
-- brion vibber (brion @ pobox.com)
On Thursday 02 October 2003 16:19, Brion Vibber wrote:
On Thu, 2003-10-02 at 04:16, Nikola Smolenski wrote:
On Wednesday 01 October 2003 04:13, Brion Vibber wrote:
Anybody wanna look into optimizing OutputPage::replaceInternalLinks()? It's a known troublemaker; it's got a bit loop that could probably be much much more efficiently done.
Why would not pages be rendered when saved and stored on disk as HTML, as they are typically saved once and viewed many times? As I understood, disk space is not a problem, but processor time is.
Well, what I wanted to say is that, even for registered users, the article (everything between <div id='article'> and its </div>) could be precalculated and stored, and then when needed concatenated between head+content (head could be joined with content on user login and whenever a new message arrives) and footer+quickbar (only several possibilities for these exist, depending on the user prefs, and they could be precalculated too). Only two concatenations would be needed, and I guess that more then half of the requests of registered users could be served this way.
On Fri, 2003-10-03 at 01:11, Nikola Smolenski wrote:
Well, what I wanted to say is that, even for registered users, the article (everything between <div id='article'> and its </div>) could be precalculated and stored, and then when needed concatenated between head+content (head could be joined with content on user login and whenever a new message arrives) and footer+quickbar (only several possibilities for these exist, depending on the user prefs, and they could be precalculated too). Only two concatenations would be needed, and I guess that more then half of the requests of registered users could be served this way.
I eagerly await your patch!
-- brion vibber (brion @ pobox.com)
wikitech-l@lists.wikimedia.org