Last modified: 2014-07-28 09:26:42 UTC
Ubuntu 14.04, HipHop VM 3.3.0-dev, labs-vagrant with simple_performant role enabled. this is a bit ugly: vagrant@nemobis:/srv/vagrant/mediawiki/tests/phpunit$ php phpunit.php PHPUnit 4.1.4 by Sebastian Bergmann. Configuration read from /srv/vagrant/mediawiki/tests/phpunit/suite.xml [...] ..........................SlowTimer [1329ms] at runtime/ext_mysql: slow query: INSERT /* JobQueueDB::doBatchPush 127.0.0.1 */ INTO `unittest_job` (job_cmd,job_namespace,job_title,job_params,job_id,job_timestamp,job_sha1,job_random) VALUES ('null','0','Main_Page','a:6:{s:5:\"lives\";i:0;s:6:\"usleep\";i:0;s:16:\"removeDuplicates\";i:0;s:1:\"i\";i:0;s:16:\"rootJobSignature\";s:40:\"486b449fb5b520e6228c37ee539588f8b7174664\";s:16:\"rootJobTimestamp\";s:14:\"20140726153847\";}',NULL,'20140726153847','lfcfwgp44xsmdatbc75gzx5yl8hqy16','2073081733') ................................... 3294 / 8426 ( 39%) [...] .......................................SlowTimer [1104ms] at runtime/ext_mysql: slow query: INSERT /* NewParserTest::addDBData 127.0.0.1 */ INTO `unittest_site_stats` (ss_row_id,ss_images,ss_good_articles) VALUES ('1','2','1') ................SlowTimer [1237ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '0' AND page_title = 'Main_Page' LIMIT 1 SlowTimer [1767ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Foo' LIMIT 1 ...... 4514 / 8426 ( 53%) ........................................SlowTimer [1130ms] at runtime/ext_mysql: slow query: DELETE /* MediaWikiTestCase::resetDB 127.0.0.1 */ FROM `unittest_site_stats` SlowTimer [1409ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '0' AND page_title = 'UTPage' LIMIT 1 SlowTimer [1094ms] at runtime/ext_mysql: slow query: INSERT /* NewParserTest::addDBData 127.0.0.1 */ INTO `unittest_site_stats` (ss_row_id,ss_images,ss_good_articles) VALUES ('1','2','1') SlowTimer [1515ms] at runtime/ext_mysql: slow query: SELECT /* DatabaseBase::selectField 127.0.0.1 */ 1 FROM `unittest_image` WHERE img_name = 'Foobar.jpg' LIMIT 1 SlowTimer [1304ms] at runtime/ext_mysql: slow query: SELECT /* DatabaseBase::selectField 127.0.0.1 */ 1 FROM `unittest_image` WHERE img_name = 'Thumb.png' LIMIT 1 SlowTimer [1106ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '0' AND page_title = 'Main_Page' LIMIT 1 .SlowTimer [1182ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '0' AND page_title = 'UTPage' LIMIT 1 SlowTimer [1549ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Foo' LIMIT 1 SlowTimer [1465ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Pipe' LIMIT 1 SlowTimer [1527ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '8' AND page_title = 'Bad_image_list' LIMIT 1 SlowTimer [1579ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Inner_list' LIMIT 1 .SlowTimer [1002ms] at runtime/ext_mysql: slow query: DELETE /* MediaWikiTestCase::resetDB 127.0.0.1 */ FROM `unittest_site_stats` SlowTimer [1263ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '0' AND page_title = 'UTPage' LIMIT 1 SlowTimer [1205ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '0' AND page_title = 'Main_Page' LIMIT 1 SlowTimer [5983ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Foo' LIMIT 1 SlowTimer [1680ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Pipe' LIMIT 1 SlowTimer [1858ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Inner_list' LIMIT 1 SlowTimer [1111ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Tbl-start' LIMIT 1 ................... 4575 / 8426 ( 54%) .........SlowTimer [3465ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '0' AND page_title = 'Main_Page' LIMIT 1 SlowTimer [1969ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Foo' LIMIT 1 SlowTimer [1455ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Blank' LIMIT 1 SlowTimer [1271ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '10' AND page_title = 'Pipe' LIMIT 1 SlowTimer [3423ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '8' AND page_title = 'Bad_image_list' LIMIT 1 .................................................... 4636 / 8426 ( 55%) ............................................................. 4697 / 8426 ( 55%) ......SlowTimer [1019ms] at runtime/ext_mysql: slow query: DELETE /* MediaWikiTestCase::resetDB 127.0.0.1 */ FROM `unittest_site_stats` ........................................SlowTimer [1041ms] at runtime/ext_mysql: slow query: DELETE /* MediaWikiTestCase::resetDB 127.0.0.1 */ FROM `unittest_site_stats` SlowTimer [2148ms] at runtime/ext_mysql: slow query: SELECT /* User::idForName 127.0.0.1 */ user_id FROM `unittest_user` WHERE user_name = 'UTSysop' LIMIT 1 SlowTimer [1235ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '0' AND page_title = 'UTPage' LIMIT 1 ............... 4758 / 8426 ( 56%) .......................................................SlowTimer [1748ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '100' AND page_title = 'AlphaTest' LIMIT 1 SlowTimer [6289ms] at runtime/ext_mysql: slow query: SELECT /* WikiPage::pageData 127.0.0.1 */ page_id,page_namespace,page_title,page_restrictions,page_counter,page_is_redirect,page_is_new,page_random,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `unittest_page` WHERE page_namespace = '0' AND page_title = '7%_Solution' LIMIT 1 .SlowTimer [4067ms] at runtime/ext_mysql: slow query: DELETE /* MediaWikiTestCase::resetDB 127.0.0.1 */ FROM `unittest_site_stats` ..... 4819 / 8426 ( 57%) ............................................................. 4880 / 8426 ( 57%) .........................SlowTimer [1457ms] at runtime/ext_mysql: slow query: SELECT /* MessageCache::loadFromDB(en)-big 127.0.0.1 */ page_title FROM `unittest_page` WHERE page_is_redirect = '0' AND page_namespace = '8' AND (page_title NOT LIKE '%/%' ) AND (page_len > 10000) .................................... 4941 / 8426 ( 58%) ............................................................. 5002 / 8426 ( 59%) ....................SlowTimer [1847ms] at runtime/ext_mysql: slow query: DELETE /* MediaWikiTestCase::resetDB 127.0.0.1 */ FROM `unittest_site_stats` SlowTimer [4315ms] at runtime/ext_mysql: slow query: SELECT /* User::idForName 127.0.0.1 */ user_id FROM `unittest_user` WHERE user_name = 'UTSysop' LIMIT 1 ......................................... 5063 / 8426 ( 60%) [...]
Wonder if its something specific to the labs-vagrant setup (e.g. Maybe a network file system causes really slow writes, so writing to an sqlite db takes a long time)?
(In reply to Bawolff (Brian Wolff) from comment #1) > Wonder if its something specific to the labs-vagrant setup (e.g. Maybe a > network file system causes really slow writes, so writing to an sqlite db > takes a long time)? There was some IO wait but the biggest problem seemed to be insufficient RAM (!). That's an instance with only 2 GB and half is consumed by puppet, as said above. 21.30 < ori> [mw1053:~] $ sudo hdparm -Tt /dev/sda1 21.30 < ori> /dev/sda1: 21.31 < ori> Timing cached reads: 9628 MB in 1.99 seconds = 4830.60 MB/sec 21.31 < ori> Timing buffered disk reads: 318 MB in 3.02 seconds = 105.39 MB/sec 21.31 < ori> [mw1053:~] $ sudo hdparm -Tt /dev/sda1 21.31 < ori> /dev/sda1: 21.31 < ori> Timing cached reads: 10612 MB in 1.99 seconds = 5320.34 MB/sec 21.31 < ori> Timing buffered disk reads: 304 MB in 3.01 seconds = 100.89 MB/sec 21.31 < ori> mw1053:~# dd if=/dev/zero of=/tmp/output bs=8k count=10k; rm -f /tmp/output 21.31 < ori> 10240+0 records in 21.31 < ori> 10240+0 records out 21.31 < ori> 83886080 bytes (84 MB) copied, 0.144263 s, 581 MB/s 21.42 < Nemo_bis> convert and texvc hammering disk, according to htop 21.45 < Nemo_bis> 83886080 bytes (84 MB) copied, 1.06678 s, 78.6 MB/s / but on an idle instance 83886080 bytes (84 MB) copied, 0.0874509 s, 959 MB/s 21.49 < Nemo_bis> Though, when slightly bigger: $ dd if=/dev/zero of=/tmp/output bs=40k count=50k; rm -f /tmp/output / 2097152000 bytes (2.1 GB) copied, 36.9018 s, 56.8 MB/s
Seems related to vagrant setup, not bug 67216 which is about having extensions pass tests together.
