I'm running gentoo linux, kernel 2.6.30. This may be related to bug 37469 and bug 37470, but I'm running mod_jk 1.2.28 (apache 2.2.11) which is supposed to have the fix for that and I still seem to have a related symptom: a two-second delay on a cgi script when tomcat isn't going to handle it. Static files are fine, it's just cgi scripts that seem to be affected. The symptoms are much like the previously mentioned bugs. If I hit a tomcat-handled uri first, then subsequent requests to any (simple) cgi-script (perl, ruby, etc) which don't use mod_jk takes exactly two seconds seemingly waiting for mod_jk to finish its pre-processing. If I turn off mod_jk, the cgi script runs in milliseconds. If I don't hit the tomcat-handled uri first, the cgi-script is also run in milliseconds. I ran an strace on the fork of apache that was doing this; I've marked the place where the 2-second delay happened with "======>": <... epoll_wait resumed> {{EPOLLHUP, {u32=136451400, u64=136451400}}}, 2, 300000) = 1 <0.000745> read(19, ""..., 8000) = 0 <0.000005> read(21, 0xbfc7c420, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000006> poll([{fd=21, events=POLLIN}], 1, 300000) = 1 ([{fd=21, revents=POLLHUP}]) <0.000012> read(21, ""..., 1) = 0 <0.000005> close(21) = 0 <0.000009> read(14, 0x8222188, 8000) = -1 EAGAIN (Resource temporarily unavailable) <0.000006> write(9, "10.49.220.36 - - [10/Nov/2009:10:"..., 71) = 71 <0.000024> close(16) = 0 <0.000007> close(17) = 0 <0.000008> close(19) = 0 <0.000007> waitpid(9331, 0xbfc825f0, WNOHANG|WSTOPPED) = 0 <0.000006> kill(9331, SIGTERM) = -1 EPERM (Operation not permitted) <0.000006> kill(9331, SIGKILL) = -1 EPERM (Operation not permitted) <0.000005> waitpid(9331, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WSTOPPED) = 9331 <0.000021> --- SIGCHLD (Child exited) @ 0 (0) --- poll([{fd=14, events=POLLIN}], 1, 15000) = 1 ([{fd=14, revents=POLLIN}]) <0.008233> read(14, "GET /styles/screen.css HTTP/1.1\r\n"..., 8000) = 659 <0.000007> gettimeofday({1257875417, 523164}, NULL) = 0 <0.000005> stat64("/var/lib/tomcat-*/webapps//styles", 0xbfc824b0) = -1 ENOENT (No such file or directory) <0.000009> stat64("/home/troy/public_html/styles/screen.css", {st_mode=S_IFREG|0644, st_size=2400, ...}) = 0 <0.000010> open("/home/troy/public_html/.htaccess", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000009> open("/home/troy/public_html/styles/.htaccess", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000008> open("/home/troy/public_html/styles/screen.css/.htaccess", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOTDIR (Not a directory) <0.000008> open("/home/troy/public_html/styles/screen.css", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 16 <0.000010> fcntl64(16, F_GETFD) = 0x1 (flags FD_CLOEXEC) <0.000005> fcntl64(16, F_SETFD, FD_CLOEXEC) = 0 <0.000005> close(16) = 0 <0.000006> writev(14, [{"HTTP/1.1 304 Not Modified\r\nDate: "..., 172}], 1) = 172 <0.000018> read(14, 0x821c170, 8000) = -1 EAGAIN (Resource temporarily unavailable) <0.000006> write(9, "10.49.220.36 - - [10/Nov/2009:10:"..., 86) = 86 <0.000012> poll([{fd=14, events=POLLIN}], 1, 15000) = 1 ([{fd=14, revents=POLLIN}]) <3.503299> read(14, "GET /styles/print.css HTTP/1.1\r\nH"..., 8000) = 658 <0.000008> gettimeofday({1257875421, 27117}, NULL) = 0 <0.000005> stat64("/var/lib/tomcat-*/webapps//styles", 0xbfc824b0) = -1 ENOENT (No such file or directory) <0.000011> stat64("/home/troy/public_html/styles/print.css", {st_mode=S_IFREG|0644, st_size=2340, ...}) = 0 <0.000010> open("/home/troy/public_html/.htaccess", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000010> open("/home/troy/public_html/styles/.htaccess", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000008> open("/home/troy/public_html/styles/print.css/.htaccess", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOTDIR (Not a directory) <0.000009> open("/home/troy/public_html/styles/print.css", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 16 <0.000010> fcntl64(16, F_GETFD) = 0x1 (flags FD_CLOEXEC) <0.000006> fcntl64(16, F_SETFD, FD_CLOEXEC) = 0 <0.000005> close(16) = 0 <0.000007> writev(14, [{"HTTP/1.1 304 Not Modified\r\nDate: "..., 172}], 1) = 172 <0.000029> read(14, 0x8220180, 8000) = -1 EAGAIN (Resource temporarily unavailable) <0.000007> write(9, "10.49.220.36 - - [10/Nov/2009:10:"..., 85) = 85 <0.000018> poll([{fd=14, events=POLLIN}], 1, 15000) = 1 ([{fd=14, revents=POLLIN}]) <3.844867> read(14, "GET / HTTP/1.1\r\nHost: gargamel.so"..., 8000) = 551 <0.000008> gettimeofday({1257875424, 872759}, NULL) = 0 <0.000004> stat64("/home/troy/public_html/", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000010> open("/home/troy/public_html/.htaccess", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000010> stat64("/var/lib/tomcat-*/webapps//index.rb", 0xbfc823b0) = -1 ENOENT (No such file or directory) <0.000009> stat64("/home/troy/public_html/index.rb", {st_mode=S_IFREG|0755, st_size=5138, ...}) = 0 <0.000009> open("/home/troy/public_html/index.rb", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 16 <0.000014> fcntl64(16, F_GETFD) = 0x1 (flags FD_CLOEXEC) <0.000006> fcntl64(16, F_SETFD, FD_CLOEXEC) = 0 <0.000005> read(16, "#!/usr/bin/ruby\n\nrequire 'cgi'\nre"..., 4096) = 4096 <0.000008> pipe([17, 18]) = 0 <0.000009> fcntl64(18, F_GETFL) = 0x1 (flags O_WRONLY) <0.000005> fcntl64(18, F_SETFL, O_WRONLY|O_NONBLOCK) = 0 <0.000005> fcntl64(18, F_GETFD) = 0 <0.000006> fcntl64(18, F_SETFD, FD_CLOEXEC) = 0 <0.000005> pipe([19, 20]) = 0 <0.000008> fcntl64(19, F_GETFL) = 0 (flags O_RDONLY) <0.000005> fcntl64(19, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000005> fcntl64(19, F_GETFD) = 0 <0.000005> fcntl64(19, F_SETFD, FD_CLOEXEC) = 0 <0.000005> pipe([21, 22]) = 0 <0.000007> fcntl64(21, F_GETFL) = 0 (flags O_RDONLY) <0.000006> fcntl64(21, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000006> fcntl64(21, F_GETFD) = 0 <0.000006> fcntl64(21, F_SETFD, FD_CLOEXEC) = 0 <0.000005> clone(Process 9334 attached child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7c9b958) = 9334 <0.000256> [pid 4536] close(17) = 0 <0.000006> [pid 4536] close(20) = 0 <0.000005> [pid 4536] close(22) = 0 <0.000006> [pid 4536] close(18 <unfinished ...> [pid 9334] close(4) = 0 <0.000011> [pid 4536] <... close resumed> ) = 0 <0.000033> [pid 9334] close(3 <unfinished ...> [pid 4536] SYS_329(0x80000, 0x821c1a0, 0xb7e56ff4, 0x821a280, 0x82234d0 <unfinished ...> [pid 9334] <... close resumed> ) = 0 <0.000020> [pid 4536] <... SYS_329 resumed> ) = 17 <0.000017> [pid 9334] close(9 <unfinished ...> [pid 4536] epoll_ctl(17, EPOLL_CTL_ADD, 19, {EPOLLIN, {u32=136459600, u64=136459600}} <unfinished ...> [pid 9334] <... close resumed> ) = 0 <0.000024> [pid 4536] <... epoll_ctl resumed> ) = 0 <0.000017> [pid 9334] close(8 <unfinished ...> [pid 4536] epoll_ctl(17, EPOLL_CTL_ADD, 21, {EPOLLIN, {u32=136459632, u64=136459632}} <unfinished ...> [pid 9334] <... close resumed> ) = 0 <0.000024> [pid 4536] <... epoll_ctl resumed> ) = 0 <0.000019> [pid 9334] close(7) = 0 <0.000006> [pid 4536] epoll_wait(17, <unfinished ...> [pid 9334] munmap(0xb802a000, 1024) = 0 <0.000010> [pid 9334] close(11) = 0 <0.000005> [pid 9334] close(12) = 0 <0.000006> [pid 9334] unlink("/var/log/apache2/mod_jk.shm.4529.lock") = -1 ENOENT (No such file or directory) <0.000011> [pid 9334] unlink("/var/log/apache2/mod_jk.shm.4529") = -1 ENOENT (No such file or directory) <0.000008> [pid 9334] time(NULL) = 1257875424 <0.000006> [pid 9334] shutdown(15, 1 /* send */) = 0 <0.000007> ======> [pid 9334] select(16, [15], NULL, NULL, {2, 0}) = 0 (Timeout) <2.002357> [pid 9334] close(15) = 0 <0.000009> [pid 9334] close(6) = 0 <0.000007> [pid 9334] close(5) = 0 <0.000006> [pid 9334] close(13) = 0 <0.000006> [pid 9334] close(14) = 0 <0.000005> [pid 9334] close(21) = 0 <0.000006> [pid 9334] close(19) = 0 <0.000005> [pid 9334] close(18) = 0 <0.000007> [pid 9334] close(16) = 0 <0.000006> [pid 9334] dup2(17, 0) = 0 <0.000007> [pid 9334] close(17) = 0 <0.000006> [pid 9334] dup2(20, 1) = 1 <0.000005> [pid 9334] close(20) = 0 <0.000005> [pid 9334] dup2(22, 2) = 2 <0.000006> [pid 9334] close(22) = 0 <0.000005> [pid 9334] rt_sigaction(SIGCHLD, {SIG_DFL, [], SA_INTERRUPT}, {SIG_DFL, [], 0}, 8) = 0 <0.000006> [pid 9334] chdir("/home/troy/public_html/") = 0 <0.000012> [pid 9334] execve("/usr/sbin/suexec", ["/usr/sbin/suexec", "10060", "100", "index.rb"], [/* 28 vars */]) = 0 <0.000327> [pid 9334] brk(0) = 0x804d000 <0.000006> ...rest of strace ran the ruby script quickly mod_jk.log (again marked with "======>" where the pause happens) [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] map_uri_to_worker_ext::jk_uri_worker_map.c (1036): Attempting to map URI '/' from 8 maps [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/soar*/*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/jmx-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/web-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/manager*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/status*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jnlp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jsp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/Soar*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] jk_translate::mod_jk.c (3450): check alias_dir: /var/lib/tomcat-*/webapps/ [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] map_uri_to_worker_ext::jk_uri_worker_map.c (1036): Attempting to map URI '/' from 8 maps [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/soar*/*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/jmx-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/web-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/manager*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/status*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jnlp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jsp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/Soar*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] jk_map_to_storage::mod_jk.c (3603): no match for / found [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] jk_translate::mod_jk.c (3411): JkAutoAlias, no DirectoryIndex file for URI /index.rb [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] map_uri_to_worker_ext::jk_uri_worker_map.c (1036): Attempting to map URI '/index.rb' from 8 maps [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/soar*/*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/jmx-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/web-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/manager*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/status*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jnlp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jsp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/Soar*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:44.354 2009] [20377:3082942736] [debug] jk_map_to_storage::mod_jk.c (3603): no match for /index.rb found ======>[Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] map_uri_to_worker_ext::jk_uri_worker_map.c (1036): Attempting to map URI '/styles/print.css' from 8 maps [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/soar*/*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/jmx-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/web-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/manager*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/status*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jnlp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jsp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/Soar*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] jk_translate::mod_jk.c (3450): check alias_dir: /var/lib/tomcat-*/webapps/ [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] jk_translate::mod_jk.c (3476): AutoAlias child_dir: print.css [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] map_uri_to_worker_ext::jk_uri_worker_map.c (1036): Attempting to map URI '/styles/print.css' from 8 maps [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/soar*/*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/jmx-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/web-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/manager*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/status*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jnlp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jsp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/Soar*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.433 2009] [20377:3082942736] [debug] jk_map_to_storage::mod_jk.c (3603): no match for /styles/print.css found [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] map_uri_to_worker_ext::jk_uri_worker_map.c (1036): Attempting to map URI '/styles/screen.css' from 8 maps [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/soar*/*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/jmx-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/web-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/manager*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/status*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jnlp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jsp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/Soar*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] jk_translate::mod_jk.c (3450): check alias_dir: /var/lib/tomcat-*/webapps/ [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] jk_translate::mod_jk.c (3476): AutoAlias child_dir: screen.css [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] map_uri_to_worker_ext::jk_uri_worker_map.c (1036): Attempting to map URI '/styles/screen.css' from 8 maps [Tue Nov 10 15:01:46.434 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/soar*/*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.435 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/jmx-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.435 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/web-console*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.435 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/manager*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.435 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/status*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.435 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jnlp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.435 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/*.jsp=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.435 2009] [20377:3082942736] [debug] find_match::jk_uri_worker_map.c (850): Attempting to map context URI '/Soar*=loadbalancer' source 'JkMount' [Tue Nov 10 15:01:46.435 2009] [20377:3082942736] [debug] jk_map_to_storage::mod_jk.c (3603): no match for /styles/screen.css found
Which Linux do you exactly use? The cgi process closes the existing backend connections after start (likely because of CLOEXEC). Since we set SO_LINGER this is done by trying to drain the connection in the tcp layer, which blocks. We need to investigate a better way. I expect we don't set SO_LINGER to prevent the OS from blocking during forked cgi processes and try to handle lingering behaviour during normal worker process shutdown on our own. Additional note: strace/truss also reveals, that the cgi process and also rotatelogs try to close the shm file and its lock. But that's not the cause of the hang here.
The linux distro is Gentoo. Best distro for people who like to drive stick-shift. ;) Thanks to your explanation, I changed the following and the delay indeed completely disappeared. I'm going to use this patch for now on my servers, since I can't stand the 2-second delay. Novice's suggestion: could the SO_LINGER option start as zero and then be modified once mod_jk knows that it is going to do real work? :) --- tomcat-connectors-1.2.28-src/native/common/jk_connect.c.old 2009-11-11 16:49:57.089490502 -0700 +++ tomcat-connectors-1.2.28-src/native/common/jk_connect.c 2009-11-11 16:46:57.583251504 -0700 @@ -640,7 +640,7 @@ #ifndef MAX_SECS_TO_LINGER #define MAX_SECS_TO_LINGER 30 #endif -#define SECONDS_TO_LINGER 2 +#define SECONDS_TO_LINGER 0 #ifndef SHUT_WR #ifdef SD_SEND
Can you check if the http://svn.apache.org/viewvc?rev=892725&view=rev fixes the issue? It uses SOCK_CLOEXEC|FD_CLOEXEC so it should close all sockets on fork()
(In reply to comment #3) > Can you check if the > http://svn.apache.org/viewvc?rev=892725&view=rev > fixes the issue? > > It uses SOCK_CLOEXEC|FD_CLOEXEC so it should close all sockets on fork() Indeed it does. Nice and speedy, no delay. Thanks so much for fixing it! When's the next release? :)
Will be part of 1.2.29.