L_bash_profile provides deterministic profiling of Bash programs. A profile is contains the whole trace of execution of a particular bash script with timestamp of each executed command. Such profile can be formatted into reports to find code hot-spots.
$ L_bash_profile profile -o ./profile.txt 'i=0; while ((i < 100)); do ((i++)); done'
PROFILING: i=0; while ((i < 100)); do ((i++)); done to ./profile.txt
PROFING ENDED, output in /dev/stdout
$ L_bash_profile analyze ./profile.txt
Top 3 cummulatively longest commands:
percent spent_us cmd calls spentPerCall topCaller1 topCaller2 topCaller3 example
--------- ---------- ----------- ------- -------------- ------------ ------------ ------------ ---------
50.1513 3_148 ((i < 100)) 101 31.1683 101 ~:13
49.4504 3_104 ((i++)) 100 31.04 100 ~:13
0.955871 60 i=0 1 60 1 ~:13
Script executed in 0:00:00.006277us, 202 instructions, 0 functions.
- generate dot callgraph
- print longest commands
- print longest functions
- generate python profile file
pipx install L_bash_profile
Executes a given script under profiling.
Profiling just executes a bash -c script that spcifies DEBUG trap that executes a command that prints timestamp, current command, and context to the given file. After setup, the script executes the commands given on command line.
To profile a script, you have to execute it in current shell context source ./yourscript args.
Analyses the prifiling information, printing commands and function hotspots.
Additionally it can generate a dot graph from the calls, for example:
$ L_bash_profile profile 'f() { sleep 0.1; }; g() { sleep 0.1; f; f; }; b() { f; g; }; b' | L_bash_profile analyze --dot profile.dot
PROFILING: f() { sleep 0.1; }; g() { sleep 0.1; f; f; }; b() { f; g; }; b to /dev/stdout
PROFING ENDED, output in /dev/stdout
Top 4 cummulatively longest commands:
percent spent_us cmd calls spentPerCall topCaller1 topCaller2 topCaller3 example
----------- ---------- --------- ------- -------------- ------------ ------------ ------------ --------------
133.307 405_612 sleep 0.1 4 101403 f 3 g 1 environment:13
0.132777 404 f 6 67.3333 f 3 g 2 b 1 environment:13
0.0374667 114 g 2 57 b 1 g 1 environment:13
0.0348375 106 b 2 53 1 b 1 ~:13
Top 3 cummulatively longest functions:
percent spent_us funcname calls spentPerCall instructions instructionsPerCall example
----------- ---------- ---------- ------- -------------- -------------- --------------------- --------------
100.093 304_552 f 3 101517 6 2 environment:13
33.3493 101_472 g 1 101472 4 4 environment:13
0.0492983 150 b 1 150 3 3 environment:13
Script executed in 0:00:00.304270us, 14 instructions, 3 functions.
Generates a profile.dot file that can be viewed:
Top 20 cummulatively longest commands:
percent spent_us cmd calls spentPerCall topCaller1 topCaller2 topCaller3 example
--------- ---------- -------------------------------------------------- ------- -------------- ---------------------------------- --------------------------------------- ------------------------- --------------------------
5.47741 115_763 "${@:2}" 1794 64.5279 L_assert2 1025 L_is_valid_variable_name 293 L_regex_match 293 ../L_lib/bin/L_lib.sh:406
4.45483 94_151 declare -p _L_optspec 174 541.098 _L_argparse_split 159 _L_argparse_parse_args_short_option 15 ../L_lib/bin/L_lib.sh:2819
3.70534 78_311 (($#)) 1292 60.6122 _L_abbreviation_v 368 L_args_contain 356 _L_argparse_split 292 ../L_lib/bin/L_lib.sh:3772
3.23247 68_317 shift 1180 57.8958 _L_abbreviation_v 368 L_args_contain 356 _L_argparse_split 200 ../L_lib/bin/L_lib.sh:662
2.54289 53_743 L_assert2 "$(declare -p _L_optspec)" L_var_is_se.. 134 401.067 _L_argparse_split 67 L_assert2 67 ../L_lib/bin/L_lib.sh:2728
1.75324 37_054 L_assert2 L_regex_match "${!3}" "^[^=]*=[(].*[).. 586 63.2321 L_nestedasa_get 293 L_assert2 293 ../L_lib/bin/L_lib.sh:1828
1.62293 34_300 L_assert2 L_is_valid_variable_name "$1" 586 58.5324 L_nestedasa_get 293 L_assert2 293 ../L_lib/bin/L_lib.sh:1827
1.59913 33_797 [[ "$1" =~ ^[a-zA-Z_][a-zA-Z0-9_]*$ ]] 311 108.672 L_is_valid_variable_name 311 ../L_lib/bin/L_lib.sh:583
1.43783 30_388 [[ "$1" =~ $2 ]] 293 103.713 L_regex_match 293 ../L_lib/bin/L_lib.sh:311
1.33175 28_146 _L_optspec_declare_p=$(declare -p _L_optspec) 44 639.682 _L_argparse_split 44 ../L_lib/bin/L_lib.sh:2826
1.23456 26_092 declare -n _L_asa="$1" 435 59.9816 L_asa_has 375 L_asa_is_empty 50 _L_asa_get_v 5 ../L_lib/bin/L_lib.sh:1734
1.15995 24_515 _L_argparse_parser_next_option _L_i _L_optspec 428 57.278 _L_argparse_parser_next_option 214 _L_argparse_parse_args_set_defaults 108 _L_argparse_parse_args 77 ../L_lib/bin/L_lib.sh:3104
1.14149 24_125 L_asa_has _L_parser "option$_L_i" 428 56.3668 _L_argparse_parser_next_option 214 L_asa_has 214 ../L_lib/bin/L_lib.sh:2909
1.1379 24_049 [[ -n "${_L_asa["$2"]+yes}" ]] 375 64.1307 L_asa_has 375 ../L_lib/bin/L_lib.sh:1735
1.13501 23_988 eval "$1=${!3#*=}" 293 81.8703 L_nestedasa_get 293 ../L_lib/bin/L_lib.sh:1829
1.11774 23_623 [[ $1 != _L_asa ]] 435 54.3057 L_asa_has 375 L_asa_is_empty 50 _L_asa_get_v 5 ../L_lib/bin/L_lib.sh:1734
1.03428 21_859 [[ "$1" = "$needle" ]] 343 63.7289 L_args_contain 343 ../L_lib/bin/L_lib.sh:664
0.950999 20_099 jq -r .v 6 3349.83 t 6 ../L_lib/bin/L_lib.sh:949
0.924124 19_531 _L_handle_v "$@" 310 63.0032 _L_handle_v 155 L_abbreviation 74 L_max 18 ../L_lib/bin/L_lib.sh:556
0.910781 19_249 _"${FUNCNAME[1]}"_v "${@:3}" 288 66.8368 _L_handle_v 144 _L_abbreviation_v 74 _L_max_v 18 ../L_lib/bin/L_lib.sh:341
Top 20 cummulatively longest functions:
percent spent_us funcname calls spentPerCall instructions instructionsPerCall example
--------- ---------- ----------------------------------- ------- -------------- -------------- --------------------- --------------------------
21.1877 447_794 _L_argparse_split 92 4867.33 4071 44.25 ../L_lib/bin/L_lib.sh:2685
6.31623 133_491 L_assert2 1025 130.235 2050 2 ../L_lib/bin/L_lib.sh:406
5.26407 111_254 _L_unittest_internal 175 635.737 1762 10.0686 ../L_lib/bin/L_lib.sh:1910
4.99153 105_494 L_nestedasa_get 293 360.048 1465 5 ../L_lib/bin/L_lib.sh:1827
4.17789 88_298 L_args_contain 117 754.684 1406 12.0171 ../L_lib/bin/L_lib.sh:662
4.11675 87_006 L_asa_has 375 232.016 1500 4 ../L_lib/bin/L_lib.sh:1734
3.86934 81_777 _L_abbreviation_v 74 1105.09 1379 18.6351 ../L_lib/bin/L_lib.sh:835
3.73776 78_996 _L_argparse_parse_args 27 2925.78 1326 49.1111 ../L_lib/bin/L_lib.sh:3324
2.82215 59_645 L_argparse 24 2485.21 880 36.6667 ../L_lib/bin/L_lib.sh:3354
2.808 59_346 _L_handle_v 154 385.364 929 6.03247 ../L_lib/bin/L_lib.sh:335
2.39025 50_517 L_is_valid_variable_name 311 162.434 622 2 ../L_lib/bin/L_lib.sh:583
2.34809 49_626 _L_argparse_parser_next_option 214 231.897 856 4 ../L_lib/bin/L_lib.sh:2907
2.26155 47_797 L_argparse_print_help 12 3983.08 836 69.6667 ../L_lib/bin/L_lib.sh:2563
2.1893 46_270 L_regex_match 293 157.918 586 2 ../L_lib/bin/L_lib.sh:310
1.62719 34_390 _L_argparse_parser_next_argument 123 279.593 588 4.78049 ../L_lib/bin/L_lib.sh:2920
1.52002 32_125 L_var_is_set 163 197.086 489 3 ../L_lib/bin/L_lib.sh:508
1.41668 29_941 _L_argparse_parse_args_short_option 10 2994.1 260 26 ../L_lib/bin/L_lib.sh:3167
1.30435 27_567 t 5 5513.4 41 8.2 ../L_lib/bin/L_lib.sh:946
1.23073 26_011 _L_argparse_parse_args_set_defaults 27 963.37 389 14.4074 ../L_lib/bin/L_lib.sh:3104
1.13184 23_921 _L_list_functions_with_prefix_v 1 23921 455 455 ../L_lib/bin/L_lib.sh:560
Script executed in 0:00:02.113461us, 28867 instructions, 123 functions.
$ L_bash_profile profile -n500 -b 'f() { "$@"; }; g() { "$@"; }; i=1' 'f eval "(($i))"; g test "$i" = 0;' | L_bash_profile analyze
PROFILING: 'f eval "(($i))"; g test "$i" = 0;' to /dev/stdout
PROFING ENDED, output in /dev/stdout
Top 6 cummulatively longest commands:
percent spent_us cmd calls spentPerCall topCaller1 topCaller2 topCaller3 example
--------- ---------- -------------- ------- -------------- ------------ ------------ ------------ -------------
31.4807 14_121 'test 1 = 0' 500 28.242 g 500 environment:6
18.8269 8_445 '(( 1 ))' 500 16.89 f 500 environment:6
17.2329 7_730 'f eval ((1))' 500 15.46 > 500 <:7
16.689 7_486 'g test 1 = 0' 500 14.972 > 500 <:7
15.6701 7_029 'eval ((1))' 500 14.058 f 500 environment:6
0.100321 45 'i=1' 1 45 > 1 <:6
Top 6 cummulatively longest commands per call:
percent spent_us cmd calls spentPerCall topCaller1 topCaller2 topCaller3 example
--------- ---------- -------------- ------- -------------- ------------ ------------ ------------ -------------
0.100321 45 'i=1' 1 45 > 1 <:6
31.4807 14_121 'test 1 = 0' 500 28.242 g 500 environment:6
18.8269 8_445 '(( 1 ))' 500 16.89 f 500 environment:6
17.2329 7_730 'f eval ((1))' 500 15.46 > 500 <:7
16.689 7_486 'g test 1 = 0' 500 14.972 > 500 <:7
15.6701 7_029 'eval ((1))' 500 14.058 f 500 environment:6
Top 2 cummulatively longest functions:
percent spent_us funcname calls spentPerCall instructions instructionsPerCall location
--------- ---------- ---------- ------- -------------- -------------- --------------------- -------------
34.4971 15_474 f 500 30.948 1000 2 environment:6
31.4807 14_121 g 500 28.242 500 1 environment:6
Top 2 cummulatively longest functions per call:
percent spent_us funcname calls spentPerCall instructions instructionsPerCall location
--------- ---------- ---------- ------- -------------- -------------- --------------------- -------------
34.4971 15_474 f 500 30.948 1000 2 environment:6
31.4807 14_121 g 500 28.242 500 1 environment:6
Script executed in 0:00:00.044856us, 2501 instructions, 2 functions.
Licensed under GPLv3. Written by Kamil Cukrowski 2024.