Dear all!
After upgrading a server to a complete new system (apache/php/mysql->mariadb) I have massive performance-problems when a large page is to be rendered.
I have added a profiling log; I do not think, it is related to the database upgrade, as the database have a very low CPU usage while rendering, while Apache's CPU usage is very high for around 16 seconds. This happens especially with large pages. I have already tried to remove all extensions which did not make any difference.
Do you have any ideas where to start?
Best regards, Johannes
Start request GET /wiki/IS_(Projekttagebuch) HTTP HEADERS: HOST: test.com USER-AGENT: Mozilla/5.0 (X11; Linux x86_64; rv:21.0) Gecko/20100101 Firefox/21.0 ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 ACCEPT-LANGUAGE: de-at,de;q=0.8,en-us;q=0.5,en;q=0.3 ACCEPT-ENCODING: gzip, deflate REFERER: https://test.com/w/index.php?title=IS_(Projekttagebuch)&action=edit%C2%A... COOKIE: mediawikiUserName=Web; mediawiki_session=qd955vfopmq2ri2limkteimp8rc8pu9v; mediawikiUserID=3; mediawikiPostEditRevision72824=1 DNT: 1 CONNECTION: keep-alive CACHES: EmptyBagOStuff[main] SqlBagOStuff[message] SqlBagOStuff[parser] [cookie] session_set_cookie_params: "0", "/", "", "1", "1" Class LanguageDe not found; skipped loading LocalisationCache: using store LCStore_DB Connected to database 0 at localhost Fully initialised Title::getRestrictionTypes: applicable restrictions to [[IS (Projekttagebuch)]] are {edit,move} [ContentHandler] Created handler for wikitext: WikitextContentHandler User: cache miss for user 3 User: loading options for user 3 from database. User: logged in from session User: loading options for user 3 from override cache. Connected to database 0 at localhost MessageCache::load: Loading de... got from global cache Unstubbing $wgParser on call of $wgParser::firstCallInit from MessageCache::getParser Parser: using preprocessor: Preprocessor_DOM Unstubbing $wgLang on call of $wgLang::_unstub from ParserOptions::__construct OutputPage::checkLastModified: client did not send If-Modified-Since header Article::tryFileCache(): not cacheable Article::view using parser cache: yes Parser cache options found. ParserOutput cache found. Article::view: showing parser cache contents Title::getRestrictionTypes: applicable restrictions to [[IS (Projekttagebuch)]] are {edit,move} Title::getRestrictionTypes: applicable restrictions to [[IS (Projekttagebuch)]] are {edit,move} Use of wfMsg was deprecated in MediaWiki 1.21. [Called from PdfBookHooks::onSkinTemplateNavigation in /usr/share/mediawiki/extensions/PdfBook/PdfBook.hooks.php at line 173] Use of wfMsgReal was deprecated in MediaWiki 1.21. [Called from wfMsg in /usr/share/mediawiki/includes/GlobalFunctions.php at line 1444] Use of wfMsgGetKey was deprecated in MediaWiki 1.21. [Called from wfMsgReal in /usr/share/mediawiki/includes/GlobalFunctions.php at line 1542] Title::getRestrictionTypes: applicable restrictions to [[IS (Projekttagebuch)]] are {edit,move} Class PEAR_Error not found; skipped loading OutputPage::sendCacheControl: private caching; Thu, 20 Jun 2013 14:20:08 GMT ** DatabaseBase::query: Writes done: UPDATE `page` SET page_counter = page_counter + 1 WHERE page_id = '4292' LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalProfiling data Profile section ended by close(): -total 20130620142023 16.176 /wiki/IS_(Projekttagebuch)
Profiling data Name Calls Total Each % Mem -total 1 16176.342 16176.342 100.000% 36200744 ( 16176.342 - 16176.342) [0] MediaWiki::main 1 16039.443 16039.443 99.154% 20009099 ( 16039.443 - 16039.443) [3614] OutputPage::output 1 15748.575 15748.575 97.356% 5828987 ( 15748.575 - 15748.575) [740] MediaWiki::performRequest 1 270.768 270.768 1.674% 11315010 ( 270.768 - 270.768) [2836] MediaWiki::performAction 1 261.395 261.395 1.616% 9682971 ( 261.395 - 261.395) [2816] Article::view 1 261.341 261.341 1.616% 9687972 ( 261.341 - 261.341) [2815] Output-skin 1 87.482 87.482 0.541% 5723286 ( 87.482 - 87.482) [736] SkinTemplate::outputPage 1 87.438 87.438 0.541% 6600319 ( 87.438 - 87.438) [735] Linker::link 522 72.747 0.139 0.450% 2660882 ( 0.108 - 4.421) [2101] Setup.php 1 52.204 52.204 0.323% 8908692 ( 52.204 - 52.204) [40] -overhead-total 3736 49.771 0.013 0.308% 4366944 ( 49.771 - 49.771) [3736] SkinTemplate::outputPage-stuff5 1 40.932 40.932 0.253% 3391878 ( 40.932 - 40.932) [247] Setup.php-globals 1 39.662 39.662 0.245% 6704621 ( 39.662 - 39.662) [30] Linker::linkUrl 522 28.209 0.054 0.174% 393323 ( 0.044 - 1.055) [522] Title::getLinkURL 528 26.079 0.049 0.161% 363712 ( 0.040 - 1.040) [0] DatabaseBase::query 131 24.619 0.188 0.152% 351600 ( 0.086 - 1.253) [135] -overhead-internal 3736 19.885 0.005 0.123% 1344960 ( 0.004 - 0.090) [0] LocalisationCache::getItem-load 15 19.628 1.309 0.121% 1964445 ( 0.232 - 15.358) [85] SkinTemplate::outputPage-execute 1 17.706 17.706 0.109% 819599 ( 17.706 - 17.706) [264] LocalisationCache::getSubitem-load 66 17.270 0.262 0.107% 50735 ( 0.229 - 0.346) [264] Parser::transformMsg 9 13.786 1.532 0.085% 1286503 ( 0.487 - 7.202) [182] Parser::preprocess 9 13.751 1.528 0.085% 1286919 ( 0.484 - 7.202) [173] SkinTemplate::outputPage-stuff4 1 13.482 13.482 0.083% 1178525 ( 13.482 - 13.482) [57] WebStart.php-conf 1 12.944 12.944 0.080% 1228568 ( 12.944 - 12.944) [0] Linker::titleAttrib 34 11.949 0.351 0.074% 94503 ( 0.033 - 0.693) [200] ResourceLoader::makeModuleResponse 2 11.389 5.694 0.070% 1669457 ( 1.286 - 10.102) [17] Parser::replaceVariables 10 10.621 1.062 0.066% 867523 ( 0.394 - 4.549) [150] query: SELECT lc_value FROM `lNn_cache` WHERE lc_lang = 'X' LIMIT N 84 9.916 0.118 0.061% 221718 ( 0.099 - 0.242) [2] LoadBalancer::getConnection 121 9.131 0.075 0.056% 1178146 ( 0.006 - 6.235) [133] SkinTemplate::outputPage-stuff2 1 8.694 8.694 0.054% 1114227 ( 8.694 - 8.694) [69] MediaWiki::initializeArticle 1 8.463 8.463 0.052% 1554850 ( 8.463 - 8.463) [15] StubObject::_unstub-wgParser 1 8.037 8.037 0.050% 1535576 ( 8.037 - 8.037) [0] ParserCache::get 1 7.942 7.942 0.049% 1841868 ( 7.942 - 7.942) [4] LoadBalancer::openConnection 121 7.814 0.065 0.048% 1171653 ( 0.001 - 6.216) [12] JobQueue::isEmpty 11 7.299 0.664 0.045% 9551 ( 0.599 - 1.047) [46] User::load 2 7.137 3.569 0.044% 759113 ( 3.443 - 3.695) [25] Parser::firstCallInit 1 6.615 6.615 0.041% 951738 ( 6.615 - 6.615) [88] PPFrame_DOM::expand 25 6.305 0.252 0.039% 391382 ( 0.026 - 1.690) [110] ResourceLoader::makeModuleResponse-user.tokens 1 5.943 5.943 0.037% 1349528 ( 5.943 - 5.943) [0] RequestContext::getSkin-createskin 1 5.670 5.670 0.035% 1232951 ( 5.670 - 5.670) [1] Linker::linkAttribs 522 5.332 0.010 0.033% 719644 ( 0.008 - 0.083) [4] Linker::accesskey 32 5.072 0.159 0.031% 77658 ( 0.028 - 0.387) [70] Setup.php-includes 1 5.045 5.045 0.031% 908872 ( 5.045 - 5.045) [0] SkinTemplate::buildContentNavigationUrls 1 5.037 5.037 0.031% 179175 ( 5.037 - 5.037) [37] -setup 1 5.029 5.029 0.031% 0 ( 5.029 - 5.029) [0] Parser::braceSubstitution 11 4.887 0.444 0.030% 332464 ( 0.169 - 1.621) [99] main-try-filecache 1 4.740 4.740 0.029% 499995 ( 4.740 - 4.740) [14] SkinTemplate::outputPage-stuff3 1 4.155 4.155 0.026% 35875 ( 4.155 - 4.155) [78] DeferredUpdates::doUpdates 1 3.651 3.651 0.023% 841 ( 3.651 - 3.651) [16] Parser::clearState 10 3.502 0.350 0.022% 446782 ( 0.067 - 2.631) [20] SkinTemplate::buildNavUrls 1 3.144 3.144 0.019% 423187 ( 3.144 - 3.144) [5] Parser::braceSubstitution-modifiers 11 2.742 0.249 0.017% 129155 ( 0.036 - 1.427) [51] SkinTemplate::buildPersonalUrls 1 2.514 2.514 0.016% 13057 ( 2.514 - 2.514) [26] MessageCache::parse 1 2.383 2.383 0.015% 31668 ( 2.383 - 2.383) [58] hook: ParserFirstCallInit 1 2.349 2.349 0.015% 345593 ( 2.349 - 2.349) [26] Parser::parse 1 2.322 2.322 0.014% 33405 ( 2.322 - 2.322) [57] Parser::parse-MessageCache::parse 1 2.322 2.322 0.014% 33422 ( 2.322 - 2.322) [56] MessageBlobStore::get 1 2.301 2.301 0.014% 224772 ( 2.301 - 2.301) [4] query: SELECT keyname,value,exptime FROM `objectcache` WHERE keyname = 'X' 6 2.207 0.368 0.014% 49424 ( 0.228 - 0.841) [0] SkinTemplate::outputPage-init 1 2.083 2.083 0.013% 56230 ( 2.083 - 2.083) [11] MessageCache::load 1 2.075 2.075 0.013% 20555 ( 2.075 - 2.075) [14] Setup.php-memcached 1 2.062 2.062 0.013% 346048 ( 2.062 - 2.062) [0] Skin::initPage 1 2.053 2.053 0.013% 54759 ( 2.053 - 2.053) [10] Skin::buildSidebar 1 1.966 1.966 0.012% 28186 ( 1.966 - 1.966) [6] query: SELECT N FROM `job` WHERE job_cmd = 'X' LIMIT N 11 1.937 0.176 0.012% 23414 ( 0.153 - 0.337) [2] MagicWord::load 145 1.927 0.013 0.012% 223354 ( 0.006 - 0.514) [6] MessageCache::load-fromcache 1 1.925 1.925 0.012% 19700 ( 1.925 - 1.925) [13] LinkBatch::executeInto 1 1.921 1.921 0.012% 59376 ( 1.921 - 1.921) [9] SkinTemplate::buildContentNavigationUrls-live 1 1.920 1.920 0.012% 9447 ( 1.920 - 1.920) [19] Preprocessor_DOM::preprocessToObj 11 1.907 0.173 0.012% 21316 ( 0.126 - 0.243) [22] Parser::internalParse 1 1.835 1.835 0.011% 31448 ( 1.835 - 1.835) [45] query: COMMIT 2 1.758 0.879 0.011% 832 ( 0.751 - 1.008) [0] ResourceLoader::filter 3 1.729 0.576 0.011% 4298 ( 0.508 - 0.675) [6] DatabaseMysql::open 2 1.723 0.861 0.011% 15375 ( 0.794 - 0.929) [10] ResourceLoader::__construct 1 1.699 1.699 0.011% 208214 ( 1.699 - 1.699) [2] Parser::braceSubstitution-pfunc 2 1.569 0.785 0.010% 193500 ( 0.210 - 1.359) [13] Parser::callParserFunction 2 1.529 0.764 0.009% 186542 ( 0.193 - 1.336) [11] Parser::callParserFunction-pfunc-plural 2 1.507 0.754 0.009% 186544 ( 0.184 - 1.323) [9] Revision::loadText 1 1.506 1.506 0.009% 370083 ( 1.506 - 1.506) [5] wfCite 1 1.493 1.493 0.009% 288896 ( 1.493 - 1.493) [0] hook: SkinTemplateNavigation 1 1.439 1.439 0.009% 85489 ( 1.439 - 1.439) [7] Setup.php-misc1 1 1.372 1.372 0.008% 195664 ( 1.372 - 1.372) [0] query: SELECT old_text,old_flags FROM `text` WHERE old_id = 'X' LIMIT N 1 1.250 1.250 0.008% 2392 ( 1.250 - 1.250) [0] Title::getUserPermissionsErrorsInternal 10 1.172 0.117 0.007% 76205 ( 0.022 - 0.632) [3] Preprocessor_DOM::preprocessToXml 11 1.127 0.102 0.007% 177616 ( 0.073 - 0.161) [0] PdfBookHooks::onSkinTemplateNavigation 1 0.957 0.957 0.006% 3906 ( 0.957 - 0.957) [6] Linker::link-checkPageExistence 522 0.940 0.002 0.006% 192741 ( 0.001 - 0.069) [3] query: SELECT page_namespace,page_title,page_touched FROM `page` WHERE (pag 4 0.925 0.231 0.006% 11408 ( 0.125 - 0.361) [0] query: UPDATE `page` SET page_counter = page_counter + N WHERE page_id = 'X 1 0.923 0.923 0.006% 600 ( 0.923 - 0.923) [0] Setup.php-exception 1 0.919 0.919 0.006% 256160 ( 0.919 - 0.919) [0] query: SELECT page_id,page_namespace,page_title,page_len,page_is_redirect,p 1 0.835 0.835 0.005% 4104 ( 0.835 - 0.835) [0] ResourceLoader::makeModuleResponse-user.cssprefs 1 0.768 0.768 0.005% 2829 ( 0.768 - 0.768) [3] ResourceLoader::makeModuleResponse-user.options 1 0.740 0.740 0.005% 4320 ( 0.740 - 0.740) [0] wfRegisterParserFunctions 1 0.726 0.726 0.004% 50775 ( 0.726 - 0.726) [19] LinkCache::addLinkObj 7 0.692 0.099 0.004% 7524 ( 0.019 - 0.526) [4] ResourceLoader::register 2 0.658 0.329 0.004% 47848 ( 0.137 - 0.522) [0] LinkBatch::doQuery 1 0.626 0.626 0.004% 5780 ( 0.626 - 0.626) [4] dbconnect-localhost 2 0.622 0.311 0.004% 14552 ( 0.304 - 0.319) [0] Preprocessor_DOM::preprocessToObj-loadXML 11 0.588 0.053 0.004% 18456 ( 0.041 - 0.071) [0] MediaWiki_I18N::translate 5 0.568 0.114 0.004% 3979 ( 0.052 - 0.314) [5] Setup.php-extensions 1 0.545 0.545 0.003% 43405 ( 0.545 - 0.545) [3] wfMsgReal 1 0.537 0.537 0.003% 1299 ( 0.537 - 0.537) [5] User::getEffectiveGroups 1 0.517 0.517 0.003% 59687 ( 0.517 - 0.517) [1] User::getAutomaticGroups 1 0.505 0.505 0.003% 59032 ( 0.505 - 0.505) [0] hook: MakeGlobalVariablesScript 1 0.458 0.458 0.003% 66894 ( 0.458 - 0.458) [2] Parser::braceSubstitution-setup 11 0.430 0.039 0.003% 10462 ( 0.032 - 0.046) [11] Parser::doDoubleUnderscore 1 0.400 0.400 0.002% 30212 ( 0.400 - 0.400) [13] query: SET NAMES binary 2 0.396 0.198 0.002% 1544 ( 0.188 - 0.209) [0] hook: ParserClearState 10 0.391 0.039 0.002% 9831 ( 0.024 - 0.064) [10] query: SELECT page_id,page_namespace,page_title,page_len,page_is_redirect,p 1 0.389 0.389 0.002% 3656 ( 0.389 - 0.389) [0] SkinTemplate::outputPage-stuff 1 0.353 0.353 0.002% 6143 ( 0.353 - 0.353) [1] query: SELECT rev_id,rev_page,rev_text_id,rev_timestamp,rev_comment,rev_use 1 0.350 0.350 0.002% 7688 ( 0.350 - 0.350) [0] query: BEGIN 3 0.346 0.115 0.002% 1808 ( 0.084 - 0.132) [0] hook: BeforePageDisplay 1 0.344 0.344 0.002% 42622 ( 0.344 - 0.344) [2] query: SELECT page_id,page_len,page_is_redirect,page_latest,page_content_mo 1 0.333 0.333 0.002% 3360 ( 0.333 - 0.333) [0] Setup.php-extensions-MathHooks::setup 1 0.299 0.299 0.002% 42224 ( 0.299 - 0.299) [0] Parser::replaceInternalLinks2-setup 1 0.282 0.282 0.002% 2899 ( 0.282 - 0.282) [5] Parser::replaceInternalLinks2 1 0.281 0.281 0.002% 2898 ( 0.281 - 0.281) [6] query: SELECT mr_blob,mr_resource,mr_timestamp FROM `msg_resource` WHERE mr 1 0.267 0.267 0.002% 2784 ( 0.267 - 0.267) [0] query: SELECT page_id,page_namespace,page_title,page_restrictions,page_coun 1 0.261 0.261 0.002% 5064 ( 0.261 - 0.261) [0] query: SET sql_mode = 'X' 2 0.254 0.127 0.002% 1104 ( 0.101 - 0.153) [0] Sanitizer::removeHTMLtags 3 0.253 0.084 0.002% 70717 ( 0.038 - 0.151) [3] query: SELECT page_namespace,page_title,page_touched FROM `page` WHERE (pag 1 0.251 0.251 0.002% 2600 ( 0.251 - 0.251) [0] query: SELECT user_name,up_value FROM `user` LEFT JOIN `user_properties` ON 1 0.251 0.251 0.002% 2360 ( 0.251 - 0.251) [0] query: UPDATE `site_stats` SET ss_total_views=ss_total_views+N 1 0.242 0.242 0.001% 616 ( 0.242 - 0.242) [0] query: SELECT user_id,user_name,user_real_name,user_password,user_newpasswo 1 0.236 0.236 0.001% 5352 ( 0.236 - 0.236) [0] Setup.php-session 1 0.228 0.228 0.001% 3128 ( 0.228 - 0.228) [0] SkinTemplate::buildContentNavigationUrls-edit 1 0.225 0.225 0.001% 1791 ( 0.225 - 0.225) [1] StubObject::_unstub-wgLang 1 0.196 0.196 0.001% 368 ( 0.196 - 0.196) [0] query: SELECT wl_notificationtimestamp FROM `watchlist` WHERE wl_user = 'X' 1 0.170 0.170 0.001% 2320 ( 0.170 - 0.170) [0] Skin::getSkinNames-init 1 0.168 0.168 0.001% 3312 ( 0.168 - 0.168) [0] Linker::linkAttribs-getClasses 4 0.165 0.041 0.001% 2848 ( 0.020 - 0.060) [0] query: SELECT up_property,up_value FROM `user_properties` WHERE up_user = ' 1 0.125 0.125 0.001% 2680 ( 0.125 - 0.125) [0] Cite::clearState 10 0.123 0.012 0.001% 2720 ( 0.007 - 0.028) [0] query: SELECT ug_group FROM `user_groups` WHERE ug_user = 'X' 1 0.119 0.119 0.001% 1944 ( 0.119 - 0.119) [0] query: SELECT user_id FROM `user_newtalk` WHERE user_id = 'X' LIMIT N 1 0.107 0.107 0.001% 2096 ( 0.107 - 0.107) [0] query: SELECT pr_type,pr_expiry,pr_level,pr_cascade FROM `page_restrictions 1 0.107 0.107 0.001% 2760 ( 0.107 - 0.107) [0] Parser::doBlockLevels 1 0.097 0.097 0.001% 2023 ( 0.097 - 0.097) [1] Parser::doMagicLinks 1 0.092 0.092 0.001% 1112 ( 0.092 - 0.092) [0] Skin::getSiteNotice 1 0.071 0.071 0.000% 390 ( 0.071 - 0.071) [2] WikiEditorHooks::makeGlobalVariablesScript 1 0.060 0.060 0.000% 1992 ( 0.060 - 0.060) [0] hook: ParserAfterParse 1 0.057 0.057 0.000% 1559 ( 0.057 - 0.057) [1] Skin::getCachedNotice 2 0.053 0.026 0.000% 2672 ( -0.000 - 0.053) [0] hook: ArticleFromTitle 1 0.051 0.051 0.000% 599 ( 0.051 - 0.051) [1] hook: ParserCloned 1 0.051 0.051 0.000% 5887 ( 0.051 - 0.051) [1] Parser::doBlockLevels-paragraph 1 0.051 0.051 0.000% 544 ( 0.051 - 0.051) [0] ParserOptions::initialiseFromUser 2 0.048 0.024 0.000% 2352 ( 0.023 - 0.025) [0] efCategoryTreeSetHooks 1 0.042 0.042 0.000% 3199 ( 0.042 - 0.042) [1] Setup.php-extensions-efLucenePrefixSetup 1 0.040 0.040 0.000% 272 ( 0.040 - 0.040) [0] SpecialPageFactory::getList 1 0.037 0.037 0.000% 1560 ( 0.037 - 0.037) [0] Parser::replaceExternalLinks 1 0.037 0.037 0.000% 744 ( 0.037 - 0.037) [0] Parser::doAllQuotes 1 0.031 0.031 0.000% 1328 ( 0.031 - 0.031) [0] BaseTemplate::getToolbox 1 0.029 0.029 0.000% 5688 ( 0.029 - 0.029) [0] VectorHooks::beforePageDisplay 1 0.029 0.029 0.000% 456 ( 0.029 - 0.029) [0] Cite::cloneState 1 0.028 0.028 0.000% 5176 ( 0.028 - 0.028) [0] Cite::checkRefsNoReferences 2 0.024 0.012 0.000% 592 ( 0.006 - 0.018) [0] hook: ParserBeforeTidy 1 0.023 0.023 0.000% 1423 ( 0.023 - 0.023) [1] Parser::initialiseVariables 1 0.023 0.023 0.000% 1856 ( 0.023 - 0.023) [0] hook: OutputPageParserOutput 1 0.020 0.020 0.000% 631 ( 0.020 - 0.020) [1] SkinTemplate::buildContentActionUrls 1 0.020 0.020 0.000% 1608 ( 0.020 - 0.020) [0] VectorHooks::makeGlobalVariablesScript 1 0.019 0.019 0.000% 1512 ( 0.019 - 0.019) [0] Parser::doHeadings 1 0.018 0.018 0.000% 648 ( 0.018 - 0.018) [0] efSyntaxHighlight_GeSHiSetup 1 0.017 0.017 0.000% 1928 ( 0.017 - 0.017) [0] Parser::doTableStuff 1 0.017 0.017 0.000% 2864 ( 0.017 - 0.017) [0] efCategoryTreeArticleFromTitle 1 0.012 0.012 0.000% 272 ( 0.012 - 0.012) [0] wfSetupImageMap 1 0.012 0.012 0.000% 1088 ( 0.012 - 0.012) [0] MediaWiki::checkMaxLag 1 0.011 0.011 0.000% 408 ( 0.011 - 0.011) [0] Setup.php-extensions-efCategoryTree 1 0.011 0.011 0.000% 1008 ( 0.011 - 0.011) [0] wfCiteBeforePageDisplay 1 0.010 0.010 0.000% 440 ( 0.010 - 0.010) [0] MathHooks::onParserFirstCallInit 1 0.010 0.010 0.000% 1216 ( 0.010 - 0.010) [0] MessageCache::saveToCaches 1 0.008 0.008 0.000% 504 ( 0.008 - 0.008) [0] Revision::getRevisionText 1 0.007 0.007 0.000% 912 ( 0.007 - 0.007) [0] LanguageGetMagic 1 0.007 0.007 0.000% 576 ( 0.007 - 0.007) [0] efCategoryTreeParserOutput 1 0.004 0.004 0.000% 272 ( 0.004 - 0.004) [0] Sanitizer::removeHTMLcomments 3 0.003 0.001 0.000% 1248 ( 0.001 - 0.002) [0] LinkHolderArray::replace 1 0.003 0.003 0.000% 416 ( 0.003 - 0.003) [0] WebStart.php-ob_start 1 0.002 0.002 0.000% 360 ( 0.002 - 0.002) [0] SkinTemplate::outputPage-stuff-head 1 0.001 0.001 0.000% 376 ( 0.001 - 0.001) [0] Profile section ended by close(): -total 1 0.000 0.000 0.000% 0 ( 0.000 - 0.000) [3734]
Total: 16.176341694734
Request ended normally
On 6/20/13, Johannes Weberhofer jweberhofer@weberhofer.at wrote:
Dear all!
After upgrading a server to a complete new system (apache/php/mysql->mariadb) I have massive performance-problems when a large page is to be rendered.
I have added a profiling log; I do not think, it is related to the database upgrade, as the database have a very low CPU usage while rendering, while Apache's CPU usage is very high for around 16 seconds. This happens especially with large pages. I have already tried to remove all extensions which did not make any difference.
Do you have any ideas where to start?
Best regards, Johannes
Start request GET /wiki/IS_(Projekttagebuch) HTTP HEADERS: HOST: test.com USER-AGENT: Mozilla/5.0 (X11; Linux x86_64; rv:21.0) Gecko/20100101 Firefox/21.0 ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 ACCEPT-LANGUAGE: de-at,de;q=0.8,en-us;q=0.5,en;q=0.3 ACCEPT-ENCODING: gzip, deflate REFERER: https://test.com/w/index.php?title=IS_(Projekttagebuch)&action=edit%C2%A... COOKIE: mediawikiUserName=Web; mediawiki_session=qd955vfopmq2ri2limkteimp8rc8pu9v; mediawikiUserID=3; mediawikiPostEditRevision72824=1 DNT: 1 CONNECTION: keep-alive CACHES: EmptyBagOStuff[main] SqlBagOStuff[message] SqlBagOStuff[parser] [cookie] session_set_cookie_params: "0", "/", "", "1", "1" Class LanguageDe not found; skipped loading LocalisationCache: using store LCStore_DB Connected to database 0 at localhost Fully initialised Title::getRestrictionTypes: applicable restrictions to [[IS (Projekttagebuch)]] are {edit,move} [ContentHandler] Created handler for wikitext: WikitextContentHandler User: cache miss for user 3 User: loading options for user 3 from database. User: logged in from session User: loading options for user 3 from override cache. Connected to database 0 at localhost MessageCache::load: Loading de... got from global cache Unstubbing $wgParser on call of $wgParser::firstCallInit from MessageCache::getParser Parser: using preprocessor: Preprocessor_DOM Unstubbing $wgLang on call of $wgLang::_unstub from ParserOptions::__construct OutputPage::checkLastModified: client did not send If-Modified-Since header Article::tryFileCache(): not cacheable Article::view using parser cache: yes Parser cache options found. ParserOutput cache found. Article::view: showing parser cache contents Title::getRestrictionTypes: applicable restrictions to [[IS (Projekttagebuch)]] are {edit,move} Title::getRestrictionTypes: applicable restrictions to [[IS (Projekttagebuch)]] are {edit,move} Use of wfMsg was deprecated in MediaWiki 1.21. [Called from PdfBookHooks::onSkinTemplateNavigation in /usr/share/mediawiki/extensions/PdfBook/PdfBook.hooks.php at line 173] Use of wfMsgReal was deprecated in MediaWiki 1.21. [Called from wfMsg in /usr/share/mediawiki/includes/GlobalFunctions.php at line 1444] Use of wfMsgGetKey was deprecated in MediaWiki 1.21. [Called from wfMsgReal in /usr/share/mediawiki/includes/GlobalFunctions.php at line 1542] Title::getRestrictionTypes: applicable restrictions to [[IS (Projekttagebuch)]] are {edit,move} Class PEAR_Error not found; skipped loading OutputPage::sendCacheControl: private caching; Thu, 20 Jun 2013 14:20:08 GMT ** DatabaseBase::query: Writes done: UPDATE `page` SET page_counter = page_counter + 1 WHERE page_id = '4292' LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalancer::reuseConnection: this connection was not opened as a foreign connection LoadBalProfiling data Profile section ended by close(): -total 20130620142023 16.176 /wiki/IS_(Projekttagebuch)
Profiling data Name Calls Total Each % Mem -total 1 16176.342 16176.342 100.000% 36200744 ( 16176.342 - 16176.342) [0] MediaWiki::main 1 16039.443 16039.443 99.154% 20009099 ( 16039.443 - 16039.443) [3614] OutputPage::output 1 15748.575 15748.575 97.356% 5828987 ( 15748.575 - 15748.575) [740] MediaWiki::performRequest 1 270.768 270.768 1.674% 11315010 ( 270.768 - 270.768) [2836] MediaWiki::performAction 1 261.395 261.395 1.616% 9682971 ( 261.395 - 261.395) [2816] Article::view 1 261.341 261.341 1.616% 9687972 ( 261.341 - 261.341) [2815] Output-skin 1 87.482 87.482 0.541% 5723286 ( 87.482 - 87.482) [736] SkinTemplate::outputPage 1 87.438 87.438 0.541% 6600319 ( 87.438 - 87.438) [735] Linker::link 522 72.747 0.139 0.450% 2660882 ( 0.108 - 4.421) [2101] Setup.php 1 52.204 52.204 0.323% 8908692 ( 52.204 - 52.204) [40] -overhead-total 3736 49.771 0.013 0.308% 4366944 ( 49.771 - 49.771) [3736] SkinTemplate::outputPage-stuff5 1 40.932 40.932 0.253% 3391878 ( 40.932 - 40.932) [247] Setup.php-globals 1 39.662 39.662 0.245% 6704621 ( 39.662 - 39.662) [30] Linker::linkUrl 522 28.209 0.054 0.174% 393323 ( 0.044 - 1.055) [522] Title::getLinkURL 528 26.079 0.049 0.161% 363712 ( 0.040 - 1.040) [0] DatabaseBase::query 131 24.619 0.188 0.152% 351600 ( 0.086 - 1.253) [135] -overhead-internal 3736 19.885 0.005 0.123% 1344960 ( 0.004 - 0.090) [0] LocalisationCache::getItem-load 15 19.628 1.309 0.121% 1964445 ( 0.232 - 15.358) [85] SkinTemplate::outputPage-execute 1 17.706 17.706 0.109% 819599 ( 17.706 - 17.706) [264] LocalisationCache::getSubitem-load 66 17.270 0.262 0.107% 50735 ( 0.229 - 0.346) [264] Parser::transformMsg 9 13.786 1.532 0.085% 1286503 ( 0.487 - 7.202) [182] Parser::preprocess 9 13.751 1.528 0.085% 1286919 ( 0.484 - 7.202) [173] SkinTemplate::outputPage-stuff4 1 13.482 13.482 0.083% 1178525 ( 13.482 - 13.482) [57] WebStart.php-conf 1 12.944 12.944 0.080% 1228568 ( 12.944 - 12.944) [0] Linker::titleAttrib 34 11.949 0.351 0.074% 94503 ( 0.033 - 0.693) [200] ResourceLoader::makeModuleResponse 2 11.389 5.694 0.070% 1669457 ( 1.286 - 10.102) [17] Parser::replaceVariables 10 10.621 1.062 0.066% 867523 ( 0.394 - 4.549) [150] query: SELECT lc_value FROM `lNn_cache` WHERE lc_lang = 'X' LIMIT N 84 9.916 0.118 0.061% 221718 ( 0.099 - 0.242) [2] LoadBalancer::getConnection 121 9.131 0.075 0.056% 1178146 ( 0.006 - 6.235) [133] SkinTemplate::outputPage-stuff2 1 8.694 8.694 0.054% 1114227 ( 8.694 - 8.694) [69] MediaWiki::initializeArticle 1 8.463 8.463 0.052% 1554850 ( 8.463 - 8.463) [15] StubObject::_unstub-wgParser 1 8.037 8.037 0.050% 1535576 ( 8.037 - 8.037) [0] ParserCache::get 1 7.942 7.942 0.049% 1841868 ( 7.942 - 7.942) [4] LoadBalancer::openConnection 121 7.814 0.065 0.048% 1171653 ( 0.001 - 6.216) [12] JobQueue::isEmpty 11 7.299 0.664 0.045% 9551 ( 0.599 - 1.047) [46] User::load 2 7.137 3.569 0.044% 759113 ( 3.443 - 3.695) [25] Parser::firstCallInit 1 6.615 6.615 0.041% 951738 ( 6.615 - 6.615) [88] PPFrame_DOM::expand 25 6.305 0.252 0.039% 391382 ( 0.026 - 1.690) [110] ResourceLoader::makeModuleResponse-user.tokens 1 5.943 5.943 0.037% 1349528 ( 5.943 - 5.943) [0] RequestContext::getSkin-createskin 1 5.670 5.670 0.035% 1232951 ( 5.670 - 5.670) [1] Linker::linkAttribs 522 5.332 0.010 0.033% 719644 ( 0.008 - 0.083) [4] Linker::accesskey 32 5.072 0.159 0.031% 77658 ( 0.028 - 0.387) [70] Setup.php-includes 1 5.045 5.045 0.031% 908872 ( 5.045 - 5.045) [0] SkinTemplate::buildContentNavigationUrls 1 5.037 5.037 0.031% 179175 ( 5.037 - 5.037) [37] -setup 1 5.029 5.029 0.031% 0 ( 5.029 - 5.029) [0] Parser::braceSubstitution 11 4.887 0.444 0.030% 332464 ( 0.169 - 1.621) [99] main-try-filecache 1 4.740 4.740 0.029% 499995 ( 4.740 - 4.740) [14] SkinTemplate::outputPage-stuff3 1 4.155 4.155 0.026% 35875 ( 4.155 - 4.155) [78] DeferredUpdates::doUpdates 1 3.651 3.651 0.023% 841 ( 3.651 - 3.651) [16] Parser::clearState 10 3.502 0.350 0.022% 446782 ( 0.067 - 2.631) [20] SkinTemplate::buildNavUrls 1 3.144 3.144 0.019% 423187 ( 3.144 - 3.144) [5] Parser::braceSubstitution-modifiers 11 2.742 0.249 0.017% 129155 ( 0.036 - 1.427) [51] SkinTemplate::buildPersonalUrls 1 2.514 2.514 0.016% 13057 ( 2.514 - 2.514) [26] MessageCache::parse 1 2.383 2.383 0.015% 31668 ( 2.383 - 2.383) [58] hook: ParserFirstCallInit 1 2.349 2.349 0.015% 345593 ( 2.349 - 2.349) [26] Parser::parse 1 2.322 2.322 0.014% 33405 ( 2.322 - 2.322) [57] Parser::parse-MessageCache::parse 1 2.322 2.322 0.014% 33422 ( 2.322 - 2.322) [56] MessageBlobStore::get 1 2.301 2.301 0.014% 224772 ( 2.301 - 2.301) [4] query: SELECT keyname,value,exptime FROM `objectcache` WHERE keyname = 'X' 6 2.207 0.368 0.014% 49424 ( 0.228 - 0.841) [0] SkinTemplate::outputPage-init 1 2.083 2.083 0.013% 56230 ( 2.083 - 2.083) [11] MessageCache::load 1 2.075 2.075 0.013% 20555 ( 2.075 - 2.075) [14] Setup.php-memcached 1 2.062 2.062 0.013% 346048 ( 2.062 - 2.062) [0] Skin::initPage 1 2.053 2.053 0.013% 54759 ( 2.053 - 2.053) [10] Skin::buildSidebar 1 1.966 1.966 0.012% 28186 ( 1.966 - 1.966) [6] query: SELECT N FROM `job` WHERE job_cmd = 'X' LIMIT N 11 1.937 0.176 0.012% 23414 ( 0.153 - 0.337) [2] MagicWord::load 145 1.927 0.013 0.012% 223354 ( 0.006 - 0.514) [6] MessageCache::load-fromcache 1 1.925 1.925 0.012% 19700 ( 1.925 - 1.925) [13] LinkBatch::executeInto 1 1.921 1.921 0.012% 59376 ( 1.921 - 1.921) [9] SkinTemplate::buildContentNavigationUrls-live 1 1.920 1.920 0.012% 9447 ( 1.920 - 1.920) [19] Preprocessor_DOM::preprocessToObj 11 1.907 0.173 0.012% 21316 ( 0.126 - 0.243) [22] Parser::internalParse 1 1.835 1.835 0.011% 31448 ( 1.835 - 1.835) [45] query: COMMIT 2 1.758 0.879 0.011% 832 ( 0.751 - 1.008) [0] ResourceLoader::filter 3 1.729 0.576 0.011% 4298 ( 0.508 - 0.675) [6] DatabaseMysql::open 2 1.723 0.861 0.011% 15375 ( 0.794 - 0.929) [10] ResourceLoader::__construct 1 1.699 1.699 0.011% 208214 ( 1.699 - 1.699) [2] Parser::braceSubstitution-pfunc 2 1.569 0.785 0.010% 193500 ( 0.210 - 1.359) [13] Parser::callParserFunction 2 1.529 0.764 0.009% 186542 ( 0.193 - 1.336) [11] Parser::callParserFunction-pfunc-plural 2 1.507 0.754 0.009% 186544 ( 0.184 - 1.323) [9] Revision::loadText 1 1.506 1.506 0.009% 370083 ( 1.506 - 1.506) [5] wfCite 1 1.493 1.493 0.009% 288896 ( 1.493 - 1.493) [0] hook: SkinTemplateNavigation 1 1.439 1.439 0.009% 85489 ( 1.439 - 1.439) [7] Setup.php-misc1 1 1.372 1.372 0.008% 195664 ( 1.372 - 1.372) [0] query: SELECT old_text,old_flags FROM `text` WHERE old_id = 'X' LIMIT N 1 1.250 1.250 0.008% 2392 ( 1.250 - 1.250) [0] Title::getUserPermissionsErrorsInternal 10 1.172 0.117 0.007% 76205 ( 0.022 - 0.632) [3] Preprocessor_DOM::preprocessToXml 11 1.127 0.102 0.007% 177616 ( 0.073 - 0.161) [0] PdfBookHooks::onSkinTemplateNavigation 1 0.957 0.957 0.006% 3906 ( 0.957 - 0.957) [6] Linker::link-checkPageExistence 522 0.940 0.002 0.006% 192741 ( 0.001 - 0.069) [3] query: SELECT page_namespace,page_title,page_touched FROM `page` WHERE (pag 4 0.925 0.231 0.006% 11408 ( 0.125 - 0.361) [0] query: UPDATE `page` SET page_counter = page_counter + N WHERE page_id = 'X 1 0.923 0.923 0.006% 600 ( 0.923 - 0.923) [0] Setup.php-exception 1 0.919 0.919 0.006% 256160 ( 0.919 - 0.919) [0] query: SELECT page_id,page_namespace,page_title,page_len,page_is_redirect,p 1 0.835 0.835 0.005% 4104 ( 0.835 - 0.835) [0] ResourceLoader::makeModuleResponse-user.cssprefs 1 0.768 0.768 0.005% 2829 ( 0.768 - 0.768) [3] ResourceLoader::makeModuleResponse-user.options 1 0.740 0.740 0.005% 4320 ( 0.740 - 0.740) [0] wfRegisterParserFunctions 1 0.726 0.726 0.004% 50775 ( 0.726 - 0.726) [19] LinkCache::addLinkObj 7 0.692 0.099 0.004% 7524 ( 0.019 - 0.526) [4] ResourceLoader::register 2 0.658 0.329 0.004% 47848 ( 0.137 - 0.522) [0] LinkBatch::doQuery 1 0.626 0.626 0.004% 5780 ( 0.626 - 0.626) [4] dbconnect-localhost 2 0.622 0.311 0.004% 14552 ( 0.304 - 0.319) [0] Preprocessor_DOM::preprocessToObj-loadXML 11 0.588 0.053 0.004% 18456 ( 0.041 - 0.071) [0] MediaWiki_I18N::translate 5 0.568 0.114 0.004% 3979 ( 0.052 - 0.314) [5] Setup.php-extensions 1 0.545 0.545 0.003% 43405 ( 0.545 - 0.545) [3] wfMsgReal 1 0.537 0.537 0.003% 1299 ( 0.537 - 0.537) [5] User::getEffectiveGroups 1 0.517 0.517 0.003% 59687 ( 0.517 - 0.517) [1] User::getAutomaticGroups 1 0.505 0.505 0.003% 59032 ( 0.505 - 0.505) [0] hook: MakeGlobalVariablesScript 1 0.458 0.458 0.003% 66894 ( 0.458 - 0.458) [2] Parser::braceSubstitution-setup 11 0.430 0.039 0.003% 10462 ( 0.032 - 0.046) [11] Parser::doDoubleUnderscore 1 0.400 0.400 0.002% 30212 ( 0.400 - 0.400) [13] query: SET NAMES binary 2 0.396 0.198 0.002% 1544 ( 0.188 - 0.209) [0] hook: ParserClearState 10 0.391 0.039 0.002% 9831 ( 0.024 - 0.064) [10] query: SELECT page_id,page_namespace,page_title,page_len,page_is_redirect,p 1 0.389 0.389 0.002% 3656 ( 0.389 - 0.389) [0] SkinTemplate::outputPage-stuff 1 0.353 0.353 0.002% 6143 ( 0.353 - 0.353) [1] query: SELECT rev_id,rev_page,rev_text_id,rev_timestamp,rev_comment,rev_use 1 0.350 0.350 0.002% 7688 ( 0.350 - 0.350) [0] query: BEGIN 3 0.346 0.115 0.002% 1808 ( 0.084 - 0.132) [0] hook: BeforePageDisplay 1 0.344 0.344 0.002% 42622 ( 0.344 - 0.344) [2] query: SELECT page_id,page_len,page_is_redirect,page_latest,page_content_mo 1 0.333 0.333 0.002% 3360 ( 0.333 - 0.333) [0] Setup.php-extensions-MathHooks::setup 1 0.299 0.299 0.002% 42224 ( 0.299 - 0.299) [0] Parser::replaceInternalLinks2-setup 1 0.282 0.282 0.002% 2899 ( 0.282 - 0.282) [5] Parser::replaceInternalLinks2 1 0.281 0.281 0.002% 2898 ( 0.281 - 0.281) [6] query: SELECT mr_blob,mr_resource,mr_timestamp FROM `msg_resource` WHERE mr 1 0.267 0.267 0.002% 2784 ( 0.267 - 0.267) [0] query: SELECT page_id,page_namespace,page_title,page_restrictions,page_coun 1 0.261 0.261 0.002% 5064 ( 0.261 - 0.261) [0] query: SET sql_mode = 'X' 2 0.254 0.127 0.002% 1104 ( 0.101 - 0.153) [0] Sanitizer::removeHTMLtags 3 0.253 0.084 0.002% 70717 ( 0.038 - 0.151) [3] query: SELECT page_namespace,page_title,page_touched FROM `page` WHERE (pag 1 0.251 0.251 0.002% 2600 ( 0.251 - 0.251) [0] query: SELECT user_name,up_value FROM `user` LEFT JOIN `user_properties` ON 1 0.251 0.251 0.002% 2360 ( 0.251 - 0.251) [0] query: UPDATE `site_stats` SET ss_total_views=ss_total_views+N 1 0.242 0.242 0.001% 616 ( 0.242 - 0.242) [0] query: SELECT user_id,user_name,user_real_name,user_password,user_newpasswo 1 0.236 0.236 0.001% 5352 ( 0.236 - 0.236) [0] Setup.php-session 1 0.228 0.228 0.001% 3128 ( 0.228 - 0.228) [0] SkinTemplate::buildContentNavigationUrls-edit 1 0.225 0.225 0.001% 1791 ( 0.225 - 0.225) [1] StubObject::_unstub-wgLang 1 0.196 0.196 0.001% 368 ( 0.196 - 0.196) [0] query: SELECT wl_notificationtimestamp FROM `watchlist` WHERE wl_user = 'X' 1 0.170 0.170 0.001% 2320 ( 0.170 - 0.170) [0] Skin::getSkinNames-init 1 0.168 0.168 0.001% 3312 ( 0.168 - 0.168) [0] Linker::linkAttribs-getClasses 4 0.165 0.041 0.001% 2848 ( 0.020 - 0.060) [0] query: SELECT up_property,up_value FROM `user_properties` WHERE up_user = ' 1 0.125 0.125 0.001% 2680 ( 0.125 - 0.125) [0] Cite::clearState 10 0.123 0.012 0.001% 2720 ( 0.007 - 0.028) [0] query: SELECT ug_group FROM `user_groups` WHERE ug_user = 'X' 1 0.119 0.119 0.001% 1944 ( 0.119 - 0.119) [0] query: SELECT user_id FROM `user_newtalk` WHERE user_id = 'X' LIMIT N 1 0.107 0.107 0.001% 2096 ( 0.107 - 0.107) [0] query: SELECT pr_type,pr_expiry,pr_level,pr_cascade FROM `page_restrictions 1 0.107 0.107 0.001% 2760 ( 0.107 - 0.107) [0] Parser::doBlockLevels 1 0.097 0.097 0.001% 2023 ( 0.097 - 0.097) [1] Parser::doMagicLinks 1 0.092 0.092 0.001% 1112 ( 0.092 - 0.092) [0] Skin::getSiteNotice 1 0.071 0.071 0.000% 390 ( 0.071 - 0.071) [2] WikiEditorHooks::makeGlobalVariablesScript 1 0.060 0.060 0.000% 1992 ( 0.060 - 0.060) [0] hook: ParserAfterParse 1 0.057 0.057 0.000% 1559 ( 0.057 - 0.057) [1] Skin::getCachedNotice 2 0.053 0.026 0.000% 2672 ( -0.000 - 0.053) [0] hook: ArticleFromTitle 1 0.051 0.051 0.000% 599 ( 0.051 - 0.051) [1] hook: ParserCloned 1 0.051 0.051 0.000% 5887 ( 0.051 - 0.051) [1] Parser::doBlockLevels-paragraph 1 0.051 0.051 0.000% 544 ( 0.051 - 0.051) [0] ParserOptions::initialiseFromUser 2 0.048 0.024 0.000% 2352 ( 0.023 - 0.025) [0] efCategoryTreeSetHooks 1 0.042 0.042 0.000% 3199 ( 0.042 - 0.042) [1] Setup.php-extensions-efLucenePrefixSetup 1 0.040 0.040 0.000% 272 ( 0.040 - 0.040) [0] SpecialPageFactory::getList 1 0.037 0.037 0.000% 1560 ( 0.037 - 0.037) [0] Parser::replaceExternalLinks 1 0.037 0.037 0.000% 744 ( 0.037 - 0.037) [0] Parser::doAllQuotes 1 0.031 0.031 0.000% 1328 ( 0.031 - 0.031) [0] BaseTemplate::getToolbox 1 0.029 0.029 0.000% 5688 ( 0.029 - 0.029) [0] VectorHooks::beforePageDisplay 1 0.029 0.029 0.000% 456 ( 0.029 - 0.029) [0] Cite::cloneState 1 0.028 0.028 0.000% 5176 ( 0.028 - 0.028) [0] Cite::checkRefsNoReferences 2 0.024 0.012 0.000% 592 ( 0.006 - 0.018) [0] hook: ParserBeforeTidy 1 0.023 0.023 0.000% 1423 ( 0.023 - 0.023) [1] Parser::initialiseVariables 1 0.023 0.023 0.000% 1856 ( 0.023 - 0.023) [0] hook: OutputPageParserOutput 1 0.020 0.020 0.000% 631 ( 0.020 - 0.020) [1] SkinTemplate::buildContentActionUrls 1 0.020 0.020 0.000% 1608 ( 0.020 - 0.020) [0] VectorHooks::makeGlobalVariablesScript 1 0.019 0.019 0.000% 1512 ( 0.019 - 0.019) [0] Parser::doHeadings 1 0.018 0.018 0.000% 648 ( 0.018 - 0.018) [0] efSyntaxHighlight_GeSHiSetup 1 0.017 0.017 0.000% 1928 ( 0.017 - 0.017) [0] Parser::doTableStuff 1 0.017 0.017 0.000% 2864 ( 0.017 - 0.017) [0] efCategoryTreeArticleFromTitle 1 0.012 0.012 0.000% 272 ( 0.012 - 0.012) [0] wfSetupImageMap 1 0.012 0.012 0.000% 1088 ( 0.012 - 0.012) [0] MediaWiki::checkMaxLag 1 0.011 0.011 0.000% 408 ( 0.011 - 0.011) [0] Setup.php-extensions-efCategoryTree 1 0.011 0.011 0.000% 1008 ( 0.011 - 0.011) [0] wfCiteBeforePageDisplay 1 0.010 0.010 0.000% 440 ( 0.010 - 0.010) [0] MathHooks::onParserFirstCallInit 1 0.010 0.010 0.000% 1216 ( 0.010 - 0.010) [0] MessageCache::saveToCaches 1 0.008 0.008 0.000% 504 ( 0.008 - 0.008) [0] Revision::getRevisionText 1 0.007 0.007 0.000% 912 ( 0.007 - 0.007) [0] LanguageGetMagic 1 0.007 0.007 0.000% 576 ( 0.007 - 0.007) [0] efCategoryTreeParserOutput 1 0.004 0.004 0.000% 272 ( 0.004 - 0.004) [0] Sanitizer::removeHTMLcomments 3 0.003 0.001 0.000% 1248 ( 0.001 - 0.002) [0] LinkHolderArray::replace 1 0.003 0.003 0.000% 416 ( 0.003 - 0.003) [0] WebStart.php-ob_start 1 0.002 0.002 0.000% 360 ( 0.002 - 0.002) [0] SkinTemplate::outputPage-stuff-head 1 0.001 0.001 0.000% 376 ( 0.001 - 0.001) [0] Profile section ended by close(): -total 1 0.000 0.000 0.000% 0 ( 0.000 - 0.000) [3734]
Total: 16.176341694734
Request ended normally
-- Johannes Weberhofer Weberhofer GmbH, Austria, Vienna
Wikitech-l mailing list Wikitech-l@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/wikitech-l
For a starting place, I would try editing the output method of includes/OutputPage.php to add more wfProfileIn( __METHOD__ . '-someIdentifier' ); wfProfileOut( __METHOD__ . '-someIdentifier' ); around various lines, to try and get a better picture of which line is taking up so much time.
--bawolff
Am 20.06.13 17:39, schrieb Brian Wolff:
On 6/20/13, Johannes Weberhofer jweberhofer@weberhofer.at wrote:
Dear all!
After upgrading a server to a complete new system (apache/php/mysql->mariadb) I have massive performance-problems when a large page is to be rendered.
I have added a profiling log; I do not think, it is related to the database upgrade, as the database have a very low CPU usage while rendering, while Apache's CPU usage is very high for around 16 seconds. This happens especially with large pages. I have already tried to remove all extensions which did not make any difference.
Do you have any ideas where to start?
Best regards, Johannes
For a starting place, I would try editing the output method of includes/OutputPage.php to add more wfProfileIn( __METHOD__ . '-someIdentifier' ); wfProfileOut( __METHOD__ . '-someIdentifier' ); around various lines, to try and get a better picture of which line is taking up so much time.
--bawolff
Thank you for your fast response. It's the ob_end_flush() call which takes a very long time to be processed. Does anyone have a hint what to do to improve speed?
Name Calls Total Each % Mem -total 1 1663.092 1663.092 100.000% 36215816 ( 1663.092 - 1663.092) [0] MediaWiki::main 1 1517.264 1517.264 91.232% 20015673 ( 1517.264 - 1517.264) [3620] OutputPage::output 1 1223.967 1223.967 73.596% 5831071 ( 1223.967 - 1223.967) [741] OutputPage::output_OB_END_FLUSH 1 1141.097 1141.097 68.613% -12656 ( 1141.097 - 1141.097) [0]
wikitech-l@lists.wikimedia.org