Re: HAProxy, Apache, Ruby & Server Timeout Errors (sH)

From: Phil Dupont <phild#scoutmob.com>
Date: Fri, 30 Jul 2010 16:33:16 -0400


I guess that's my point... I don't know where else to check. There's nothing between the HAProxy box and the webservers but a switch. Certainly nothing I can get logs from.

If I drill into an example, I end up with nothing. See below for the logs of one scenario I tried to trace. But essentially:

From the HAProxy Log:

Jul 29 20:21:47 localhost haproxy[17405]:

68.174.74.20:55350[29/Jul/2010:20:20:57.478] http_proxy
primary_farm/WS01 4/0/1/-1/50006 504
194 - - sH-- 14/14/14/13/0 0/0 "GET /new-york/howitworks HTTP/1.1"

From the WS01 Apache Log (grep'd on 29/Jul | 68.174.74.20 | howitworks):

68.174.74.20 - - [29/Jul/2010:20:21:31 -0400] "GET /images/counter/counter_small_line.png HTTP/1.1" 200 393 " http://scoutmob.com/new-york/howitworks" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.99 Safari/533.4"
68.174.74.20 - - [29/Jul/2010:20:20:57 -0400] "GET /new-york/howitworks HTTP/1.1" 200 0 "http://scoutmob.com/new-york/deal" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.99 Safari/533.4"
68.174.74.20 - - [29/Jul/2010:20:21:30 -0400] "GET /new-york/howitworks HTTP/1.1" 200 5698 "http://scoutmob.com/new-york/howitworks" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.99 Safari/533.4"
68.174.74.20 - - [29/Jul/2010:20:21:31 -0400] "GET /new-york/unexpired.json HTTP/1.1" 200 43098 "http://scoutmob.com/new-york/howitworks" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_8; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.99 Safari/533.4"

Request-Log-Analyzer against Ruby Log (for the 20:00 to 21:00 hour):

HTTP statuses returned



200 - 3 hits - 100.0% -

Rails action cache hits



No hit - 3 hits - 100.0% -


Request duration - by sum - Hits - Sum - Mean - StdDev - Min -  Max

SessionsController#howitwork - 3 - 0.03s - 0.01s - 0.00s - 0.01s -  0.01s

PhilD

*
*

On Fri, Jul 30, 2010 at 3:04 PM, Willy Tarreau <w#1wt.eu> wrote:

> On Fri, Jul 30, 2010 at 02:57:15PM -0400, Phil Dupont wrote:
> > Thanks, I'm certainly on the same page with you... I've certainly run
> into
> > this kind of stuff when there's a run away process and the like.
> >
> > That said, I've run the production log of ruby through their log analysis
> > tool (request-log-analyzer). That tool will chew on the logs and give
> you
> > the min, max, and average load times for any transaction that occurs in
> > Ruby... thing is... I don't see any query with a taking over a few
> seconds.
> >
> >
> > Essentially, from what I can tell, apache is responding within seconds...
> or
> > if it's not, it's not tossing any errors to the access or error logs.

>

> OK, but if you see haproxy report 504, you must check haproxy's logs to
> find what requests experienced those errors, when, after how much time.
> Maybe you'll find that you never see them in apache logs simply because
> the apache process dies after running a loop and cannot log. It's common
> not to find errors on the component which causes them. That's the reason
> why you must first isolate those errors from haproxy's logs, and then
> search them on the other components. If you see that haproxy says that
> apache took 40 seconds while apache says it took 2 seconds on the same
> requests, then you know it's somewhere between the two. But as long as
> you don't have anything to compare, you're in the total darkness.
>

> Willy

>
> Received on 2010/07/30 22:33

This archive was generated by hypermail 2.2.0 : 2010/07/30 22:45 CEST