strace 输出：测量系统调用所花费的时间答案

【问题标题】：strace output: measure time taken for system callstrace 输出：测量系统调用所花费的时间
【发布时间】：2014-12-10 04:38:15
【问题描述】：

我想格式化使用选项“strace -s 1024 -vftT”获得的 strace 输出数据，并且日志类似于，

... <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>

-> 我想找出所有 sendto(4, ) 调用所花费的总时间。 -> 这也应该考虑在线程切换后 sendto() 恢复调用。 -> 时间计算应忽略对文件描述符 4 以外的不同文件描述符的 sendto() 调用。

所以在这种情况下我的要求是我需要一些脚本（最好使用 sed）来添加 sendto(4, ...) 调用所采取的所有时间（在本例中为 0.000050+0.652744=0.652794）。

欢迎任何与上下文相似的参考（我尝试查找，但找不到任何相关内容）。

【问题讨论】：

grymoire.com/Unix/Awk.html 可以满足您的所有需求。抱歉，Stack Overflow 不是免费的编码服务。祝你好运。
随时使用所需的输出更新您的问题（基于上面的示例输入）（以及您需要的确切格式）以及解决您问题的任何尝试。包括您当前的输出和错误消息。 sed 可以做很多事情，但除此之外，总计将是一个超级天才的 sed 用户。 awk 就是为此而设计的。提示是awk '/text 2 match/{timeval=$(NF);gsub(/[<>/, "", timeval); totTime+=timeval} END{print "totalTime=" totTime}' /path/to/log/file。祝你好运。
感谢@Shellter，以下是更新脚本的示例输出...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
哇，你读得真快！但是......真的很难阅读您当前的输出。为什么不将其添加到您的问题中。还有，有问题吗？这看起来像您想要的输出。 如果这是一个有效的答案，您应该将其作为答案发布，然后在 48 小时后接受它以获得声誉积分。将来，您将希望将示例数据编辑为可以轻松放入一行（每条记录）的内容，仅是使每一行唯一的内容和感兴趣的值（带有一两条“忽略这一行”添加）。祝你好运。
即使这是一个可行的解决方案，我也有 99% 的把握 awk 支持很多 idoms，应该将这段代码减少到 2-3 行！如果我能在 S.O. 上找到示例，我会添加一个链接。

标签： time awk strace

【解决方案1】：

以下对我有用，感谢 Shellter 建议使用 awk（尽管我没有考虑“sendto”本身是其他系统调用数据的一部分的特殊情况）

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

【讨论】：