Hi,

I'd appreciate any thoughts about what I can do to troubleshoot and fix a site whose performance has become slower over the last month or so. Traffic has stayed stable, and I've installed nothing new besides routine updates using "sudo apt-get update && sudo apt-get upgrade". I've received this message when doing so and have held off on trying to upgrade these packages because I was worried I'd break something: The following packages have been kept back:
libgnome2-0 mysql-client-5.5 mysql-server-5.5 mysql-server-core-5.5

I have a few domains hosted on the server. The ones which are just static HTML files served by Apache are fine. The system resources appear far from being maxed out. Only the domain which is a MediaWiki installation using MySQL has been slower of late:



These response times are for a query to a dynamic page in the wiki which uses the database (http://hemonc.org/wiki/Special:RecentChanges). I'm inexperienced when it comes to MySQL optimization and maintenance, so any diagnostics or troubleshooting things to try would be appreciated. The main database uncompressed is 180mb--not sure if fragmentation is something that I should be concerned about.

Ubuntu 12.04.4 LTS
Apache/2.2.22
MediaWiki 1.20.3
PHP 5.3.10-1ubuntu3.9 (apache2handler)
MySQL 5.5.31-0ubuntu0.12.04.1

Thank you in advance!

_________________
Amateur, eager to learn.
My hematology, oncology, and chemotherapy regimen wiki

That does look intriguing, see if you can check the stats of the MySQL server, trough something like phpMyAdmin, actually, see if you can get Linode LongView running on that server, it will show you apache+mysql stats, to better locate the issue.

Thanks. I just installed Linode Longview, and will report back once it's had the chance to gather some stats.

_________________
Amateur, eager to learn.
My hematology, oncology, and chemotherapy regimen wiki

Are we to assume that you've already gone through these options and they haven't solved your load issues?
http://www.mediawiki.org/wiki/User:Aaro ... aWiki_fast

I forgot to mention that my Linode is 1 GB.



I had gone through that guide in my initial setup and used some of the suggestions, e.g. enabling PHP APC. I guess I'll decrease the update frequency on the hit counters to see if it makes any difference. I don't want to compress revisions since I often use the ReplaceText function, which apparently will not work properly if that's enabled.

However, the issue for me is not that it was slow in the past. I was fine with the performance. My issue is that, without me knowingly changing anything about the previous configuration which was working fine, response times are 3 to 4 times slower.

--------------

Nothing is sticking out in Longview thus far for either Apache or MySQL in terms of excess resource utilization. MySQL currently is just one process using ~188MB, 15 max connections.

Not sure if info from the Longview process explorer output would be preferable, but here is an abridged version of what I get from ps aux:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root      1358  0.0  0.0   3188   612 ?        S    Jan19   0:00 upstart-udev-bridge --daemon
root      1366  0.0  0.1   3104  1052 ?        Ss   Jan19   0:00 /sbin/udevd --daemon
root      2306  0.0  0.0   2852   344 ?        S    Jan19   0:00 upstart-socket-bridge --daemon
root      5129  0.0  0.0   2936   656 ?        Ss   Jan19   0:00 dhclient3 -e IF_METRIC=100 -pf /var/run/dhclient.eth0.pi
syslog    5224  0.0  0.1  31068  1464 ?        Sl   Jan19   1:15 rsyslogd -c5
daemon    5259  0.0  0.0   2480   352 ?        Ss   Jan19   0:00 atd
root      5260  0.0  0.0   2628   920 ?        Ss   Jan19   0:02 cron
102       5261  0.0  0.1   3404  1080 ?        Ss   Jan19   0:00 dbus-daemon --system --fork --activation=upstart
mysql     5291  0.1 18.7 353264 192256 ?       Ssl  Jan19  12:05 /usr/sbin/mysqld
whoopsie  5304  0.0  0.3  24452  3404 ?        Ssl  Jan19   0:03 whoopsie
root      5343  0.0  0.3  75020  3800 ?        Ss   Jan19   0:44 php-fpm: master process (/etc/php5/fpm/php-fpm.conf)
www-data  5345  0.0  0.2  75020  2984 ?        S    Jan19   0:00 php-fpm: pool www
www-data  5346  0.0  0.2  75020  2984 ?        S    Jan19   0:00 php-fpm: pool www
www-data  5347  0.0  0.2  75020  2984 ?        S    Jan19   0:00 php-fpm: pool www
www-data  5348  0.0  0.2  75020  2984 ?        S    Jan19   0:00 php-fpm: pool www
root      5464  0.0  0.1   4588  1448 ?        Ss   Jan19   0:04 /usr/lib/postfix/master
postfix   5477  0.0  0.1   4752  1572 ?        S    Jan19   0:00 qmgr -l -t fifo -u
root      5578  0.0  1.1  79364 11508 ?        Ss   Jan19   1:04 /usr/sbin/apache2 -k start
ntp       5631  0.0  0.1   5740  1976 ?        Ss   Jan19   1:02 /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 106:113
root      5636  0.0  0.5  29408  6124 ?        Sl   Jan19   2:42 /usr/bin/python /usr/bin/fail2ban-server -b -s /var/run/
root      5638  0.0  0.1   3876  1308 ?        S    Jan19   0:05 /usr/lib/gamin/gam_server
root      5744  0.0  0.3  42408  3212 ?        Sl   Jan19   0:00 /usr/sbin/console-kit-daemon --no-daemon
root      5811  0.0  0.2  24568  2608 ?        Sl   Jan19   0:00 /usr/lib/policykit-1/polkitd --no-debug
root      6065  0.0  0.0   2412   712 hvc0     Ss+  Jan19   0:00 /sbin/getty -8 38400 hvc0
postfix  26943  0.0  0.1   4608  1324 ?        S    12:12   0:00 pickup -l -t fifo -u -c
www-data 30961  0.0  0.4  31660  4588 ?        S    12:30   0:00 /usr/sbin/fcgi-pm -k start
root     31017  2.2  1.6  33928 16812 ?        Ss   12:30   0:50 linode-longview
www-data 31055  0.4  3.1  82400 32212 ?        S    12:31   0:10 /usr/sbin/apache2 -k start
www-data 31078  0.5  2.6  82616 27688 ?        S    12:39   0:09 /usr/sbin/apache2 -k start
www-data 31089  1.0  3.6  87808 37732 ?        S    12:47   0:13 /usr/sbin/apache2 -k start
www-data 31094  0.4  2.6  84192 27052 ?        S    12:55   0:03 /usr/sbin/apache2 -k start
www-data 31095  0.4  2.4  82340 24832 ?        S    12:55   0:03 /usr/sbin/apache2 -k start
www-data 31110  1.3  3.4  88064 35340 ?        S    13:03   0:03 /usr/sbin/apache2 -k start
www-data 31117  0.5  1.9  82852 19864 ?        S    13:04   0:01 /usr/sbin/apache2 -k start
www-data 31118  1.4  2.3  82388 24228 ?        S    13:04   0:03 /usr/sbin/apache2 -k start
www-data 31119  0.4  2.3  82336 24320 ?        S    13:04   0:01 /usr/sbin/apache2 -k start
www-data 31127  2.3  2.7  84444 28360 ?        S    13:05   0:03 /usr/sbin/apache2 -k start

_________________
Amateur, eager to learn.
My hematology, oncology, and chemotherapy regimen wiki

yaz,
Do php & mysql have enough ram allocated to them?
Are there any entries in WM's slow-query-log?
Are you seeing any irregular traffic?

MSJ

I appreciate your help. I'll do my best to answer your questions, but please let me know if I'm giving you the wrong information....


In /etc/php5/apache2/php.ini, I have: memory_limit = 64M

In /etc/mysql/my.cnf, I have:

# * Fine Tuning
#
key_buffer              = 16M
max_allowed_packet      = 16M
thread_stack            = 192K
thread_cache_size       = 8
# This replaces the startup script and checks MyISAM tables if needed
# the first time they are touched
myisam-recover         = BACKUP
max_connections        = 200
table_cache            = 64
thread_concurrency     = 8

#
# * Query Cache Configuration
#
query_cache_limit       = 1M
query_cache_size        = 32M
query_cache_type        = 1

I don't know if they're being constrained otherwise.


Yes, it appears so. This wasn't previously enabled, so I went to my.cnf and did:

# Here you can see queries with especially long duration
log_slow_queries        = /var/log/mysql/mysql-slow.log
long_query_time = 2
log-queries-not-using-indexes

Looking at mysql-slow.log, there are lots of entries within a short amount of time, for example (the wiki database is oncdryangorg):

/usr/sbin/mysqld, Version: 5.5.31-0ubuntu0.12.04.1-log ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 140126 14:09:55
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.000446  Lock_time: 0.000161 Rows_sent: 1  Rows_examined: 6
SET timestamp=1390763395;
SELECT count(*) FROM mysql.user WHERE user='root' and password='';
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.150106  Lock_time: 0.000194 Rows_sent: 42  Rows_examined: 143
SET timestamp=1390763395;
select concat('select count(*) into @discard from `',
                    TABLE_SCHEMA, '`.`', TABLE_NAME, '`')
      from information_schema.TABLES where ENGINE='MyISAM';
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.212197  Lock_time: 0.000478 Rows_sent: 0  Rows_examined: 1193
SET timestamp=1390763395;
select count(*) into @discard from `information_schema`.`COLUMNS`;
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.000960  Lock_time: 0.000791 Rows_sent: 0  Rows_examined: 0
SET timestamp=1390763395;
select count(*) into @discard from `information_schema`.`EVENTS`;
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.000943  Lock_time: 0.000724 Rows_sent: 0  Rows_examined: 0
SET timestamp=1390763395;
select count(*) into @discard from `information_schema`.`PARAMETERS`;
# Time: 140126 14:09:56
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.892206  Lock_time: 0.000697 Rows_sent: 0  Rows_examined: 143
SET timestamp=1390763396;
select count(*) into @discard from `information_schema`.`PARTITIONS`;
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.001102  Lock_time: 0.000386 Rows_sent: 0  Rows_examined: 23
SET timestamp=1390763396;
select count(*) into @discard from `information_schema`.`PLUGINS`;
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.000666  Lock_time: 0.000405 Rows_sent: 0  Rows_examined: 1
SET timestamp=1390763396;
select count(*) into @discard from `information_schema`.`PROCESSLIST`;
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.000946  Lock_time: 0.000754 Rows_sent: 0  Rows_examined: 0
SET timestamp=1390763396;
select count(*) into @discard from `information_schema`.`ROUTINES`;
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.006651  Lock_time: 0.000418 Rows_sent: 0  Rows_examined: 0
SET timestamp=1390763396;
select count(*) into @discard from `information_schema`.`TRIGGERS`;
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.006799  Lock_time: 0.000411 Rows_sent: 0  Rows_examined: 0
SET timestamp=1390763396;
select count(*) into @discard from `information_schema`.`VIEWS`;
# Time: 140126 14:10:00
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000539  Lock_time: 0.000188 Rows_sent: 0  Rows_examined: 1
use onc_dryang_org;
SET timestamp=1390763400;
UPDATE /* SiteStatsUpdate::doUpdate PeterYang */  `wiki_site_stats` SET ss_total_views=ss_total_views+1;
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.001931  Lock_time: 0.000525 Rows_sent: 12  Rows_examined: 21
SET timestamp=1390763400;
SELECT /* ResourceLoader::preloadModuleInfo  */  md_module,md_deps  FROM `wiki_module_deps`  WHERE md_module IN ('site',$
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000642  Lock_time: 0.000178 Rows_sent: 11  Rows_examined: 51
SET timestamp=1390763400;
SELECT /* ResourceLoader::preloadModuleInfo  */  mr_resource,mr_timestamp  FROM `wiki_msg_resource`  WHERE mr_resource I$
# Time: 140126 14:10:04
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000321  Lock_time: 0.000152 Rows_sent: 0  Rows_examined: 0
SET timestamp=1390763404;
SELECT /* ChangeTags::listDefinedTags PeterYang */  vt_tag  FROM `wiki_valid_tag`;
# Time: 140126 14:12:58
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000554  Lock_time: 0.000225 Rows_sent: 0  Rows_examined: 0
SET timestamp=1390763578;
SELECT /* Block::newLoad PeterYang */  ipb_id,ipb_address,ipb_by,ipb_by_text,ipb_reason,ipb_timestamp,ipb_auto,ipb_anon_$
# Time: 140126 14:12:59
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000554  Lock_time: 0.000151 Rows_sent: 0  Rows_examined: 21
SET timestamp=1390763579;
SELECT /* ResourceLoader::preloadModuleInfo  */  md_module,md_deps  FROM `wiki_module_deps`  WHERE md_module IN ('jquery$
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000759  Lock_time: 0.000155 Rows_sent: 17  Rows_examined: 51
SET timestamp=1390763579;
SELECT /* MessageBlobStore::getFromDB  */  mr_blob,mr_resource,mr_timestamp  FROM `wiki_msg_resource`  WHERE mr_resource$
# Time: 140126 14:13:49
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000526  Lock_time: 0.000191 Rows_sent: 0  Rows_examined: 0
SET timestamp=1390763629;
SELECT /* Block::newLoad 64.237.55.3 */  ipb_id,ipb_address,ipb_by,ipb_by_text,ipb_reason,ipb_timestamp,ipb_auto,ipb_ano$
# Time: 140126 14:15:56
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000253  Lock_time: 0.000088 Rows_sent: 0  Rows_examined: 1
SET timestamp=1390763756;
UPDATE /* SiteStatsUpdate::doUpdate 217.69.133.67 */  `wiki_site_stats` SET ss_total_views=ss_total_views+1;
# Time: 140126 14:17:42
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000898  Lock_time: 0.000626 Rows_sent: 0  Rows_examined: 7
SET timestamp=1390763862;
CREATE /* ViewCountUpdate::collect PeterYang */ TEMPORARY TABLE `wiki_acchits` ENGINE=HEAP  AS SELECT hc_id,COUNT(*) AS $
# Time: 140126 14:17:43
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.003027  Lock_time: 0.000122 Rows_sent: 0  Rows_examined: 4
SET timestamp=1390763863;
UPDATE /* ViewCountUpdate::collect PeterYang */ `wiki_page`,`wiki_acchits` SET page_counter=page_counter + hc_n WHERE pa$
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000246  Lock_time: 0.000090 Rows_sent: 0  Rows_examined: 1
SET timestamp=1390763863;
UPDATE /* SiteStatsUpdate::doUpdate PeterYang */  `wiki_site_stats` SET ss_total_views=ss_total_views+1;
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000584  Lock_time: 0.000176 Rows_sent: 11  Rows_examined: 51
SET timestamp=1390763863;
SELECT /* ResourceLoader::preloadModuleInfo  */  mr_resource,mr_timestamp  FROM `wiki_msg_resource`  WHERE mr_resource I$
# Time: 140126 14:18:22
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000285  Lock_time: 0.000102 Rows_sent: 0  Rows_examined: 1
SET timestamp=1390763902;
UPDATE /* SiteStatsUpdate::doUpdate 217.69.133.84 */  `wiki_site_stats` SET ss_total_views=ss_total_views+1;
# Time: 140126 14:18:24
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000265  Lock_time: 0.000095 Rows_sent: 0  Rows_examined: 1
SET timestamp=1390763904;
UPDATE /* SiteStatsUpdate::doUpdate 217.69.133.217 */  `wiki_site_stats` SET ss_total_views=ss_total_views+1;
# Time: 140126 14:18:50
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000474  Lock_time: 0.000173 Rows_sent: 0  Rows_examined: 0
SET timestamp=1390763930;
SELECT /* Block::newLoad 204.152.200.42 */  ipb_id,ipb_address,ipb_by,ipb_by_text,ipb_reason,ipb_timestamp,ipb_auto,ipb_$
# Time: 140126 14:23:49
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000477  Lock_time: 0.000180 Rows_sent: 0  Rows_examined: 0
SET timestamp=1390764229;
SELECT /* Block::newLoad 95.211.87.85 */  ipb_id,ipb_address,ipb_by,ipb_by_text,ipb_reason,ipb_timestamp,ipb_auto,ipb_an$
# Time: 140126 14:25:55
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.001025  Lock_time: 0.000751 Rows_sent: 0  Rows_examined: 9
SET timestamp=1390764355;
CREATE /* ViewCountUpdate::collect 217.69.133.85 */ TEMPORARY TABLE `wiki_acchits` ENGINE=HEAP  AS SELECT hc_id,COUNT(*)$
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.002450  Lock_time: 0.000123 Rows_sent: 0  Rows_examined: 6
SET timestamp=1390764355;
UPDATE /* ViewCountUpdate::collect 217.69.133.85 */ `wiki_page`,`wiki_acchits` SET page_counter=page_counter + hc_n WHER$
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000260  Lock_time: 0.000106 Rows_sent: 0  Rows_examined: 1
SET timestamp=1390764355;
UPDATE /* SiteStatsUpdate::doUpdate 217.69.133.85 */  `wiki_site_stats` SET ss_total_views=ss_total_views+1;
# Time: 140126 14:28:01
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000247  Lock_time: 0.000084 Rows_sent: 0  Rows_examined: 1
SET timestamp=1390764481;
UPDATE /* SiteStatsUpdate::doUpdate 209.107.208.158 */  `wiki_site_stats` SET ss_total_views=ss_total_views+1;
# Time: 140126 14:28:42
# User@Host: oncdryangorg[oncdryangorg] @ localhost []
# Query_time: 0.000227  Lock_time: 0.000070 Rows_sent: 0  Rows_examined: 1
SET timestamp=1390764522;
UPDATE /* SiteStatsUpdate::doUpdate 157.55.35.109 */  `wiki_site_stats` SET ss_total_views=ss_total_views+1;
# Time: 140126 14:28:43
# User@Host: oncdryangorg[oncdryangorg] @ localhost []

I don't know what to make of this, and the query time & lock times don't seem to be that long to me. I don't understand why these requests necessarily ended up in this log given the parameters in my.cnf/


Not really (based on looking at Apache's access.log and error.log). It's a site with modest traffic. Being a public wiki, there are some attempts for automated spammers to sign up and post spam, but I have a decent captcha in place, and any accounts need to be manually approved to get any editing rights, so there's minimal harm done.

I forgot to mention that I've seen a "system will be checked for errors at next reboot" message at least once, and it performed the equivalent of a chkdsk at the next reboot; not sure if bad sectors or disk issues is something I need to be worried about.

_________________
Amateur, eager to learn.
My hematology, oncology, and chemotherapy regimen wiki

FYI I updated to MySQL to 5.5.35. The site subjectively feels a little faster, but the objective response times aren't much better.

I believe the default innoDB buffer pool size is only 128MB, so I increased it by editing my.cnf and adding:

innodb_buffer_pool_size=512M
innodb_additional_mem_pool_size=20M

_________________
Amateur, eager to learn.
My hematology, oncology, and chemotherapy regimen wiki

Update: This appeared to be an issue with one of my VPS neighbors hogging resources or an issue with the host, since speeds have returned to what they used to be after migration to another Newark host.

My Linode had pretty poor results on a PHP benchmark script, which I've started a thread about here.

--------------------------------------
|        PHP BENCHMARK SCRIPT        |
--------------------------------------
Start : 2014-01-29 01:23:13
Server : @
PHP version : 5.3.10-1ubuntu3.9
Platform : Linux
--------------------------------------
test_math                 : 10.459 sec.
test_stringmanipulation   : 15.231 sec.
test_loops                : 7.115 sec.
test_ifelse               : 5.976 sec.
--------------------------------------
Total time:               : 38.781 sec.

If the issue was with CPU resources being hogged, could I have misinterpreted how this is reported in Longview? There, my CPU usage is consistently <10%, so I didn't think that I was running into any CPU limitations. But perhaps the stats are averaged over a period of time? So, if I go to 100% for 10 seconds, but for 90 other seconds I'm basically at 0%, I guess it'll report 10% usage instead of making me aware of the actual limiting spike?

_________________
Amateur, eager to learn.
My hematology, oncology, and chemotherapy regimen wiki