如何调试Bash脚本并获取每个命令的执行时间

Question

如何调试Bash脚本并获取每个命令的执行时间

15

我有一个bash脚本，运行需要近5秒钟。我想要调试它，并确定哪些命令花费了最长时间。有没有一种最好的方法来做到这一点？是否有一个标志可以设置？设置#!/bin/bash -vx并不能真正帮助我。我想要的基本上是按行号执行的执行时间。

- Justin

你为什么这么着急？难道要花一个小时来删减运行脚本时的奇怪秒数吗？ - Ed Heal

2

脚本经常运行，需要进行优化。 - Justin

1

多久算是“经常”？如果速度很重要，也许用C++编写会是更好的选择。另外，为什么不发布脚本呢？ - Ed Heal

Perl、Scala和Clojure比bash更快吗？只是一个想法。 - octopusgrabbus

bash -x myscript.sh 2> >(ts -i) 当您安装了moreutils并且您的脚本没有输出到stderr时，可以使用此命令。但是，所给出的时间持续时间是上一个命令的。 - 12431234123412341234123

4个回答

6

你可以使用time实用工具来测量你的单个命令/函数的运行时间。

例如：

[ben@imac ~]$ cat times.sh
#!/bin/bash

test_func ()
{
    sleep 1
    echo "test"
}

echo "Running test_func()"
time test_func
echo "Running a 5 second external command"
time sleep 5

运行该脚本将会得到以下结果：

[ben@imac ~]$ ./times.sh
Running test_func()
test

real    0m1.003s
user    0m0.001s
sys     0m0.001s
Running a 5 second external command

real    0m5.002s
user    0m0.001s
sys     0m0.001s

- Ben

请勿将 test 用作函数名，它是一个 shell 内置命令。请将其重命名为 test_time 或其他名称。 - anishsane

1

一个小问题：time默认是一个_shell关键字_（同时也作为一个外部实用程序/usr/bin/time存在）。只有shell关键字才能够测量任意shell命令_整体_的时间（将 time ls | sleep 1 的输出与 /usr/bin/time ls | sleep 1 相比较）。 - mklement0

2

试试这个：

sed 's/^\([^#]\)/time \1/' script.sh>tmp.sh && ./tmp.sh

它在所有非命令行之前添加一个时间命令。

- staticd

4

这种方法并非总是有效的：考虑 for i in {1..3}\ndo\necho $i\ndone。这很简单，但 time do 和 time done 不是有效的。 - SheetJS

这是正确的，但至少它允许一定程度的自动化。我喜欢这个想法，不过还需要改进... - icedwater

2

您可以使用set -x使脚本在执行每个命令之前打印出来。我不知道有什么办法可以自动添加命令时间。您可以在脚本中添加date命令来标记时间。

- Barmar

你可以将其与 moreutils 中的 ts 结合使用。 - 12431234123412341234123

网页内容由stack overflow 提供, 点击上面的

可以查看英文原文，
原文链接

- Shoko · Accepted Answer

以下是使用内置的bash调试工具得出的最接近答案，因为它提供了自脚本执行开始时间以来的总体时间信息。

在脚本顶部添加以下内容来进行秒数计数：

export PS4='+[${SECONDS}s][${BASH_SOURCE}:${LINENO}]: ${FUNCNAME[0]:+${FUNCNAME[0]}(): }'; set -x;

同样的内容，但以毫秒为单位：

N=`date +%s%N`; export PS4='+[$(((`date +%s%N`-$N)/1000000))ms][${BASH_SOURCE}:${LINENO}]: ${FUNCNAME[0]:+${FUNCNAME[0]}(): }'; set -x;

最后一个示例可以达到微秒级精度，只需记住您正在使用的是bash :)

示例脚本：

#!/bin/bash
N=`date +%s%N`
export PS4='+[$(((`date +%s%N`-$N)/1000000))ms][${BASH_SOURCE}:${LINENO}]: ${FUNCNAME[0]:+${FUNCNAME[0]}(): }'; set -x;
sleep 1
exit

示例调试输出：

+[3ms][/root/db_test.sh:5]: sleep 1
+[1012ms][/usr/local/bin/graphite_as_rand_stat.sh:6]: exit

请记住，您可以通过在调试开始处使用 'set -x' 并在调试结束处使用 'debug +x' 来选择性地调试脚本的特定部分。时序数据仍将正确显示自执行开始以来的计数。

补充说明

为了完整起见，如果您确实需要差异化的时间数据，您可以将调试信息重定向到文件中，并在之后进行处理。

给定这个示例脚本：

#!/bin/bash
N=`date +%s%N`
export PS4='+[$(((`date +%s%N`-$N)/1000000))ms][${BASH_SOURCE}:${LINENO}]: ${FUNCNAME[0]:+${FUNCNAME[0]}(): }'; set -x;
sleep 1
for ((i=0;i<2;i++)); do
        o=$(($RANDOM*$RANDOM/$RANDOM))
        echo $o
        sleep 0.$o
done
exit

将其运行并将调试重定向到文件：

./example.sh 2>example.dbg

使用此功能输出差分调试计时（适用于多行）：

p=0; cat example.dbg | while read l; do [[ ! ${l%%[*} =~ ^\+ ]] && echo $l && continue; i=`echo $l | sed 's#[^0-9]*\([0-9]\+\).*#\1#'`; echo $l | sed "s#${i}ms#${i}ms+$(($i-$p))ms#"; p=$i; done

输出：

+[2ms+2ms][./example.sh:5]: sleep 1
+[1006ms+1004ms][./example.sh:6]: (( i=0 ))
+[1009ms+3ms][./example.sh:6]: (( i<2 ))
+[1011ms+2ms][./example.sh:7]: o=19258
+[1014ms+3ms][./example.sh:8]: echo 19258
+[1016ms+2ms][./example.sh:9]: sleep 0.19258
+[1213ms+197ms][./example.sh:6]: (( i++ ))
+[1217ms+4ms][./example.sh:6]: (( i<2 ))
+[1220ms+3ms][./example.sh:7]: o=176
+[1226ms+6ms][./example.sh:8]: echo 176
+[1229ms+3ms][./example.sh:9]: sleep 0.176
+[1442ms+213ms][./example.sh:6]: (( i++ ))
+[1460ms+18ms][./example.sh:6]: (( i<2 ))
+[1502ms+42ms][./example.sh:11]: exit