You are viewing a plain text version of this content. The canonical link for it is here.
Posted to apache-bugdb@apache.org by Dean Gaudet <dg...@arctic.org> on 1999/04/22 04:40:00 UTC
Re: os-linux/4268: Performance drops off after high specweb loads on highperformance-conf-dist (fwd)
The following reply was made to PR os-linux/4268; it has been noted by GNATS.
From: Dean Gaudet <dg...@arctic.org>
To: apbugs@apache.org
Cc: Subject: Re: os-linux/4268: Performance drops off after high specweb loads on highperformance-conf-dist (fwd)
Date: Wed, 21 Apr 1999 19:31:51 -0700 (PDT)
---------- Forwarded message ----------
Date: Thu, 22 Apr 1999 02:45:13 +0000
From: Karthik Prabhakar <ka...@corp.hp.com>
To: dgaudet@apache.org
Cc: apache-bugdb@apache.org, prab@cs.purdue.edu
Subject: Re: os-linux/4268: Performance drops off after high specweb loads on highperformance-conf-dist
dgaudet@apache.org wrote:
>
> Synopsis: Performance drops off after high specweb loads on highperformance-conf-dist
>
> State-Changed-From-To: open-feedback
> State-Changed-By: dgaudet
> State-Changed-When: Tue Apr 20 09:52:08 PDT 1999
> State-Changed-Why:
> Can you strace the children and see what they're doing?
> Specifically use "strace -r -T" so that we can see where
> time is being spent.
>
> Do the children grow in size?
>
> Does this happen on a redhat 5.2 system? (I don't like getting
> reports from beta versions of anything... especially something
> like glibc 2.1)
>
> Dean
I finally got a hold of a redhat 5.2 / glibc2.1 system running a
stock 2.2.5 kernel, and replicated the problem. Attached is a
tcpdump, as well as a strace of the httpd processes.
>From the strace, it appears that the read() from the socket is
taking a bit of time, as well as the flock(). I might
conclude that this could be a linux problem, except that killing
& restarting the apache process fixes the problem. Besides, the
problem does not occur with other web server's I've tried.
Again, I've only managed to make this happen on the
highperformance-conf.dist config file, and not on the default
apache httpd.conf file.
Do you think I need to bring this up on the linux-kernel list?
thanks!
karthik
tcpdump:18:17:06.539084 15.54.164.205.2284 > 15.5.2.41.80: S 570626839:570626839(0) win 8192 <mss 1460> (DF) (ttl 126, id 5983)
18:17:06.539135 15.5.2.41.80 > 15.54.164.205.2284: S 2713308169:2713308169(0) ack 570626840 win 0 <mss 1460> (DF) (ttl 64, id
25657)
18:17:06.539979 15.54.164.205.2284 > 15.5.2.41.80: . ack 1 win 8760 (DF) (ttl 126, id 6239)
18:17:09.544373 15.54.164.205.2284 > 15.5.2.41.80: . 1:2(1) ack 1 win 8760 (DF) (ttl 126, id 6495)
18:17:09.544414 15.5.2.41.80 > 15.54.164.205.2284: . ack 1 win 32120 (DF) (ttl 64, id 25658)
18:17:09.545829 15.54.164.205.2284 > 15.5.2.41.80: P 1:267(266) ack 1 win 8760 (DF) (ttl 126, id 6751)
18:17:09.545871 15.5.2.41.80 > 15.54.164.205.2284: . ack 267 win 31854 (DF) (ttl 64, id 25659)
18:17:09.547965 15.5.2.41.80 > 15.54.164.205.2284: . 1:1461(1460) ack 267 win 32120 (DF) (ttl 64, id 25660)
18:17:09.744598 15.54.164.205.2284 > 15.5.2.41.80: . ack 1461 win 8760 (DF) (ttl 126, id 7007)
18:17:09.744643 15.5.2.41.80 > 15.54.164.205.2284: . 1461:2921(1460) ack 267 win 32120 (DF) (ttl 64, id 25661)
18:17:09.744653 15.5.2.41.80 > 15.54.164.205.2284: . 2921:4381(1460) ack 267 win 32120 (DF) (ttl 64, id 25662)
[...... uninteresting stuff deleted ......]
18:17:10.620546 15.5.2.41.80 > 15.54.164.205.2284: . 128481:129941(1460) ack 267 win 32120 (DF) (ttl 64, id 25748)
18:17:10.625721 15.54.164.205.2284 > 15.5.2.41.80: . ack 128481 win 1460 (DF) (ttl 126, id 21855)
18:17:10.645192 15.54.164.205.2284 > 15.5.2.41.80: . ack 129941 win 4380 (DF) (ttl 126, id 22111)
18:17:10.645237 15.5.2.41.80 > 15.54.164.205.2284: P 129941:131401(1460) ack 267 win 32120 (DF) (ttl 64, id 25749)
18:17:10.645246 15.5.2.41.80 > 15.54.164.205.2284: . 131401:132861(1460) ack 267 win 32120 (DF) (ttl 64, id 25750)
18:17:10.645256 15.5.2.41.80 > 15.54.164.205.2284: P 132861:134287(1426) ack 267 win 32120 (DF) (ttl 64, id 25751)
18:17:10.650327 15.54.164.205.2284 > 15.5.2.41.80: . ack 132861 win 1460 (DF) (ttl 126, id 22367)
18:17:10.669796 15.54.164.205.2284 > 15.5.2.41.80: . ack 134287 win 4414 (DF) (ttl 126, id 22623)
18:17:10.693746 15.54.164.205.2284 > 15.5.2.41.80: . ack 134287 win 8760 (DF) (ttl 126, id 22879)
18:17:26.757288 15.5.2.41.80 > 15.54.164.205.2284: F 134287:134287(0) ack 267 win 32120 (DF) (ttl 64, id 25752)
18:17:26.758424 15.54.164.205.2284 > 15.5.2.41.80: . ack 134288 win 8760 (DF) (ttl 126, id 23647)
strace:
[pid 376] 0.000000 flock(18, LOCK_EX <unfinished ...>
[pid 375] 0.000203 flock(18, LOCK_EX <unfinished ...>
[pid 374] 0.000071 flock(18, LOCK_EX <unfinished ...>
[pid 373] 0.000068 flock(18, LOCK_EX <unfinished ...>
[pid 296] 0.000068 flock(18, LOCK_EX <unfinished ...>
[pid 282] 0.000068 flock(18, LOCK_EX <unfinished ...>
[pid 281] 0.000068 flock(18, LOCK_EX <unfinished ...>
[pid 280] 0.000068 flock(18, LOCK_EX <unfinished ...>
[pid 279] 0.000068 flock(18, LOCK_EX <unfinished ...>
[pid 278] 0.000090 accept(15, <unfinished ...>
[pid 277] 0.000105 select(0, NULL, NULL, NULL, {0, 610000}) = 0 (Timeout) <0.604967>
[pid 277] 0.605065 time(NULL) = 924743824 <0.000015>
[pid 277] 0.000111 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000018>
[pid 277] 0.000106 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999685>
[pid 277] 0.999778 time(NULL) = 924743825 <0.000016>
[pid 277] 0.000093 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000018>
[pid 277] 0.000112 select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[pid 278] 0.783613 <... accept resumed> {sin_family=AF_INET, sin_port=htons(2284), sin_addr=inet_addr("15.54.164.205")},
[16]) = 3 <2.388926>
[pid 278] 0.000340 flock(18, LOCK_UN <unfinished ...>
[pid 279] 0.000108 <... flock resumed> ) = 0 <2.389484>
[pid 279] 0.000062 accept(15, <unfinished ...>
[pid 278] 0.000068 <... flock resumed> ) = 0 <0.000197>
[pid 278] 0.000057 sigaction(SIGUSR1, {SIG_IGN}, {0x80581b0, [], SA_STACK|0x77c5c}) = 0 <0.000017>
[pid 278] 0.000261 getsockname(3, {sin_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("15.5.2.41")}, [16]) = 0
<0.000021>
[pid 278] 0.000133 setsockopt(3, IPPROTO_TCP, 1, [1], 4) = 0 <0.000020>
[pid 278] 0.000151 read(3, <unfinished ...>
[pid 277] 0.214964 <... select resumed> ) = 0 (Timeout) <0.999700>
[pid 277] 0.000055 time(NULL) = 924743826 <0.000017>
[pid 277] 0.000107 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000016>
[pid 277] 0.000097 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999685>
[pid 277] 0.999779 time(NULL) = 924743827 <0.000016>
[pid 277] 0.000091 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000097 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999717>
[pid 277] 0.999812 time(NULL) = 924743828 <0.000015>
[pid 277] 0.000092 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000016>
[pid 277] 0.000096 select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[pid 278] 0.789548 <... read resumed> "GET /spec/file4000 HTTP/1.0\r\nC"..., 4096) = 266 <3.004643>
[pid 278] 0.000138 sigaction(SIGUSR1, {SIG_IGN}, {SIG_IGN}) = 0 <0.000020>
[pid 278] 0.000224 time(NULL) = 924743829 <0.000015>
[pid 278] 0.000214 stat("/disk2/web/spec/file4000", {st_mode=0, st_size=0, ...}) = 0 <0.000045>
[pid 278] 0.000294 open("/disk2/web/spec/file4000", O_RDONLY) = 4 <0.000033>
[pid 278] 0.000184 mmap(0, 133979, PROT_READ, MAP_PRIVATE, 4, 0) = 0x40136000 <0.000029>
[pid 278] 0.000211 writev(3, [{"HTTP/1.1 200 OK\r\nDate: Thu, 22"..., 307}, {"Number Of Classes: 4\n#\nClass N"...,
32768}], 2) = 33075 <0.000602>
[pid 278] 0.000791 write(3, "action: 1\nAccessType: POISSON\n"..., 32768 <unfinished ...>
[pid 277] 0.208189 <... select resumed> ) = 0 (Timeout) <0.999729>
[pid 277] 0.000059 time(NULL) = 924743829 <0.000015>
[pid 277] 0.000113 wait4(-1, <unfinished ...>
[pid 278] 0.000178 <... write resumed> ) = 32768 <0.208458>
[pid 278] 0.000083 write(3, " 8\nAccess Fraction: 1\nAccessTy"..., 32768 <unfinished ...>
[pid 277] 0.000133 <... wait4 resumed> 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000353>
[pid 277] 0.000077 select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[pid 278] 0.289883 <... write resumed> ) = 32768 <0.289994>
[pid 278] 0.000067 write(3, "Number Range: 0 8\nAccess Fracti"..., 32768) = 32768 <0.228609>
[pid 278] 0.228799 close(4) = 0 <0.000019>
[pid 278] 0.000116 select(4, [3], NULL, NULL, {0, 0}) = 0 (Timeout) <0.000027>
[pid 278] 0.000178 write(3, "et/dir258/class3_\nNumber Range:"..., 2907) = 2907 <0.026451>
[pid 278] 0.026582 munmap(0x40136000, 133979) = 0 <0.000046>
[pid 278] 0.000128 sigaction(SIGUSR1, {0x80581b0, [], SA_STACK|0x4fb76}, {SIG_IGN}) = 0 <0.000018>
[pid 278] 0.000257 read(3, <unfinished ...>
[pid 277] 0.453349 <... select resumed> ) = 0 (Timeout) <0.999265>
[pid 277] 0.000059 time(NULL) = 924743830 <0.000016>
[pid 277] 0.000094 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000099 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999671>
[pid 277] 0.999771 time(NULL) = 924743831 <0.000017>
[pid 277] 0.000108 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000016>
[pid 277] 0.000098 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999693>
[pid 277] 0.999787 time(NULL) = 924743832 <0.000015>
[pid 277] 0.000092 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000097 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999719>
[pid 277] 0.999812 time(NULL) = 924743833 <0.000015>
[pid 277] 0.000090 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000096 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999719>
[pid 277] 0.999813 time(NULL) = 924743834 <0.000015>
[pid 277] 0.000092 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000095 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999719>
[pid 277] 0.999813 time(NULL) = 924743835 <0.000017>
[pid 277] 0.000105 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000098 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999704>
[pid 277] 0.999802 time(NULL) = 924743836 <0.000016>
[pid 277] 0.000093 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000098 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999712>
[pid 277] 0.999805 time(NULL) = 924743837 <0.000015>
[pid 277] 0.000092 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000016>
[pid 277] 0.000096 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999717>
[pid 277] 0.999812 time(NULL) = 924743838 <0.000015>
[pid 277] 0.000092 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000016>
[pid 277] 0.000096 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999717>
[pid 277] 0.999811 time(NULL) = 924743839 <0.000017>
[pid 277] 0.000105 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000098 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999702>
[pid 277] 0.999798 time(NULL) = 924743840 <0.000016>
[pid 277] 0.000091 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000016>
[pid 277] 0.000096 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999727>
[pid 277] 0.999824 time(NULL) = 924743841 <0.000015>
[pid 277] 0.000093 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000016>
[pid 277] 0.000097 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999704>
[pid 277] 0.999799 time(NULL) = 924743842 <0.000016>
[pid 277] 0.000091 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000097 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999716>
[pid 277] 0.999809 time(NULL) = 924743843 <0.000018>
[pid 277] 0.000132 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000098 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999677>
[pid 277] 0.999772 time(NULL) = 924743844 <0.000015>
[pid 277] 0.000092 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000097 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999732>
[pid 277] 0.999860 time(NULL) = 924743845 <0.000015>
[pid 277] 0.000098 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000017>
[pid 277] 0.000099 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999671>
[pid 277] 0.999775 time(NULL) = 924743846 <0.000016>
[pid 277] 0.000089 kill(278, SIGALRM <unfinished ...>
[pid 278] 0.000090 <... read resumed> 0x8077c9c, 4096) = ? ERESTARTSYS (To be restarted) <16.453510>
[pid 278] 0.000058 --- SIGALRM (Alarm clock) ---
[pid 278] 0.000454 sigaction(SIGPIPE, {SIG_IGN}, {0x8057110, [], SA_NOMASK|0x740e2}) = 0 <0.000019>
[pid 278] 0.000240 close(3) = 0 <0.000157>
[pid 278] 0.000245 sigprocmask(SIG_SETMASK, [], NULL) = 0 <0.000016>
[pid 278] 0.000160 sigaction(SIGURG, {0x8057110, [], SA_STACK|0x77c5c}, {0x8057110, [], SA_NOCLDSTOP|0xb5a}) = 0
<0.000018>
[pid 278] 0.000249 sigaction(SIGPIPE, {0x8057110, [], SA_STACK|0x4fb76}, {SIG_IGN}) = 0 <0.000017>
[pid 278] 0.000227 sigaction(SIGALRM, {0x8057380, [], SA_STACK|SA_RESTART|SA_INTERRUPT|SA_ONESHOT|0x7fffbc8}, {0x8057380,
[], SA_STACK|SA_RESTART|SA_INTERRUPT
|SA_ONESHOT|0x7fffba0}) = 0 <0.000017>
[pid 278] 0.000254 sigaction(SIGUSR1, {0x80581b0, [], SA_STACK|0x4fb76}, {0x80581b0, [], SA_STACK|0x77c5c}) = 0
<0.000020>
[pid 278] 0.000351 flock(18, LOCK_EX <unfinished ...>
[pid 277] 0.000067 <... kill resumed> ) = 0 <0.002352>
[pid 277] 0.000060 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000016>
[pid 277] 0.000112 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.997244>
[pid 277] 0.997347 time(NULL) = 924743847 <0.000016>
[pid 277] 0.000093 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000016>
[pid 277] 0.000098 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout) <0.999692>
[pid 277] 0.999793 time(NULL) = 924743848 <0.000016>
[pid 277] 0.000093 wait4(-1, 0xbffffd14, WNOHANG, NULL) = -1 ECHILD (No child processes) <0.000016>
[pid 277] 0.000099 select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>