strace output: measure time taken for system call

Question

I wanted to format strace output data obtained with options "strace -s 1024 -vftT" and has the log something like,

... <log that is un-important>
24339 01:51:55 sendto(4, "<logging to required file>", <size>, MSG_NOSIGNAL, NULL, 0) = 114 <0.000050>
...
15016 01:51:55 sendto(594, "<some log to different file>, not included for time measure", <size>, 0, NULL, 0 <unfinished ...>
... <log from different threads>
15016 01:51:55 <... sendto resumed> )   = 5 <0.000076>
... <log that is un-important>
29192 01:51:57 sendto(4, "<logging to required file>", <size>, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
...
29192 01:51:58 <... sendto resumed> )   = 109 <0.652744>
... <log that is un-important>

-> I wanted to find the total time spent in all sendto(4, ) calls. -> This should also consider sendto() resumed calls after thread switch. -> Time calculation should ignore sendto() calls to different file-descriptor other than file-descriptor 4.

So my requirement in this case is I need some script (preferably using sed) to add all the timings taken by sendto(4, ...) calls (in this example it is 0.000050+0.652744=0.652794).

Any references to similar to context is welcome (I tried finding, but could not find anything relevant).

Answer 1

Following worked for me, Thanks to Shellter for suggestion to use awk (though I have not considered special cases where "sendto" itself is part of data for other system calls)

cat strace.txt | awk ' 
function find_thread(maxInd, threads, threadStrArr, reqThr)
{
    for (ind = 1; ind <= maxInd; ind++)
    {
        if (reqThr == threads[ind])
        {
            printf "...\n%s\n...\n", threadStrArr[ind]
            for ( ; ind < maxInd; ind++)
            {
                threads[ind] = threads[ind + 1]
                threadStrArr[ind]=threadStrArr[ind + 1]
            }
            return reqThr
        }
    }
    return -1
}
{
    thrCnt=0
    totmatchCnt=0
    totTimetaken=0
    syscall_name="sendto"
    while ((getline myline) > 0) {
        found_syscall_finished=0
        resumed_found=match(myline, "<... "syscall_name" resumed>")
        if (resumed_found != 0)
        {
            # Found "<system call> resumed" string in the input line
            split(myline,a," ");
            thread_id=a[1]
            if (thrCnt > 0)
            {
                # Now need to find matching thread (if any) from the unfinished calls
                foundThr=find_thread(thrCnt, threads, threadStrArr, thread_id)
                if (foundThr != -1)
                {
                    # There is a matching unfinished call found in the trace
                    thrCnt--
                    found_syscall_finished=1
                }
            }
        }
        else
        {
            # It is not resumed system call, check if required system call found
            syscall_found = match(myline, syscall_name"\\(4,")  # Please note the 4, ie first parameter is 4
            if (syscall_found != 0)
            {
                # It is required system call
                unfinished_found=match(myline, "<unfinished ...>$")
                if (unfinished_found != 0)
                {
                    # It is an unfinished call, add thread number to the array for search later
                    split(myline,a," ");
                    thrCnt++
                    threadStrArr[thrCnt]=myline
                    threads[thrCnt]=a[1]
                }
                else
                {
                    found_syscall_finished=1
                }
            }
        }
        if (found_syscall_finished != 0)
        {
            # current line contains required system call which is finished, fetch time and add to total time
            printf "%s\n", myline
            n=split(myline,a,"[ <>]");
            time_took=a[n-1]
            totmatchCnt++
            totTimetaken=totTimetaken+time_took
        }
    }
    if (totmatchCnt != 0)
    {
        avgTime=totTimetaken/totmatchCnt
        printf "total = %s, cnt = %s, average = %s\n", totTimetaken, totmatchCnt, avgTime
    }
}
'

sample output,
-------------------------------------------------------------------------------------------
24339 01:51:55 sendto(4, "<logging to required file>", <size>, MSG_NOSIGNAL, NULL, 0) = 114 <0.000050>
...
29192 01:51:57 sendto(4, "<logging to required file>", <size>, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
...
29192 01:51:58 <... sendto resumed> )   = 109 <0.652744>
total = 0.652794, cnt = 2, average = 0.326397