httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Dean Gaudet <>
Subject Re: SIGPIPE handling
Date Mon, 09 Feb 1998 04:14:51 GMT
On Mon, 9 Feb 1998, Brian Havard wrote:

> On Sun, 8 Feb 1998 19:03:34 -0800 (PST), Dean Gaudet wrote:
> >I'm not sure how well we can do in general.  Consider pipelined
> >connections -- we log a success even before we've flushed the last write.
> >Without affecting performance, we'd have to queue "completed" requests
> >until their last byte is written onto the net, and then do the logging.
> >(This could be considered a bug, it didn't occur to me until today
> >though.)
> This also messes with the %T value (time taken to serve request). I often see
> values of 0 for this on small requests even even though it would be
> impossible (EG I've seen logged a 9k GIF down my 14.4k SLIP link in less than
> a second. I don't think so...).

In the normal case the final write() (or writev()) to the client has
already occured at this point, and the kernel has returned essentially
saying "sure, that's done".  Then the logging happens.  It looks like this
in a trace:

open("/home/dgaudet/ap/apachen/htdocs/12k", O_RDONLY) = 4
mmap(0, 12288, PROT_READ, MAP_PRIVATE, 4, 0) = 0x113000
writev(3, [{"HTTP/1.1 200 OK\r\nDate: Mon, 09"..., 246}, {"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
12288}], 2) = 12534
close(4)                                = 0
time(NULL)                              = 886996842
write(17, " - - [08/Feb/1998:20:00"..., 73) = 73

descriptor 17 is the log.  For an HTTP/1.1 persistant pipelined connection
we get this (two requests of /index.html which is 1316 bytes long and
so it fits into our 4k buffer):

open("/home/dgaudet/ap/apachen/htdocs/index.html", O_RDONLY) = 4
mmap(0, 1316, PROT_READ, MAP_PRIVATE, 4, 0) = 0x113000
close(4)                                = 0
write(17, " - - [08/Feb/1998:20:03"..., 79) = 79
munmap(0x113000, 1316)                  = 0
open("/home/dgaudet/ap/apachen/htdocs/index.html", O_RDONLY) = 4
mmap(0, 1316, PROT_READ, MAP_PRIVATE, 4, 0) = 0x113000
close(4)                                = 0
oldselect(4, [3], NULL, NULL, {0, 0})   = 0 (Timeout)
write(3, "HTTP/1.1 200 OK\r\nDate: Mon, 09"..., 3080) = 3080
time(NULL)                              = 886997009
write(17, " - - [08/Feb/1998:20:03"..., 79) = 79

Notice that one log entry is written before any network traffic is
created.  This is a performance improvement -- to decrease network
traffic by building larger packets.

This second case we can certainly do better on.  We add functionality to
BUFF so that we can "hang" a function/data on a byte in the output buffer.
When that byte is written we call the function(data).  So we'd hang
log_transaction(r) on the last byte of a response (well a bit more,
like we would delay the destroy_pool(r->pool) until this point too).
These changes aren't too tough, and if folks want this bug fixed in 1.3
I can do it.

But for cases like the first case we really don't have the information
we need... the kernel doesn't tell us when it has flushed its buffer.


P.S. And yes there's another perceived performance problem here...
while what we do now is certainly great for static files and other
lightweight requests, our pipeline chokes up if a request is expensive.
There is no timer that can cause the buffer to be flushed early, so when
a long running request occurs in the middle of a pipeline it will delay
the last packet of the previous request(s).  Fixing this is more work...
which may be useful work given the existance of some new transparent
proxies that do use pipelining.

View raw message