Apache - sites are slow

Submitted by raptik on Fri, 06/12/2009 - 00:14

Hello, I have problem with slow loading and too long connection time to sites (virtual servers), created in Virtualmin... More: http://www.virtualmin.com/node/9973

Status: 
Closed (fixed)

Comments

Joe's picture
Submitted by Joe on Fri, 06/12/2009 - 00:20 Pro Licensee

You haven't really given us a lot to go on. What kind of application is it? The process count is a little high but not horrifyingly so (that's a decent amount of traffic). What's in the error_log for the virtual server in question?

Anything in dmesg to indicate what's happening?

I'm guessing there's maybe I/O contention. So, increasing memory buffers in MySQL would be a good start (the my-huge.cnf configuration file example gives an good example of what a bigger configuration would look like, and that's the config recommended for 2+GB systems...it's roughly what we use on Virtualmin.com for our Drupal site).

Submitted by raptik on Fri, 06/12/2009 - 00:52

There is running banner exchange script on the server with 100 000 UIPs/day and over 2 000 000 pageviews/day.

There are last rows of error_log file:

[Fri Jun 12 09:09:46 2009] [notice] suEXEC mechanism enabled (wrapper: /usr/sbin /suexec) [Fri Jun 12 09:09:46 2009] [notice] Digest: generating secret for digest authent ication ... [Fri Jun 12 09:09:46 2009] [notice] Digest: done [Fri Jun 12 09:09:47 2009] [notice] mod_python: Creating 4 session mutexes based on 384 max processes and 0 max threads. [Fri Jun 12 09:09:47 2009] [notice] Apache/2.2.3 (CentOS) configured -- resuming normal operations [Fri Jun 12 09:10:07 2009] [error] server reached MaxClients setting, consider r aising the MaxClients setting

MaxClients is set to 384.

dmesg result: (flooded with:) possible SYN flooding on port 80. Sending cookies. printk: 245 messages suppressed. ip_conntrack: table full, dropping packet.

Latest LoadImpact test: http://loadimpact.com/result/www.rapidcpm.info-d332a8df279b919a9710fa622...

Joe's picture
Submitted by Joe on Fri, 06/12/2009 - 00:32 Pro Licensee

So, raise MaxClients like the log says! ;-)

Submitted by raptik on Fri, 06/12/2009 - 00:56

Yes, I tried to increase MaxClients value... I had there 512, 728 and 1024...

with 512,728 it does nothing, no change... (still: server reached MaxClients setting, consider r aising the MaxClients setting)

with 1024 server fell down, because it creates over 1500 processes... And Average CPU load raises up to 600 and more...

Joe's picture
Submitted by Joe on Fri, 06/12/2009 - 00:57 Pro Licensee

OK, so, leave it at 512ish, and then we'll figure out what to do from there.

Have you updated MySQL to have bigger buffers as I mentioned? That'd be a good first step to speeding up requests.

Then we need to figure out what else is going slow and fix it.

Submitted by raptik on Fri, 06/12/2009 - 01:00

Yes MySQL buffers are now bigger... maybe it has to do sth with dmesg flooding errors...

Joe's picture
Submitted by Joe on Fri, 06/12/2009 - 01:10 Pro Licensee

Is MySQL still eating 80% of CPU? That makes me think IO contention is a problem. Vaguely. ;-)

Submitted by raptik on Fri, 06/12/2009 - 06:20

No, mysqld is now "eating" 10-30% of cpu... But site is still loading slowly...

I think that main source of my problems are these errors (dmesg):

possible SYN flooding on port 80. Sending cookies.

and

printk: 245 messages suppressed.

ip_conntrack: table full, dropping packet.

Is there any way, how to solve these errors? How to disable ip_conntrack...?

ronald's picture
Submitted by ronald on Fri, 06/12/2009 - 12:29 Pro Licensee

why disable ip_conntrack? and not raise the value?

track the connections:
sudo cat /proc/sys/net/ipv4/netfilter/ip_conntrack_max
65563

then you can increase it:
sudo nano /etc/sysctl.conf

add the line or change it when it's there:
net.ipv4.netfilter.ip_conntrack_max = 131072

reload sysctl.conf
$sudo sysctl -p

Joe, agree?

Joe's picture
Submitted by Joe on Fri, 06/12/2009 - 12:32 Pro Licensee

Either one works. If you aren't in need of the features it provides, it could be disabled. But, any firewall rules that are based on the state of the connection do need the features it provides...so raising the limit is almost certainly the sane solution.

Joe's picture
Submitted by Joe on Fri, 06/12/2009 - 12:32 Pro Licensee

So, yes, I agree with ronald.

ronald's picture
Submitted by ronald on Fri, 06/12/2009 - 12:33 Pro Licensee

also to see your server’s current tracked connections run:
cat /proc/sys/net/ipv4/netfilter/ip_conntrack_count

Submitted by raptik on Fri, 06/12/2009 - 14:12

Ok, ip_conntrack_max was increased... (error with full table is not showing anymore), but site is still loading slowly (longest time takes the first connection - about 3 minutes, every next page reload is faster, but still slow in my eyes - about 10-30 sec)...

Any other idea, how to solve that?

Dmesg still returns console flooded with: possible SYN flooding on port 80. Sending cookies.

Mysqld is still sometimes unaccessible: Can't connect to local MySQL server through socket '/var/lib/mysql/mysql.sock' (11), this error is displaying randomly...

Does anyone know what tthis error means and how to fix it (increasing of mysqld buffers does not help...)?

ronald's picture
Submitted by ronald on Fri, 06/12/2009 - 14:03 Pro Licensee

I went to both sites just now (from the forum thread) and both sites loads below 5 seconds for me. NL to CZ Did you try loading your sites from a different place, a friends house or so? Per haps you also have a local issue.

what about server load? is it acceptable?

Joe's picture
Submitted by Joe on Fri, 06/12/2009 - 14:10 Pro Licensee

Yes, it's actually a lot faster from my neck of the woods in the US. It's not blazing, by any means, but the full page loads in 4.83 seconds, according to Firebug.

There's definite improvement here. So, now it's just a matter of figuring out what else is slowing you down. What's the biggest CPU hog? Is DNS plenty fast for your domains? Is the MySQL database now snappy if you interact with it directly? It might be useful to do further tuning of MySQL. I'm not sure.

Keep checking the logs for clues, as well. We're flying blind without any errors, warnings, etc. from the Apache logs and messages and dmesg.

Joe's picture
Submitted by Joe on Fri, 06/12/2009 - 14:12 Pro Licensee

Oh, and rapidcpm.info loads in well under a second. So, I think Apache can be ruled out now. I'm betting more MySQL tuning is called for.

Submitted by raptik on Fri, 06/12/2009 - 14:17

Actual CPU load: 35.47 (1 min) 50.32 (5 mins) 58.55 (15 mins)

Running processes: 584

First 6 running processes (as you can see mysqld is still using almost 50% of cpu):

2655 mysql 49.5 % /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --pid-f ...

19681 apache 9.2 % /usr/sbin/httpd

8602 apache 1.9 % /usr/sbin/httpd

31210 apache 1.9 % /usr/sbin/httpd

8943 apache 1.4 % /usr/sbin/httpd

22839 apache 1.4 % /usr/sbin/httpd

4379 apache 1.3 % /usr/sbin/httpd

637 apache 1.1 % /usr/sbin/httpd

Joe's picture
Submitted by Joe on Fri, 06/12/2009 - 14:28 Pro Licensee

Yep, you're still working MySQL pretty hard. I'm not at all an expert on tuning MySQL, but that's where we need to be looking, as it's pretty much certainly the source of the sluggishness you're seeing.

Also, does your application support any kind of caching? If so, now would might be the time to turn it on, as it might reduce the load on MySQL a bit. ;-)

Any clues in the /var/log/mysqld.log?

There's also ways to query MySQL for performance information, but I don't know how, off-hand.

Submitted by raptik on Fri, 06/12/2009 - 14:33

mysqld.log is absolutely clear - no errors there, I am going to run slow queries logging, maybe there will be the problem logged...

Submitted by JamieCameron on Fri, 06/12/2009 - 14:50

One thing you should look at is what MySQL commands are running for a long time - they could be slow queries that need optimization. Go to Webmin -> Servers -> MySQL Database -> Database Connections, and see what queries are running. Any that have been executing for more than a few seconds are good candidates for analysis.

Last time I saw an issue like this, the cause was a query on a large table with no indexes, which caused MySQL to do a slow full-table scan. Creating an index on the right column fixed it.

Submitted by raptik on Fri, 06/12/2009 - 14:52

Ok there are queries, that takes 2 or more seconds... any idea how to optimize them?

User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

use e2ads_e2ads;

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 1485554867 BETWEEN start AND end;

Time: 090612 23:37:11 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 973635756 BETWEEN start AND end;

Time: 090612 23:37:21 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 1333086826 BETWEEN start AND end;

Time: 090612 23:38:06 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 0

SELECT COUNT(*) AS count, ad_type, w_popups, w_popunders, loading, approved FROM sites WHERE id='1391' AND user=(SELECT username FROM users WHERE id='683') AND approved!='3' GROUP BY id;

Time: 090612 23:38:32 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3716110494 BETWEEN start AND end;

User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3740567520 BETWEEN start AND end;

Time: 090612 23:40:11 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3396104290 BETWEEN start AND end;

Time: 090612 23:40:17 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 1128660724 BETWEEN start AND end;

Time: 090612 23:40:53 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 0

SELECT COUNT(*) AS count, ad_type, w_popups, w_popunders, loading, approved FROM sites WHERE id='1904' AND user=(SELECT username FROM users WHERE id='1045') AND approved!='3' GROUP BY id;

Time: 090612 23:42:24 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 0 Rows_examined: 0

UPDATE history SET views='28172', earnings='6.0287506' WHERE date='06/12/2009' AND user='ccnever';

Time: 090612 23:42:26 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3733295989 BETWEEN start AND end;

Time: 090612 23:43:21 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3545754491 BETWEEN start AND end;

Time: 090612 23:43:22 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3716110494 BETWEEN start AND end;

Time: 090612 23:45:49 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3716110494 BETWEEN start AND end;

Time: 090612 23:46:19 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3716110494 BETWEEN start AND end;

Time: 090612 23:47:18 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 1921676282 BETWEEN start AND end;

Time: 090612 23:47:21 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 973632872 BETWEEN start AND end;

Time: 090612 23:49:25 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 0 Rows_examined: 0

SET insert_id=1825;

INSERT INTO 24history(date,views,clicks) VALUES('06/12/2009','1','0') ON DUPLICATE KEY UPDATE views = views + 1;

Time: 090612 23:50:24 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3716110494 BETWEEN start AND end;

User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3716110494 BETWEEN start AND end;

Time: 090612 23:50:35 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 2085273925 BETWEEN start AND end;

Time: 090612 23:50:36 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 0

SELECT ad_type FROM sites WHERE id='2007' AND user=(SELECT username FROM users WHERE id='1069');

Time: 090612 23:51:28 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3664264694 BETWEEN start AND end;

Time: 090612 23:51:33 User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 3716110494 BETWEEN start AND end;

User@Host: e2ads[e2ads] @ localhost [] Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 106422

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 1447296545 BETWEEN start AND end;

ronald's picture
Submitted by ronald on Fri, 06/12/2009 - 14:54 Pro Licensee

there is still a dns error. in fact results of my test give back only one dns server (ns.4-web.info).
http://www.squish.net/dnscheck

100.0% of queries will be returned by 89.185.253.9 (ns.4-web.info)

rapidcpm.info. 38400 IN MX 5 mail.rapidcpm.info.
rapidcpm.info. 38400 IN TXT "v=spf1 a mx a:rapidcpm.info ip4:89.185.253.9 ?all"
rapidcpm.info. 38400 IN SOA ns.4-web.info. root.ns.4-web.info. (
1243417640 ; Serial
10800 ; Refresh
3600 ; Retry
604800 ; Expire
38400 ) ; Minimum TTL
rapidcpm.info. 38400 IN NS ns.4-web.info.
rapidcpm.info. 38400 IN A 89.185.253.9

ERROR: One or more of the nameservers listed at the parent servers are not listed as NS records at your nameservers. The problem NS records are:
ns2.4-web.info

Submitted by JamieCameron on Fri, 06/12/2009 - 14:59

I see a large number of "rows examined". Check your ip table and make sure it has indexes on the cc column, and perhaps start and end too.

Submitted by raptik on Fri, 06/12/2009 - 15:08

And the sites are again slow :( I dont know why, but sometimes it is running fast and sometimes it slows down...

And dmesg still answers with: possible SYN flooding on port 80. Sending cookies.

ronald's picture
Submitted by ronald on Fri, 06/12/2009 - 15:17 Pro Licensee

sometimes slow is probably cause the dns has issues. the domain is running on 1 dns server instead of 2

Submitted by raptik on Sat, 06/13/2009 - 03:06

It does not causes DNS setting, because when I try to access direct server IP: http://89.185.253.9/ (when the sites are slow), access to website via this ip is slow too...

And the mysqld process, is still a bit challenging:

2658 mysql 25 0 426m 52m 4352 R 77.8% 1.4% 404:21.53 mysqld

And mysql is still randomly disconnecting users with error: Can't connect to local MySQL server through socket '/var/lib/mysql/mysql.sock' (11)

Any idea, how to optimize these queries ?: http://pastebin.com/f3e3a4411

Thanks a lot.

Submitted by JamieCameron on Sat, 06/13/2009 - 10:13

Did you try creating the indexes that I suggested? The following type of query seems most in needed of indexing :

SELECT cc, cn FROM ip NATURAL JOIN cc WHERE 1947295570 BETWEEN start AND end;

You should be able to go to Webmin -> Servers -> MySQL Database -> your database -> ip and create an index on the cc column. I assume that the ip table has a large number of rows?

Submitted by raptik on Sun, 06/14/2009 - 03:26

yes, but table ip, contains just start, end and ci. Column cc is in cc table, and there is column cc indexed...

Submitted by JamieCameron on Sun, 06/14/2009 - 11:46

Ok, how large is the ip table? If it's big, it may need an index on the 'ci' column.

ronald's picture
Submitted by ronald on Mon, 06/15/2009 - 10:02 Pro Licensee

I have tried the sites in question since yesterday and each time the sites load really fast, as if I run them locally.

is this then fixed?

Joe's picture
Submitted by Joe on Mon, 06/15/2009 - 16:17 Pro Licensee

I'm thinking yes. They're really fast for me too.

raptik, everything looking good to you, now?

Joe's picture
Submitted by Joe on Wed, 06/17/2009 - 17:36 Pro Licensee

I'm gonna call this one fixed, since no new word from raptik in a couple of days.

Let us know if problems persist. Feel free to open a new issue, as well, since we kinda veered way far away from this being an Apache issue (it seems like it never really was an Apache issue, actually).

ronald's picture
Submitted by ronald on Wed, 06/17/2009 - 17:40 Pro Licensee

too bad there's no feedback from raptik cause whatever fixed it, it fixed it good, boy, those sites are fast from where I am.

Joe's picture
Submitted by Joe on Wed, 06/17/2009 - 18:14 Pro Licensee

Hehehe...yeah, they're very zippy. I'm guessing it was all MySQL tuning that did the trick.

Submitted by Issues on Wed, 07/01/2009 - 18:18

Automatically closed -- issue fixed for 2 weeks with no activity.