Am 23.02.2015 um 22:53 schrieb Jesse Defer:
-----Original Message-----
Am 23.02.2015 um 19:03 schrieb Jesse Defer:
I have a farm of Apache httpd servers proxying to Tomcat with mod_jk and
I am having issues with Apache processes getting stuck (as seen by the W
state in server-status). I am sending to this list because the stack
traces show httpd gets stuck in mod_jk.
httpd is configured for prefork and with 512 servers on start and
maximum. When the problem occurs we end up with nearly all 512 processes
in the W state until we restart it. The problem occurs more often when
load is high but is not restricted to high load. The problem started
occuring more often when we increased the servers from 384 to 512. The
hosts have enough memory and do not swap. The issue occurs intermitently
and is not tied to a particular host or instance Tomcat (there are ~150
Tomcat instances). The JkShmFile is on tmpfs.
Why on tmpfs?
Not sure, might be because of poor local IO performance (hosts are VMs) or
historic use of network filesystems.
I haven't checked the details, but I don't expect the shared memory
activity to be reflected by FS activity. I don't have an indication,
that tmpfs is a problem for the locking either, but once we run out of
ideas, you could try whether moving away from tmpfs and network
filesystems for the JkShmFile and instead using a path to a local file
for JkShmFile helps.
Environment: RHEL5.11, Apache 2.4.10 (prefork), JK 1.2.40, APR 1.5.1,
APR-UTIL 1.5.4
The stuck httpd processes all show the same stack and strace:
pstack:
#0 0x00002b3439026bff in fcntl () from /lib64/libpthread.so.0
#1 0x00002b3440911656 in jk_shm_lock () from
/usr/local/apache2/modules/mod_jk.so
#2 0x00002b3440917805 in ajp_maintain () from
/usr/local/apache2/modules/mod_jk.so
#3 0x00002b3440906cac in maintain_workers () from
/usr/local/apache2/modules/mod_jk.so
#4 0x00002b3440901140 in wc_maintain () from
/usr/local/apache2/modules/mod_jk.so
#5 0x00002b34408f40b6 in jk_handler () from
/usr/local/apache2/modules/mod_jk.so
#6 0x0000000000448eca in ap_run_handler ()
#7 0x000000000044cc92 in ap_invoke_handler ()
#8 0x000000000045e24f in ap_process_async_request ()
#9 0x000000000045e38f in ap_process_request ()
#10 0x000000000045ab65 in ap_process_http_connection ()
#11 0x00000000004530ba in ap_run_process_connection ()
#12 0x000000000046423a in child_main ()
#13 0x0000000000464544 in make_child ()
#14 0x00000000004649ae in prefork_run ()
#15 0x0000000000430634 in ap_run_mpm ()
#16 0x000000000042ad97 in main ()
So mod_jk tries to get a lock on the shared memory before reading and
updating some shared memory data. That as one of many things mod_jk does
is normal. It would be not normal, if most processes seem to almost always
sit in this stack.
strace:
fcntl(19, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=1}) =
0 fcntl(19, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=1}) =
0
time(NULL) = 1424711498
fcntl(19, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=1}) =
0 fcntl(19, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=1})
= 0 fcntl(19, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0,
len=1}) = 0 fcntl(19, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET,
start=0, len=1}) = 0 fcntl(19, F_SETLKW, {type=F_WRLCK,
whence=SEEK_SET, start=0, len=1}) = 0 fcntl(19, F_SETLKW,
{type=F_UNLCK, whence=SEEK_SET, start=0, len=1}) = 0
Any help tracking this issue down would be appreciated.
This doesn't look like mod_jk is hanging in the jk_shm_lock() but instead
it looks like normal processing, locking and then unlocking.
Locking and unlocking suceeds (return code 0).
You didn't provide time stamps to get an idea, whether it is normal
behavior or not. What is your request throughput (requests per second
forwarded by mod_jk as long as it is running well)?
Next time it happens I will capture timestamps, but it scrolls pretty
quickly and doesn't seem to get hung up on any calls. We have very seasonal
traffic, but normally around 30/sec. The high period peaks at around 200/sec.
OK, strace should be able to print time stamps plus the time that the
call took.
Load around 30/s up to 200/s is not extreme.
I suspect something else is wrong. Have you checked, whether in fact
mod_jk waits for the response from requests it has send to the backend and
which do not return quickly, e.g. looking at a Java thread dump
(not: heap dump) of the backend during the times you have problems?
I haven't, next time it happens I'll look.
What are the error or warn messages in your mod_jk log file?
Here is one instance of each type of warn/error in the logs of an affected host.
All of these are fairly common but we have tomcats going up and down all the
time and I think most are related to that. Log level is info.
[Mon Feb 23 03:05:37 2015] [25833:47348544151936] [error]
ajp_service::jk_ajp_common.c (2693): (my27) connecting to tomcat failed.
[Mon Feb 23 03:05:39 2015] [25944:47348544151936] [error]
ajp_connect_to_endpoint::jk_ajp_common.c (1050): (ead21) cping/cpong after
connecting to the backend server failed (errno=110)
[Mon Feb 23 03:05:39 2015] [25944:47348544151936] [error]
ajp_send_request::jk_ajp_common.c (1663): (ead21) connecting to backend failed.
Tomcat is probably not started or is listening on the wrong port (errno=110)
[Mon Feb 23 12:59:18 2015] [25927:47348544151936] [error]
ajp_get_reply::jk_ajp_common.c (2176): (dir16) Tomcat is down or refused
connection. No response has been sent to the client (yet)
[Mon Feb 23 14:12:12 2015] [26170:47348544151936] [warn]
ajp_handle_cping_cpong::jk_ajp_common.c (965): awaited reply cpong, received 3
instead. Closing connection
I don't expect those to be consequences of a mod_jk problem. More likely
it is the other way round. How many threads do you have configured for
your AJP connector? Which connector (bio, nio, apr) do you use for Tomcat?
How many Apache web servers sit in front of the Tomcats? Is each of the
Apaches configured with 512 processes?
Did you use "apachectl graceful" shortly before the problems start, or
change configuration via the mod_jk status worker?
No.
What is special here, is the use of many processes plus many workers. So
the lock is used quite a lot. Still the "global maintain" functionality
which uses the jk_shm_lock() in the stack above should be called by each
process only every worker.maintain seconds, by default every 60 seconds.
And each project should quickly detect whether another process already did
the global maintain. During the global maintain, for any ajp13 worker
there is really just a few simply local code statements. For any lb (load
balancer) worker, there is a little more to do, especialy checking whether
any members have failed long ago and should now be recovered. ut still
those operations are all local, not going on the network.
What is your workr struture? Are the 150 workers part of few load
balancers or are they all in the worker.list? Can you show significant
parts of your workers.properties? Are you using the non-default
"pessimistic" locking?
I misspoke, we have ~150 applications so that would be the load balancer
count. Total worker count between all the LBs would be ~700. We are using
the default locking. Here is one LB:
# 109t
worker.109t1.port=62037
worker.109t1.host=java1
worker.109t1.type=ajp13
worker.109t1.lbfactor=1
worker.109t1.connection_pool_timeout=539
worker.109t1.socket_keepalive=true
worker.109t1.ping_mode=CP
worker.109t1.ping_timeout=5000
worker.109t1.redirect=109t2
worker.109t2.reference=worker.109t1
worker.109t2.host=java2
worker.109t2.redirect=109t3
worker.109t3.reference=worker.109t1
worker.109t3.host=java3
worker.109t3.redirect=109t4
worker.109t4.reference=worker.109t1
worker.109t4.host=java4
worker.109t4.redirect=109t1
worker.109tlb.type=lb
worker.109tlb.balance_workers=109t1,109t2,109t3,109t4
worker.109tlb.sticky_session=true
And only the lb is added to the worker.list? Or also the individual AJP
workers?
If your Apache uses a threaded APR library, you could try using
JkWatchdogInterval. That moved the maintenance from the normal request
processing code to a separate thread per Apache process.
I suspect that once your app (one or some of your apps) gets slow,
requests pile up in Apache and >Apache can no longer connect to Tomcat,
because it doesn't have free threads. Some Apache children still can
connect, because the connect is handled by the OS underneath Tomcat, but
those connections do not get the awaited cping reply.
In addition to the Thread Dumps, you should also activate GC-Logs for
your Tomcat JVMs.
- using the worker or prefork MPM in combination with JkWatchdogInterval would
reduce the amount of shm locking due to global maintenance calls, because it
is done per process, not per thread. You might have other reasons for using
prefork though. Have you?
Use of prefork is historical. We have been looking at going to event, but
Haven't made the switch yet.
If you are using many Apaches each with 512 children, you will most
likely need to use an NIO connector on the Tomcat processes and would
also benefit from worker or event MPM for Apache. Each process e.g. with
50 or 100 threads and a relatively short connection_pool_timeout like
e.g. 60 seconds.
What was the reason, that you started suspecting the fcntl() underneath
jk_shm_lock? Are we sure, that the stack you provided is really the
typical one? And was the strace dumping all system calls or only the
fcntl calls?
Regards,
Rainer
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
