我正在尝试加速调用子shell 并执行各种操作的脚本集合。我想知道是否有任何工具可用于计算 shell 脚本及其嵌套 shell 的执行时间，并报告脚本的哪些部分最昂贵。
例如，如果我有如下脚本。
#!/bin/bash
echo "hello"
echo $(date)
echo "goodbye"
我想知道这三行中的每一行花了多长时间。 time 只会给我脚本的总时间。 bash -x 很有趣，但不包括时间戳或其他时间信息。
【问题讨论】：
time echo "hello"
标签： performance bash
您可以设置PS4 显示时间和行号。这样做不需要安装任何实用程序，并且无需将 stderr 重定向到 stdout 即可工作。
对于这个脚本：
#!/bin/bash -x
# Note the -x flag above, it is required for this to work
PS4='+ $(date "+%s.%N ($LINENO) ")'
for i in {0..2}
do
echo $i
done
sleep 1
echo done
输出如下：
+ PS4='+ $(date "+%s.%N ($LINENO) ")'
+ 1291311776.108610290 (3) for i in '{0..2}'
+ 1291311776.120680354 (5) echo 0
0
+ 1291311776.133917546 (3) for i in '{0..2}'
+ 1291311776.146386339 (5) echo 1
1
+ 1291311776.158646585 (3) for i in '{0..2}'
+ 1291311776.171003138 (5) echo 2
2
+ 1291311776.183450114 (7) sleep 1
+ 1291311777.203053652 (8) echo done
done
这假定 GNU 日期，但您可以将输出规范更改为您喜欢的任何内容或与您使用的日期版本匹配的任何内容。
注意：如果您想要在不修改的情况下使用现有脚本，您可以这样做：
PS4='+ $(date "+%s.%N ($LINENO) ")' bash -x scriptname
在即将到来的 Bash 5 中，您将能够节省分叉 date（但您获得的是微秒而不是纳秒）：
PS4='+ $EPOCHREALTIME ($LINENO) '
【讨论】：
#!/bin/bash -x顶部的-x很重要
您可以将在-x 下运行的输出通过管道传输到接收到每行时为其加时间戳的东西。例如，来自 djb 的daemontools 的tai64n。
举个基本的例子，
sh -x slow.sh 2>&1 | tai64n | tai64nlocal
这将 stdout 和 stderr 混为一谈，但它确实为所有内容提供了时间戳。 然后，您必须分析输出以找到昂贵的行并将其与您的源相关联。
您可能还会发现使用strace 很有帮助。例如，
strace -f -ttt -T -o /tmp/analysis.txt slow.sh
这将生成一个非常详细的报告，在 /tmp/analysis.txt 中包含大量时间信息，但在每个系统调用级别，这可能过于详细。
【讨论】：
听起来你想为每个回声计时。如果 echo 是您所做的全部，那么这很容易
alias echo='time echo'
如果您正在运行其他命令，这显然是不够的。
【讨论】：
参见 enable_profiler/disable_profiler https://github.com/vlovich/bashrc-wrangler/blob/master/bash.d/000-setup
这是我现在使用的。我还没有在所有版本的 BASH 上进行测试，但如果你安装了 ts 实用程序，它可以很好地工作，而且开销很低。
我的首选方法如下。原因是它也支持 OSX（它没有高精度日期）并且即使您没有安装 bc 也可以运行。
#!/bin/bash
_profiler_check_precision() {
if [ -z "$PROFILE_HIGH_PRECISION" ]; then
#debug "Precision of timer is unknown"
if which bc > /dev/null 2>&1 && date '+%s.%N' | grep -vq '\.N$'; then
PROFILE_HIGH_PRECISION=y
else
PROFILE_HIGH_PRECISION=n
fi
fi
}
_profiler_ts() {
_profiler_check_precision
if [ "y" = "$PROFILE_HIGH_PRECISION" ]; then
date '+%s.%N'
else
date '+%s'
fi
}
profile_mark() {
_PROF_START="$(_profiler_ts)"
}
profile_elapsed() {
_profiler_check_precision
local NOW="$(_profiler_ts)"
local ELAPSED=
if [ "y" = "$PROFILE_HIGH_PRECISION" ]; then
ELAPSED="$(echo "scale=10; $NOW - $_PROF_START" | bc | sed 's/\(\.[0-9]\{0,3\}\)[0-9]*$/\1/')"
else
ELAPSED=$((NOW - _PROF_START))
fi
echo "$ELAPSED"
}
do_something() {
local _PROF_START
profile_mark
sleep 10
echo "Took $(profile_elapsed) seconds"
}
【讨论】：
time 将为您完成此操作。
bc 的msys 下，此脚本增加了大约300 毫秒的开销（调用which && date | grep 大约需要150 毫秒，调用echo | bc | sed 大约需要150 毫秒）。在 WSL 下，开销下降到大约 5 毫秒。这种差异是通过在同一命令上调用 time 来衡量的。
time 将要求您手动注释每个步骤。
复制自here:
由于我现在至少在这里结束了两次，我实施了一个解决方案：
https://github.com/walles/shellprof
它运行您的脚本，透明地记录所有打印的行，并在最后打印屏幕上最长的行的前 10 个列表：
~/s/shellprof (master|✔) $ ./shellprof ./testcase.sh
quick
slow
quick
Timings for printed lines:
1.01s: slow
0.00s: <<<PROGRAM START>>>
0.00s: quick
0.00s: quick
~/s/shellprof (master|✔) $
【讨论】：
这是一个几乎适用于所有 Unix 且不需要特殊软件的简单方法：
set -x
sh -x ./slow_script 2>&1 | logger
这会将输出写入系统日志，系统日志会自动为每条消息添加时间戳。如果您将 Linux 与 journald 一起使用，则可以使用
获得高精度时间戳journalctl -o short-monotonic _COMM=logger
许多传统的 syslog 守护进程还提供高精度时间戳（对于 shell 脚本来说毫秒应该足够了）。
这是我刚刚以这种方式分析的脚本中的一个示例：
[1940949.100362] bremer root[16404]: + zcat /boot/symvers-5.3.18-57-default.gz
[1940949.111138] bremer root[16404]: + '[' -e /var/tmp/weak-modules2.OmYvUn/symvers-5.3.18-57-default ']'
[1940949.111315] bremer root[16404]: + args=(-E $tmpdir/symvers-$krel)
[1940949.111484] bremer root[16404]: ++ /usr/sbin/depmod -b / -ae -E /var/tmp/weak-modules2.OmYvUn/symvers-5.3.18-57-default 5.3.18-57>
[1940952.455272] bremer root[16404]: + output=
[1940952.455738] bremer root[16404]: + status=0
您可以看到“depmod”命令花费了很多时间。
【讨论】：