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