Performance of log parsing shell script very slow

sowmitr · #1 (**permalink**) 04-08-2009

Hello,
I am an absolute newbie and whatever I've written in the shell script (below) has all been built with generous help from googling the net and this forum. Please forgive any schoolboy mistakes.

Now to the qn, my input file looks like this -

2009:04:03 08:21:41:513,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,Start - SvcName: OIS - EndUserName: - RequestId: null20090403082313
2009:04:03 08:21:41:775,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,End - SvcName: OIS - EndUserName: - RequestId: null20090403082313 - StatusCode: 0 - StatusText: Success
2009:04:03 08:21:45:660,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,Start - SvcName: VCC - EndUserName: - RequestId: 411111111111111120090403082318
2009:04:03 08:21:46:171,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,End - SvcName: VCC - EndUserName: - RequestId: 411111111111111120090403082318 - StatusCode: 0 - StatusText: Success
2009:04:03 08:21:49:583,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,Start - SvcName: CO - EndUserName: - RequestId: 20090403082321
2009:04:03 08:22:03:571,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,End - SvcName: CO - EndUserName: - RequestId: 20090403082321 - StatusCode: 0 - StatusText: Success

From this I have to find out the resp time (start time - end time) for each request id for the SvcName CO. I have written this shell script (not finished though) however the performance is very slow (takes a minute to process a 100 line file). can you please point me in the right direction to improve the performance? Although not the exact subject of this post, if any pointers can be given to calculate the difference between start and end time, it will be quite helpful.

Code:

#!/bin/bash
#script to resptime timings for CO call from logfile
#////////////////////////////////////
#if no command line args
    if [ $# -ne 1 ]
    then
    echo 1>&2"Oops......Usage is wrong. $0 <tgtsrchfile>"
    exit 2
    fi
#assigning command line params to variables
srchFN=$1
#remove resptime.log if already present
checkfile="./resptime.log"
tempfile="./temp.log"
tempfile1="./temp1.log"
    if [ -e $checkfile ];then
    rm -r $checkfile
    fi
    if [ -e $tempfile ];then
        rm -r $tempfile
    fi
    if [ -e $tempfile1 ];then
        rm -r $tempfile1
    fi
    #if keywordfile not present
    if [ ! -r $srchFN ]; then
    echo Target search file $srchFN not present
    exit 2
    fi
#grep for request id
        grep 'Start.*CO' $srchFN | awk -F "RequestId: " '{print $2}'>temp.log
#for each request id get starttime and end time and print into temp file
        cat temp.log | while read line; do
        #if string is empty
        if [ -n $line ];then
        sttime=`grep Start.*CO.*$line $srchFN | awk -F "," '{print $1}'|awk -F " " '{print $2}'`
        endtime=`grep End.*CO.*$line $srchFN | awk -F "," '{print $1}'|awk -F " " '{print $2}'`
            if [ -n "$sttime" -o -n "$endtime" ];then
            echo $line,$sttime,$endtime>>temp1.log
            fi
        fi        
        done;
        
#/////////////////////////////////////

Thanks in advance

quirkasaurus · #2 (**permalink**) 04-08-2009

something wrong with this line, no delimiter specified:

Code:

grep 'Start.*CO' $srchFN | awk -F "RequestId: " '{print $2}'>temp.log

should be something like:

Code:

grep 'Start.*CO' $srchFN | awk -F, "RequestId: " '{print $2}'>temp.log

it looks like the problem is you're rereading the whole $srchFN for every line
of your temp.log twice through those grep commands.

You'll need to reformat your logic so that these extra greps are NOT even done.

Try to rethink things so that you know what you're looking for while only
reading the file once.

sowmitr · #3 (**permalink**) 04-08-2009

Quote:

Originally Posted by quirkasaurus

it looks like the problem is you're rereading the whole $srchFN for every line
of your temp.log twice through those grep commands.

Try to rethink things so that you know what you're looking for while only
reading the file once.

My input file has one line for the start of a request and one for the end of the request. And there are hundreds of unique requests. So I am struggling to think of how else I can get the start and end time with one grep, for each req id...

ghostdog74 · #4 (**permalink**) 04-08-2009

too many greps, too many awks, useless cats....

quirkasaurus · #5 (**permalink**) 04-08-2009

something like this? substitute 'd' for your log file:

Code:

cat d |
while read line ; do

#----------------------------------------------------------------------#
# Start time and service name.                                         #
#----------------------------------------------------------------------#
  if [[ $line = *Service,Start* ]] ; then
    echo $line |
      sed -e 's/^.*SvcName: //' -e 's/ - .*$//' |
      read service_name

    echo $line |
      sed -e 's/,INFO.*$//' |
      read start_time
  fi

#----------------------------------------------------------------------#
# End time.                                                            #
#----------------------------------------------------------------------#
  if [[ $line = *Service,End*SvcName*$svcname*EndUser* ]] ; then
    echo $line |
      sed -e 's/,INFO.*$//' |
      read end_time
  echo start-time $start_time end-time $end_time service-name $service_name
  fi
done

radoulov · #6 (**permalink**) 04-08-2009

I would use Perl to calculate the date and time differences (using an external module Date::Manip):

Code:

#!/usr/bin/perl 

use warnings;
use strict;

use Date::Manip;

my $infile = 'file';

open FH, $infile or die "$infile: $!";

my ( $sdate, $edate, $delta, $err, $ustart, $uend, $rtime );

while (<FH>) {
    if (/SvcName: CO/) {
        /Start -/ and ( $sdate = ( split ',' )[0] ) =~ s|:(.*?):|/$1/|;
        /End -/   and ( $edate = ( split ',' )[0] ) =~ s|:(.*?):|/$1/|;
    }
    if ( $sdate && $edate ) {
        $ustart = UnixDate( $sdate, "%s" );
        $uend   = UnixDate( $edate, "%s" );
        if ($edate) {
            $rtime = $ustart - $uend;
            print $sdate, " - ", $edate, "\n";
            print DateCalc( $sdate, $edate, \$err ), "\n";
        }
    }
}

With your sample data it produces the following output:

Code:

% cat file
2009:04:03 08:21:41:513,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,Start - SvcName: OIS - EndUserName: - RequestId: null20090403082313
2009:04:03 08:21:41:775,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,End - SvcName: OIS - EndUserName: - RequestId: null20090403082313 - StatusCode: 0 - StatusText: Success
2009:04:03 08:21:45:660,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,Start - SvcName: VCC - EndUserName: - RequestId: 411111111111111120090403082318
2009:04:03 08:21:46:171,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,End - SvcName: VCC - EndUserName: - RequestId: 411111111111111120090403082318 - StatusCode: 0 - StatusText: Success
2009:04:03 08:21:49:583,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,Start - SvcName: CO - EndUserName: - RequestId: 20090403082321
2009:04:03 08:22:03:571,INFO ,servername,yyyy,undefined,,INFO,null,.....Out:xxService,End - SvcName: CO - EndUserName: - RequestId: 20090403082321 - StatusCode: 0 - StatusText: Success
zsh-4.3.9[t]% ./s       
2009/04/03 08:21:49:583 - 2009/04/03 08:22:03:571
+0:0:0:0:0:0:14

fpmurphy · #7 (**permalink**) 04-08-2009

Here is another way to solve your problem using ksh93 ....

Code:

#!/usr/bin/ksh93

LOGFILE=./logfile
SVCNAME="CO"

awk -v str="$SVCNAME" -F, '$10 ~ "SvcName: "str {
     split($10, arr1, " ")
     date1=$1
     getline
     date2=$1
     print arr1[4], arr1[9], date1, date2
     next
}' $LOGFILE |  while read svc id sdate stime fdate ftime
do
    sdate1=$(printf '%(%s.%3N)T' "${sdate//:/-} ${stime:0:8}.${stime:9}")
    fdate1=$(printf '%(%s.%3N)T' "${fdate//:/-} ${ftime:0:8}.${ftime:9}")

    diff=$(( fdate1 - sdate1 ))
    idiff=$(( int(diff) ))
    usecs=$(( 1000 * (diff - int(diff)) ))
    secs=$(( idiff % 60 ))
    mins=$(( idiff % (60 * 60) / 60 ))
    hours=$(( idiff / (60 * 60) ))

    printf "%s %s - %s %s +%02d:%02d:%02d.%03d\n"  ${sdate//://} $stime ${fdate//://} $ftime $hours $mins $secs $usecs
done

exit 0

This is the output for your sample file

Code:

2009/04/03 08:21:49:583 - 2009/04/03 08:22:03:571 +00:00:13.988

More UNIX and Linux Forum Topics You Might Find Helpful
Thread	Thread Starter	Forum	Replies	Last Post
FTP run from shell script gives slow transfer rates	Countificus	Shell Programming and Scripting	8	04-07-2009 05:50 PM
Shell script to parsing log	justbow	Shell Programming and Scripting	10	12-06-2008 03:20 PM
egrep is very slow : How to improve performance	hidnana	Shell Programming and Scripting	7	02-12-2008 07:13 AM
Help! Slow Performance	Neo	Post Here to Contact Site Administrators and Moderators	6	08-25-2003 04:08 PM

Thread Tools	Search this Thread
Show Printable Version Email this Page	Search this Thread: Advanced Search
Display Modes	Rate This Thread
Switch to Linear Mode Hybrid Mode Switch to Threaded Mode	Rate This Thread: