LinuxQuestions.org

LinuxQuestions.org (/questions/)
-   Linux - Newbie (https://www.linuxquestions.org/questions/linux-newbie-8/)
-   -   Script - Find time between entries in log file (https://www.linuxquestions.org/questions/linux-newbie-8/script-find-time-between-entries-in-log-file-4175418304/)

blsimpson 07-23-2012 07:29 PM

Script - Find time between entries in log file
 
Hello all,

I have a log file that looks like this:

Quote:

280898275 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] INFO c.v.i.c.c.s.CardGenServiceImpl - generating VirtualCard
280952720 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] INFO c.v.i.c.c.s.CardGenServiceImpl - Found Fundingcard com.xxxxxxx.xxxxxxx.transactional.FundingCard@15ffb1bd
280952737 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] INFO c.v.i.c.c.s.CardGenServiceImpl - Completed generating VirtualCard
280952787 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] INFO c.v.i.c.c.s.CardGenServiceImpl - Card controls stored for Virtual Card Hanlde :19096
280953126 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] INFO c.v.i.c.c.s.CardGenServiceImpl - generating VirtualCard
281007859 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] INFO c.v.i.c.c.s.CardGenServiceImpl - Found Fundingcard com.xxxxxxxx.xxxxxxx.transactional.FundingCard@3ad721b1
281007874 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] INFO c.v.i.c.c.s.CardGenServiceImpl - Completed generating VirtualCard
The first part is the time in milliseconds. (I cant change this, I dont have access to the code for that.) What I need is to grep the file for "generating VirtualCard" take the number in the beginning and make it "variable a". Then grep for "Completed generating VirtualCard", take the number in the beginning, and make it "variable b". Once thats done, I need to take variable a and subtract it from variable b, and output the result. I just need the output.

What I am looking for is the amount of time it take for the card generation. Any help would be great, as I am not familiar with this..

antegallya 07-23-2012 07:53 PM

Hello

That should be as easy as
Code:

timeA=$(grep "generating VirtualCard" logfile | egrep -o "^[0-9]*")
timeB=$(grep "Completed generating VirtualCard" logfile | egrep -o "^[0-9]*")
echo Time elapsed : $(expr $timeB - $timeA)


antegallya 07-23-2012 08:20 PM

Well, I saw your log file actually has multiple generations of VirtualCard.
Do you need the generation time for each log entry ? If so, you could pipe your file to the following awk script :
Code:

#!/usr/bin/awk -f
BEGIN {
        start = -1;
}

/generating VirtualCard/ {
        if (start == -1) {
                start = $1;
        } else {
                print "Generations are not sequential !";
                exit 1;
        }
}

/Completed generating VirtualCard/ {
        if (start != -1) {
                print "Generated a VirtualCard in", $1 - start, "ms";
                start = "-1";
        } else {
                print "Bad log file";
                exit 1;
        }
}


blsimpson 07-23-2012 08:29 PM

That is correct, there are multiple entries in the same log file that I need the times for. I will try both of these options, and get back to you. Thank you so much!

antegallya 07-23-2012 08:35 PM

Okay, but note that first one won't work with multiple entries.

blsimpson 07-23-2012 08:37 PM

Oh, Okay. Will the second one loop through the whole file and output them all?

antegallya 07-23-2012 08:38 PM

Yes. That is what you want, right ?

blsimpson 07-23-2012 08:49 PM

Thats correct. Thank you so much!

blsimpson 07-23-2012 10:03 PM

Ok, I guess I dont know enough about this.. Can you point me in the direction on how I would accomplish what you said, pipe the logfile into the script..

antegallya 07-23-2012 10:16 PM

Once you've created the script and made it executable with chmod +x, you can pipe your log file as with any command
Code:

cat logfile | ./script

blsimpson 07-23-2012 10:24 PM

Thanks. I'm getting "Generations are not sequential !"

blsimpson 07-24-2012 01:13 PM

Thought I would check in and let you know where I got to. Using the code you gave me, I changed it a little, and came up with this:

Code:

#!/usr/bin/awk -f

BEGIN {
        start = 1;
}

/- generating VirtualCard/ {
        if (start < $1) {
                start = $1;
        } else {
                print "Generations are not sequential !";
                exit 1;
        }
}

/Completed generating VirtualCard/ {
        if (start != -1) {
                print "Generated a VirtualCard in", $1 - start, "ms";
                start = "-1";
        } else {
                print "Bad log file";
                exit 1;
        }
}

Gives me output of:

Quote:

Generated a VirtualCard in 1041 ms
Generated a VirtualCard in 1060 ms
Generated a VirtualCard in 1060 ms
Generated a VirtualCard in 1082 ms
Now to change them to seconds. :)

blsimpson 07-24-2012 02:14 PM

Ok, pass on the seconds.. Maybe someone can help me with this next part. I need to be able to write a script to loop through the log directory in sequence based on date, and write the output to a file. Example:

Directory:
~/test/
logFile.2012-06-04.log
logFile.2012-06-05.log
logFile.2012-06-06.log
logFile.2012-06-07.log
script.sh
generation.log

Command I am using:
cat logFile.2012-06-04.log | ./script.sh > generation.log

I could do them all manually, by just changing the date of the log file in the command, but I would like to be able to put other files in there, and have it pick them up as well. The log file names will always be logFile.YYYY.MM.DD.log

blsimpson 07-24-2012 02:35 PM

Using this seems to get me what I want:

Code:

#!/bin/bash

i=1
for file in /test/*.log
do
echo "$file" >> generation.log
cat $file | ./script.sh >> generation.log
# echo "File $((i++)) : $file"
done

Now to add some clean up, checking if the generation.log file exists, and if it does, move it to generation.bak.

Will continue to work through it :)

blsimpson 07-24-2012 02:49 PM

That was pretty easy. Added a simple if\then:

Code:

DATE=`date '+%m-%d-%y:%H:%M:%S'`
LOG=generation.log
LOGBACK=generation.$DATE.bak

if [ -f $LOG ];
then
        mv $LOG $LOGBACK
fi


antegallya 07-24-2012 04:35 PM

Quote:

Thanks. I'm getting "Generations are not sequential !"
That's because you have generations taking place simultaneously. The problem there is to define what to do in that case
If you in your logs something like
Code:

1 generating
4 generating
8 completed
10 completed

Does it means there was a generation that took 4ms and the other took 9. Or the first one took 7ms and the second one took 6ms ?

The code you modified takes the first solution. But I don't find it the most correct as it will most likely give you generation times really far from reality if there's a lot of nesting. I personnaly prefer the second interpretation. For that one, here is another code :
Code:

#!/usr/bin/awk -f
BEGIN {
        idxb = 0;
        idxe = 0;
}

/- generating VirtualCard/ {
        jobs[idxe++] = $1;
}

/Completed generating VirtualCard/ {
        print "Generated a VirtualCard in", ($1 - jobs[idxb++]) / 1000, "s";
}

It doesn't check for an invalid log file anymore. I will give an incorrect generation time if the log starts with "Completed".
I've also modified it to display seconds instead of milliseconds -- it's as simple as dividing the answer by 1000...

Concerning the calling of the script, you can avoid using that loop (which seems somewhat wrong, why do you append the content of the logs to generation.log ?) :
Code:

cat logFile.*.log | ./script.sh > generation.log
Regards,
Antegallya

blsimpson 07-24-2012 07:03 PM

Awesome. That takes care of everything. :)

The reason I am writing to another log file, is I need to take the times, and plot them in a graph to watch the time increase.


All times are GMT -5. The time now is 01:25 AM.