linux awk sed strace,[20200402]strace过滤使用awk问题.txt

[20200402]strace过滤使用awk问题.txt

--//昨天使用strace跟踪io_submit，我想计算每次调用io_submit的平均值。遇到一些问题做1个记录。

1.问题提出：

# strace -f -e io_submit -Ttt  -p 3831

Process 3831 attached - interrupt to quit

11:15:20.217558 io_submit(47787382317056, 2, {{0x2b765df0c210, 0, 1, 0, 256}, {0x2b765df0c460, 0, 1, 0, 257}}) = 2 <0.055500>

11:15:21.274563 io_submit(47787382317056, 2, {{0x2b765df0c210, 0, 1, 0, 256}, {0x2b765df0c460, 0, 1, 0, 257}}) = 2 <0.014881>

11:15:22.291352 io_submit(47787382317056, 2, {{0x2b765df0c210, 0, 1, 0, 256}, {0x2b765df0c460, 0, 1, 0, 257}}) = 2 <0.022738>

Process 3831 detached

--//就是计算最后字段的平均值。

# strace -f -e io_submit -Ttt  -p 3831 | awk '{print $16}'

Process 3831 attached - interrupt to quit

11:16:10.716024 io_submit(47787382317056, 2, {{0x2b765df0c210, 0, 1, 0, 256}, {0x2b765df0c460, 0, 1, 0, 257}}) = 2 <0.038544>

11:16:11.755982 io_submit(47787382317056, 2, {{0x2b765df0c210, 0, 1, 0, 256}, {0x2b765df0c460, 0, 1, 0, 257}}) = 2 <0.039956>

Process 3831 detached

--//很明显strace的输出信息到错误句柄2.无法通过awk过滤获得标准输入1的信息，修改如下：

# strace -f -e io_submit -Ttt  -p 3831 2>&1 | awk '{print $16}'

<0.028540>

<0.031370>

<0.023189>

<0.031105>

<0.023580>

--//OK现在视乎可以了。现在删除"<>"字符。

# strace -f -e io_submit -Ttt  -p 3831 2>&1 | awk '{print $16}' | tr -d "<>"

--//奇怪现在没有任何输出，为什么呢？ 原来awk已经显示了输出，我在通过管道tr处理失败。为什么呢？

2.分析:

# pstree -p

...

|-tmux(19985)-+-bash(5192)---su(5225)---bash(5226)

|             |-bash(19986)-+-awk(7010)

|             |             |-strace(7009)

|             |             `-tr(7011)

# ls -l /proc/7009/fd

total 0

lrwx------ 1 root root 64 2020-04-02 11:21:51 0 -> /dev/pts/3

l-wx------ 1 root root 64 2020-04-02 11:21:51 1 -> pipe:[352472722]

l-wx------ 1 root root 64 2020-04-02 11:21:51 2 -> pipe:[352472722]

--//strace可以发现句柄1，2指向pipe:[352472722]。

# ls -l /proc/7010/fd

total 0

lr-x------ 1 root root 64 2020-04-02 11:22:34 0 -> pipe:[352472722]

l-wx------ 1 root root 64 2020-04-02 11:22:34 1 -> pipe:[352472724]

lrwx------ 1 root root 64 2020-04-02 11:22:34 2 -> /dev/pts/3

--//awk ,句柄0 指向pipe:[352472722]，也就是接收strace 句柄1，2的输出。句柄1指向pipe:[352472724]。

# ls -l /proc/7011/fd

total 0

lr-x------ 1 root root 64 2020-04-02 11:24:26 0 -> pipe:[352472724]

lrwx------ 1 root root 64 2020-04-02 11:24:26 1 -> /dev/pts/3

lrwx------ 1 root root 64 2020-04-02 11:24:26 2 -> /dev/pts/3

--//tr 句柄0 指向 pipe:[352472724]，没有任何问题啊

--//等一段时间我才发现有输出。也就是awk具有缓存输出的功能。当前版本是oracle 5.9。

--//我仅仅知道这个版本sed -u 参数关闭缓存。也就是如果通过管道过滤，中间使用awk要注意缓存问题。

# strace -f -e io_submit -Tt  -p 3831 2>&1  | sed -u -e "s/^.*/;s/>$//"

Process 3831 attached - interrupt to quit

0.029298

0.056492

0.023080

0.030876

0.030940

0.023609

0.031302

--//ok，现在有输出了。

#  strace -q -f -e io_submit -Tt  -p 3831 2>&1  | sed  -e "s/^.*/;s/>$//"  |  awk '{j++;i=i+$NF;print j,i,i/j}END{print j,i,i/j}'

--//又不行，也就是sed也具有类似缓存的功能，只有缓存满了才会输出。ses 加入-u测试：

# strace -q -f -e io_submit -Tt  -p 3831 2>&1  | sed  -u -e "s/^.*/;s/>$//"  |  awk '{j++;i=i+$NF;print j,i,i/j}END{print j,i,i/j}'

1 0.018685 0.018685

2 0.037464 0.018732

3 0.059714 0.0199047

4 0.095627 0.0239067

5 0.126476 0.0252952

6 0.15808 0.0263467

7 0.226031 0.0322901

8 0.244658 0.0305822

--//注：strace -q 避免开头输出。你可以发现现在有输出。但是最后awk的END部分没有执行。限制输出行数就ok了。

# strace -q -f -e io_submit -Tt  -p 3831 2>&1  | sed  -u -e "s/^.*/;s/>$//"  |  head -10 | awk '{j++;i=i+$NF;print j,i,i/j}END{print j,i,i/j}'

1 0.034537 0.034537

2 0.065231 0.0326155

3 0.088592 0.0295307

4 0.11966 0.029915

5 0.146256 0.0292512

6 0.190617 0.0317695

7 0.208893 0.0298419

8 0.240214 0.0300267

9 0.276311 0.0307012

10 0.307035 0.0307035

10 0.307035 0.0307035

--//现在ok了。

3.总结

--//实际上这些都不重要。主要是现场遇到这些问题有一些困惑。做一个记录。我仅仅知道sed -u,tcpdump -l可以关闭缓存。

--//expect包里面包含一个unbuffer,可以禁止输出缓存.

--//一些新版本linux版本的coreutils包里面包括一个命令stdbuf(Red Hat Enterprise Linux Server release 7.5就有这个命令)

--//找一台centos 7.7的机器测试:

# strace -q -f -e pwrite -Tt  -p 15386 2>&1  | stdbuf -i0 -o0 -e0 sed   -e "s/^.*/;s/>$//"  |   awk '{j++;i=i+$NF;print j,i,i/j}END{print j,i,i/j}'

1 0.000124 0.000124

2 0.000201 0.0001005

3 0.000348 0.000116

4 0.000439 0.00010975

^C

# strace -q -f -e pwrite -Ttt  -p 15386 2>&1 | stdbuf -i0 -o0 -e0  awk '{print $8}' | tr -d "<>"

0.000152

0.000101

0.000161

0.000076

^C

--//OK,这样就没有这个问题了。

# strace -q -f -e pwrite -Tt  -p 15386  2>&1  | sed  -u -e "s/^.*/;s/>$//"  | stdbuf -i0 -o0 -e0 head -10 | stdbuf -i0 -o0 -e0 awk '{j++;i=i+$NF;print j,i,i/j}END{print j,i,i/j}' | ts.awk

[2020-04-03 09:23:03] 1 0.000156 0.000156

[2020-04-03 09:23:03] 2 0.000301 0.0001505

[2020-04-03 09:23:06] 3 0.000528 0.000176

[2020-04-03 09:23:06] 4 0.000681 0.00017025

[2020-04-03 09:23:09] 5 0.000959 0.0001918

[2020-04-03 09:23:09] 6 0.001158 0.000193

[2020-04-03 09:23:12] 7 0.001352 0.000193143

[2020-04-03 09:23:12] 8 0.00146 0.0001825

[2020-04-03 09:23:15] 9 0.001738 0.000193111

[2020-04-03 09:23:15] 10 0.00193 0.000193

[2020-04-03 09:23:15] 10 0.00193 0.000193

--//注意看前面的时间戳。间隔3秒。奇怪这里变成间隔3秒，另外探究看看，难道没有配置dg就是这样吗?

# strace -q -f -e pwrite -Tt  -p 15386  2>&1  | sed  -u -e "s/^.*/;s/>$//"  | head -10 |  awk '{j++;i=i+$NF;print j,i,i/j}END{print j,i,i/j}' | ts.awk

[2020-04-03 09:24:57] 1 0.000216 0.000216

[2020-04-03 09:24:57] 2 0.000344 0.000172

[2020-04-03 09:24:57] 3 0.000484 0.000161333

[2020-04-03 09:24:57] 4 0.00058 0.000145

[2020-04-03 09:24:57] 5 0.000718 0.0001436

[2020-04-03 09:24:57] 6 0.000817 0.000136167

[2020-04-03 09:24:57] 7 0.001014 0.000144857

[2020-04-03 09:24:57] 8 0.001114 0.00013925

[2020-04-03 09:24:57] 9 0.001305 0.000145

[2020-04-03 09:24:57] 10 0.001428 0.0001428

[2020-04-03 09:24:57] 10 0.001428 0.0001428

--//时间都是一样的。

--//附上ts.awk的源代码。

# cat /usr/local/bin/ts.awk

# /bin/bash

gawk '{ print strftime("[%Y-%m-%d %H:%M:%S]"), $0 }'