Как профилировать сценарий командной оболочки bash при медленном запуске?
Моя оболочка bash запускается до 3-4 секунд, а если я запускаю ее с --norc это бежит немедленно.
Я начал "профилирование" /etc/bash.bashrc а также ~/.bashrc вручную вставив return заявления и стремление к улучшению скорости, но это не количественный процесс и он не эффективен.
Как я могу профилировать свои bash-скрипты и посмотреть, какие команды требуют больше времени для запуска?
8 ответов
Если у вас есть 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, трассировка которого вы хотите остановить).
Вы должны получить журнал трассировки /tmp/bashstart.PID.log который показывает метку времени seconds.nanoseconds каждой команды, которая была выполнена. Разница от одного раза к следующему - это количество времени, которое потребовался для промежуточного шага.
Когда вы сужаете вещи, вы можете двигаться set -x позже и set +x ранее (или выборочно выделите несколько интересующих разделов).
Профилирование Bash (4 ответа)
Изменить: март 2016 добавить script метод
Прочитав это и потому, что профилирование является важным шагом, я провел несколько тестов и исследований по всему этому вопросу SO и уже опубликовал ответы.
Есть 4+ ответа:
- Первый основан на идее @DennisWilliamson, но с гораздо меньшим потреблением ресурсов.
- Второй был моим (до этого;)
- Третий основан на ответе @fgm, но более точен.
Последнее использование
script,scriptreplayи файл времени.Наконец, небольшое сравнение выступлений в конце.
С помощью set -x а также date но с ограниченными вилками
Возьмите идею @DennisWilliamson, но со следующим синтаксисом будет только один начальный ответвление на 3 команды:
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 - идентификатор процесса запущенного скрипта).
Вы можете представить их с помощью 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
С помощью trap debug а также /proc/timer_list на последних ядрах GNU/Linux, без вилок.
В последних ядрах 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
Где текущее время является суммой 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
Сделать рендер на моем хосте:
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
С помощью 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 не так прост в этом...
С помощью script, scriptreplay и файл времени
В составе 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
"'
Будет производить:
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
Тесты и заключение
Чтобы сделать тесты, я скачал второй пример в bash complex hello world, этот сценарий занимает около 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и начальный форк в длинную команду 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 сек
- elap.bash 13,18 сек
- установить + дата @ PS4 54,61 сек
- комплект + 1 вилка 1,45 сек
- файл сценария и времени 2.19 сек
- полоса 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и начальный форк в длинную команду 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
Заключение
Что ж! Если мой чистый bash быстрее, чем разветвление на сегодняшний день для каждой команды, мой чистый bash подразумевает некоторые операции для каждой команды.
Способ выделения независимого процесса для регистрации и хранения явно более эффективен.
strace это интересный способ, более подробный, но трудно читать.
script, с scriptreplay и коэффициент ускорения тоже очень хороший, не такой точности, поскольку он основан на обмене консолей вместо выполнения процесса, но очень легкий и эффективный (не та же цель, не то же самое использование).
Наконец, я думаю, что более эффективным, с точки зрения читаемости и производительности set + 1 fork, Первый из этого ответа, но в порядке, в зависимости от конкретного случая, я использую когда-нибудь strace и / или screen тоже.
Часто помогает отследить системные вызовы
strace -c -f ./script.sh
Из руководства:
-c Подсчитывать время, вызовы и ошибки для каждого системного вызова и сообщать сводные данные о выходе из программы.
-f Следить за дочерними процессами...
Это не совсем то, что вы хотите, и то, что вам покажет линейно-ориентированный профилировщик, но обычно это помогает находить горячие точки.
Вы можете взглянуть на trap команда с условием отладки. Есть способ установить команду (ы) для выполнения вместе с вашими командами. Смотрите примечания к ответу.
Вот очень глупый метод, если запуск находится в диапазоне секунд, и это одна команда, которая медленная. Бежать
bash -xили же
bash -lx(в зависимости от того, что медленно), а затем продолжайте нажимать ввод так быстро, как можете, пока bash не завершит инициализацию. Затем прокрутите назад и обратите внимание на команду, у которой после этого больше всего пустых строк. Это твоя медленная команда.
Добавьте это перед скриптом:
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
Этот пост Алана Харгривза описывает метод профилирования сценария оболочки Bourne с использованием провайдера DTrace. Насколько я знаю, это работает с Solaris и OpenSolaris (см.: / bin / sh Поставщик DTrace).
Итак, учитывая следующий сценарий 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));
}
Вы можете отследить поток функций, включая время дельты.
Образец вывода:
# ./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 Команда, вы можете отсортировать вывод, чтобы показать наиболее потребляющие вызовы.
Я не знаю ни одного провайдера, доступного для других оболочек, поэтому проведите какое-то исследование (поиск GitHub?) Или, если вы хотите потратить некоторое время, вы можете написать такое на основе существующего примера sh: (см.: Как активировать sh Поставщик DTrace?).
Время, извлечение, bash -x, set -x а также set+x ( http://tldp.org/LDP/Bash-Beginners-Guide/html/sect_02_03.html) остаются ортодоксальным способом отладки скрипта.
Тем не менее, чтобы расширить наш кругозор, можно проверить некоторые системы на наличие отладки и профилирования, доступных для обычных программ Linux [здесь один из списков], например, это должно привести к полезной проверке, основанной на valgrind, особенно для отладки памяти или sysprof в профиль. вся система:
Для sysprof:
С помощью sysprof вы можете профилировать все приложения, работающие на вашем компьютере, включая многопоточное или многопроцессорное приложение...
А после выберите ветвь подпроцессов, которые вам интересны.
Для Вальгринда:
Появив немного гимнастики, кажется, что Valgrind может сделать видимыми некоторые программы, которые мы обычно устанавливаем из двоичного кода (например, OpenOffice).
Из FAQ по Valgrind можно прочитать, что Valgrind будет профилировать дочерние процессы, если явно запрошено.
... Даже если по умолчанию он профилирует только трассировку процесса верхнего уровня, и поэтому, если ваша программа запускается сценарием оболочки, сценарием Perl или чем-то подобным, Valgrind будет отслеживать оболочку, или интерпретатор Perl, или его эквивалент...
Это будет сделано при включенной опции
--trace-children=yes
Дополнительные ссылки:
- Valgrind инструкция.
- Некоторые новости об интерфейсах KCachegrind и Callgrind или также здесь, все еще используемые, как сообщается в вики из CERN
- Руководство по GDB . для gdb это может быть полезно для профиля c, C++ программа вызывается скриптом.