Site that's become much slower -- MySQL issue?
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 (
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!~~
8 Replies
@Main Street James:
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">http://www.mediawiki.org/wiki/User:AaronSchulz/HowtomakeMediaWiki_fast
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
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
@Main Street James:
yaz,
Do php & mysql have enough ram allocated to them?
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.
> Are there any entries in WM's slow-query-log?
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/
> Are you seeing any irregular traffic?
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.
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
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?