如何分析 Bash shell 脚本启动缓慢?

发布于 2024-10-17 15:22:43 字数 235 浏览 1 评论 0 原文

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

我开始通过手动插入 return 语句并寻求速度改进来“分析”/etc/bash.bashrc~/.bashrc,但它这不是一个定量的过程,而且效率不高。

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

My Bash shell takes up to 3-4 seconds to start up, while if I start it with --norc it runs immediately.

I started "profiling" /etc/bash.bashrc and ~/.bashrc by manually inserting return statements and seeking for speed improvements, but it is not a quantitative process and it is not efficient.

How can I profile my Bash scripts, and see which commands take the most time to execute?

如果你对这篇内容有疑问,欢迎到本站社区发帖提问 参与讨论,获取更多帮助,或者扫码二维码加入 Web 技术交流群。

扫码二维码加入Web技术交流群

发布评论

需要 登录 才能够评论, 你可以免费 注册 一个本站的账号。

评论(8

长伴 2024-10-24 15:22:43

如果您有 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 中获得跟踪日志,其中显示已执行的每个命令的秒数.纳秒时间戳。一次与下一次的差异是中间步骤所花费的时间。

当您缩小范围时,您可以将 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.txtstdoutstdout 正常输出(或单独重定向)。

理解结果

我们可以使用 OpenOffice / Libre calc 查看每个命令所花费的时间以及运行总计,从而很容易发现在下面的示例中,lesspipe 花费了 6 毫秒。

颜色编码calc Spreadsheet

  1. 将生成的日志文件复制粘贴到新的电子表格中。
  2. 在时间戳后插入新列,用于与下一个时间戳的差异;如果您插入了 C 列,请在单元格 C1 中插入 =B2-B1,然后将该单元格复制粘贴到整个 C 列。
  3. 我们可以从 0 开始,而不是使用绝对时间戳,方法是复制第一个时间戳,选择时间戳列,然后按 Ctrl+Shift+V 特殊粘贴 >减去
  4. 您可以颜色值高于X< /a> 红色突出显示长的单个命令。

If you have GNU date (or another version that can output nanoseconds), do this at the beginning of /etc/bash.bashrc (or wherever you'd like to begin a trace in any Bash script):

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

add

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

at the end of ~/.bashrc (or at the end of the section of any Bash script you'd like tracing to stop). The \011 is an octal tab character.

You should get a trace log in /tmp/bashstart.PID.log that shows the seconds.nanoseconds timestamp of each command that was executed. The difference from one time to the next is the amount of time that the intervening step took.

As you narrow things down, you can move set -x later and set +x earlier (or bracket several sections of interest selectively).

Although it's not as fine-grained as GNU date's nanoseconds, Bash 5 includes a variable which gives the time in microseconds. Using it saves you from spawning an external executable for every line and works on Macs or elsewhere that doesn't have GNU date - as long as you have Bash 5, of course. Change the setting of PS4:

PS4='+ $EPOCHREALTIME\011 '

As pointed out by @pawamoy, you can use BASH_XTRACEFD to send the output of the trace to a separate file descriptor if you have Bash 4.1 or later. From this answer:

#!/bin/bash

exec 5> command.txt
BASH_XTRACEFD="5"

echo -n "hello "

set -x
echo -n world
set +x

echo "!"

This will cause the trace output to go to the file command.txt leaving stdout and stdout to be output normally (or be redirected separately).

Making sense of the results

We can see the time each command took, as well as a running total, using OpenOffice / Libre calc, making it easy to spot that in the example below, lesspipe is taking 6ms.

color coded calc spreadsheet

  1. Copy-paste the resulting log file into a new spreadsheet.
  2. Insert a new column after the timestamp for the diff to the next timestamp; if you inserted column C, insert =B2-B1 in cell C1, then copy paste that cell to the whole C column.
  3. Instead of absolute timestamps, we can start things at 0 by copying the first timestamp, selecting the timestamp column, and Ctrl+Shift+V Special Paste > subtract.
  4. You can color values higher than X red to highlight long individual commands.
随梦而飞# 2024-10-24 15:22:43

分析 Bash(四个答案,还有更多...)

阅读本文,因为分析是一个重要的一步,我已经对整个堆栈溢出问题做了一些测试和研究,并已经发布了答案。

这里有四个以上的答案:

  • 第一个是基于@DennisWilliamson的想法,但资源消耗少很多

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

  • 第三个基于@fgm的答案,但更准确。

  • 最后使用scriptscriptreplay计时文件

  • 最后,对最终的性能进行一些比较。

1. 使用 set -xdate 但使用有限的分叉

取自 @DennisWilliamson 的想法,但使用以下语法,将只有一个初始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>&-

通过运行此脚本,您可以创建 2 个文件:/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.使用trap debug/proc/ 最近 GNU/Linux 内核上的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,但以纳秒为单位。

因此,为了计算经过的时间,不需要知道偏移量。

对于此类工作,我写了 elap.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

Do render on my主机:

 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 作为 source 命令:

#!/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.

使用 scriptscriptreplay定时文件

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

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

作为 的一部分>BSD Utilsscript(和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

进一步 :如何操作由“script”命令创建的计时和打字稿文件?

解决 scriptReplay问题 为了

进行测试,我在 Bash 复杂Hello, World 下载了第二个示例!。该脚本在我的主机上大约需要 0.72 秒才能完成。

我在脚本顶部添加了以下之一:

  • by elap.bash function

    <前><代码> #!/bin/bash

    源 elap.bash-v2 trap2

    eval "BUNCHS=(" $(perl <

  • 通过set -xPS4

    <前><代码> #!/bin/bash

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

    eval "BUNCHS=(" $(perl <

  • 通过 set -x初始 fork 到长执行命令
    <前><代码> #!/bin/bash

    执行3>&2 2> >(tee /tmp/sample-time.$$.log |
    sed -u 's/^.*$/now/' | sed -u 's/^.*$/now/' |
    日期 -f - +%s.%N >/tmp/sample-time.$$.tim)
    设置-x

    eval "BUNCHS=(" $(perl <

  • 通过script(和set +x

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

时间

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

  • 直接 0.72 秒
  • elap.bash< /strong> 13.18 秒
  • set + date@PS4 54.61 秒
  • set + 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 -xPS4
    ++ 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 到长执行命令(以及我的第二个 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< /code>
    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

结论

好吧!如果我的纯 Bash 脚本比在每个命令上分支到日期更快,那么使用它意味着对每个命令进行一些操作。

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

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

script,带有scriptreplay和加速因子也非常好,但精度不一样,因为这是基于控制台交换而不是进程执行,但非常轻且高效(不同的目标,不同的用途)。

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

更多技巧

当前正在运行脚本的哪一部分?

当您询问计算机(备份服务器或其他)当前发生的情况时,您可以使用 ps -C 命令,但为了显示当前经过的时间:

ps -C rsync ho lstart,etime
Fri Aug 11 09:57:41 2023    01:38:49

或更好:

ps --sid $(ps ho sid -C rsync) fwho pid,lstart,cmd
2778 Fri Aug 11 09:08:00 2023 /bin/sh -c  ps -C backup.sh >/dev/null || /path/to/backup.sh -q
2780 Fri Aug 11 09:08:00 2023  \_ /bin/bash /path/to/backup.sh -q
7688 Fri Aug 11 09:57:41 2023      \_ rsync -ax --delete --exclude '*/cache/*' --excl

这显示 进程及其当前子进程和所有开始时间

当前正在处理哪些文件或路径

在 Linux 上,您可以浏览 /proc 伪文件系统,用于显示当前由任何进程打开的文件描述符

ls -l /proc/$(($(ps ho pid -C rsync)))/fd |
    sed -ne 's|.* -> /path/to/source||p'

当然,所有这些都必须是使用root权限完成(在root会话中或使用sudo)。

Profiling Bash (four answers, and more...)

Reading this and because profiling is an important step, I've done some test and research about this whole Stack Overflow question and already posted answers.

Here are more than four answers:

  • The first is based on @DennisWilliamson's idea, but with a lot less of resource consumption

  • The second was my own (before this;)

  • The third is based on @fgm's answer, but more accurate.

  • The last uses script, scriptreplay and timing file.

  • Finally, a little comparison of performance at end.

1. Using set -x and date but with limited forks

Take from @DennisWilliamson's idea, but with the following syntax, there will only one initial fork to three commands:

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

Doing this will run date only once. There is a quick demo/test to show how it work:

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

Sample script:

#!/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>&-

By running this script, you make 2 files: /tmp/sample-XXXX.log and /tmp/sample-XXXX.tim (where XXXX is process id of running script).

You could present them by using paste:

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

Or you may even compute diff time:

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

or on two columns:

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

May render:

 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. Using trap debug and /proc/timer_list on recent GNU/Linux kernels, without forks.

Under GNU/Linux's recent kernels, you may find a /proc file named timer_list:

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

Where current time is the sum of 5461935212966259 + 1383718821564493249, but in nanoseconds.

So for computing elapsed time, there is no need of knowing offset.

For this kind of jobs, I wrote elap.bash (V2), that be sourced by the following syntax:

source elap.bash-v2

or

. elap.bash-v2 init

(See comments for the full syntax)

So you could simply add this line at top of your script:

. elap.bash-v2 trap2

A little sample:

#!/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

Do render on my host:

 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

Using trap2 instead of trap as an argument to the source command:

#!/bin/bash

. elap.bash-v2 trap2
...

Will render two columns last command and total:

 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. Using strace

Yes, strace could do the job:

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

But it could make a lot of stuff!

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

Using a more restricted command:

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

Will dump a lighter log:

  4519  36695 374453 sample-script-strace.log

Depending on what you're searching for, you may be more restrictive:

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

Reading them will be a little harder:

{
    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) ---

The original bash script is not so easy to follow in this...

4. Using script, scriptreplay and timing file

For debugging scripts, I often use:

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

As part of BSD Utils, script (and scriptreplay) is a very old tool which can be used to profile bash, with a very small footprint.

Little demo:

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
"'

Will produce:

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

and generate two files:

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

File script.log contain all traces and script.tim is the timing file:

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

You could see the total time execution with the first and last lines of the logfile and/or by summarizing times in the timing file:

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

In the timing file, the second value is the number of the next bytes in corresponding logfile. This let you have the ability of replaying the log file optionally with an acceleration factor:

scriptreplay script.{tim,log}

or

scriptreplay script.{tim,log} 5

or

scriptreplay script.{tim,log} .2

Showing times and commands side-by-side is a little more complex too:

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

Further work around scriptReplay: How to manipulate timing and typescript files created by "script" command?

Tests and conclusion

To make tests, I've downloaded second sample at Bash complex Hello, World!. This script take approx 0.72 seconds to complete on my host.

I've add at the top of the script one of:

  • by elap.bash function

     #!/bin/bash
    
     source elap.bash-v2 trap2
    
     eval "BUNCHS=(" $(perl <<EOF | gunzip
     ...
    
  • by set -x and PS4

     #!/bin/bash
    
     PS4='+ $(date "+%s.%N")\011 '
     exec 3>&2 2>/tmp/bashstart.$.log
     set -x
    
     eval "BUNCHS=(" $(perl <<EOF | gunzip
     ...
    
  • by set -x and initial fork to long exec command

     #!/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
    
  • by script (and set +x)

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

Times

And compare execution times (on my host):

  • Direct 0.72 sec
  • elap.bash 13.18 sec
  • set + date@PS4 54.61 sec
  • set + 1 fork 1.45 sec
  • script and timing file 2.19 sec
  • strace 4.47 sec

Outputs

  • by elap.bash function
         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))
  • by set -x and 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=
  • by set -x and initial fork to long exec command (and my second paste sample script)
     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=
  • by 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)         = ?
  • by 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

Conclusion

Well! If my pure Bash script is quicker than forking to date on each command, using this implies some operations on each command.

The way of dedicating an independent process for logging and storing is clearly more efficient.

strace is an interesting way, more detailed, but hard to read.

script, with scriptreplay and acceleration factor is very nice too, but not the same precision as this is based on a console exchange instead of process execution, but very light and efficient (not same goal, not same usage).

Finally, I think that the more efficient, in readability and performances is set + 1 fork, The first of this answer, but in fine, depending on the specific case, I use sometimes strace and/or script too.

Some more tricks

Which part of script are currently running?

As you are asking about what's currently happen in your machine (backup server or else), you could use ps -C command, but for showing currently elapsed time:

ps -C rsync ho lstart,etime
Fri Aug 11 09:57:41 2023    01:38:49

or better:

ps --sid $(ps ho sid -C rsync) fwho pid,lstart,cmd
2778 Fri Aug 11 09:08:00 2023 /bin/sh -c  ps -C backup.sh >/dev/null || /path/to/backup.sh -q
2780 Fri Aug 11 09:08:00 2023  \_ /bin/bash /path/to/backup.sh -q
7688 Fri Aug 11 09:57:41 2023      \_ rsync -ax --delete --exclude '*/cache/*' --excl

This show the root process with his currents childs and all start times.

Which files or path are currently in progress

On linux, you could browse /proc pseudo filesystem, for showing file descriptors currently open by any process:

ls -l /proc/$(($(ps ho pid -C rsync)))/fd |
    sed -ne 's|.* -> /path/to/source||p'

Of course all this have to be done with root's rights (in a root session or by using sudo).

静若繁花 2024-10-24 15:22:43

它通常有助于跟踪系统调用

strace -c -f ./script.sh

来自手册:

-c 计算每个系统调用的时间、调用和错误,并报告程序退出时的摘要。

-f 跟踪子进程...

这并不完全是您想要的,也不是面向行的分析器向您显示的内容,但它通常有助于找到热点。

It often helps to trace the system calls

strace -c -f ./script.sh

From the manual:

-c Count time, calls, and errors for each system call and report a summary on program exit.

-f Trace child processes ...

This is not exactly what you want and what a line-oriented profiler would show to you but it usually helps to find hot spots.

愛上了 2024-10-24 15:22:43

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

You may have a look at trap command with DEBUG condition. There is a way to set a command(s) to be executed along with your commands. See the notes to the answer.

染柒℉ 2024-10-24 15:22:43

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

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

Add this in the front of the script:

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

The output file lists commands in millisecond scale:

$ 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
清醇 2024-10-24 15:22:43

这是一个非常笨的方法
如果启动在秒范围内
而且这是一个缓慢的命令。
运行 bash -x 或 bash -lx (以较慢者为准)
然后尽可能快地继续 bash 输入,直到 bash 完成初始化。
然后向后滚动并观察后面空行最多的命令。
那是你缓慢的命令。

Here's a very dumb method
if the startup is in the seconds range
and it's a single command that is slow.
Run bash -x or bash -lx (whichever is slow)
and then keep bashing the enter as quickly as you can until bash finishes initialization.
Then scroll back and observe the command which has the most empty lines afterwards.
That's your slow command.

瑶笙 2024-10-24 15:22:43

Alan Hargreaves 的这篇文章介绍了分析 Bourne 的方法使用 DTrace 提供程序的 shell 脚本。据我所知,这适用于 SolarisOpenSolaris (请参阅:/bin/sh DTrace 提供程序)。

因此,给出以下 DTrace 脚本 (sh_flowtime.d< /code> 在 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 示例编写此类探针(请参阅如何激活 sh DTrace 提供程序?):

This post by Alan Hargreaves describes the method of profiling Bourne shell script using a DTrace provider. As far as I know, this works with Solaris and OpenSolaris (see: /bin/sh DTrace Provider).

So given the following DTrace script (sh_flowtime.d at GH based on the original):

#!/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));
}

you can trace the function flow including delta times.

Sample output:

# ./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

Then using sort -nrk7 command, you may sort the output to show most consuming calls.

I'm not aware of any provider probes availably for other shells, so do some research (GitHub search?) or if you want to invest some time, you can write such based on the existing sh example (see How to activate sh DTrace Provider?):

沧笙踏歌 2024-10-24 15:22:43

时间、xtrace、bash -x、set -xset +x2.3. 调试 Bash 脚本)仍然是调试脚本的正统方法。

尽管如此,为了拓宽我们的视野或更精确地控制资源的使用,可以检查 Linux 下可用的一些调试和分析系统 (这里是来自互联网的众多列表之一):例如,Valgrind ,专门用于内存调试,或 sysprof 来分析整个系统系统:

对于 sysprof:

使用 sysprof,您可以分析计算机上运行的所有应用程序,包括多线程或多进程应用程序...

然后,选择您感兴趣的子进程分支。


对于 Valgrind:

有了更多的gym,似乎可以让我们通常从二进制安装的一些程序对 Valgrind 可见(例如 OpenOffice)。

可以从 Valgrind 将分析的Valgrind 常见问题解答中阅读如果明确请求,则子进程

...即使默认情况下它只跟踪顶级进程,
因此,如果你的程序是由 shell 脚本、Perl 脚本或类似的东西启动的,Valgrind 将跟踪 shell、Perl 解释器或等效...

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

 --trace-children=yes

其他参考:

Time, xtrace, bash -x, set -x and set +x (2.3. Debugging Bash scripts) remain the orthodox way to debug a script.

Nevertheless, to broaden our horizon or to have more precise control over the use of resources, it is possible to check some debugging and profiling systems available under Linux (here one of the many lists from internet): for example, Valgrind, specifically for memory debugging, or sysprof to profile the whole system:

For sysprof:

With sysprof, you can profile all the applications that are running on your machine, including a multithreaded or multiprocessed application...

And after, to select the branch of sub-processes that you find interesting.


For Valgrind:

With some more gym, it seems to be possible to make visible to Valgrind some programs that we usually install from binary (e.g. OpenOffice).

It is possible to read from the FAQ of Valgrind that Valgrind will profile the child processes if explicitly requested.

... Even if by default it profiles only traces the top-level process,
and so if your program is started by a shell script, Perl script, or something similar, Valgrind will trace the shell, or the Perl interpreter, or equivalent...

It will do it with this option enabled:

 --trace-children=yes

Additional references:

~没有更多了~
我们使用 Cookies 和其他技术来定制您的体验包括您的登录状态等。通过阅读我们的 隐私政策 了解更多相关信息。 单击 接受 或继续使用网站,即表示您同意使用 Cookies 和您的相关数据。
原文