如何分析 BashShell 脚本启动缓慢的情况？

我的 Bash shell 启动需要3-4秒，而如果我用 --norc启动它，它会立即运行。

我开始“分析”/etc/bash.bashrc和 ~/.bashrc通过手动插入 return语句和寻求速度的提高，但它不是一个定量的过程，它是没有效率的。

如何分析 Bash 脚本，并查看哪些命令执行时间最长？

36317 次浏览
小开
最佳答案

如果您有 GNU date(或其他可以输出纳秒的版本) ，请在 /etc/bash.bashrc的开头执行此操作(或在任何您希望在任何 Bash 脚本中开始跟踪的地方执行此操作) :

PS4='+ $(date "+%s.%N")\011 '
exec 3>&2 2>/tmp/bashstart.$$.log
set -x

加

set +x
exec 2>&3 3>&-

在 ~/.bashrc的末尾(或者在您希望跟踪停止的任何 Bash 脚本的末尾)。\011是一个八进制制表符。

您应该在 /tmp/bashstart.PID.log中获得一个跟踪日志，其中显示每个执行的命令的 second. nanoseconds 时间戳。一次与下一次的不同之处在于中间步骤所花费的时间。

当您缩小范围时，您可以稍后移动 set -x，然后移动 set +x(或者有选择地括起几个感兴趣的部分)。

虽然它不像 GNU date的纳秒那样细粒度，但 Bash 5包含一个变量，它以微秒为单位给出时间。使用它可以避免为每一行生成一个外部可执行文件，并且可以在 Mac 或其他没有 GNU date的地方工作——当然，只要你有 Bash 5。更改 PS4的设置:

PS4='+ $EPOCHREALTIME\011 '

正如@pawamoy 指出的，如果有 Bash 4.1或更高版本，可以使用 BASH_XTRACEFD将跟踪的输出发送到单独的文件描述符。来自 这个答案:

#!/bin/bash


exec 5> command.txt
BASH_XTRACEFD="5"


echo -n "hello "


set -x
echo -n world
set +x


echo "!"

这将导致跟踪输出转到文件 command.txt，使 stdout和 stdout正常输出(或者单独重定向)。

小开

跟踪系统调用通常会有所帮助

strace -c -f ./script.sh

手册上说:

- c 计算每个系统调用的时间、调用和错误，并在程序退出时报告总结。

- f 跟踪子进程..。

这并不是你想要的，也不是一个面向行的分析器会向你展示的，但是它通常会帮助你找到热点。

小开

您可以查看带有 调试条件的 trap命令。有一种方法可以设置与您的命令一起执行的命令。看答案的注释。

小开

分析 巴斯(四个答案)

阅读这篇文章，并且因为 侧写是一个重要的步骤，所以我对这个 Stack Overflow 问题做了一些测试和研究，并且已经发布了答案。

这里有四个以上的答案:

  • 第一个是基于@Dennis Williamson 的想法，但是资源消耗要少得多

  • 第二个是我自己的(在此之前;)

  • 第三个是基于@fgm 的回答，但更准确。

  • 最后使用 script、 scriptreplay和 计时文件。

  • 最后，比较一下最后的性能。

1. 使用 set -x和 date，但使用有限的 叉子

取自@Dennis Williamson 的想法，但是使用以下语法，只有一个初始 fork 指向三个命令:

exec 3>&2 2> >(tee /tmp/sample-time.$$.log |
sed -u 's/^.*$/now/' |
date -f - +%s.%N >/tmp/sample-time.$$.tim)
set -x

这样做将只运行 date一次。有一个快速的演示/测试来展示它是如何工作的:

for i in {1..4};do echo now;sleep .05;done| date -f - +%N

示例脚本:

#!/bin/bash


exec 3>&2 2> >( tee /tmp/sample-$$.log |
sed -u 's/^.*$/now/' |
date -f - +%s.%N >/tmp/sample-$$.tim)
set -x


for ((i=3;i--;));do sleep .1;done


for ((i=2;i--;))
do
tar -cf /tmp/test.tar -C / bin
gzip /tmp/test.tar
rm /tmp/test.tar.gz
done


set +x
exec 2>&3 3>&-

通过运行这个脚本，可以生成两个文件: /tmp/sample-XXXX.log和 /tmp/sample-XXXX.tim(其中 XXXX 是运行脚本的进程 id)。

你可以使用 paste来展示它们:

paste tmp/sample-XXXX.{tim,log}

或者你甚至可以计算不同的时间:

paste <(
while read tim ;do
crt=000000000$((${tim//.}-10#0$last))
printf "%12.9f\n" ${crt:0:${#crt}-9}.${crt:${#crt}-9}
last=${tim//.}
done < sample-time.24804.tim
) sample-time.24804.log


1388487534.391309713        + (( i=3 ))
0.000080807        + (( i-- ))
0.000008312        + sleep .1
0.101304843        + (( 1 ))
0.000032616        + (( i-- ))
0.000007124        + sleep .1
0.101251684        + (( 1 ))
0.000033036        + (( i-- ))
0.000007054        + sleep .1
0.104013813        + (( 1 ))
0.000026959        + (( i-- ))
0.000006915        + (( i=2 ))
0.000006635        + (( i-- ))
0.000006844        + tar -cf /tmp/test.tar -C / bin
0.022655107        + gzip /tmp/test.tar
0.637042668        + rm /tmp/test.tar.gz
0.000823649        + (( 1 ))
0.000011314        + (( i-- ))
0.000006915        + tar -cf /tmp/test.tar -C / bin
0.016084482        + gzip /tmp/test.tar
0.627798263        + rm /tmp/test.tar.gz
0.001294946        + (( 1 ))
0.000023187        + (( i-- ))
0.000006845        + set +x

或两栏:

paste <(
while read tim ;do
[ -z "$last" ] && last=${tim//.} && first=${tim//.}
crt=000000000$((${tim//.}-10#0$last))
ctot=000000000$((${tim//.}-10#0$first))
printf "%12.9f %12.9f\n" ${crt:0:${#crt}-9}.${crt:${#crt}-9} \
${ctot:0:${#ctot}-9}.${ctot:${#ctot}-9}
last=${tim//.}
done < sample-time.24804.tim
) sample-time.24804.log

可能呈现:

 0.000000000  0.000000000   + (( i=3 ))
0.000080807  0.000080807   + (( i-- ))
0.000008312  0.000089119   + sleep .1
0.101304843  0.101393962   + (( 1 ))
0.000032616  0.101426578   + (( i-- ))
0.000007124  0.101433702   + sleep .1
0.101251684  0.202685386   + (( 1 ))
0.000033036  0.202718422   + (( i-- ))
0.000007054  0.202725476   + sleep .1
0.104013813  0.306739289   + (( 1 ))
0.000026959  0.306766248   + (( i-- ))
0.000006915  0.306773163   + (( i=2 ))
0.000006635  0.306779798   + (( i-- ))
0.000006844  0.306786642   + tar -cf /tmp/test.tar -C / bin
0.022655107  0.329441749   + gzip /tmp/test.tar
0.637042668  0.966484417   + rm /tmp/test.tar.gz
0.000823649  0.967308066   + (( 1 ))
0.000011314  0.967319380   + (( i-- ))
0.000006915  0.967326295   + tar -cf /tmp/test.tar -C / bin
0.016084482  0.983410777   + gzip /tmp/test.tar
0.627798263  1.611209040   + rm /tmp/test.tar.gz
0.001294946  1.612503986   + (( 1 ))
0.000023187  1.612527173   + (( i-- ))
0.000006845  1.612534018   + set +x

2. 在 最近 GNU/Linux 内核中使用 trap debug和 /proc/timer_list，没有 叉子。

在 GNU/Linux最近的内核中，您可以找到一个名为 timer_list的 /proc文件:

grep 'now at\|offset' /proc/timer_list
now at 5461935212966259 nsecs
.offset:     0 nsecs
.offset:     1383718821564493249 nsecs
.offset:     0 nsecs

其中当前时间是 5461935212966259 + 1383718821564493249的总和，但以纳秒为单位。

因此，对于计算 过去的时间，不需要知道偏移量。

对于这类作业，我编写了 Bash (V2)，它的来源是以下语法:

source elap.bash-v2

或者

. elap.bash-v2 init

(请参阅完整语法的注释)

所以你可以简单地在你的脚本上添加这一行:

. elap.bash-v2 trap2

一个小例子:

#!/bin/bash


. elap.bash-v2 trap


for ((i=3;i--;));do sleep .1;done


elapCalc2
elapShowTotal \\e[1mfirst total\\e[0m


for ((i=2;i--;))
do
tar -cf /tmp/test.tar -C / bin
gzip /tmp/test.tar
rm /tmp/test.tar.gz
done


trap -- debug
elapTotal \\e[1mtotal time\\e[0m

请告诉我的主人:

 0.000947481 Starting
0.000796900 ((i=3))
0.000696956 ((i--))
0.101969242 sleep .1
0.000812478 ((1))
0.000755067 ((i--))
0.103693305 sleep .1
0.000730482 ((1))
0.000660360 ((i--))
0.103565001 sleep .1
0.000719516 ((1))
0.000671325 ((i--))
0.000754856 elapCalc2
0.316018113 first total
0.000754787 elapShowTotal \e[1mfirst total\e[0m
0.000711275 ((i=2))
0.000683408 ((i--))
0.075673816 tar -cf /tmp/test.tar -C / bin
0.596389329 gzip /tmp/test.tar
0.006565188 rm /tmp/test.tar.gz
0.000830217 ((1))
0.000759466 ((i--))
0.024783966 tar -cf /tmp/test.tar -C / bin
0.604119903 gzip /tmp/test.tar
0.005172940 rm /tmp/test.tar.gz
0.000952299 ((1))
0.000827421 ((i--))
1.635788924 total time
1.636657204 EXIT

使用 trap2而不是 trap作为 来源命令的参数:

#!/bin/bash


. elap.bash-v2 trap2
...

将呈现两列 最后一个命令和总数:

 0.000894541      0.000894541 Starting
0.001306122      0.002200663 ((i=3))
0.001929397      0.004130060 ((i--))
0.103035812      0.107165872 sleep .1
0.000875613      0.108041485 ((1))
0.000813872      0.108855357 ((i--))
0.104954517      0.213809874 sleep .1
0.000900617      0.214710491 ((1))
0.000842159      0.215552650 ((i--))
0.104846890      0.320399540 sleep .1
0.000899082      0.321298622 ((1))
0.000811708      0.322110330 ((i--))
0.000879455      0.322989785 elapCalc2
0.322989785 first total
0.000906692      0.323896477 elapShowTotal \e[1mfirst total\e[0m
0.000820089      0.324716566 ((i=2))
0.000773782      0.325490348 ((i--))
0.024752613      0.350242961 tar -cf /tmp/test.tar -C / bin
0.596199363      0.946442324 gzip /tmp/test.tar
0.003007128      0.949449452 rm /tmp/test.tar.gz
0.000791452      0.950240904 ((1))
0.000779371      0.951020275 ((i--))
0.030519702      0.981539977 tar -cf /tmp/test.tar -C / bin
0.584155405      1.565695382 gzip /tmp/test.tar
0.003058674      1.568754056 rm /tmp/test.tar.gz
0.000955093      1.569709149 ((1))
0.000919964      1.570629113 ((i--))
1.571516599 total time
0.001723708      1.572352821 EXIT

3. 使用 Strace

是的，Strace可以做到这一点:

strace -q -f -s 10 -ttt sample-script 2>sample-script-strace.log

但它可以制造很多东西！

wc sample-script-strace.log
6925  57637 586518 sample-script-strace.log

使用更受限制的命令:

strace -f -s 10 -ttt -eopen,access,read,write ./sample-script 2>sample-script-strace.log

将倾倒一个较轻的原木:

  4519  36695 374453 sample-script-strace.log

根据你所搜索的内容，你可能会有更多的限制:

 strace -f -s 10 -ttt -eaccess,open ./sample-script 2>&1 | wc
189    1451   13682

阅读它们会有点困难:

{
read -a first
first=${first//.}
last=$first
while read tim line;do
crt=000000000$((${tim//.}-last))
ctot=000000000$((${tim//.}-first))
printf "%9.6f %9.6f %s\n" ${crt:0:${#crt}-6}.${crt:${#crt}-6} \
${ctot:0:${#ctot}-6}.${ctot:${#ctot}-6} "$line"
last=${tim//.}
done
} < <(
sed </tmp/sample-script.strace -e '
s/^ *//;
s/^\[[^]]*\] *//;
/^[0-9]\{4\}/!d
')


0.000110  0.000110 open("/lib/x86_64-linux-gnu/libtinfo.so.5", O_RDONLY) = 4
0.000132  0.000242 open("/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY) = 4
0.000121  0.000363 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY) = 4
0.000462  0.000825 open("/dev/tty", O_RDWR|O_NONBLOCK) = 4
0.000147  0.000972 open("/usr/lib/locale/locale-archive", O_RDONLY) = 4
...
0.000793  1.551331 open("/etc/ld.so.cache", O_RDONLY) = 4
0.000127  1.551458 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY) = 4
0.000545  1.552003 open("/usr/lib/locale/locale-archive", O_RDONLY) = 4
0.000439  1.552442 --- SIGCHLD (Child exited) @ 0 (0) ---

原来的 Bash 脚本不是那么容易遵循在这个..。

4. 使用 script、 scriptreplay和 计时文件

对于调试脚本，我经常使用:

script -t script.log 2>script.tim -c 'bash -x /path/script.sh'

作为 BSD 实用程序的一部分，script(和 scriptreplay)是一个非常古老的工具，可用于分析 bash，只占用非常小的内存。

小样本:

script -t script.log 2>script.tim -c 'bash -x -c "
for ((i=3;i--;));do sleep .1;done


for ((i=2;i--;)) ;do
tar -cf /tmp/test.tar -C / bin
gzip /tmp/test.tar
rm /tmp/test.tar.gz
done
"'

将产生:

Script started on Fri Mar 25 08:29:37 2016
+ (( i=3 ))
+ (( i-- ))
+ sleep .1
+ (( 1 ))
+ (( i-- ))
+ sleep .1
+ (( 1 ))
+ (( i-- ))
+ sleep .1
+ (( 1 ))
+ (( i-- ))
+ (( i=2 ))
+ (( i-- ))
+ tar -cf /tmp/test.tar -C / bin
+ gzip /tmp/test.tar
+ rm /tmp/test.tar.gz
+ (( 1 ))
+ (( i-- ))
+ tar -cf /tmp/test.tar -C / bin
+ gzip /tmp/test.tar
+ rm /tmp/test.tar.gz
+ (( 1 ))
+ (( i-- ))
Script done on Fri Mar 25 08:29:39 2016

并生成两个文件:

ls -l script.*
-rw-r--r-- 1 user user 450 Mar 25 08:29 script.log
-rw-r--r-- 1 user user 177 Mar 25 08:29 script.tim

文件 script.log包含所有的跟踪和 script.tim是 计时文件:

head -n 4 script.*
==> script.log <==
Script started on Fri Mar 25 08:29:37 2016
+ (( i=3 ))
+ (( i-- ))
+ sleep .1


==> script.tim <==
0.435331 11
0.000033 2
0.000024 11
0.000010 2

您可以通过日志文件的第一行和最后一行和/或通过在计时文件中汇总时间来查看总时间执行情况:

head -n1 script.log ;tail -n1 script.log
Script started on Fri Mar 25 08:29:37 2016
Script done on Fri Mar 25 08:29:39 2016


sed < script.tim  's/ .*$//;H;${x;s/\n/+/g;s/^\+//;p};d' | bc -l
2.249755

在计时文件中，第二个值是相应日志文件中的下一个字节数。这使您可以选择使用 加速因子来处理日志文件:

scriptreplay script.{tim,log}

或者

scriptreplay script.{tim,log} 5

或者

scriptreplay script.{tim,log} .2

并排显示时间和命令也有点复杂:

exec 4<script.log
read -u 4 line
echo $line ;while read tim char;do
read -u 4 -N $char -r -s line
echo $tim $line
done < script.tim &&
while read -u 4 line;do
echo $line
done;exec 4<&-
Script started on Fri Mar 25 08:28:51 2016
0.558012 + (( i=3 ))
0.000053
0.000176 + (( i-- ))
0.000015
0.000059 + sleep .1
0.000015
+ sleep .1) + (( 1 ))
+ sleep .1) + (( 1 ))
+ tar -cf /tmp/test.tar -C / bin
0.035024 + gzip /tmp/test.tar
0.793846 + rm /tmp/test.tar.gz
+ tar -cf /tmp/test.tar -C / bin
0.024971 + gzip /tmp/test.tar
0.729062 + rm /tmp/test.tar.gz
+ (( i-- )) + (( 1 ))
Script done on Fri Mar 25 08:28:53 2016

围绕 ScriptReplay: 如何操作“脚本”命令创建的计时和打字脚本文件？的进一步工作

测试和结论

为了进行测试，我在 你好，世界下载了 第二示例。这个脚本在我的主机上大约需要0.72秒才能完成。

我在剧本的开头添加了以下内容:

  • 通过 elap.bash函数

     #!/bin/bash


source elap.bash-v2 trap2


eval "BUNCHS=(" $(perl <<EOF | gunzip
...

  • 由 set -x和 PS4

     #!/bin/bash


PS4='+ $(date "+%s.%N")\011 '
exec 3>&2 2>/tmp/bashstart.$$.log
set -x


eval "BUNCHS=(" $(perl <<EOF | gunzip
...

  • 通过 set -x和 < em > 初始 fork to long exec 命令

     #!/bin/bash


exec 3>&2 2> >(tee /tmp/sample-time.$$.log |
sed -u 's/^.*$/now/' |
date -f - +%s.%N >/tmp/sample-time.$$.tim)
set -x


eval "BUNCHS=(" $(perl <<EOF | gunzip

  • 由 script(及 set +x)

     script -t helloworld.log 2>helloworld.tim -c '
bash -x complex_helloworld-2.sh' >/dev/null

时代杂志

然后比较执行时间(在我的主机上) :

  • 直接 0.72秒
  • Bash 13.18秒
  • Set + date@PS4 54.61秒
  • Set + 1 fork 1.45 sec 设置 + 1 fork 1.45秒
  • 脚本和 计时文件 2.19秒
  • Strace 4.47秒

输出

  • 通过 elap.bash函数
         0.000950277      0.000950277 Starting
0.007618964      0.008569241 eval "BUNCHS=(" $(perl <<EOF | gunzi
0.005259953      0.013829194 BUNCHS=("2411 1115 -13 15 33 -3 15 1
0.010945070      0.024774264 MKey="V922/G/,2:"
0.001050990      0.025825254 export RotString=""
0.004724348      0.030549602 initRotString
0.001322184      0.031871786 for bunch in "${BUNCHS[@]}"
0.000768893      0.032640679 out=""
0.001008242      0.033648921 bunchArray=($bunch)
0.000741095      0.034390016 ((k=0))
  • 由 set -x和 PS4
    ++ 1388598366.536099290  perl
++ 1388598366.536169132  gunzip
+ 1388598366.552794757   eval 'BUNCHS=(' '"2411' 1115 -13 15 33 -3 15 1
++ 1388598366.555001983  BUNCHS=("2411 1115 -13 15 33 -3 15 13111 -6 1
+ 1388598366.557551018   MKey=V922/G/,2:
+ 1388598366.558316839   export RotString=
+ 1388598366.559083848   RotString=
+ 1388598366.560165147   initRotString
+ 1388598366.560942633   local _i _char
+ 1388598366.561706988   RotString=
  • 由 set -x和 初始 fork 到 long exec 命令(和我的第二个 paste样本脚本)
     0.000000000  0.000000000    ++ perl
0.008141159  0.008141159    ++ gunzip
0.000007822  0.008148981    + eval 'BUNCHS=(' '"2411' 1115 -13 15 33 -3
0.000006216  0.008155197    ++ BUNCHS=("2411 1115 -13 15 33 -3 15 13111
0.000006216  0.008161413    + MKey=V922/G/,2:
0.000006076  0.008167489    + export RotString=
0.000006007  0.008173496    + RotString=
0.000006006  0.008179502    + initRotString
0.000005937  0.008185439    + local _i _char
0.000006006  0.008191445    + RotString=
  • 作者: strace
     0.000213  0.000213 brk(0)                = 0x17b6000
0.000044  0.000257 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000047  0.000304 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7faf1c0dc000
0.000040  0.000344 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
0.000040  0.000384 open("/etc/ld.so.cache", O_RDONLY) = 4
...
0.000024  4.425049 close(10)             = 0
0.000042  4.425091 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
0.000028  4.425119 read(255, "", 4409)   = 0
0.000058  4.425177 exit_group(0)         = ?
  • 作者: script
    Le script a débuté sur ven 25 mar 2016 09:18:35 CET
0.667160 ++ gunzip
0.000025
0.000948 ++ perl
0.000011
0.005338 + eval 'BUNCHS=(' '"2411' 1115 -13 15 33 -3 15 13111 -6 1 111 4
0.000044 1223 15 3311 121121 17 3311 121121 1223 3311 121121 17 3311 121
0.000175 ++ BUNCHS=("2411 1115 -13 15 33 -3 15 13111 -6 15 1114 15 12211
0.000029 1 1321 12211 412 21211 33 21211 -2 15 2311 11121 232 121111 122
0.000023 4 3311 121121 12221 3311 121121 12221 3311 121121 1313 -6 15 33

结论

嗯! 如果我的 纯粹的巴斯脚本比 分叉到每个命令的日期快，那么使用它意味着对每个命令都要进行一些操作。

为日志记录和存储专用独立进程的方法显然更有效。

Strace 是一种有趣的方式，更详细，但难以阅读。

带有 scriptreplay和加速因子的 script也非常好，但是精度不如基于控制台交换而不是进程执行的 script，但是非常轻便和高效(不同的目标，不同的用法)。

最后，我认为在可读性和性能方面，更有效的是 set + 1 fork，这是第一个答案，但总的来说，根据具体情况，我有时也使用 strace和/或 script。

小开

Time、 xtrace、 bash-x、 set -x和 set +x(2.3. 调试 Bash 脚本)仍然是调试脚本的常规方法。

尽管如此，为了扩大我们的视野或者更精确地控制资源的使用，我们可以检查一些 Linux (这是互联网上众多列表中的一个)下可用的调试和分析系统: 例如，瓦尔荷恩，专门用于内存调试，或者 Sysprof来分析整个系统:

对于 sysprof:

使用 sysprof，您可以分析在您的计算机上运行的所有应用程序，包括多线程或多处理应用程序..。

然后，选择您感兴趣的子流程的分支。

对于瓦尔格伦:

有了更多的健身房，我们似乎有可能把我们通常从二进制文件安装的程序(例如 OpenOffice)制作成 看得见到 Valgrind。

从 Valgrind 常见问题中可以读出，如果明确要求，瓦尔恩将对 子进程进行概要分析。

即使在默认情况下它只能追踪最高级别的过程, 因此，如果使用 你的程序是由一个 shell 脚本启动的、 Perl 脚本或类似的代码，Val哪里将跟踪 shell 或 Perl 解释器，或等价的..。

它将在启用此选项的情况下执行此操作:

 --trace-children=yes

其他参考资料:

小开

Alan Hargreaves的这篇文章 描述了使用 DTrace 提供程序分析 Bourne shell 脚本的方法。据我所知，这适用于 索拉里斯和 OpenSolaris(参见: /bin/sh DTrace 提供程序)。

因此，给出以下 DTrace 脚本(基于 原版的的 sh_flowtime.d at GH) :

#!/usr/sbin/dtrace -Zs
#pragma D option quiet
#pragma D option switchrate=10


dtrace:::BEGIN
{
depth = 0;
printf("%s %-20s  %-22s   %s %s\n", "C", "TIME", "FILE", "DELTA(us)", "NAME");
}


sh*:::function-entry
{
depth++;
printf("%d %-20Y  %-22s %*s-> %s\n", cpu, walltimestamp,
basename(copyinstr(arg0)), depth*2, "", copyinstr(arg1));
}


sh*:::function-return
{
printf("%d %-20Y  %-22s %*s<- %s\n", cpu, walltimestamp,
basename(copyinstr(arg0)), depth*2, "", copyinstr(arg1));
depth--;
}


sh*:::builtin-entry
{
printf("%d %-20Y  %-22s %*s   > %s\n", cpu, walltimestamp,
basename(copyinstr(arg0)), depth*2, "", copyinstr(arg1));
}


sh*:::command-entry
{
printf("%d %-20Y  %-22s %*s   | %s\n", cpu, walltimestamp,
basename(copyinstr(arg0)), depth*2, "", copyinstr(arg1));
}

您可以跟踪函数流，包括增量时间。

输出样本:

# ./sh_flowtime.d
C TIME                  FILE                 DELTA(us)  -- NAME
0 2007 Aug 10 18:52:51  func_abc.sh                  0   -> func_a
0 2007 Aug 10 18:52:51  func_abc.sh                 54      > echo
0 2007 Aug 10 18:52:52  func_abc.sh            1022880      | sleep
0 2007 Aug 10 18:52:52  func_abc.sh                 34     -> func_b
0 2007 Aug 10 18:52:52  func_abc.sh                 44        > echo
0 2007 Aug 10 18:52:53  func_abc.sh            1029963        | sleep
0 2007 Aug 10 18:52:53  func_abc.sh                 44       -> func_c
0 2007 Aug 10 18:52:53  func_abc.sh                 43          > echo
0 2007 Aug 10 18:52:54  func_abc.sh            1029863          | sleep
0 2007 Aug 10 18:52:54  func_abc.sh                 33       <- func_c
0 2007 Aug 10 18:52:54  func_abc.sh                 14     <- func_b
0 2007 Aug 10 18:52:54  func_abc.sh                  7   <- func_a

然后使用 sort -nrk7命令，可以对输出进行排序，以显示最耗时的调用。

我不知道是否有任何提供者探测其他 shell，所以做一些研究(GitHub 搜索?)或者，如果你想投入一些时间，你可以根据现有的 嘘例子(见 如何激活 sh DTrace Provider)编写:

小开

在脚本前面添加以下内容:

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

输出文件以毫秒为单位列出命令:

$ tailf ~/logfile
++[389426ms][/home/subtleseeker/.iterm2_shell_integration.bash:96]: __bp_preexec_invoke_exec(): type -t preexec
++[389428ms][/home/subtleseeker/.iterm2_shell_integration.bash:113]: __bp_preexec_invoke_exec(): __bp_set_ret_value 0 /home/subtleseeker/.bashrc
++[389431ms][/home/subtleseeker/.iterm2_shell_integration.bash:1]: __bp_set_ret_value(): return 0
+[389433ms][:69]: tailf /home/subtleseeker/logfile
小开

这是一个非常愚蠢的方法 如果启动在秒范围内 这是一个单一的命令，是缓慢的。 运行 bash -x或 bash -lx(以速度慢者为准) 然后尽可能快地重击输入，直到重击完成初始化。 然后向后滚动，观察空行最多的命令。 那是你的慢命令。


提交答案