如何分析 bash shell 脚本启动缓慢？
声明：本页面是StackOverFlow热门问题的中英对照翻译，遵循CC BY-SA 4.0协议，如果您需要使用它，必须同样遵循CC BY-SA许可，注明原文地址和作者信息，同时你必须将它归于原作者（不是我）：StackOverFlow
原文地址: http://stackoverflow.com/questions/5014823/
Warning: these are provided under cc-by-sa 4.0 license. You are free to use/share it, But you must attribute it to the original authors (not me):
StackOverFlow
How to profile a bash shell script slow startup?
提问by Andrea Spadaccini
My bash shell takes up to 3-4 seconds to start up, while if I start it with --norcit runs immediately.
我的 bash shell 最多需要 3-4 秒才能启动，而如果我用--norc它启动它，它会立即运行。
I started "profiling" /etc/bash.bashrcand ~/.bashrcby manually inserting returnstatements and seeking for speed improvements, but it is not a quantitative process and it is not efficient.
我开始“分析”/etc/bash.bashrc并~/.bashrc通过手动插入return语句并寻求速度改进，但这不是一个量化过程，而且效率不高。
How can I profile my bash scripts and see which commands take most time to start up?
如何分析我的 bash 脚本并查看哪些命令需要最长时间启动？
回答by Paused until further notice.
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):
如果您有 GNU date（或其他可以输出纳秒的版本），请在开始时/etc/bash.bashrc（或您想在任何 Bash 脚本中开始跟踪的任何地方）执行此操作：
PS4='+ $(date "+%s.%N")1 '
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 \011is an octal tab character.
在~/.bashrc（或在您希望跟踪停止的任何 Bash 脚本部分的末尾）。该\011是一个八进制制表符。
You should get a trace log in /tmp/bashstart.PID.logthat 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.
您应该得到一个跟踪日志，/tmp/bashstart.PID.log其中显示了已执行的每个命令的 seconds.nanoseconds 时间戳。从一次到下一次的差异是干预步骤所花费的时间。
As you narrow things down, you can move set -xlater and set +xearlier (or bracket several sections of interest selectively).
当您缩小范围时，您可以更set -x晚或set +x更早地移动（或有选择地将几个感兴趣的部分括起来）。
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:
虽然它不像 GNUdate的纳秒那么细粒度，但 Bash 5 包含一个变量，以微秒为单位给出时间。使用它可以避免为每一行生成外部可执行文件，并且可以在 Mac 或其他没有 GNU 的地方运行date——当然，只要你有 Bash 5。更改设置PS4：
PS4='+ $EPOCHREALTIME1 '
As pointed out by @pawamoy, you can use BASH_XTRACEFDto send the output of the trace to a separate file descriptor if you have Bash 4.1 or later. From this answer:
正如@pawamoy 所指出的，BASH_XTRACEFD如果您有 Bash 4.1 或更高版本，您可以使用将跟踪的输出发送到单独的文件描述符。从这个答案：
#!/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.txtleaving stdoutand stdoutto be output normally (or be redirected separately).
这将导致跟踪输出转到文件command.txt离开stdout并stdout正常输出（或单独重定向）。
回答by F. Hauri
Profiling bash(4 answers)
分析bash（4 个回答）
Edit: March 2016add scriptmethod
编辑：2016 年 3 月添加script方法
Reading this and because profilingis an important step, I've done some test and research about this whole SO question and already posted answers.
阅读这篇文章，因为分析是一个重要的步骤，我已经对整个 SO 问题进行了一些测试和研究，并且已经发布了答案。
There is 4+ answer:
有 4+ 个答案：
- 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 answer, but more accurate.
The last use
script,scriptreplayand timing file.Finally, a little comparison of performances at end.
- 第一个基于@DennisWilliamson 的想法，但资源消耗要少得多
- 第二个是我自己的（在此之前；）
- 第三个基于@fgm 的答案，但更准确。
最后使用
script，scriptreplay和计时文件。最后，对最后的表演进行一些比较。
Using set -xand datebut with limited forks
使用set -x和date但有限的叉子
Take from @DennisWilliamson's idea, but with the following syntax, there will only one initial fork to 3 commands:
取自 @DennisWilliamson 的想法，但使用以下语法，只有一个初始 fork 到 3 个命令：
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 dateonly once. There is a quick demo/test to show how it work:
这样做只会运行date一次。有一个快速演示/测试来展示它是如何工作的：
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.logand /tmp/sample-XXXX.tim(where XXXX is process id of running script).
通过运行此脚本，您可以生成 2 个文件：/tmp/sample-XXXX.log和/tmp/sample-XXXX.tim（其中 XXXX 是运行脚本的进程 ID）。
You could present them by using paste:
您可以使用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
Using trap debugand /proc/timer_liston recentGNU/Linux kernels, withoutforks.
在最新的GNU/Linux 内核上使用trap debug和，没有fork。/proc/timer_list
Under GNU/Linux's recent kernels, you may find a /procfile named timer_list:
在GNU/Linux的最新内核下，您可能会找到一个/proc名为的文件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.
其中当前时间是 的总和5461935212966259 + 1383718821564493249，但以纳秒为单位。
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:
对于此类作业，我编写了elap.bash (V2)，其来源如下：
source elap.bash-v2
or
或者
. elap.bash-v2 init
(See comments for full syntax)
（完整语法见评论）
So you could simply add this line at top of your script:
所以你可以简单地在你的脚本顶部添加这一行：
. elap.bash-v2 trap2
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 trap2instead of trapas argument to source command:
使用trap2而不是trap作为源命令的参数：
#!/bin/bash
. elap.bash-v2 trap2
...
Will render two columns last command and total:
将呈现两列last command 和 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
Using strace
使用 strace
Yes, stracecould do the job:
是的，strace可以完成这项工作：
strace -q -f -s 10 -ttt sample-script 2>sample-script-strace.log
But there could make a lot of stuff!
但是可以做很多东西！
wc sample-script-strace.log
6925 57637 586518 sample-script-strace.log
Using more restricted command:
使用更受限制的命令：
strace -f -s 10 -ttt -eopen,access,read,write ./sample-script 2>sample-script-strace.log
Will dump 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 scriptis not so easy to follow in this...
原始的bash 脚本在这方面并不容易遵循......
Using script, scriptreplayand timing file
使用script,scriptreplay和计时文件
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.
作为BSD Utils 的一部分，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
"'
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.logcontain all traces and script.timis the timing file:
文件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
You could see total time execution with first and last lines of logfile and/or by summarizing times in 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 timing file, the second value is number of next bytes in corresponding logfile. This let you the ability of replayinglog 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
Tests and conclusion
测试和结论
To make tests, I've downloaded secondsample at bash complex hello world, this script take approx 0.72 sec to complete on my host.
为了进行测试，我已经在bash complex hello world下载了第二个示例，这个脚本大约需要 0.72 秒才能在我的主机上完成。
I've add at top on of the script one of:
我在脚本的顶部添加了以下内容之一：
by
elap.bashfunction#!/bin/bash source elap.bash-v2 trap2 eval "BUNCHS=(" $(perl <<EOF | gunzip ...by
set -xandPS4#!/bin/bash PS4='+ $(date "+%s.%N")1 ' exec 3>&2 2>/tmp/bashstart.$$.log set -x eval "BUNCHS=(" $(perl <<EOF | gunzip ...by
set -xand 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 | gunzipby
script(andset +x)script -t helloworld.log 2>helloworld.tim -c ' bash -x complex_helloworld-2.sh' >/dev/null
按
elap.bash功能#!/bin/bash source elap.bash-v2 trap2 eval "BUNCHS=(" $(perl <<EOF | gunzip ...由
set -x和PS4#!/bin/bash PS4='+ $(date "+%s.%N")1 ' exec 3>&2 2>/tmp/bashstart.$$.log set -x eval "BUNCHS=(" $(perl <<EOF | gunzip ...by
set -x和初始 fork 到 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
Times
时代
And compare execution times (on my host):
并比较执行时间（在我的主机上）：
- Direct0.72 sec
- elap.bash13.18 sec
- set + date@PS454.61 sec
- set + 1 fork1.45 sec
- script and timing file2.19 sec
- strace4.47 sec
- 直接0.72 秒
- elap.bash13.18 秒
- 设置 + 日期@PS454.61 秒
- 设置 + 1 个叉子1.45 秒
- 脚本和计时文件2.19 秒
- 跟踪4.47 秒
Outputs
输出
by
elap.bashfunction0.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 -xandPS4++ 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 -xand initial fork to long exec command(and my secondpastesample 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
strace0.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
scriptLe 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
按
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=by
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=经过
strace0.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) = ?经过
scriptLe 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 bashis quicker than forking to date on each command, my pure bash implies some operations on each command.
好！如果我的纯 bash比在每个命令上分叉日期更快，那么我的纯 bash 意味着对每个命令进行一些操作。
The way of dedicating an independent process for logging and storing is clearly more efficient.
专用于记录和存储的独立进程的方式显然更有效。
straceis an interesting way, more detailed, but hard to read.
strace是一种有趣的方式，更详细，但难以阅读。
script, with scriptreplayand acceleration factor is very nice too, not same precision as this is based on console exchange instead of process
execution, but very light and efficient (not same goal, not same usage).
script,scriptreplay和加速因子也非常好，与基于控制台交换而不是进程执行的精度不同，但非常轻巧高效（目标不同，用法不同）。
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 specific case, I use sometime straceand/or scripttoo.
最后，我认为在可读性和性能方面更有效的是set + 1 fork，这个答案的第一个，但很好，根据具体情况，我有时strace和/或script也使用。
回答by Fritz G. Mehner
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.
-c 计算每个系统调用的时间、调用和错误，并在程序退出时报告摘要。
-f Trace child processes ...
-f 跟踪子进程...
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.
这并不完全是您想要的，也不是面向线的探查器会向您显示的内容，但它通常有助于找到热点。
回答by Fritz G. Mehner
You may have a look at trapcommand with DEBUGcondition. There is a way to set a command(s) to be executed along with your commands. See the notes to the answer.
您可以查看trap带有DEBUG条件的命令。有一种方法可以设置要与您的命令一起执行的命令。请参阅答案的注释。
回答by Hastur
Time, xtrace, bash -x, set -xand set+x(http://tldp.org/LDP/Bash-Beginners-Guide/html/sect_02_03.html) remain the orthodox way to debug a script.
时间、xtrace、bash -xset -x和set+x( http://tldp.org/LDP/Bash-Beginners-Guide/html/sect_02_03.html) 仍然是调试脚本的正统方式。
Neverteless to enlarge our horizon, it's possible to give a check to some system for debugging and profiling available for the usual Linux programs [here one of the lists], e.g. it should result useful one based on valgrindespecially to debug memory or sysprofto profile the whole system:
无论如何，要扩大我们的视野，可以检查一些系统，用于调试和分析可用于通常的 Linux 程序[这里是列表之一]，例如，它应该会产生基于valgrind 的有用的结果，尤其是调试内存或sysprof以进行分析整个系统：
For sysprof:
对于系统教授：
With sysprof, you can profile all the applications that are running on your machine, including a multithreaded or multiprocessed application...
使用 sysprof，您可以分析机器上运行的所有应用程序，包括多线程或多处理应用程序...
And after to select the branch of sub-processes that you find interesting.
然后选择您感兴趣的子流程分支。
For Valgrind:
With some more gym, it seems it's possible to make visibleto Valgrind some programs that usually we install from binary (e.g. OpenOffice).
对于 Valgrind：
有了更多的健身房，似乎可以让Valgrind看到一些我们通常从二进制安装的程序（例如OpenOffice）。
It's possible to read from the FAQ of valgrindthat Valgrindwill profile the child processesif explicitely requested.
有可能从阅读的valgrind的常见问题是 Valgrind将配置文件中的子进程，如果明确地提出要求。
... 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...
... 即使默认情况下它只跟踪顶级进程，因此如果您的程序由 shell 脚本、Perl 脚本或类似的东西启动，Valgrind 将跟踪 shell、Perl 解释器或等效程序。 ..
It will do it with this option enabled
它会在启用此选项的情况下执行此操作
--trace-children=yes
Additional References:
其他参考资料：
回答by kenorb
This postby Alan Hargreavesdescribes the method of profiling Bourne shell script using DTrace provider. As far as I know this works with Solaris and OpenSolaris (see: /bin/sh DTrace Provider).
该职位由阿兰·哈格里夫斯描述剖析使用DTrace提供Bourne shell脚本的方法。据我所知，这适用于 Solaris 和 OpenSolaris（请参阅：/bin/sh DTrace Provider）。
So given the following dtrace script (sh_flowtime.dat GH based on the original):
因此，给出以下 dtrace 脚本（sh_flowtime.d在基于原始的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));
}
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 -nrk7command, you may sort the output to show most consuming calls.
然后使用sort -nrk7命令，您可以对输出进行排序以显示最消耗的调用。
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 shexample: (see: How to activate sh DTrace Provider?).
我不知道其他 shell 有任何可用的提供程序探测，所以做一些研究（GitHub 搜索？）或者如果你想投入一些时间，你可以根据现有的sh示例编写这样的：（请参阅：如何激活 sh DTrace 提供程序？）。
