Performance tests of quoting and dequoting, printf -v turned out slow

Performance tests of quoting and dequoting, printf -v turned out slow

[Sebastian Gniazdowski]

[-- Attachment #1: Type: text/plain, Size: 668 bytes --]

Hello
Two scripts:

- short.txt
Test of quoting, (q)-flag vs. printf -v output '%q '
result: 35 ms vs. 26.6 sec

- Q_short.txt – test of dequoting, (Q)-flag vs. eval "str=$quoted"
result: 25 ms vs. 77 ms

I've compared "printf -v" code to Bash 4.4 and it yields 227 ms there, so much better than 26.6 sec. So while "Bash can serialize/deserialize too, let's compare speed of this method" is interesting thing and I share, performance of "printf -v" on Zsh is troubling. Any idea from where it comes from and if it can be improved?

https://github.com/zdharma/hacking-private/tree/master/quoting

--  
Sebastian Gniazdowski
psprint /at/ zdharma.org

[-- Attachment #2: Q_short.txt --]
[-- Type: text/plain, Size: 574 bytes --]

# This file should be sourced.
# It tests performance of dequoting, (Q) vs eval "s=$quoted"

INPUT='ice as"program" pick"$ZPFX/bin/prll_(qer|bfr)" src"prll.sh" make"install PREFIX=$ZPFX"'
INPUT="${(q)INPUT}"

# The same output
eval "str=$INPUT"
print -r -- "$str"
print -r -- "${(Q)INPUT}"

Qflag() {
    local OUTPUT
    repeat 50000; do
        OUTPUT="${(Q)INPUT}"
    done
}

evl() {
    local OUTPUT
    repeat 50000; do
        eval "OUTPUT=$INPUT"
    done
}

typeset -F2 SECONDS=0
Qflag
print "(Q)-flag result: $SECONDS"

SECONDS=0
evl
print "eval result: $SECONDS"

[-- Attachment #3: short.txt --]
[-- Type: text/plain, Size: 555 bytes --]

# This file should be sourced.
# It tests performance of quoting, (q) vs printf '%q '.

INPUT='ice as"program" pick"$ZPFX/bin/prll_(qer|bfr)" src"prll.sh" make"install PREFIX=$ZPFX"'

# The same output
printf '%q ' "$INPUT"
print
print -r -- "${(q)INPUT}"

qflag() {
    local OUTPUT
    repeat 10000; do
        OUTPUT="${(q)INPUT}"
    done
}

prtf() {
    local OUTPUT
    repeat 10000; do
        printf -v OUTPUT '%q ' "$INPUT"
    done
}

typeset -F3 SECONDS=0
qflag
print "(q)-flag result: $SECONDS"

SECONDS=0
prtf
print "printf result: $SECONDS"

Re: Performance tests of quoting and dequoting, printf -v turned out slow

[Stephane Chazelas]

2018-03-09 07:22:46 +0100, Sebastian Gniazdowski:
> Hello
> Two scripts:
> 
> - short.txt
> Test of quoting, (q)-flag vs. printf -v output '%q '
> result: 35 ms vs. 26.6 sec
> 
> - Q_short.txt – test of dequoting, (Q)-flag vs. eval "str=$quoted"
> result: 25 ms vs. 77 ms
> 
> I've compared "printf -v" code to Bash 4.4 and it yields 227
> ms there, so much better than 26.6 sec. So while "Bash can
> serialize/deserialize too, let's compare speed of this method"
> is interesting thing and I share, performance of "printf -v"
> on Zsh is troubling. Any idea from where it comes from and if
> it can be improved?
[...]

I can't reproduce with zsh 5.4.2 (x86_64-debian-linux-gnu)
compared with 4.4.18(1)-release (x86_64-pc-linux-gnu).
in a en_GB.UTF-8 locale.

FWIW, I find:

$ time INPUT='ice as"program" pick"$ZPFX/bin/prll_(qer|bfr)" src"prll.sh" make"install PREFIX=$ZPFX"' bash -c 'for ((i = 0; i < 50000; i++)); do printf -v OUTPUT %q "$INPUT"; done'
INPUT= bash -c   1.48s user 0.00s system 99% cpu 1.485 total
$ time INPUT='ice as"program" pick"$ZPFX/bin/prll_(qer|bfr)" src"prll.sh" make"install PREFIX=$ZPFX"' zsh -c 'for ((i = 0; i < 50000; i++)); do printf -v OUTPUT %q "$INPUT"; done'
INPUT= zsh -c   0.83s user 0.14s system 99% cpu 0.979 total

What's your version and locale?

-- 
Stephane

Re: Performance tests of quoting and dequoting, printf -v turned out slow

[Sebastian Gniazdowski]

On 9 marca 2018 at 14:23:44, Stephane Chazelas (stephane.chazelas@gmail.com) wrote:
> I can't reproduce with zsh 5.4.2 (x86_64-debian-linux-gnu)
> compared with 4.4.18(1)-release (x86_64-pc-linux-gnu).
> in a en_GB.UTF-8 locale.
>  
> FWIW, I find:
>  
> $ time INPUT='ice as"program" pick"$ZPFX/bin/prll_(qer|bfr)" src"prll.sh" make"install  
> PREFIX=$ZPFX"' bash -c 'for ((i = 0; i < 50000; i++)); do printf -v OUTPUT %q "$INPUT";  
> done'
> INPUT= bash -c 1.48s user 0.00s system 99% cpu 1.485 total
> $ time INPUT='ice as"program" pick"$ZPFX/bin/prll_(qer|bfr)" src"prll.sh" make"install  
> PREFIX=$ZPFX"' zsh -c 'for ((i = 0; i < 50000; i++)); do printf -v OUTPUT %q "$INPUT"; done'  
> INPUT= zsh -c 0.83s user 0.14s system 99% cpu 0.979 total
>  
> What's your version and locale?

5.3.1, I looked also at 5.4.2 and the results were the same. For your snippets I get the same results as you. If I source short.zsh, I again get ~25 sec time. I will find some time to narrow this shortly.

-- 
Sebastian Gniazdowski
psprint /at/ zdharma.org

Re: Performance tests of quoting and dequoting, printf -v turned out slow

[Stephane Chazelas]

2018-03-09 14:39:10 +0100, Sebastian Gniazdowski:
[...]
> 5.3.1, I looked also at 5.4.2 and the results were the same.
> For your snippets I get the same results as you. If I source
> short.zsh, I again get ~25 sec time. I will find some time to
> narrow this shortly.
[...]

Maybe a heavy (that forks for instance) "DEBUG" trap?

or a wrapper function around "printf"?

-- 
Stephane

Re: Performance tests of quoting and dequoting, printf -v turned out slow

[Sebastian Gniazdowski]

On 9 marca 2018 at 15:53:52, Stephane Chazelas (stephane.chazelas@gmail.com) wrote:
> 2018-03-09 14:39:10 +0100, Sebastian Gniazdowski:
> [...]
> > 5.3.1, I looked also at 5.4.2 and the results were the same.
> > For your snippets I get the same results as you. If I source
> > short.zsh, I again get ~25 sec time. I will find some time to
> > narrow this shortly.
> [...]
> 
> Maybe a heavy (that forks for instance) "DEBUG" trap?
> 
> or a wrapper function around "printf"?

I only changed method of time measurement in your snippet, and obtained the slowness:

% typeset -F3 SECONDS=0; INPUT='ice as"program" pick"$ZPFX/bin/prll_(qer|bfr)" src"prll.sh" make"install PREFIX=$ZPFX"'; for ((i = 0; i < 50000; i++)); do printf -v OUTPUT '%q' "$INPUT"; done; echo $SECONDS
151.137

Not sure what using `time' instead of $SECONDS does, but above method is less suspected of any side effects.

-- 
Sebastian Gniazdowski
psprint /at/ zdharma.org

Re: Performance tests of quoting and dequoting, printf -v turned out slow

[Stephane Chazelas]

2018-03-10 09:36:42 +0100, Sebastian Gniazdowski:
[...]
> I only changed method of time measurement in your snippet, and obtained the slowness:
> 
> % typeset -F3 SECONDS=0; INPUT='ice as"program" pick"$ZPFX/bin/prll_(qer|bfr)" src"prll.sh" make"install PREFIX=$ZPFX"'; for ((i = 0; i < 50000; i++)); do printf -v OUTPUT '%q' "$INPUT"; done; echo $SECONDS
> 151.137
[...]
> 
> Not sure what using `time' instead of $SECONDS does, but above method is less suspected of any side effects.
[...]

More importantly here, the difference is that you have that code
interpreted by your interactive shell that has read your
~/.zshrc, while the "time" version starts a new non-interactive
shell that doesn't read ~/.zshrc to interpret the code.

There is probably something in your interactive shell
environment that is causing that.

What do you see, if you run:

(set -x; repeat 5 printf -v x x)

What's the output of:

type printf
trap

Do you get the same behaviour if you run that same code after
"zsh -f" (a new interactive shell instance that doesn't read
your ~/.zshrc)?

-- 
Stephane

Re: Performance tests of quoting and dequoting, printf -v turned out slow

[Sebastian Gniazdowski]

On 10 marca 2018 at 16:03:11, Stephane Chazelas (stephane.chazelas@gmail.com) wrote:
> More importantly here, the difference is that you have that code
> interpreted by your interactive shell that has read your
> ~/.zshrc, while the "time" version starts a new non-interactive
> shell that doesn't read ~/.zshrc to interpret the code.
>  
> There is probably something in your interactive shell
> environment that is causing that.

Before sending email I've created script.zsh with #!/usr/local/bin/zsh-5.3.1 shebang and pasted the code, it was still slow.

> What do you see, if you run:
>  
> (set -x; repeat 5 printf -v x x)

% (set -x; repeat 5 printf -v x x)
+/usr/local/bin/zsh-5.3.1-dev-0:130> printf -v x x
+/usr/local/bin/zsh-5.3.1-dev-0:130> printf -v x x
+/usr/local/bin/zsh-5.3.1-dev-0:130> printf -v x x
+/usr/local/bin/zsh-5.3.1-dev-0:130> printf -v x x
+/usr/local/bin/zsh-5.3.1-dev-0:130> printf -v x x

> What's the output of:
>  
> type printf
> trap

"printf is a shell builtin"
<empty output>


> Do you get the same behaviour if you run that same code after
> "zsh -f" (a new interactive shell instance that doesn't read
> your ~/.zshrc)?

Yes, it is still slow after /usr/local/bin/zsh-5.3.1 -f. I've recorded this: https://asciinema.org/a/X2T0PlE62gVh363c5oOZeckTz		

> --
> Stephane
>  

--  
Sebastian Gniazdowski
psprint /at/ zdharma.org

Re: Performance tests of quoting and dequoting, printf -v turned out slow

[Oliver Kiddle]

Sebastian Gniazdowski wrote:
> Two scripts:
>
> - short.txt
> Test of quoting, (q)-flag vs. printf -v output '%q '
> result: 35 ms vs. 26.6 sec

I can't reproduce speeds that bad from printf -v. I get a factor of 4 at
most vs. (q).

What may affect things is whether or not zsh was built to use
open_memstream from libc. FreeBSD and GNU libc have open_memstream. If
you're using some other OS or an alternative libc on Linux it might be
using a temporary file. Having /tmp on tmpfs may help.

Rearranging printf to use sprintf() might make it faster but calculating
suitable buffer sizes is not necessarily easy given that the format
is essentially arbitrary. It was originally written without printf -v
being a feature: print -s and -z combined with -f were never going to be
performance critical. Being able to do printf to a stdio stream keeps
the code simpler.

Oliver

Re: Performance tests of quoting and dequoting, printf -v turned out slow

[Bart Schaefer]

On Sat, Mar 10, 2018 at 7:40 AM, Oliver Kiddle <okiddle@yahoo.co.uk> wrote:
>
> What may affect things is whether or not zsh was built to use
> open_memstream from libc. FreeBSD and GNU libc have open_memstream.

Indeed:

schaefer[556] Src/zsh -f
% qflag() {
    local OUTPUT
    repeat 10000; do
        OUTPUT="${(q)INPUT}"
    done
}
% typeset -F SECONDS=0; qflag; print $SECONDS
0.0282280000
% prtf() {
    local OUTPUT
    repeat 10000; do
        printf -v OUTPUT '%q ' "$INPUT"
    done
}
% typeset -F SECONDS=0; prtf; print $SECONDS
3.8363050000
%

schaefer[557] grep -i memstream config.h
/* Define to 1 if you have the `open_memstream' function. */
/* #undef HAVE_OPEN_MEMSTREAM */

Re: Performance tests of quoting and dequoting, printf -v turned out slow

[Sebastian Gniazdowski]

On 11 marca 2018 at 09:33:46, Bart Schaefer (schaefer@brasslantern.com) wrote:
> On Sat, Mar 10, 2018 at 7:40 AM, Oliver Kiddle wrote:
> >
> > What may affect things is whether or not zsh was built to use
> > open_memstream from libc. FreeBSD and GNU libc have open_memstream.
>  
> Indeed:
> ...
> % typeset -F SECONDS=0; prtf; print $SECONDS
> 3.8363050000
> %
>  
> schaefer[557] grep -i memstream config.h
> /* Define to 1 if you have the `open_memstream' function. */
> /* #undef HAVE_OPEN_MEMSTREAM */

I confirm this. I've had additional complication, because OS X El Captain didn't have that function, and I used build from that OS, so tested zsh was slow. A quick look at config.log revealed however that it DOES have it. But it was a wrong conclusion, I've updated to OS X High Sierra and it is that OS that has open_memstream. Looking at older config.log from El Captain confirmed this – no open_memstream there. Fresh Zsh build is fast.

--  
Sebastian Gniazdowski
psprint /at/ zdharma.org