Need to get the time difference for all the transactions in a day

Hello Experts,

I need to evaluate my API [for ex: for getNEData() as given below] performance, so need a script to get the time difference[between Entering and Exiting] for all the transaction that has gone through my application in a day. The challenge is the multi threaded logs, so I cant just get all the Telephone Numbers and check the entering and existing time, i have to keep in mind the thread factor here. There could be multiple calls for the same Telephone number in different threads for different APIs. Please suggest.

2012-08-17 00:00:06,369   INFO  [[ACTIVE] ExecuteThread: '33' for queue: 'weblogic.kernel.Default (self-tuning)'] service.impl.SDXInventoryImpl - Entering getNEData() for 5417543010 of com.sdx.services.impl.SDXInventoryImpl
 2012-08-17 00:00:06,369   DEBUG [[ACTIVE] ExecuteThread: '120' for queue: 'weblogic.kernel.Default (self-tuning)'] nmo.dc.RackDC - Exiting getRackInfo() for 5627562233 of com.sdx.services.nmo.dc.RackDC
2012-08-17 00:01:08,369   INFO  [[ACTIVE] ExecuteThread: '33' for queue: 'weblogic.kernel.Default (self-tuning)'] service.impl.SDXInventoryImpl - Exiting getNEData() for 5417543010 of com.sdx.services.impl.SDXInventoryImpl

Based on the very small sample, this may work:

awk '
    /Entering/ { startt[$6, $(NF-2)] = $1 " " $2; next; }
    /Exiting/ { tn = $(NF-2); printf( "TN %s start: %s  end: %s %s\n", tn, startt[$6, tn], $1, $2 ); }
' input-file >output-file

I assumed the thread number, other than for matching, was unimportant.

Agama, I am getting syntax error for this. Please check.

What is your operating system and version of awk? If you are using Solaris, try using nawk instead of awk.

Agama,

Its Solaris 10. However I cant seem to find the version of awk. awk --version gets stuck. I tried your script with nawk, I dont see any output.

Solaris 10 1/06 s10s_u1wos_19a SPARC

I am pretty sure that there should be some problem with my input file, let me double check..

---------- Post updated at 07:37 PM ---------- Previous update was at 06:51 PM ----------

Agama,

 Its working. But I would need:
  1. To filter out [pipe the output] the result with another string, just to get the response time of a specific API. Like how we do with grep:
grep Starting inputFile | grep getNEData
  1. To get the time difference. Right now it just displays the Start and End time, could you also show me how to get the difference calculated in minutes.

If your version of nawk supports mktime() then this is the simple case:

awk '
    /Entering/ { startt[$6, $(NF-2)] = $1 " " $2; next; }
    /Exiting/ {
        tn = $(NF-2);
        edt = $1 " " $2;            # bang together start/end time into "yyyy mm dd hh mm ss"
        sdt = startt[$6, tn];
        gsub( "[-:]", " ", sdt );
        gsub( "[-:]", " ", edt );
        gsub( ",", ".", edt );      # dont know if mktime handles fractions, so dropping them
        gsub( ",", ".", sdt );
        printf( "TN %s start: %s  end: %s %s diff: %.2f min\n", tn, startt[$6, tn], $1, $2, (mktime( edt ) - mktime( sdt ))/60 ); }
'  input-file >output-file

If mktime() isn't supported (likely won't be), then coding a function to convert a date stamp to seconds past epoch isn't difficult. The function assumes that the date has been adjusted to convert local time to zulu, but for subtracting dates from the same log this shouldn't be necessary.

awk '
    BEGIN {
        epoch_yr = 1970;
        soup = "000031059090120151181212243273304334";          # sum of days in months prior to indexed month
    }

    # dt is yyyymmddhhmmss
    # returns seconds past epoch (unix time stamp)
    function time2spe( date, time,     dt, tm, y, m, d, yep, dep, ld, ldep, ssm )    # assumes time is adjusted to zulu, but for this it doesnt matter
    {
        split( date, dt, "-" );
        split( time, tm, ":" );
        tm[3] = tm[3] + 0;          # drop fraction
        y = dt[1];                  # unnecessary, but easier to read
        m = dt[2];
        d = (dt[3] + substr( soup, (m*3)-2, 3 ))-1;          # sum of days before the day indicated in dt

        ssm = (tm[1] * 3600) + (tm[2] * 60) + tm[3];   # seconds since midnight for given date/time

        yep = y - epoch_yr;                 # years since epoch, before date year
        dep = yep * 365;                    # normal days since epoch, but before date year
        ldep = int((yep-1)/4);              # leap days since epoch, not including date year

        if( (ld = m > 2 ? ( y % 4 == 0 ? 1 : 0) : 0) )  # possible leap day this year?  count only if we are march or beyond
            if( (y % 100 == 0) && (y % 400) )           # century years must also be divisible by 400 to be a leap year
                ld = 0;                                 # if it is not, then reset ld count

        return ((dep + ldep + ld + d) * 86400) + ssm;
    }


    /Entering/ {
            startd[$6, $(NF-2)] = $1;
            startt[$6, $(NF-2)] = $2;
            next;
    }
    /Exiting/ {
        tn = $(NF-2);
        st = startt[$6, tn];    # easier to read
        sd = startd[$6, tn]
        printf( "TN %s start: %s %s  end: %s %s diff: %.2f min\n", tn, sd, st, $1, $2, (time2spe( $1, $2 ) - time2spe( sd, st ))/60 ); 
    }
' input-file >output-file

This could likely be optimised a bit, but I'm tired and it should work.

You can adjust the printf() statement to output exactly what you need. Right now it should produce the same as before with the difference between start and end times in minutes.

Hope this helps.

---------- Post updated at 23:51 ---------- Previous update was at 23:45 ----------

Not sure what identifies the API, but assuming it's something like getRackInfo , then you could do it this way:

grep "getRackInfo" input-file | awk ' ...... ' >output'file

filling in "......." with the awk programme that you want to use.

There are other ways to do it from within the awk, but this is the most straight forward.