Bug 48169

Summary: two second delay for cgi scripts mixed with mod_jk
Product: Tomcat Connectors Reporter: Troy Bowman <troy>
Component: mod_jkAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: normal    
Priority: P2    
Version: 1.2.28   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description Troy Bowman 2009-11-10 14:13:45 UTC
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
Comment 1 Rainer Jung 2009-11-10 16:10:35 UTC
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.
Comment 2 Troy Bowman 2009-11-11 16:24:45 UTC
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
Comment 3 Mladen Turk 2009-12-21 00:34:01 UTC
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()
Comment 4 Troy Bowman 2010-01-06 16:51:04 UTC
(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?  :)
Comment 5 Rainer Jung 2010-02-23 02:54:09 UTC
Will be part of 1.2.29.