The following reply was made to PR os-linux/4268; it has been noted by GNATS.
From: Dean Gaudet <[EMAIL PROTECTED]> To: [EMAIL PROTECTED] 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 <[EMAIL PROTECTED]> To: [EMAIL PROTECTED] Cc: apache-bugdb@apache.org, [EMAIL PROTECTED] Subject: Re: os-linux/4268: Performance drops off after high specweb loads on highperformance-conf-dist [EMAIL PROTECTED] 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 ...>