On 18/09/2007, Simetrical Simetrical+wikilist@gmail.com wrote:
On 9/17/07, Andreas Rindler mediawiki@jenandi.com wrote:
I got it to work. I can see a whole bunch of requests and sql queries, but I can't see anything unusual. I tried running some of the queries manually and they run very fast.
The queries will all run very fast in MediaWiki. Slowness will probably come from some oddity in the PHP code. Did you compare the before-and-after profiling data? Maybe you could post it for others to look at?
==================== file before upgrade: ====================
Start request GET /mike2/index.php/Main_Page Host: 192.168.100.15 User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-GB; rv:1.8.1.6) Gecko/20070725 Firefox/2.0.0.6 Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5 Accept-Language: en-gb,en;q=0.5 Accept-Encoding: gzip,deflate Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 Keep-Alive: 300 Connection: keep-alive Cookie: [removed by me] Cache-Control: max-age=0
Main cache: FakeMemCachedClient Message cache: MediaWikiBagOStuff Parser cache: MediaWikiBagOStuff Unstubbing $wgParser on call of $wgParser->setHook from setupSpecialChars Unstubbing $wgMessageCache on call of $wgMessageCache->addMessages from efNewestPagesBlog Fully initialised Unstubbing $wgContLang on call of $wgContLang->checkTitleEncoding from WebRequest::getGPCVal Unstubbing $wgLoadBalancer on call of $wgLoadBalancer->getConnection from wfGetDB SQL: BEGIN SQL: SET /* Database::open */ sql_mode = '' SQL: /* LinkCache::addLinkObj */ SELECT page_id FROM `omw_page` WHERE page_namespace = '0' AND page_title = 'Main_Page' LIMIT 1 Unstubbing $wgLang on call of $wgLang->getCode from MessageCache::get Unstubbing $wgUser on call of $wgUser->getOption from StubUserLang::_newObject Cache miss for user 129 SQL: /* User::loadFromDatabase */ SELECT * FROM `omw_user` WHERE user_id = '129' LIMIT 1 SQL: SELECT /* User::loadFromDatabase Andreas.rindler */ ug_group FROM `omw_user_groups` WHERE ug_user = '129' Language::loadLocalisation(): got localisation for en from source IP: 192.168.100.51 SQL: SELECT /* MediaWikiBagOStuff::_doquery 192.168.100.51 */ value,exptime FROM `omw_objectcache` WHERE keyname='openmeth_omwikidb-omw_:messages-hash' SQL: SELECT /* MediaWikiBagOStuff::_doquery 192.168.100.51 */ value,exptime FROM `omw_objectcache` WHERE keyname='openmeth_omwikidb-omw_:messages' MessageCache::load(): got from global cache SQL: /* Article::pageData 192.168.100.51 */ SELECT page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len FROM `omw_page` WHERE page_namespace = '0' AND page_title = 'Main_Page' LIMIT 1 SQL: SELECT /* Title::loadRestrictions 192.168.100.51 */ * FROM `omw_page_restrictions` WHERE pr_page = '1' SQL: /* Title::loadRestrictionsFromRow 192.168.100.51 */ SELECT page_restrictions FROM `omw_page` WHERE page_id = '1' LIMIT 1 SQL: /* Revision::fetchRow 192.168.100.51 */ SELECT page_namespace,page_title,page_latest,rev_id,rev_page,rev_text_id,rev_comment,rev_user_text,rev_user,rev_minor_edit,rev_timestamp,rev_deleted,rev_len FROM `omw_page`,`omw_revision` WHERE (page_id=rev_page) AND rev_id = '5909' LIMIT 1 SQL: /* Revision::loadText 192.168.100.51 */ SELECT old_text,old_flags FROM `omw_text` WHERE old_id = '5845' LIMIT 1 SQL: /* Article::pageData 192.168.100.51 */ SELECT page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len FROM `omw_page` WHERE page_namespace = '0' AND page_title = 'Main_Page' LIMIT 1 SQL: /* Revision::fetchRow 192.168.100.51 */ SELECT page_namespace,page_title,page_latest,rev_id,rev_page,rev_text_id,rev_comment,rev_user_text,rev_user,rev_minor_edit,rev_timestamp,rev_deleted,rev_len FROM `omw_page`,`omw_revision` WHERE (page_id=rev_page) AND rev_id = '5909' LIMIT 1 SQL: /* Revision::loadText 192.168.100.51 */ SELECT old_text,old_flags FROM `omw_text` WHERE old_id = '5845' LIMIT 1 SQL: /* Article::pageData 192.168.100.51 */ SELECT page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len FROM `omw_page` WHERE page_namespace = '0' AND page_title = 'MIKE2.0_Methodology' LIMIT 1 SQL: SELECT /* Title::loadRestrictions 192.168.100.51 */ * FROM `omw_page_restrictions` WHERE pr_page = '1650' SQL: /* Title::loadRestrictionsFromRow 192.168.100.51 */ SELECT page_restrictions FROM `omw_page` WHERE page_id = '1650' LIMIT 1 Unstubbing $wgOut on call of $wgOut->setSquidMaxage from MediaWiki::performAction OutputPage::checkLastModified: client did not send If-Modified-Since header Article::tryFileCache(): not cacheable Article::view using parser cache: yes Trying parser cache openmeth_omwikidb-omw_:pcache:idhash:1650-0!1!0!!en!2!edit=0 SQL: SELECT /* MediaWikiBagOStuff::_doquery 192.168.100.51 */ value,exptime FROM `omw_objectcache` WHERE keyname='openmeth_omwikidb-omw_:pcache:idhash:1650-0!1!0!!en!2!edit=0' Parser cache miss. SQL: /* Revision::fetchRow 192.168.100.51 */ SELECT page_namespace,page_title,page_latest,rev_id,rev_page,rev_text_id,rev_comment,rev_user_text,rev_user,rev_minor_edit,rev_timestamp,rev_deleted,rev_len FROM `omw_page`,`omw_revision` WHERE (page_id=rev_page) AND rev_id = '10331' LIMIT 1 SQL: /* Revision::loadText 192.168.100.51 */ SELECT old_text,old_flags FROM `omw_text` WHERE old_id = '10087' LIMIT 1 SQL: /* Article::pageData 192.168.100.51 */ SELECT page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len FROM `omw_page` WHERE page_namespace = '0' AND page_title = 'MIKE2.0_Methodology' LIMIT 1 SQL: /* Revision::fetchRow 192.168.100.51 */ SELECT page_namespace,page_title,page_latest,rev_id,rev_page,rev_text_id,rev_comment,rev_user_text,rev_user,rev_minor_edit,rev_timestamp,rev_deleted,rev_len FROM `omw_page`,`omw_revision` WHERE (page_id=rev_page) AND rev_id = '10331' LIMIT 1 SQL: /* Revision::loadText 192.168.100.51 */ SELECT old_text,old_flags FROM `omw_text` WHERE old_id = '10087' LIMIT 1 Parser output marked as uncacheable. SQL: /* LinkCache::addLinkObj 192.168.100.51 */ SELECT page_id FROM `omw_page` WHERE page_namespace = '14' AND page_title = 'MIKE2.0_Methodology' LIMIT 1 img_width match: 60 SQL: SHOW /* Database::indexInfo 192.168.100.51 */ INDEX FROM `omw_image` SQL: SHOW /* Database::indexExists 192.168.100.51 */ INDEX FROM `omw_image` SQL: /* Image::loadFromDB 192.168.100.51 */ SELECT img_size,img_width,img_height,img_bits,img_media_type,img_major_mime,img_minor_mime,img_metadata FROM `omw_image` WHERE img_name = 'Mike2logo_notext_wbg.png' LIMIT 1 BitmapHandler::doTransform: creating 60x61 thumbnail at /var/www/mike2/images/thumb/b/ba/Mike2logo_notext_wbg.png/60px-Mike2logo_notext_wbg.png SQL: SELECT /* Title::getInterwikiLink 192.168.100.51 */ iw_url,iw_local,iw_trans FROM `omw_interwiki` WHERE iw_prefix = 'es' SQL: SELECT /* Title::getInterwikiLink 192.168.100.51 */ iw_url,iw_local,iw_trans FROM `omw_interwiki` WHERE iw_prefix = 'ko' SQL: SELECT /* Title::getInterwikiLink 192.168.100.51 */ iw_url,iw_local,iw_trans FROM `omw_interwiki` WHERE iw_prefix = 'fr' SQL: SELECT /* Title::getInterwikiLink 192.168.100.51 */ iw_url,iw_local,iw_trans FROM `omw_interwiki` WHERE iw_prefix = 'ja' SQL: SELECT /* Parser::replaceLinkHolders 192.168.100.51 */ page_id, page_namespace, page_title FROM `omw_page` WHERE (page_namespace=0 AND page_title IN('The_5_Phases_of_MIKE2', 'Overall_Task_List', 'Usage_Model', 'Overall_Implementation_Guide_Overview', 'FAQs', 'Receive_or_Run_MIKE2.0_training', 'Integrating_MIKE2.0_to_External_Assets', 'Core_Solution_Offerings', 'Business_Solution_Offerings', 'Data_Governance_and_Management_Consortium', 'Priority_Activities', 'Open_Source_Solution_Offerings', 'Inf SQL: UPDATE /* 192.168.100.51 */ `omw_page` SET page_counter = page_counter + 1 WHERE page_id = 1650 SQL: /* SiteStatsUpdate::doUpdate 192.168.100.51 */ SELECT * FROM `omw_site_stats` LIMIT 1 SQL: BEGIN SQL: /* SiteStatsUpdate::doUpdate 192.168.100.51 */ UPDATE `omw_site_stats` SET ss_total_views=ss_total_views+1 LIMIT 1 SQL: COMMIT SQL: BEGIN SQL: /* Job::pop 192.168.100.51 */ SELECT * FROM `omw_job` WHERE job_id >= 0 ORDER BY job_id LIMIT 1 SQL: COMMIT SQL: BEGIN SQL: SELECT /* LinkBatch::doQuery 192.168.100.51 */ page_id, page_namespace, page_title FROM `omw_page` WHERE (page_namespace=2 AND page_title IN ('192.168.100.51')) OR (page_namespace=3 AND page_title IN ('192.168.100.51')) OR (page_namespace=1 AND page_title IN ('MIKE2.0_Methodology')) SQL: /* User::checkNewtalk 192.168.100.51 */ SELECT user_ip FROM `omw_user_newtalk` WHERE user_ip = '192.168.100.51' LIMIT 1 OutputPage::sendCacheControl: no caching ** 20070918091515 0.452 /mike2/index.php/Main_Page anon SQL: COMMIT Request ended normally
================= file after upgrade =================
Start request GET /mike2/index.php/Main_Page Host: 192.168.100.15 User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-GB; rv:1.8.1.6) Gecko/20070725 Firefox/2.0.0.6 Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5 Accept-Language: en-gb,en;q=0.5 Accept-Encoding: gzip,deflate Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 Keep-Alive: 300 Connection: keep-alive Cookie: [removed by me] Cache-Control: max-age=0
Main cache: FakeMemCachedClient Message cache: MediaWikiBagOStuff Parser cache: MediaWikiBagOStuff Unstubbing $wgParser on call of $wgParser->setHook from setupSpecialChars Unstubbing $wgMessageCache on call of $wgMessageCache->addMessages from efNewestPagesBlog Fully initialised Unstubbing $wgContLang on call of $wgContLang->checkTitleEncoding from WebRequest::getGPCVal Unstubbing $wgUser on call of $wgUser->isAllowed from Title::userCanRead Unstubbing $wgLoadBalancer on call of $wgLoadBalancer->getConnection from wfGetDB IP: 192.168.100.51 SQL: BEGIN SQL: SET /* Database::open 192.168.100.51 */ sql_mode = '' SQL: /* Article::pageData 192.168.100.51 */ SELECT page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len FROM `omw_page` WHERE page_namespace = '0' AND page_title = 'Main_Page' LIMIT 1 SQL: SELECT /* Title::loadRestrictions 192.168.100.51 */ * FROM `omw_page_restrictions` WHERE pr_page = '1' SQL: /* Title::loadRestrictionsFromRow 192.168.100.51 */ SELECT page_restrictions FROM `omw_page` WHERE page_id = '1' LIMIT 1 Unstubbing $wgLang on call of $wgLang->getCode from MessageCache::get Language::loadLocalisation(): got localisation for en from source SQL: DELETE /* MediaWikiBagOStuff::_doquery 192.168.100.51 */ FROM `omw_objectcache` WHERE exptime < '20070918093232' SQL: SELECT /* MediaWikiBagOStuff::_doquery 192.168.100.51 */ value,exptime FROM `omw_objectcache` WHERE keyname='openmeth_omwikidb-omw_:messages-hash' SQL: SELECT /* MediaWikiBagOStuff::_doquery 192.168.100.51 */ value,exptime FROM `omw_objectcache` WHERE keyname='openmeth_omwikidb-omw_:messages' MessageCache::load(): got from global cache SQL: /* Revision::fetchRow 192.168.100.51 */ SELECT page_namespace,page_title,page_latest,rev_id,rev_page,rev_text_id,rev_comment,rev_user_text,rev_user,rev_minor_edit,rev_timestamp,rev_deleted,rev_len FROM `omw_page`,`omw_revision` WHERE (page_id=rev_page) AND rev_id = '5909' LIMIT 1 SQL: /* Revision::loadText 192.168.100.51 */ SELECT old_text,old_flags FROM `omw_text` WHERE old_id = '5845' LIMIT 1 SQL: /* Article::pageData 192.168.100.51 */ SELECT page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len FROM `omw_page` WHERE page_namespace = '0' AND page_title = 'MIKE2.0_Methodology' LIMIT 1 SQL: SELECT /* Title::loadRestrictions 192.168.100.51 */ * FROM `omw_page_restrictions` WHERE pr_page = '1650' SQL: /* Title::loadRestrictionsFromRow 192.168.100.51 */ SELECT page_restrictions FROM `omw_page` WHERE page_id = '1650' LIMIT 1 Unstubbing $wgOut on call of $wgOut->setSquidMaxage from MediaWiki::performAction OutputPage::checkLastModified: client did not send If-Modified-Since header Article::tryFileCache(): not cacheable Article::view using parser cache: yes Trying parser cache openmeth_omwikidb-omw_:pcache:idhash:1650-0!1!0!!en!2!edit=0 SQL: SELECT /* MediaWikiBagOStuff::_doquery 192.168.100.51 */ value,exptime FROM `omw_objectcache` WHERE keyname='openmeth_omwikidb-omw_:pcache:idhash:1650-0!1!0!!en!2!edit=0' Parser cache miss. SQL: /* Revision::fetchRow 192.168.100.51 */ SELECT page_namespace,page_title,page_latest,rev_id,rev_page,rev_text_id,rev_comment,rev_user_text,rev_user,rev_minor_edit,rev_timestamp,rev_deleted,rev_len FROM `omw_page`,`omw_revision` WHERE (page_id=rev_page) AND rev_id = '10331' LIMIT 1 SQL: /* Revision::loadText 192.168.100.51 */ SELECT old_text,old_flags FROM `omw_text` WHERE old_id = '10087' LIMIT 1 Parser output marked as uncacheable. SQL: /* LinkCache::addLinkObj 192.168.100.51 */ SELECT page_id FROM `omw_page` WHERE page_namespace = '14' AND page_title = 'MIKE2.0_Methodology' LIMIT 1 SQL: /* LocalFile::loadFromDB 192.168.100.51 */ SELECT img_size,img_width,img_height,img_bits,img_media_type,img_major_mime,img_minor_mime,img_metadata,img_timestamp,img_sha1 FROM `omw_image` WHERE img_name = 'Mike2logo_notext_wbg.png' LIMIT 1 File::transform: Doing stat for /var/www/mike2/images/thumb/b/ba/Mike2logo_notext_wbg.png/60px-Mike2logo_notext_wbg.png BitmapHandler::doTransform: creating 60x61 thumbnail at /var/www/mike2/images/thumb/b/ba/Mike2logo_notext_wbg.png/60px-Mike2logo_notext_wbg.png SQL: SELECT /* Title::getInterwikiLink 192.168.100.51 */ iw_url,iw_local,iw_trans FROM `omw_interwiki` WHERE iw_prefix = 'es' SQL: SELECT /* Title::getInterwikiLink 192.168.100.51 */ iw_url,iw_local,iw_trans FROM `omw_interwiki` WHERE iw_prefix = 'ko' SQL: SELECT /* Title::getInterwikiLink 192.168.100.51 */ iw_url,iw_local,iw_trans FROM `omw_interwiki` WHERE iw_prefix = 'fr' SQL: SELECT /* Title::getInterwikiLink 192.168.100.51 */ iw_url,iw_local,iw_trans FROM `omw_interwiki` WHERE iw_prefix = 'ja' SQL: SELECT /* Parser::replaceLinkHolders 192.168.100.51 */ page_id, page_namespace, page_title FROM `omw_page` WHERE (page_namespace=0 AND page_title IN('The_5_Phases_of_MIKE2', 'Overall_Task_List', 'Usage_Model', 'Overall_Implementation_Guide_Overview', 'FAQs', 'Receive_or_Run_MIKE2.0_training', 'Integrating_MIKE2.0_to_External_Assets', 'Core_Solution_Offerings', 'Business_Solution_Offerings', 'Data_Governance_and_Management_Consortium', 'Priority_Activities', 'Open_Source_Solution_Offerings', 'Inf SQL: UPDATE /* 192.168.100.51 */ `omw_page` SET page_counter = page_counter + 1 WHERE page_id = 1650 SQL: /* SiteStatsUpdate::doUpdate 192.168.100.51 */ SELECT * FROM `omw_site_stats` LIMIT 1 SQL: BEGIN SQL: /* SiteStatsUpdate::doUpdate 192.168.100.51 */ UPDATE `omw_site_stats` SET ss_total_views=ss_total_views+1 LIMIT 1 SQL: COMMIT SQL: BEGIN SQL: /* Job::pop 192.168.100.51 */ SELECT * FROM `omw_job` WHERE job_id >= 0 ORDER BY job_id LIMIT 1 SQL: COMMIT SQL: BEGIN SQL: SELECT /* LinkBatch::doQuery 192.168.100.51 */ page_id, page_namespace, page_title FROM `omw_page` WHERE (page_namespace=2 AND page_title='192.168.100.51') OR (page_namespace=3 AND page_title='192.168.100.51') OR (page_namespace=1 AND page_title='MIKE2.0_Methodology') SQL: /* User::checkNewtalk 192.168.100.51 */ SELECT user_ip FROM `omw_user_newtalk` WHERE user_ip = '192.168.100.51' LIMIT 1 OutputPage::sendCacheControl: no caching ** 20070918093232 0.447 /mike2/index.php/Main_Page anon SQL: COMMIT Request ended normally