httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jeff Trawick <traw...@gmail.com>
Subject Re: debugging dropped output on v2.2.15
Date Sat, 19 Oct 2013 13:45:56 GMT
On Fri, Oct 18, 2013 at 1:28 PM, Martin Langhoff
<martin.langhoff@gmail.com>wrote:

> Hi all,
>
> I am trying to debug a very strange bug where the apache child takes some
> time to compute the (html) output, but eventually writes it to the fd.
> However, looking at the http stream with wireshark shows that the
> client/server connection never sees that output, it continues to send
> keepalive msgs back and forth.
>
> Apache parent/child communication seems to be broken... but not entirely:
> the child poll()s the fd and gets a new request to process from the parent.
>
> Any hints to narrow this down? Is there a timeout I should be looking for?
> Known parent/child communication issues?
>

I'm not sure what you mean by parent/child, or there's some confusion on
your part.

On Unix, here's the normal parent/child relationship, where parent has
detached from its initial session (e.g., terminal) and has parent pid 1.

1->parent->child1,child2,child3,child4,...

There's no coordinating between parent and child, or childM and childN,
during connection/request handling.

If you're looking at a particular connected socket fd number in different
children then you're looking at unrelated processing/different connections.

Does that help, or did I miss your point?


>
> (mod_php is also involved, but I think this strace mostly absolves it from
> guilt)
>
> chdir("/")                              = 0
> pwrite(17, "SESSION|O:8:\"stdClass\":9:{s:7:\"f"..., 83538, 0) = 83538
> close(17)                               = 0
> write(14, "\1\0\0\0\1", 5)              = 5
> shutdown(14, 2 /* send and receive */)  = 0
> close(14)                               = 0
> close(18)                               = 0
> futex(0x7f3e4273f088, FUTEX_WAIT, 2, NULL) = 0
> futex(0x7f3e4273f088, FUTEX_WAKE, 1)    = 0
> futex(0x7f3e4273f088, FUTEX_WAIT, 2, NULL) = 0
> futex(0x7f3e4273f088, FUTEX_WAKE, 1)    = 0
> futex(0x7f3e4273f088, FUTEX_WAIT, 2, NULL) = 0
> futex(0x7f3e4273f088, FUTEX_WAIT, 2, NULL) = 0
> futex(0x7f3e4273f088, FUTEX_WAKE, 1)    = 0
> umask(022)                              = 0
> setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
> setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={300, 0}}, NULL) = 0
>  brk(0x7f3e7036c000)                     = 0x7f3e7036c000
> brk(0x7f3e6f9ec000)                     = 0x7f3e6f9ec000
> setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
>
>  # here is the writev() to the fd to the parent - >20K which is about
> what we expect
> # this never appears in the network
> writev(12, [{"HTTP/1.1 200 OK\r\nDate: Thu, 17 O"..., 551},
> {"\37\213\10\0\0\0\0\0\0\3", 10},
> {"\355}\353v\3346\362\347\347\370)\220\316f,\317\364E\27\313\311\337\2664+\313v\3429\226\255\261"...,
> 8096},
> {"\365\f[[!\3123\333Z}\220e\330\5\367k6\263=\201h\324\357cW\307\7\324\367\206
> \201"..., 5976}, {"\213\217\210y`\222\2\0", 8}], 5) = 14641
> gettimeofday({1382045277, 805849}, NULL) = 0
> gettimeofday({1382045277, 806019}, NULL) = 0
> gettimeofday({1382045277, 806134}, NULL) = 0
> write(11, "174.61.34.0 - - [17/Oct/2013:16:"..., 274) = 274
> gettimeofday({1382045277, 806555}, NULL) = 0
> times({tms_utime=25626, tms_stime=5554, tms_cutime=0, tms_cstime=0}) =
> 1363113295
> gettimeofday({1382045277, 807014}, NULL) = 0
> poll([{fd=12, events=POLLIN}], 1, 1000) = 0 (Timeout)
> gettimeofday({1382045278, 809332}, NULL) = 0
> gettimeofday({1382045278, 809465}, NULL) = 0
> shutdown(12, 1 /* send */)              = 0
>
> # done - and now polling for the next req
> poll([{fd=12, events=POLLIN}], 1, 2000) = 0 (Timeout)
> close(12)                               = 0
> read(7, 0x7fffc30697df, 1)              = -1 EAGAIN (Resource temporarily
> unavailable)
> gettimeofday({1382045280, 822223}, NULL) = 0
> semop(9207812, {{0, -1, SEM_UNDO}}, 1)  = 0
> epoll_wait(9, {{EPOLLIN, {u32=1752040504, u64=139906016740408}}}, 2,
> 10000) = 1
> accept(4, {sa_family=AF_INET6, sin6_port=htons(55341), inet_pton(AF_INET6,
> "::ffff:24.190.105.161", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0},
> [28]) = 12
> fcntl(12, F_GETFD)                      = 0
> fcntl(12, F_SETFD, FD_CLOEXEC)          = 0
> semop(9207812, {{0, 1, SEM_UNDO}}, 1)   = 0
> gettimeofday({1382045287, 803986}, NULL) = 0
> getsockname(12, {sa_family=AF_INET6, sin6_port=htons(80),
> inet_pton(AF_INET6, "::ffff:204.13.103.195", &sin6_addr), sin6_flowinfo=0,
> sin6_scope_id=0}, [28]) = 0
> fcntl(12, F_GETFL)                      = 0x2 (flags O_RDWR)
> fcntl(12, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
> gettimeofday({1382045287, 804351}, NULL) = 0
> gettimeofday({1382045287, 804470}, NULL) = 0
> gettimeofday({1382045287, 804538}, NULL) = 0
> read(12, "GET /theme/javascript.php/tri/13"..., 8000) = 443
>
> Naturally, this repros only in a busy production environment.
>
> thanks,
>
>
>
> m
> --
>  martin.langhoff@gmail.com
>  -  ask interesting questions
>  - don't get distracted with shiny stuff  - working code first
>  ~ http://docs.moodle.org/en/User:Martin_Langhoff
>



-- 
Born in Roswell... married an alien...
http://emptyhammock.com/

Mime
View raw message