I had to restore to the version before the upgrade because the speed was unacceptable. I performed the upgrade again and had the same result. So I restored the before the upgrade again. I checked with the hosting provider, there is apparantly nothing on their side that could be causing it. It must be something with the database. Maybe it has to do with the 'Deleting old default messages' processing taking so long? What are these messages anyway? Do I need to perform any maintenance on the database?

Thanks, Andi

On 14/09/2007, Andreas Rindler mediawiki@jenandi.com wrote:

ah, it completed! Took something like 45 minutes!!

The site is still very slow. I am gonna check with the hosting provider, but does anyone have a suggestion on what else I should check?

Thanks, Andi

On 14/09/2007, Andreas Rindler mediawiki@jenandi.com wrote:

...

Hi, I am upgrading my 1.10.0 installation to 1.11.0 and the update.php script is stuck (~20 min.) at:

Deleting old default messages (this may take a long time!)...

I can check the site in the mean time and it appears as if the upgrade has gone ahead (Special:Version shows 1.11.0). The site is extremely slow, probably due to the server load by the script.

Any suggestions what I should do? Kill it and re-run?

Thanks, Andi

On 9/16/07, Andreas Rindler mediawiki@jenandi.com wrote:

I had to restore to the version before the upgrade because the speed was unacceptable. I performed the upgrade again and had the same result.

Try turning on profiling and seeing if you can spot a difference in what functions are taking up time.

It must be something with the database.

No, it could easily be the PHP code, and in fact it probably is. Perhaps there's some PHP module you don't have and we implemented (slow!) emulation of its functions, say, then started using them all over the place. That would explain why the difference wouldn't show up on Wikipedia, which would have the relevant PHP module installed.

Maybe it has to do with the 'Deleting old default messages' processing taking so long? What are these messages anyway?

It has nothing to do with that. The messages make up most of the interface: you can see a complete list of messages at Special:Allmessages. Formerly, all messages were stored in the database by default, so that they could be customized by editing pages in the MediaWiki: namespace. More recently, it was realized that if a message is unmodified, it's faster to not put it in the database to begin with, and to just draw it directly from the PHP files. Thus we now only store modified messages in the database.

For upgrading sites to benefit from this speed improvement, the update script checks each message in the database against the default message (or something to that effect), and if they're the same, it deletes them. Since there are a fairly large number of messages and the check is slow, it can take a very long time. Thus, we added the hint to the update script: "(this can take a long time!)". 45 minutes is not especially out of the ordinary, from my recollection of user reports, although a fast server should be able to do it quite a lot more quickly.

If you skipped that step of the update script, things would be slower if anything. You're welcome to try, and nothing will break, but it's not going to be what's causing your problems.

On 17/09/2007, Andreas Rindler mediawiki@jenandi.com wrote:

On 16/09/2007, Simetrical Simetrical+wikilist@gmail.com wrote:

...

On 9/16/07, Andreas Rindler mediawiki@jenandi.com wrote:

...

I had to restore to the version before the upgrade because the speed was unacceptable. I performed the upgrade again and had the same result.

Try turning on profiling and seeing if you can spot a difference in what functions are taking up time.

I was following http://www.mediawiki.org/wiki/How_to_debug_MediaWiki but there is nothing showing up in my log file because I don't know where to put the debug code. What do I need to do?

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.

I have nothing in my php error log, http log, http error log.

I tried the upgrade on two additional servers (Ubuntu, Windows XP) and I am seeing the same issue of super slow speed. I must admit that the deleting of old default messages took less than 1 minute on these two. So there seems to be a difference in performance as well.

I have upgraded another wiki from 1.10.0 to 1.11.0 and I have no issues. It is only this particular instance that I am having troubles with...

Anyone any other other ideas? If I can't solve it, then I will have to skip this upgrade...

Thanks, Andi

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

I never was able to turn on profiling. But I managed to upgrade the instance by restoring it to a second server, upgrading it on the second server and restoring it to the production server. I have no idea why it failed, but we are back on track.

Thanks for everyone's help, Andreas

On 18/09/2007, Simetrical Simetrical+wikilist@gmail.com wrote:

On 9/18/07, Andreas Rindler arindler@jenandi.com wrote:

...

...

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: ====================

. . .

That's debugging info, not profiling info. Debugging info tells you what's happening, which should be broadly the same before and after. Profiling info tells you how long everything is taking, which evidently is not the same before and after.

---

Wikitech-l mailing list Wikitech-l@lists.wikimedia.org http://lists.wikimedia.org/mailman/listinfo/wikitech-l