time diffrence between two lines in a log file

Shell Programming and Scripting
1

Hi Experts,

I am writing a shell/Perl script tp get a time diffrence of two lines in a log file. I am pasting a snippet of my log file, how it look likes.

Sun Apr 26 02:11:03.162 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: calling ARRF_LIB_Evaluate.
Sun Apr 26 02:11:03.162 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Entering ARRF_LIB_Evaluate
Sun Apr 26 02:11:03.162 2009 Greenwich Standard Time INFO:    pid 488 tid 2072: 0: 251360: Received Request ARRF_LIB_Evaluate
Sun Apr 26 02:11:03.162 2009 Greenwich Standard Time LOW:     pid 488 tid 1
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Decrementing load for 0 pool in Primary List
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Exiting ArPFExtRuleSetEval::evaluate
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: CollatedResultDetail [USERKNOWN.DETAIL=RESULT=0|DEVICEIDCHECK.DETAIL=RESULT=0|UNTRUSTEDIP.DETAIL=RESULT=0|SIGMATCH.DETAIL=RESULT=0;REASON=DEVICEIDCHECK_FAILED|TDDefaultAmount.DETAIL=|TDDefaultMerchantCountry.DETAIL=RESULT=1|SCORE.DETAIL=SCORE=65;ADVICE=4;EXITAT=TDDefaultMerchantCountry|]
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Entering setEvaluateResponse
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Exiting setEvaluateResponse
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Entering ARRFDbOperations::insertEvalTx
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Entering getIntResult
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Exiting getIntResult
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Entering getIntResult
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Exiting getIntResult
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Entering getIntResult
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Exiting getIntResult
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Entering getIntResult
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Exiting getIntResult
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Entering ARRFDbOperations::insertSysAuditLog
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Acquiring ReaderWriter Lock
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Acquired ReaderWriter Lock, going to select pool
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Selecting Pool with minimum load
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Trying to find next in round robin
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: _numberOfPools [1] activePool size [1]
Sun Apr 26 02:11:03.224 2009 Greenwich Standard Time LOW:     pid 488 tid Sun Apr 26 02:11:03.240 2009 Greenwich Standard Time INFO:    pid 488 tid 2072: 0: 251360: Sending Response ARRF_LIB_Evaluate
Sun Apr 26 02:11:03.240 2009 Greenwich Standard Time LOW:     pid 488 tid 2072: 0: 251360: Exiting ARRF_LIB_Evaluate

I want to get a time diffrence between the lines "Entering ARRF_LIB_Evaluate" and "Exiting ARRF_LIB_Evaluate".
Thses lines come repeatedly in the log file so everytime i need to get what is the difference of timebetween these lines.
Any kind of help is greatly appericiated. I am trying with my own and will post you with my script, what i have tried so far.

If any information is required kindly let me know.

Thanks
NT

2

Hi,

I have tried this so far but time diffrence is not coming , it is showing syntax error for the time diffrence line.

#!/usr/bin/ksh
#set -x
start_time=0;
end_time=0;
result=0;
while [ logfile ]
       do
           for line in logfile
           do
           var1=`grep "Entering ARRF_LIB_Evaluate" $line`
           start_time=`echo $var1 | cut -d " " -f4`
           echo "$start_time"
           var2=`grep "Exiting ARRF_LIB_Evaluate" $line`
           end_time=`echo $var2 | cut -d " " -f4`
           echo "$end_time"
           result=`expr $end_time - $start_time`
           echo $result
           done
done

When i ran this script i am getting --
[root@tsrh4ent shell_perl_script]# sh timediff.sh
02:11:03.162
02:11:03.240
expr: non-numeric argument

and it is going on in infinite loop, i want it like, when the logfile ends it should stop.

Kindly help me in this..

Thanks
NT

3

You missed out "$" in the below line:

 result=`expr $end_time - $start_time`

Give it a try!!!

4

In my shell script which i am trying has $ sign before start_time. Here by mistake i guess i forgot.

Thanks
NT

5

Hello,

Before coming to a conclusion, i wanted to know what exactly this line meant??

Sun Apr 26 02:11:03.224

I am not sure what that red things mean!!!

Comming to the script, you need to sort out one problem:

`echo $var1 | cut -d " " -f4`

the output of the above command looks like this: 02:11:03.162
which you are storing in the variable start_time.
And same's the case with end_time.

So it is known that a shell cannot evaluate a non-integer thing. Hence expr: non-numeric argument

And one more thing, no need to print the start_time and end_time values inside the loop, hence commenting out could be better as you are looking for the timestamp diff. But depends on your requirement. What say!!!

6 
Sun Apr 26 02:11:03.224

The red thing means that the time is in mili seconds.

That is fine and that is why i want to know how i can get the diffrence of those two variable. I just wanted to see the values of the variable so i echoed them.
I hope things are clear now.
I want to get the diffrence of the two time stamps i captured in start_time and end_time and i want when the logfile ends it should also stop, it should not go to infinite loop.
Rest everything printing and decorating i will do later.

Thanks
NT

7

you can't just expr and subtract time/date like that. you might want to use some date manipulation module, like that of Date::Calc/strptime/strftime that goes with Perl. here's one way with Python

import time

def calctime(line):
    line = line.split()
    day,month,mday, TIME, year = line[0],line[1],line[2],line[3],line[4]    
    hr,mm,sec = TIME.split(":")
    sec,ms = sec.split(".")
    time2parse = "%s %s %s %s:%s:%s %s" % (day,month,mday,hr,mm,sec, year)
    stringtime = time.strptime(time2parse,"%a %b %d %H:%M:%S %Y")
    return [time.strftime("%s",stringtime),ms]

for line in open("file"):
    flag=1
    line=line.strip()
    if "Entering ARRF_LIB_Evaluate" in line:
        startT,startms = calctime(line)        
    if "Exiting ARRF_LIB_Evaluate" in line:
        endT,endms = calctime(line)        
        flag=0
    if flag == 0:
        diff = int(endT) - int(startT)
        if diff==0: print "Time difference(ms) " , int(endms) - int(startms)
        else: print "Time different %d (s)" % diff

output

# ./test.py
Time difference(ms)  78
8

Hi Ghostdog,

Thank you very much for your reply, but i am not aware of python and even do not know how to use it.
Anything in shell script or Perl will be a great help.

Thanks
NT

9

Try this:

for line in logfile
do
var1=`grep "Entering ARRF_LIB_Evaluate" $line`
start_time=`echo $var1 | cut -d " " -f4 | sed -e 's/://g' -e 's/\.//g'`
#echo "$start_time"
var2=`grep "Exiting ARRF_LIB_Evaluate" $line`
end_time=`echo $var2 | cut -d " " -f4 | sed -e 's/://g' -e 's/\.//g'`
#echo "$end_time"
result=`expr $end_time - $start_time`
done
echo "$result ms"
10

Just save the script as myscript.py. then on the command prompt, type python myscript.py
that's all. of course, you must have Python installed.

11

as i mentioned, you can't just use expr to subtract 2 dates/time like that. what if the end time is 1 hour later, eg Sun Apr 26 03:11:03.224. how are you going to calculate that?

12

Hi,

This is not what i am looking for. just removing : and . from the variable will not result in desired output. That is wrong apporoach.
Kindly do not misguide me.

I hope what i want is clearly mentioned. Experts please give me some suggestions or help.

Thanks
NT

13

Hi Ghostdog,

Thank you for the information, But i should be aware what i am doing and i don't have any idea of python. I will be able to run the program with python installed but later if i need to do any changes then i won't be able. So i am looking for anything in shell or perl.

I appericiate your response very much and need some help in doing it in shell/perl.

Thanks
NT

14

A few questions.

Do you really need such a high time resolution? Would up to the second be fine as well?

Could you install/use external Perl modules (like Date::Manip for instance)?

What platform you are using?

What version of ksh?

15

Hi ghostdog,

Its a great point, never thought about that. I didn't thought of new logic, just trying to modify the logic what NT has posted, as my day was ending!!!
Will correct my thinking and apologies for my post.

Thank you!!!

16

Hi Radoulov,

Yes the high time resolution is very much needed. In the log files there are plenty of lines where there is diffrence in only miliiseconds and upto seconds field the diffrence of time is same,so most of the time the diffrence will be zero not as expected.
I am ruuning the script is Linux plateform.

The ksh verios is --

echo $KSH_VERSION
@(#)PD KSH v5.2.14 99/07/13.2

Is there any alternate way without installing the extra module in perl.
I appericiate your response.

Thanks
NT

17

Try to implement this

        start_time=`echo $var1 | cut -d " " -f4` | sed 's/[:.]//g'
           end_time=`echo $var2 | cut -d " " -f4`| sed 's/[:.]//g'
           h1=`echo $start_time | cut -c1-2`	
    	   m1=`echo $start_time | cut -c3-4`	
           s1=`echo $start_time | cut -c5-6`	
           mm1=`echo $start_time | cut -c7-9`

           h2=`echo $end_time | cut -c1-2`	
           m2=`echo $end_time | cut -c3-4`	
           s2=`echo $end_time | cut -c5-6`
           mm2=`echo $end_time | cut -c7-9`	
    
          mm3=`expr $mm2 - $mm1`
          if [ $mm3 -lt 0 ]		
          then
	  mm3=`expr $mm3 + 1000`	
	  s1=`expr $s1 + 1`		
          fi
          s3=`expr $s2 - $s1`
          if [ $s3 -lt 0 ]		
          then
	  s3=`expr $s3 + 60`	
	  m1=`expr $m1 + 1`	
          fi

         m3=`expr $m2 - $m1`		
         if [ $m3 -lt 0 ]		
         then
	 m3=`expr $m3 + 60`	
	h1=`expr $h1 + 1`	
        fi
        h3=`expr $h2 - $h1`		
        if [ $h3 -lt 0 ]	
        then
	h3=`expr $h3 + 24`	
        fi
    for number in $h3 $m3 $s3 $mm3	
    do
	if [ $number -lt 10 ]	
	then
	    echo "0$number\c" 
	else
	    echo "$number\c"  
	fi

cheers,
Devaraj Takhellambam

18

It would be most efficient (easy, fast) to convert time strings to epoch for calculating I think.

19

Can you suggest me how i can achieve that.

Thanks
NT

20

You may try something like this but you need to install the DateTime module:

#!/usr/bin/env perl

use strict;
use warnings;
use DateTime;

my $logfile = shift || die "usage: $0 <filename>\n";

my %mon2num = qw(
  Jan 1  Feb 2  Mar 3  Apr 4  May 5  Jun 6
  Jul 7  Aug 8  Sep 9  Oct 10 Nov 11 Dec 12
);

my ( $start_dt, $end_dt );

open LF, $logfile or die "$logfile: $!\n";

while (<LF>) {

    if (/(?:Entering|Exiting) ARRF_LIB_Evaluate/) {
        $end_dt = '';
        my @dtA = split;
        my @time = split /[:.]/, $dtA[3];
        ( /Exiting/ ? $end_dt : $start_dt ) = DateTime->new(
            year       => $dtA[4],
            month      => $mon2num{ $dtA[1] },
            day        => $dtA[2],
            hour       => $time[0],
            minute     => $time[1],
            second     => $time[2],
            nanosecond => $time[3],
        );

        if ($end_dt) {
            print "start: ", $start_dt, "\n";
            print "end: ",   $end_dt,   "\n";
            my $e = $end_dt->subtract_datetime($start_dt);
            printf
"elapsed: %s year(s), %s month(s), %s week(s), %s day(s), %s hour(s), %s min, %s sec, %s ms\n",
              $e->years, $e->months, $e->weeks, $e->days, $e->hours,
              $e->minutes, $e->seconds, $e->nanoseconds;

        }
    }
}