home > general > adding-cpu-stats-to-java-stack-traces

Adding CPU Stats to Java Stack Traces

10 | 08 Aug 2015

UPDATE 2017-01-31:

I've updated this script here:

http://www.mikejonesey.co.uk/general/calculating-psutils-ps-etimes-for-java-threads

CPU Java Stack Traces

Java stack traces include all the information on what process are currently running, and what thier state are. This information can be extented in linux by matching the java thread with the OS thread which can have all sorts of cpu information availible.

Extra CPU Information availble

  • Thread duration (etimes) will show how long the thread has been running for.
  • Major page faults and Minor page faults (maj_flt,min_flt) will give an idea of how often code is being reloaded and reused.
  • CPU Percentage (pcpu), this will show what percentage of the availible cpu is being used by each and every thread.
  • Processor that is currently executing the thread code (sgi_p) this gives an indication of core distribution.

Below is a script that will grab the information required using ps, then match this and update each thread in a java stack trace produced using the jstack tool.

The resulting file will change thread descriptor lines from:

"main" #1 prio=6 os_prio=0 tid=0x00007f26ac00a000 nid=0x2980 runnable [0x00007f26b41f1000]
   java.lang.Thread.State: RUNNABLE

to:

"main" #1 prio=6 os_prio=0 tid=0x00007f26ac00a000 nid=0x2980 pcpu=92.4 core=2 page=364 mpage=12372 secs=13 runnable [0x00007f26b41f1000]
   java.lang.Thread.State: RUNNABLE

Creating Extended Stack Traces

#!/bin/bash
################################################
# take-stacks.sh
# take stack traces with the pcpu mapped to each thread
# this can be used to identify which threads are consuming cpu
# Author        Michael Jones
# Date          07/08/2015
################################################
#

TRACE_COUNT=10
TRACE_INTERVAL=1
JAVA_PID=$(ps -ef | grep java | grep -v grep | tail -1 | awk '{print $2}')
TMP_DIR="/tmp/$(date +"%Y-%m-%d")"

mkdir $TMP_DIR 2>/dev/null

for ((i=0; i<$TRACE_COUNT; i++)); do
  TRACETIME=$(date +"%s")
  jstack -l "$JAVA_PID" > $TMP_DIR/stack-$TRACETIME.out
  EXINF=$(ps -eLo pcpu,lwp,sgi_p,maj_flt,min_flt,etimes,cmd | grep java | grep -v grep | sort -k1,1 -n | while read al; do nid=$(printf "0x%xn" $(echo "$al" | awk '{print $2}')); echo "$nid $al"; done)
  echo "$EXINF" | while read al; do
    NID=$(echo "$al" | awk '{print $1}')
    ESTR="$(echo "$al" | awk '{print "pcpu=" $2 " core=" $4 " page=" $5 " mpage=" $6 " secs=" $7}')"
    sed -i "s/nid=$NID/nid=$NID $ESTR/" $TMP_DIR/stack-$TRACETIME.out
  done
  sleep $TRACE_INTERVAL
done

With the updated stack trace, you will be able to profile average cpu costs of given tasks / isolate high cost process, and even fathom some ideas into where caching could be useful to promote code re-use once in memory.

Update: older ps don't have the option for etimes

#!/bin/bash
################################################
# take-stacks.sh
# take stack traces with the pcpu mapped to each thread
# this can be used to identify which threads are consuming cpu
# Author        Michael Jones
# Date          07/08/2015
################################################
#

TRACE_COUNT=10
TRACE_INTERVAL=1
JAVA_PID=$(ps -ef | grep java | grep -v grep | tail -1 | awk '{print $2}')
TMP_DIR="/tmp/$(date +"%Y-%m-%d")"

mkdir $TMP_DIR 2>/dev/null

for ((i=0; i<$TRACE_COUNT; i++)); do
  TRACETIME=$(date +"%s")
  jstack -l "$JAVA_PID" > $TMP_DIR/stack-$TRACETIME.out
  EXINF=$(ps -eLo pcpu,lwp,sgi_p,maj_flt,min_flt,cmd | grep java | grep -v grep | sort -k1,1 -n | while read al; do nid=$(printf "0x%x" $(echo "$al" | awk '{print $2}')); echo "$nid $al"; done)
  echo "$EXINF" | while read al; do
    NID=$(echo "$al" | awk '{print $1}')
    ESTR="$(echo "$al" | awk '{print "pcpu=" $2 " core=" $4 " page=" $5 " mpage=" $6}')"
    sed -i "s/nid=$NID/nid=$NID $ESTR/" $TMP_DIR/stack-$TRACETIME.out
  done
  sleep $TRACE_INTERVAL
done

Post a Comment