httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Dean Gaudet <dgau...@arctic.org>
Subject some buff.c tuning
Date Mon, 04 Aug 1997 09:45:56 GMT
Here's a bunch of straces where I'm refining some of the buff.c code in
1.3.  I've got a cgi, written in C, that does write (1, "x", 1) 17000
times.  I'm making an HTTP/1.1 request against it so that the response is
chunked.  Here's a strace from it, edited. 

# httpd reads from the CGI for the first time.
read(6, "Content-Type: text/html\r\n\r\nx"..., 4096) = 4096
alarm(0)                                = 300
alarm(300)                              = 0
alarm(0)                                = 300

# shift into non-blocking mode
fcntl(6, F_SETFL, O_RDONLY|O_NONBLOCK)  = 0
alarm(300)                              = 0

# first write includes headers, and a big whack of 'x's, this is large_write
# in action assembling this writev
writev(3, [{"HTTP/1.1 200 OK\r\nDate: Mon, 04"..., 154}, {"fe5\r\n", 5}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"...,
4069}, {"\r\n", 2}], 4) = 4230
alarm(300)                              = 300

# next read from CGI
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 4096

# no writev used here, so this ~4k was memcpy'd ... which is a manifestation
# of that bug Roy just pointed out in my "obscure chunking error" patch
write(3, "ffb\r\nxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4098) = 4098
alarm(300)                              = 300
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 4096

# the first 5 are left overs from the last memcpy'd hunk, the rest is
# large_write in action
writev(3, [{"5  \r\nxxxxx\r\n", 12}, {"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"...,
4096}, {"\r\n", 2}], 4) = 4116
alarm(300)                              = 300
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 4096
--- SIGCHLD (Child exited) ---

# Roy's bug again
write(3, "ffb\r\nxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4098) = 4098
alarm(300)                              = 300
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 616
alarm(300)                              = 300
read(6, "", 8192)                       = 0
alarm(0)                                = 300
close(6)                                = 0
alarm(300)                              = 0
read(8, "", 4096)                       = 0
alarm(0)                                = 300
close(8)                                = 0
alarm(300)                              = 0
alarm(0)                                = 300
time(NULL)                              = 870685293
time(NULL)                              = 870685293
write(16, "127.0.0.1 - - [04/Aug/1997:02:01"..., 78) = 78
time(NULL)                              = 870685293
gettimeofday({870685293, 851127}, NULL) = 0
times({tms_utime=3, tms_stime=1, tms_cutime=2, tms_cstime=0}) = 384087
alarm(30)                               = 0

# This is expected, but bizarre behaviour.  This is the final bflush()
# being called, which happens after the log is written, when the client
# closes its connection (or when it notices that the client has no request
# pending).  Note that this is unfortunately a little burp
# in our possible performance (i.e. the log write might delay for a hostname
# lookup)... but we can't flush without screwing up pipelined behaviour.
# We could do our test select() earlier ...
#
# This probably explains the behaviour where you're surfing and it starts
# downloading a file, gets essentially 100% done and then PAUSES... it's
# blocked doing a host lookup while you wait for your final packet.
write(3, "26d\r\nxxxxxxxxxxxxxxxxxxxxxxxxx"..., 633) = 633

--------------------------------

Ok here we go again, using my suggested fix for Roy's bug (move start_chunk
into bflush()).  I haven't ported my entire patch to 1.3 yet, just this
one part.

read(6, "Content-Type: text/html\r\n\r\nx"..., 4096) = 4096
writev(3, [{"HTTP/1.1 200 OK\r\nDate: Mon, 04"..., 154}, {"fe5\r\n", 5}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"...,
4069}, {"\r\n", 2}], 4) = 4230
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 4096
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 4096
writev(3, [{"", 0}, {"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n",
2}], 4) = 4104
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 4096
--- SIGCHLD (Child exited) ---
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 616
read(6, "", 8192)                       = 0
write(16, "127.0.0.1 - - [04/Aug/1997:02:10"..., 79) = 79
write(3, "268\r\nxxxxxxxxxxxxxxxxxxxxxxxxx"..., 628) = 628

Much more clean ... but a cute bug there with the 0 length iov.

--------------------------------

Fix the 0 length iov bug (and another sent_bytes bug! I suck.).

read(6, "Content-Type: text/html\r\n\r\nx"..., 4096) = 4096
writev(3, [{"HTTP/1.1 200 OK\r\nDate: Mon, 04"..., 154}, {"fe5\r\n", 5}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"...,
4069}, {"\r\n", 2}], 4) = 4230
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 4096
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 4096
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 4096
--- SIGCHLD (Child exited) ---
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
read(6, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 8192) = 616
read(6, "", 8192)                       = 0
write(16, "127.0.0.1 - - [04/Aug/1997:02:16"..., 80) = 80
write(3, "268\r\nxxxxxxxxxxxxxxxxxxxxxxxxx"..., 628) = 628

--------------------------------

So does anyone think we should fix that flush after log?  It's another
refinement of the B_SAFEREAD stuff...  I whipped up something and here's
a nice trace, just the writes, from a pipelined keepalive connection
asking for the 17000 `x' CGI twice:

writev(3, [{"HTTP/1.1 200 OK\r\nDate: Mon, 04"..., 135}, {"fe5\r\n", 5}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"...,
4069}, {"\r\n", 2}], 4) = 4211
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
write(16, "127.0.0.1 - - [04/Aug/1997:02:39"..., 80) = 80
writev(3, [{"268\r\nxxxxxxxxxxxxxxxxxxxxxxxxx"..., 782}, {"fe5\r\n", 5}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"...,
4069}, {"\r\n", 2}], 4) = 4858
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
writev(3, [{"1000\r\n", 6}, {"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096}, {"\r\n", 2}], 3)
= 4104
write(3, "268\r\nxxxxxxxxxxxxxxxxxxxxxxxxx"..., 628) = 628
write(16, "127.0.0.1 - - [04/Aug/1997:02:39"..., 80) = 80

Note the two log writes (descriptor 16).  The first case doesn't have a 
flush before it because there's still a request pending on the connection.
But the second case the network socket is flushed before the log write.

Dean


Mime
View raw message