ITPub博客

首页 > 自动化运维 > 大规模网络运维 > [20200402]strace过滤使用awk问题.txt

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

原创 大规模网络运维 作者:lfree 时间:2020-04-03 09:32:46 0 删除 编辑

[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 }'

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/267265/viewspace-2684279/,如需转载,请注明出处,否则将追究法律责任。

全部评论
熟悉oracle相关技术,擅长sql优化,rman备份与恢复,熟悉linux shell编程。

注册时间:2008-01-03

  • 博文量
    2695
  • 访问量
    6464175