Re: Why are long functions slower?

[Bernhard M. Wiedemann]

On 2017-10-15 20:53, Eduardo A. Bustamante López wrote:
> I have some questions:
> 
> 1. Which specific versions of 4.3 and 4.4?
> 2. Did you compile bash from source? (if so, what did you use for CFLAGS and 
> the configure script parameters? are you
>using bash's malloc or the system malloc?)
> 3. ... Or did you use a distro package? (if so, can you provide links to the 
> specific packages used?)


I was testing with the openSUSE Tumbleweed packages, which is probably
compiled with -O2 and pretty standard configure options:
https://build.opensuse.org/package/view_file/openSUSE:Factory/bash/bash.spec
around line 429

> 4. Do you have precise timing information? How specifically did you test? How 
> many iterations? etc

I used the reproducer script in my previous email, containing two
similar functions (one short, one long) that both do nothing in a loop
with N=3
and was comparing the timing of those two on the same bash version.

e.g. for bash-4.3 on a 2.80GHz Core i7 I get

real0m0.271s
user0m0.270s
sys 0m0.003s

real0m0.482s
user0m0.483s
sys 0m0.000s


interestingly, the number of colons has a much larger impact on runtime
than the number of spaces.

Thanks for looking into that.



signature.asc
Description: OpenPGP digital signature

Re: Why are long functions slower?

[Eduardo A . Bustamante López]

On Sun, Oct 15, 2017 at 01:53:15PM -0500, Eduardo A. Bustamante López wrote:
[...]
> From what I can tell, most of the overhead should be in `execute_function' 
> (execute_cmd.c):
> 
> - calls `tc = (COMMAND *)copy_command (function_cell (var));' for every 
> function invocation. For large functions, this
>   means a lot of copying. 
> 
> - It also calls `dispose_command(tc)' to dispose of this temporary COMMAND 
> structure.

Just out of curiosity, I hacked bash to remove the copy_command /
dispose_command overhead (which AFAICT breaks the handling of errexit for 
functions).

I ran the script at the bottom (N = 100). The results:

- Unpatched bash, -O2 & bash malloc: ~263.78ms per function invocation
- Patched bash, -O2 & bash malloc: ~3.36ms per function invocation
- Unpatched bash, -O2 & glibc malloc (2.26-0ubuntu2): ~1.5ms per function 
invocation

So my current guess is that you're comparing a bash built with the internal 
malloc, vs bash built to use glibc's malloc.


BTW, Chet: Is there a reason for all the object copying / destruction, other 
than setting the `flags' attribute in the
COMMAND structure?


dualbus@ubuntu:~/src/gnu$ for bash in ./build/bash ./build-patched/bash; do 
time $bash ~/bash-func/script ; done

real0m26.378s
user0m26.368s
sys 0m0.004s

real0m0.336s
user0m0.332s
sys 0m0.000s

# I ran this after the two above; unpatched bash, --without-bash-malloc
dualbus@ubuntu:~/src/gnu$ for bash in ./build-libcmalloc/bash; do time $bash 
~/bash-func/script ; done

real0m0.150s
user0m0.148s
sys 0m0.000s


dualbus@ubuntu:~/src/gnu$ (cd bash; PAGER= git diff)
diff --git a/execute_cmd.c b/execute_cmd.c
index 8d38378e..cdb2ce6d 100644
--- a/execute_cmd.c
+++ b/execute_cmd.c
@@ -4724,7 +4724,7 @@ execute_function (var, words, flags, fds_to_close, async, 
subshell)
   GET_ARRAY_FROM_VAR ("BASH_LINENO", bash_lineno_v, bash_lineno_a);
 #endif
 
-  tc = (COMMAND *)copy_command (function_cell (var));
+  tc = function_cell (var);
   if (tc && (flags & CMD_IGNORE_RETURN))
 tc->flags |= CMD_IGNORE_RETURN;
 
@@ -4743,7 +4743,6 @@ execute_function (var, words, flags, fds_to_close, async, 
subshell)
   unwind_protect_int (function_line_number);
   unwind_protect_int (return_catch_flag);
   unwind_protect_jmp_buf (return_catch);
-  add_unwind_protect (dispose_command, (char *)tc);
   unwind_protect_pointer (this_shell_function);
   unwind_protect_int (funcnest);
   unwind_protect_int (loop_level);


dualbus@ubuntu:~/src/gnu$ cat ~/bash-func/script
f() {
return
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : : 
: : : : : : : : : : : : : : : : 

Re: Why are long functions slower?

[Eduardo A . Bustamante López]

On Tue, Oct 10, 2017 at 03:46:38PM +0200, Bernhard M. Wiedemann wrote:
> Hi,
> 
> today I was debugging performance issues with a 200KB bash script [1]
> with bash-4.3 and 4.4
> and it seems that much of it came from a function call that took 0.1
> seconds (and it was done in a loop for 37000 files)
> even though it basically just consisted of an
>   if [[ 0 != 0 ]] ; then

Hi Bernhard,

I have some questions:

1. Which specific versions of 4.3 and 4.4?
2. Did you compile bash from source? (if so, what did you use for CFLAGS and 
the configure script parameters? are you
   using bash's malloc or the system malloc?)
3. ... Or did you use a distro package? (if so, can you provide links to the 
specific packages used?)
4. Do you have precise timing information? How specifically did you test? How 
many iterations? etc


From what I can tell, most of the overhead should be in `execute_function' 
(execute_cmd.c):

- calls `tc = (COMMAND *)copy_command (function_cell (var));' for every 
function invocation. For large functions, this
  means a lot of copying. 

- It also calls `dispose_command(tc)' to dispose of this temporary COMMAND 
structure.


There were no changes there between 4.3.30 and 4.4.12. The only noticeable 
change I can see is the addition of the
`restore_funcarray_state' function and `struct func_array_state', used to 
restore the contents of FUNCNAME between
function invocations. Although from my observation, this doesn't seem to have a 
noticeable effect in performance.


signature.asc
Description: PGP signature

Why are long functions slower?

[Bernhard M. Wiedemann]

Hi,

today I was debugging performance issues with a 200KB bash script [1]
with bash-4.3 and 4.4
and it seems that much of it came from a function call that took 0.1
seconds (and it was done in a loop for 37000 files)
even though it basically just consisted of an
  if [[ 0 != 0 ]] ; then


I also wrote this simpler reproducer:

function func1
{
[[ 0 != 0 ]] || return
echo neverdone
}

function func2
{
[[ 0 != 0 ]] || return
echo neverdone
:
:
:
:
:
:
:
:
:
:
:
:
:
:
:
:
:
:
:
:
}

time for i in $(seq 3) ; do
func1 someparameters
done
time for i in $(seq 3) ; do
func2 someparameters
done


showing significant difference in execution time with the longer
function taking 2x to 4x as much time.
Even though the length is comparable, it is not nearly as slow as 0.1s
per call of the original file.

1) could it be that the overall file size or complexity influences the
time it takes for a function to be parsed and executed?

2) is there a way to avoid the slowdown from length of such functions?
I tried
readonly func2
declare -fr func2

but it did not make a difference


Thanks in advance for your insights
Bernhard M.


[1]
https://github.com/g23guy/supportutils/blob/1e89b672d61ac6da5d8cf4a164b529693eab0cd9/bin/supportconfig#L304