Mailing List Archive

Problem with rotatelogs? high cpu usage
I've been trying to figure out why our web servers have loads of 30-60+ and I
think I just found the culprit: rotatelogs.

Removing rotatelogs the load immediately dropped to 10 and hovered around
10-12. That's actually a reasonable level given my calculations about the
database latency and the number of processes we have.

Why would rotatelogs cause high cpu usage? Does the httpd spin waiting to
acquire some lock on the pipe? Or does the write fail and it keeps retrying?
I don't really believe either of these hypotheses though, and I've run strace
which of course doesn't help much.

Actually, I replaced the |rotatelogs with /dev/null. So it's possible it's
some other portion of the logging code. But it still seems wrong to me that it
would cause high cpu usage.

--
greg
Re: Problem with rotatelogs? high cpu usage [ In reply to ]
According to Greg Stark:
>
> I've been trying to figure out why our web servers have loads of 30-60+ and I
> think I just found the culprit: rotatelogs.
>
> Removing rotatelogs the load immediately dropped to 10 and hovered around
> 10-12. That's actually a reasonable level given my calculations about the
> database latency and the number of processes we have.
>
> Why would rotatelogs cause high cpu usage? Does the httpd spin waiting to
> acquire some lock on the pipe? Or does the write fail and it keeps retrying?
> I don't really believe either of these hypotheses though, and I've run strace
> which of course doesn't help much.
>
> Actually, I replaced the |rotatelogs with /dev/null. So it's possible it's
> some other portion of the logging code. But it still seems wrong to me that it
> would cause high cpu usage.

I use the apache rotatelogs program with hourly rollover and have not
seen anything like that. Something must be failing and spinning in
retries. Are you using lots of separate logfiles for virtual hosts?
A load of 10 is not really a good thing for a web server anyway. This
means your processes are waiting on CPU and unless your programs
are compute-intensive you should be mostly I/O bound. Are you
forking lots of CGI scripts instead of running them under mod_perl
or starting new database backends instead of using Apache::DBI?

Les Mikesell
les@mcs.com
Re: Problem with rotatelogs? high cpu usage [ In reply to ]
Leslie Mikesell <les@mcs.net> writes:

> I use the apache rotatelogs program with hourly rollover and have not
> seen anything like that. Something must be failing and spinning in
> retries. Are you using lots of separate logfiles for virtual hosts?
> A load of 10 is not really a good thing for a web server anyway. This
> means your processes are waiting on CPU and unless your programs
> are compute-intensive you should be mostly I/O bound. Are you
> forking lots of CGI scripts instead of running them under mod_perl
> or starting new database backends instead of using Apache::DBI?

So now the load has gone back up to 60-80 again. So rotatelogs isn't the
problem.

We're using mod_perl, no CGI, using Apache::DBI, database is on another
machine. My own profiling doesn't turn up anything surprising.


--
greg
Re: Problem with rotatelogs? high cpu usage [ In reply to ]
According to Greg Stark:
> Leslie Mikesell <les@mcs.net> writes:
>
> > I use the apache rotatelogs program with hourly rollover and have not
> > seen anything like that. Something must be failing and spinning in
> > retries. Are you using lots of separate logfiles for virtual hosts?
> > A load of 10 is not really a good thing for a web server anyway. This
> > means your processes are waiting on CPU and unless your programs
> > are compute-intensive you should be mostly I/O bound. Are you
> > forking lots of CGI scripts instead of running them under mod_perl
> > or starting new database backends instead of using Apache::DBI?
>
> So now the load has gone back up to 60-80 again. So rotatelogs isn't the
> problem.
>
> We're using mod_perl, no CGI, using Apache::DBI, database is on another
> machine. My own profiling doesn't turn up anything surprising.

If top doesn't show any single process consuming the CPU time chances
are you are forking something off so fast you don't see it. Check
how fast process id's are changing by doing a ps twice and noting
the pid of the ps process itself. Apache 3.6 had a bug where if
you have proxypass enable it forks off a process to clean up the
cache every hit (even if you don't have a cache). Something like
that burns CPU almost invisibly. In a system working normally
top should only show a few programs at a time in 'run' state. If
some are stuck in 'run' you have a bug there.

Les Mikesell
les@mcs.com
Re: Problem with rotatelogs? high cpu usage [ In reply to ]
Update: killing rotatelogs only helped for a short while. the system load is
back up in the 30-65 range.

You describe exactly the situation I see. Every modpelr process has 2-3% cpu
usage. The total is far less than the actual load, leading me to think most of
the system load time consists of disk wait and context switching.

I've straced the processes and I don't see excessive forking. We actually
independently discovered and fixed that bug as I'm sure a lot of admins did.


Leslie Mikesell <les@mcs.net> writes:

> If top doesn't show any single process consuming the CPU time chances
> are you are forking something off so fast you don't see it. Check
> how fast process id's are changing by doing a ps twice and noting
> the pid of the ps process itself. Apache 3.6 had a bug where if
> you have proxypass enable it forks off a process to clean up the
> cache every hit (even if you don't have a cache). Something like
> that burns CPU almost invisibly. In a system working normally
> top should only show a few programs at a time in 'run' state. If
> some are stuck in 'run' you have a bug there.
>
> Les Mikesell
> les@mcs.com
>

--
greg