*** WiscMail warning: attached executable file was renamed *** * * Attached to this message is an executable file or an archive * that contains an executable file. The attachment has been * renamed for your protection. * * The file was scanned by the WiscMail anti-virus scanners and * no threat was found. However, executable files should be * treated with great caution. It's possible for viruses to * slip through undetected in the minutes before anti-virus * definitions are published. * * Please confirm with the sender that the file was sent * intentionally, and that the file is safe to run before * renaming the file by removing the "_renamed" from the end of * the filename. * * For more information and support, please visit the following * link to the DoIT Help Desk * * http://kb.wisc.edu/wiscmail/page.php?id=6056 * ********************** end of warning ************************
No problem!
And, before I forget, some additional troubleshooting steps I do if
things get really weird:
I'll create a new folder in /root/dump with today's date, then run the
following commands while I'm in it:
(first, run 'ps aux | grep tomcat' to get the PID for tomcat
(will show up as Java))jstack -l [tomcatpid] >
threaddump[date].txtnetstat -aln | grep tcp | grep -i "close_wait" >
closewait[date].txtlsof | wc -l > lsof[date].txt
Then I'll go into the /root/dump folder and run the command
'java ParseJStack [newdatefolder]/threaddump[date].txt'
and see if anything looks really abnormal (high numbers for I/O Read,
etc.) and see what threads are causing the high counts to see if it
gives me any pointers (high counts are typically over 200 threads; when
we had issues with the LDAP server a while back, the numbers were over
1000 threads waiting for an LDAP connection.)Then I'll tail catalina.out
(/var/log/tomcat) and see if anything
is being reported, and copy catalina.out into the new dump folder that I
created if anything looks potentially useful.I then load the gui
(startx) and kick off JConsole and VisualVM
(shortcuts on root's desktop) and look at the heap utilization graphs to
see if anything's peaking. I also check out the thread graph to see
what the counts look like.
I might add or change the steps I use based on information I find as I
go through the steps and see things that point me in different
directions, but that's the core that I walk through.
More details about the parsejstack stuff:
Found this blog entry:
http://javakenai-dev.cognisync.net/blogs/sdo/faban.sunsource.net (easier
to read:
http://javakenai-dev.cognisync.net/blog/sdo/archive/2009/10/16/fun-jstack
)
The guy wrote a parser for jstack output. I downloaded and compiled the
code, and have it attached to this Jira issue. To run it:
jstack [tomcat_pid] > jstack.out
java ParseJStack jstack.out
The last time myM locked up, I did a thread dump (as I usually do.)
Most of the threads were locked waiting for an I/O read of
com.novell.ldap.asn1.ASN1Identifier.<init>(Unknown) which is in
the ldap.jar library of myM. According to the blog article:
But another problem creeps up in the threads waiting for
I/O read – these are threads that are doing a blocking I/O call (usually
socketRead0 – not accept, which will show up in the jstack parsing as
waiting for I/O accept). This is something else that is hampering your
throughput – the thread is waiting for a backend resource to answer its
request. Most often this is a database – again, you can look at the full
stack in the output to see exactly what the call is. Maybe your app is
making a the same call to a database; if that keeps showing up, its time
to optimize the SQL or tune the database so that call happens faster.
So...it looks like it's time to try to get another LDAP server to handle
the load?
Threads in state Running
1 threads running in
java.net.PlainDatagramSocketImpl.receive0(Native
1 threads running in
sun.nio.ch.EPollArrayWrapper.epollWait(Native
Total Running Threads: 2
Threads in state Blocked by Locks
9 threads running in System Thread
Total Blocked by Locks Threads: 9
Threads in state Waiting for notify
140 threads running in
org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:458)
5 threads running in System Thread
3 threads running in
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662)
1 threads running in
com.novell.ldap.Connection.acquireWriteSemaphore(Unknown
1 threads running in
org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565)
Total Waiting for notify Threads: 150
Threads in state Waiting for I/O read
3911 threads running in
com.novell.ldap.asn1.ASN1Identifier.<init>(Unknown
18 threads running in
org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:735)
8 threads running in
org.apache.jk.common.ChannelSocket.read(ChannelSocket.java:628)
3 threads running in
com.sun.jndi.ldap.Connection.run(Connection.java:849)
Total Waiting for I/O read Threads: 3940
Threads in state Waiting for I/O accept
1 threads running in System Thread
1 threads running in
org.apache.catalina.core.StandardServer.await(StandardServer.java:431)
1 threads running in
org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:311)
1 threads running in
org.apache.tomcat.util.net.jsse.JSSESocketFactory.acceptSocket(JSSESocketFactory.java:178)
Total Waiting for I/O accept Threads: 4
Threads in state Polling
Total Polling Threads: 0
Threads in state Sleeping
1 threads running in
com.novell.webaccess.common.BaseServlet.run(BaseServlet.java:699)
1 threads running in
com.novell.webaccess.common.Log.run(Log.java:760)
1 threads running in
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1631)
1 threads running in
org.apache.catalina.tribes.group.GroupChannel$HeartbeatThread.run(GroupChannel.java:660)
1 threads running in
org.apache.catalina.tribes.membership.McastServiceImpl$SenderThread.run(McastServiceImpl.java:455)
Total Sleeping Threads: 5
Threads in state Unknown (system)
Total Unknown (system) Threads: 0
Total # of VM threads: 9
>>> Bryan Wooten <[email protected]> 08/31/15 3:45 PM >>>
Thanks Chris!
This is really helpful.
Bryan Wooten
Tel: (801)585-9323
Email: [email protected]
From: Christopher Myers [mailto:[email protected]]
Sent: Monday, August 31, 2015 2:35 PM
To: [email protected]; Bryan Wooten
Subject: Re: [cas-user] Hazelcast / Slow CAS
In the past when I've run into things like this, I've started a VNC
session on the server and let jvisualvm watch the tomcat process so that
it could give me statistics on gc activity.
For memory tuning, I spent roughly two months slowly tweaking the
config for our (very active) cluster nodes (which also host our webmail
and campus portal,) and came up with:
-Xms6g -Xmx6g -Xss512k
-Dorg.apache.jasper.runtime.BodyContentImpl.LIMIT_BUFFER=true
-XX:+UseCompressedOops -XX:MaxPermSize=256m -XX:NewRatio=3
-XX:SurvivorRatio=8 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
-XX:+DisableExplicitGC -XX:+UseCMSInitiatingOccupancyOnly
-XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark
-XX:CMSInitiatingOccupancyFraction=68
This routinely ends up with regular minor collections, and very few
major collections even after an extended period of high use.
For additional monitoring, we also have a home-built diagnostics page
(attached) that we run on all of our cluster nodes, polled by our load
balancer. It polls things like used db threads, server connections, ldap
connections, heap size, gc activity, etc. :
15:16pm up 19 days 5:55, 0 users, load average: 0.19, 0.31, 0.31
Connection to PROD ok : connections in use/idle/max: 18/4/25
Connection to Moodle ok : connections in use/idle/max: 1/1/25
Connection to Jira ok : connections in use/idle/max: 1/0/25
Connection to Diebold ok : connections in use/idle/max: 1/1/25
Connection to LDAP on mulinedir1 is ok.
Connection to LDAPS on mulinedir1 is ok.
Connection to LDAP on mulinedir2 is ok.
Connection to LDAPS on mulinedir2 is ok.
Java Heap in use/max: 2140M/5990M
Java non-Heap in use/max: 112M/304M
Number of Java threads: 177
Peak Java threads: 226
Garbage Collection: Copy: 5969
Garbage Collection: ConcurrentMarkSweep: 11
Waiting for I/O accept: org.apache.catalina.core.StandardServer
active internet connections (w/o servers)
proto recv-q send-q local address foreign address state
tcp 9630 0 muwacnode1.millik:60700 muoradbprod.milli:6010 established
tcp 10200 0 muwacnode1.millik:54433 muoradbprod.milli:6010 established
tcp 10200 0 muwacnode1.millik:54433 muoradbprod.milli:6010 establ tcp 0 0
muwacnode1.millik:44428 muoradbprod.milli:6010 established
tcp 0 0 localhost:8009 localhost:40585 established
<snip/>
---------------------------
ESTABLISHED: 104
TIME_WAIT: 42
CLOSE_WAIT: 2
LDAP: 45
LDAPS: 0
HTTP: 0
HTTPS: 3
eDir1 Est: 7
eDir2 Est: 10
Filesystem Size Used Avail Use% Mounted on
/dev/sda4 74G 17G 58G 23% /
udev 4.0G 96K 4.0G 1% /dev
tmpfs 4.0G 0 4.0G 0% /dev/shm
/dev/sda1 92M 21M 66M 25% /boot
/dev/sda3 4.0G 1.6G 2.5G 40% /var
172.16.Y.X:/srv/www/htdocs 26G 8.7G 16G 36% /srv/www/htdocs
172.16.Y.X:/var/export 4.0G 2.0G 1.9G 51% /var/export
172.16.Y.X:/srv/deploy 26G 8.7G 16G 36% /srv/deploy
172.16.Y.X:/mnt/data 26G 8.7G 16G 36% /data
//muoesfile2/data 3.2T 2.6T 610G 81% /mnt/oesfile2
myMILLIKIN project is deployed.
Finally, we run JavaMelody on our cluster nodes as well, which gives
some really good statistics (note that these stats also include our
campus portal and webmail, not just CAS, but you get the idea):
>>> Bryan Wooten <[email protected]> 08/31/15 2:58 PM >>>
Hi all,
So twice in the past few months CAS (3.5.2) has gotten really slow. A
restart of the Tomcat servers makes the issue go away.
There are no errors in either cas.log or catalina.out, it is just
really slow.
Because the issue occurs only in production and not in test I have
never had time to attempt any kind of root cause analysis.
Now our hazelcast is configured to use 85% of heap which is set to
2048meg. We get about 200k logins a day.
I think I may be running into a tomcat/jvm tuning issue (heap size or
garbage collection issue).
Does anyone have suggestions on how I should monitor this or what
config settings for tomcat I should be using/
Thanks,
Bryan Wooten
Tel: (801)585-9323
Email: [email protected]
--
You are currently subscribed to [email protected] as:
[email protected]
To unsubscribe, change settings or access archives, see
http://www.ja-sig.org/wiki/display/JSG/cas-user
--
You are currently subscribed to [email protected] as:
[email protected]
To unsubscribe, change settings or access archives, see
http://www.ja-sig.org/wiki/display/JSG/cas-user
import java.util.*;
import java.io.*;
/**
*
* Parse output from jstack to provide a snapshot of where threads are running
or blocked.
*
* usage: java ParseJStack [ -name threadname ] file1 [file2 ...]
*
* The list of files should be from one or more JDK 6 jstack commands.
*
* The threadname can be used to restrict output to threads that match a
particular pattern.
* For example, in the appserver you can say -name thread-pool-1 to get all
threads in the
* default ORB threadpool. TODO: this should use regular expression pattern
matching; right
* now it simply uses substring matching (indexOf).
*
*/
public class ParseJStack {
static class HashMapValueComparator implements Comparator {
HashMap<String, Integer> hm;
public HashMapValueComparator(HashMap<String, Integer> hm) {
this.hm = hm;
}
public int compare(Object o1, Object o2) {
String s1 = (String) o1;
String s2 = (String) o2;
int i1 = hm.get(s1).intValue();
int i2 = hm.get(s2).intValue();
if (i1 == i2)
return s1.compareTo(s2);
return i2 - i1;
}
public boolean equals(Object o) {
// For this app, we only care if the actual objects are
// the same; we're not comparing hm contents
return hm == o;
}
}
private static Map<String, Integer> getSortedMap(HashMap<String, Integer>
hm) {
TreeMap<String, Integer> tm =
new TreeMap<String, Integer>(new HashMapValueComparator(hm));
Iterator<String> keys = hm.keySet().iterator();
while (keys.hasNext()) {
String s = keys.next();
tm.put(s, hm.get(s));
}
return tm;
}
private static void printTable(HashMap<String, Integer> hm, String title) {
String s;
Map<String, Integer> table = getSortedMap(hm);
Iterator<String> keys = table.keySet().iterator();
System.out.println("Threads in state " + title);
int total = 0;
while (keys.hasNext()) {
s = keys.next();
Integer i = table.get(s);
total += i;
System.out.println("\t" + i + " threads running in " + s);
}
System.out.println("Total " + title + " Threads: " + total);
System.out.println("");
}
private static class JStackParser {
private BufferedReader br;
private int lineNo = 0;
private int vmThreads = 0;
private String curMethodLine;
private StringTokenizer threadTokenizer;
private String fname;
private boolean peeked = false;
public JStackParser(String fname) throws IOException {
this.fname = fname;
br = new BufferedReader(new FileReader(fname));
}
public void close() throws IOException {
br.close();
lineNo = 0;
vmThreads = 0;
threadTokenizer = null;
fname = null;
peeked = false;
}
public String getNextThread() throws IOException {
peeked = false;
String s = br.readLine();
lineNo++;
while (s != null) {
if (!(s.startsWith("\""))) {
s = br.readLine();
lineNo++;
continue;
}
if (s.startsWith("\"Concurrent Mark-Sweep GC Thread")) {
s = br.readLine();
lineNo++;
vmThreads++;
continue;
}
if (restrictThreads && s.indexOf(threadName) < 0) {
s = br.readLine();
lineNo++;
continue;
}
s = br.readLine();
lineNo++;
if (s.equals("")) {
vmThreads++;
continue;
}
break;
}
if (s == null)
return null;
threadTokenizer = new StringTokenizer(s);
threadTokenizer.nextToken(); // java.lang.Thread.State:
return threadTokenizer.nextToken(); // BLOCKED, etc.
}
public String peekCurrentMethod() throws IOException {
curMethodLine = br.readLine();
lineNo++;
peeked = true;
if (curMethodLine.equals(""))
vmThreads++;
return curMethodLine;
}
public String getThreadSubState() {
return threadTokenizer.nextToken();
}
public void insertJavaMethod(HashMap<String, Integer>curTable,
boolean skip) throws IOException {
if (!peeked) {
curMethodLine = br.readLine();
lineNo++;
}
else peeked = false;
if (curMethodLine.equals("")) {
vmThreads++;
return;
}
if (skip) {
skipJavaClasses();
}
updateTable(curTable, curMethodLine);
}
private void skipJavaClasses() throws IOException {
do {
curMethodLine = br.readLine();
lineNo++;
if (curMethodLine.equals(""))
break;
} while ((curMethodLine.indexOf("at java.") > 0) ||
(curMethodLine.indexOf("at ") < 0) ||
(curMethodLine.indexOf("at sun.") > 0));
}
private void updateTable(HashMap<String, Integer> table,
String methodString) {
StringTokenizer tok = new StringTokenizer(methodString);
String method = null;
try {
tok.nextToken(); // at
method = tok.nextToken();
} catch (NoSuchElementException nsee) {
method = "System Thread";
}
Integer i = (Integer) table.get(method);
if (i == null)
i = new Integer(1);
else i = new Integer(i.intValue() + 1);
table.put(method, i);
}
public int getVMThreads() {
return vmThreads;
}
public String toString() {
return "parsing file " + fname + " at line " + lineNo;
}
}
private static String threadName = null;
private static boolean restrictThreads = false;
public static void main(String[] args) throws Exception {
int arg;
int vmThreads = 0;
for (arg = 0; arg < args.length; arg++) {
if (!args[arg].startsWith("-"))
break;
if (args[arg].equals("-name")) {
restrictThreads = true;
threadName = args[++arg];
continue;
}
System.out.println(
"usage: java ParseJStack [-name threadname] file1 ...");
System.exit(-1);
}
HashMap<String, Integer> waitingThreads = new HashMap<String,
Integer>();
HashMap<String, Integer> sleepingThreads = new HashMap<String,
Integer>();
HashMap<String, Integer> runningThreads = new HashMap<String,
Integer>();
HashMap<String, Integer> ioReadThreads = new HashMap<String, Integer>();
HashMap<String, Integer> ioPollThreads = new HashMap<String, Integer>();
HashMap<String, Integer> ioAcceptThreads = new HashMap<String,
Integer>();
HashMap<String, Integer> blockedThreads = new HashMap<String,
Integer>();
HashMap<String, Integer> unknownThreads = new HashMap<String,
Integer>();
while (arg < args.length) {
JStackParser jsp = new JStackParser(args[arg]);
try {
String state = jsp.getNextThread();
while (state != null) {
if (state.equals("BLOCKED")) {
jsp.insertJavaMethod(blockedThreads, true);
}
else if (state.equals("TIMED_WAITING")) {
String subState = jsp.getThreadSubState();
if (subState.equals("(on")) { // )
jsp.insertJavaMethod(waitingThreads, true);
}
else if (subState.equals("(parking)")) {
jsp.insertJavaMethod(blockedThreads, true);
}
else if (subState.equals("(sleeping)")) {
jsp.insertJavaMethod(sleepingThreads, true);
}
else {
throw new IllegalStateException(
"Unknown thread substate while " + jsp);
}
}
else if (state.equals("WAITING")) {
String subState = jsp.getThreadSubState();
if (subState.equals("(parking)")) {
jsp.insertJavaMethod(blockedThreads, true);
}
else if (subState.equals("(on")) { // )
jsp.insertJavaMethod(waitingThreads, true);
}
else {
throw new IllegalStateException(
"Unknown thread substate while " + jsp);
}
}
else if (state.equals("RUNNABLE")) {
String s = jsp.peekCurrentMethod();
if (s.equals("")) {
// VM thread; just get next one
} else if (s.indexOf("socketRead0") > 0) {
jsp.insertJavaMethod(ioReadThreads, true);
} else if (s.indexOf("poll0") > 0) {
jsp.insertJavaMethod(ioPollThreads, true);
} else if (s.indexOf("socketAccept") > 0) {
jsp.insertJavaMethod(ioAcceptThreads, true);
} else {
jsp.insertJavaMethod(runningThreads, false);
}
}
else throw new IllegalStateException(
"Unknown thread state " + state + " while " + jsp);
state = jsp.getNextThread();
}
vmThreads += jsp.getVMThreads();
jsp.close();
arg++;
} catch (Exception e) {
System.out.println("Exception while " + jsp);
e.printStackTrace();
System.exit(-1);
}
}
printTable(runningThreads, "Running");
printTable(blockedThreads, "Blocked by Locks");
printTable(waitingThreads, "Waiting for notify");
printTable(ioReadThreads, "Waiting for I/O read");
printTable(ioAcceptThreads, "Waiting for I/O accept");
printTable(ioPollThreads, "Polling");
printTable(sleepingThreads, "Sleeping");
printTable(unknownThreads, "Unknown (system)");
System.out.println("Total # of VM threads: " + vmThreads);
}
}
ParseJStack.class_renamed
Description: Binary data
