Profiling tool

This a tool for proof a j2ee application . The first tool is a ServletFilter, this filter log to standard output.
The second part of the tool is a secuence of shell scripts for parsing the filter log and create reports.

Servlet Filter (RequestProfilerFilter.java)
package com.oracle.ar.proftools.web;

//log4j
//import org.apache.log4j.Logger;
//servlet
import javax.servlet.*;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpSession;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.text.DateFormat;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.Calendar;

/**
* Created: Aug 11, 2006, 6:33:12 PM
* Last Modification Date: $Date$
*
* @author maldito_orco (maldito_orco@users.sourceforge.net)
* @version $Revision$
*/
public class RequestProfilerFilter implements Filter {
public static final String RCS_ID = "$Header$";
//private static Logger logger = Logger.getLogger(RequestProfilerFilter.class);

public static final String BLANK = " ";
public static final String LINE_PREFIX = "+++ ";
public static final int LINE_PREFIX_LENGTH = LINE_PREFIX.length();
public static final String NOVALUE = "-";
public static final String REMOTE_USER_PREFIX = "bue/";
public static final int REMOTE_USER_PREFIX_LENGTH = REMOTE_USER_PREFIX.length();
public static final String EXP = "EXP";
public static final String EXPINT = "INT";

private static int concurrent = -1;
private static final Object concurrentMutex = new Object();

private FilterConfig filterConfig = null;
private StringBuffer sb = new StringBuffer();

//
// apache format: [14/Aug/2006:16:29:15 -0300]
private DateFormat df = new SimpleDateFormat("[dd/MMM/yyyy:HH:mm:ss Z]");


public RequestProfilerFilter() {
sb.append(LINE_PREFIX);
}

public void init(FilterConfig filterConfig) throws ServletException {
this.filterConfig = filterConfig;
}

public void destroy() {
filterConfig = null;
}

public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
//
// calculate concurrent
int thisConcurrency;
synchronized(concurrentMutex) {
thisConcurrency = ++concurrent;
}
//
// get now (Date)
Date now = Calendar.getInstance().getTime();
//
// get time after execution
long begin = System.currentTimeMillis();
//
// process request
String exception = NOVALUE;
try {
filterChain.doFilter(servletRequest,servletResponse);
} catch (IOException e) {
exception = EXP;
throw e;
} catch (ServletException e) {
exception = EXP;
throw e;
} finally {
//
// get time after execution
long end = System.currentTimeMillis();
String URI = null;
String method = null;
String protocol = null;
String user = null;
String sessionid = null;
try {
//
// get request info
HttpServletRequest httpServletRequest = (HttpServletRequest)servletRequest;
URI = httpServletRequest.getRequestURI();
method = httpServletRequest.getMethod();
protocol = httpServletRequest.getProtocol();
//
// get response info
//HttpServletResponse httpServletResponse = (HttpServletResponse)servletResponse;
//httpServletResponse.
//
// get user
user = httpServletRequest.getRemoteUser();
if (user==null)
user = NOVALUE;
else
if (user.startsWith(REMOTE_USER_PREFIX))
user = user.substring(REMOTE_USER_PREFIX_LENGTH).toUpperCase();
//
// get sessionid
HttpSession session = httpServletRequest.getSession(false);
if (session!=null)
sessionid = session.getId();
else
sessionid = NOVALUE;
} catch (Exception e) {
exception =EXPINT;
}
//
// print results (like apache format)
// 167.252.7.177 - FLTOMASZ [14/Aug/2006:16:29:16 -0300] "GET /BaseCero2007/images/burbujas.jpg HTTP/1.1" 200 2709
//
// clear buffer
if (sb.length()>=LINE_PREFIX_LENGTH)
sb.delete(LINE_PREFIX_LENGTH,sb.length());
//
// add user
sb.append(user);
sb.append(BLANK);
//
// add date
sb.append(df.format(now));
sb.append(BLANK);
//
// add request
sb.append("\"");
sb.append(method);
sb.append(" ");
sb.append(URI);
sb.append(" ");
sb.append(protocol);
sb.append("\" ");
//
// process millis
sb.append(end-begin);
sb.append(BLANK);
//
// begin millis
sb.append(begin);
sb.append(BLANK);
//
// end millis
sb.append(end);
sb.append(BLANK);
//
// concurrency
sb.append(thisConcurrency);
sb.append(BLANK);
//
// sessionid
sb.append(sessionid);
sb.append(BLANK);
//
// exception
sb.append(exception);
//
// print log
System.out.println(sb.toString());
//
// decrement concurrent
synchronized(concurrentMutex) {
--concurrent;
}
}
}
}


Master Shell Script
#!/bin/bash
#
. /home/oracle/bin/setEnvMt10gR2.sh

APPNAME=BaseCero2007

HOST=`hostname | awk -F"." ' { print $1 }'`
DATE=`date +%Y%m%d`
DATEALL=`date +%Y%m%d%H%M%S`
DATELS=`date +'%b %d'`
BASE_DIR=/Backup/monitoreo/logs
DIR=$BASE_DIR/$DATE


if [ ! -d "$DIR" ]
then
mkdir $DIR
fi

if [ ! -d "$DIR/opmn" ]
then
mkdir $DIR/opmn
fi

if [ ! -d "$DIR/apache" ]
then
mkdir $DIR/apache
fi

if [ ! -d "$DIR/oc4j" ]
then
mkdir $DIR/oc4j
fi

if [ ! -d "$DIR/app" ]
then
mkdir $DIR/app
fi
##
##
# copy and clear log opmn
cp -v $ORACLE_HOME/opmn/logs/OC4J~OC4J_$APPNAME~default_island~1 $DIR/opmn/$HOST.$DATEALL.OC4J~OC4J_$APPNAME~default_island~1
echo > $ORACLE_HOME/opmn/logs/OC4J~OC4J_$APPNAME~default_island~1

##
##
# copy log apache
for i in `ls -ltr $ORACLE_HOME/Apache/Apache/logs | grep "$DATELS" | awk '{ print $9 }'`
do
cp -v $ORACLE_HOME/Apache/Apache/logs/$i $DIR/apache/$HOST.$DATEALL.$i
done

##
##
# copy and clear log oc4j
for i in `ls $ORACLE_HOME/j2ee/OC4J_$APPNAME/log/OC4J_"$APPNAME"_default_island_1`
do
if [ -f $ORACLE_HOME/j2ee/OC4J_$APPNAME/log/OC4J_"$APPNAME"_default_island_1/$i ]
then
cp -v $ORACLE_HOME/j2ee/OC4J_$APPNAME/log/OC4J_"$APPNAME"_default_island_1/$i $DIR/oc4j/$HOST.$DATEALL.$i
echo > $ORACLE_HOME/j2ee/OC4J_$APPNAME/log/OC4J_"$APPNAME"_default_island_1/$i
fi
done

##
##
# copy and clear log app
cp -v $ORACLE_HOME/j2ee/OC4J_$APPNAME/application-deployments/"$APPNAME"APP/OC4J_"$APPNAME"_default_island_1/"$APPNAME"-OC4J-APP.log $DIR/app/$HOST.$DATEALL."$APPNAME"-OC4J-APP.log
echo > $ORACLE_HOME/j2ee/OC4J_$APPNAME/application-deployments/"$APPNAME"APP/OC4J_"$APPNAME"_default_island_1/"$APPNAME"-OC4J-APP.log

##
##
# runs stats
$BASE_DIR/stats.sh $DATE


Stats Shell Script (stats.sh)
#!/bin/sh
#

if [ ! $1 ]; then
echo "usage stats.sh YYYYMMDD"
echo "sample: dorank.sh 20060801"
exit 0
fi

if [ ! $ORACLE_HOME ]; then
echo "Please set ORACLE_HOME "
exit 0
fi

if [ -d "$DIR" ]
then
rm -rf $DIR/stats
fi

DATE=$1
BASE_DIR=/Backup/monitoreo/logs
DIR=$BASE_DIR/$DATE

if [ ! -d "$DIR" ]
then
echo "Directory not exists $DIR"
exit 0
fi

if [ -d "$DIR/stats" ]
then
rm -rf $DIR/stats
fi
mkdir $DIR/stats

for i in `ls $DIR/opmn`
do
##
## extraccion del log del oracle-proftool
cat $DIR/opmn/$i | $BASE_DIR/filter-proftool.sh > $DIR/stats/$i.proftool
# generar req x action
cat $DIR/stats/$i.proftool | $BASE_DIR/dorank.sh > $DIR/stats/$i.req_x_action
# generar actions
cat $DIR/stats/$i.req_x_action | awk '{ print $2 }' | awk 'BEGIN { FS="/" } { print $3 }' > $DIR/stats/$i.actions
# generar stat x action
$BASE_DIR/dorankext.sh $DIR/stats/$i.proftool $DIR/stats/$i.actions > $DIR/stats/$i.stat_x_action
# generar req x ususrio
cat $DIR/stats/$i.proftool | awk '{ print $4}' | sort | uniq -c > $DIR/stats/$i.req_x_user
# generar concurrent rank
cat $DIR/stats/$i.proftool | awk '{ print $13}' | sort -n | uniq -c > $DIR/stats/$i.concurrent_rank

##
## extracion del log del GC
cat $DIR/opmn/$i | $BASE_DIR/filter-jvmgc.sh > $DIR/stats/$i.gc
done


Stats AWK Script (stats.awk)
BEGIN {
total=0;
avg=0;
max1=0;
max2=0;

ni=0;
}

{
if (ni==0) {
# Me
nme=nnr/2;
if(nme<1) nme="1;
# Q1
nq1=nnr/4;
if(nq1<1) nq1="1;
# Q3
nq3=(3*nnr)/4;
if(nq3<1) nq3="1;
# P10
np10=(9*nnr)/10;
if(np10<1) np10="1;
}
++ni;
total+=$10;
#
# Me
if(ni>=nme && ni<(nme+1)) me=$10
#
# Q1
if(ni>=nq1 && ni<(nq1+1)) q1=$10
#
# Q3
if(ni>=nq3 && ni<(nq3+1)) q3=$10
#
# P10
if(ni>=np10 && ni<(np10+1)) p10=$10
#
# maxs
if (max1<$10) {
max2=max1;
max1=$10
}
else {
if(max2<$10) {
max2=$10
}
}
}

END {
avg=total/NR;
print $8,NR,total,avg,max1,max2,nq1,q1,nme,me,nq3,q3,np10,p10
}


ServlterFilter Log Filter Shell Script (filter-proftool.sh)
#!/bin/sh
#
grep -e "^[0-9][0-9]/[0-9][0-9]/[0-9][0-9] [0-9][0-9]:[0-9][0-9]:[0-9][0-9] +++ [A-Za-z0-9-]* \[[0-9][0-9]/[A-Z][a-z][a-z]/[0-9]\{4\}:[0-9][0-9]:[0-9][0-9]:[0-9][0-9] [-+][0-9]\{4\}\] \"[A-Z]\{3,4\} /[A-Za-z0-9/._-]* HTTP/1.1\" [0-9]* [0-9]* [0-9]* [0-9]* [A-Za-z0-9-]* [A-Z-]\{1,3\}"


Garbage Collector Log Filter Shell Sctipt (filter-jvmgc.sh)
#!/bin/bash
#
grep -e "K->"


Ranking Shell Script (dorank.sh)
#!/bin/sh
#
awk '{ print $8 }' | grep '/BaseCero' | sort | uniq -c | sort -n


Ranking Extendido Shell Script (dorankext.sh)
#!/bin/sh
#

ACTIONS=`cat $2`

for i in $ACTIONS
do
#echo Procesing $i
grep "/$i" $1 > $1.$i
sort -n --key=10 $1.$i > $1.$i.sort
NNR=`wc -l $1.$i.sort | awk '{print $1}'`
#echo 'awk -f ./stats.awk nnr='$NR' $1.$i.sort'
awk -f ./stats.awk nnr=$NNR $1.$i.sort
#cat $1 | grep "/$i" | awk 'BEGIN { total=0; avg=0; max1=0; max2=0 } { total+=$10; if (max1<$10){max2=max1;max1=$10} else { if(max2<$10){max2=$10} } } END { avg=total/NR; print $8,NR,total,avg,max1,max2 }'
done


Report Shell Script (viewstat.sh)
(printf "REQUEST FR TOTAL(ms) AVG(ms) MAX1(ms) MAX2(ms) #Q1 Q1(ms) #ME ME(ms) #Q3 Q3(ms) #P10 P10(ms)\n"; cat $1/stats/*.stat_x_action | sort -n --key=3) | column -t