Re: Slowdown around 5.0.5-dev-0

[Sebastian Gniazdowski <sgniazdowski@gmail.com>]

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

On 19 October 2015 at 19:21, Bart Schaefer <schaefer@brasslantern.com> wrote:
> We leave that empty arena at the end, but then on the next zhalloc()
> it's still not big enough, so another one gets allocated.
>
> You could try removing that "else" to let the trailing block be freed
> again, but then we're back to needing to compare speed as well as space
> across shell versions.

I removed the else, code works longer and memory is still allocated.
This is seen in mem-test3.txt, where there are many samples and large
numbers, and in perf-test.txt, where there noted is long running time
(numbers are milliseconds)

I wrote perf-test.zsh to automatically perform performance tests:
https://github.com/psprint/zsh-tools/

With it and with mem-test.zsh I tested following zsh variants:
- 5.0.2 osx
- newheaps patch (zsh-newheaps-only)
- newheaps and zhalloc patch 36836 (zsh-newheaps-zhalloc)
- zhalloc and the previous patch 36834 (zsh-head-both-patches)
- all three patches (zsh-newheaps-three-patches)
- a 5.1.1-dev-0 clean zsh
- the empty arena else removed

My conclusions:
- 36834 introduces high memory usage; I would suggest to use only two
optimizations – newheaps and zhalloc; my znavtools are instant fast
with them, what's slower is searching (wrote search_test function,
results attached); basically half of pattern search speedup is lost
with 36834, however what's gained is beautiful memory usage, without
firefox-like values for RES (~700 MB); newheaps is responsible for
instant-responsivity of my script, 36836 for much faster searching –
that's a good compromise

- searching with patterns through very large arrays (700k) allocates
264 MB of memory regardless of zsh version; this probably tells
something

- still not sure why 36834 allocates much memory for the string test

- newheaps makes function calls longer, but it's not a substantial
difference – 21196 ms vs. 18549 ms

Best regards,
Sebastian Gniazdowski

[-- Attachment #2: mem-test3.txt --]
[-- Type: text/plain, Size: 2620 bytes --]

# Tests for zsh-empty-arena-else
# string_test 51, 152, 206, 247, 280, 305, 327, 345, 363, 380, 394, 407, 421, 432, 444, 455, 464, 474, 483, 493, 502, 509, 518, 525, 534, 541, 549, 555, 560, 569, 575, 581, last: 586
string_test 421.3
# array_test 1, 2.7, 2.9, 3.8, 4.3, 5.6, 6.5, 7.6, 8, 8.4, 8.7, 8.9, last: 9.1
array_test 5.4
# function_test 2.6, 2.9, 2.7, 2.9, 2.9, 2.8, 2.9, 2.7, last: 2.6
function_test 2.8
# search_test 110, 215, last: 264
search_test 110.0


# Tests for zsh-newheaps-zhalloc
# string_test 2.9, 7.7, 9.3, 11, 11, 11, 12, 11, 12, 11, 11, 11, 12, last: 11
string_test 10.1
# array_test 1, 2, 3.1, 3.3, 4.5, 5.3, 6.3, 7.5, 7.8, 8.2, 8.5, 8.7, last: 8.9
array_test 5.2
# function_test 2.7, 2.7, 2.8, 2.6, 2.6, 2.9, 2.9, 3, last: 2.6
function_test 2.7
# search_test 86, 158, 200, 237, last: 265
search_test 148.0


# Tests for zsh-newheaps-only
# string_test 3, 7.7, 9.1, 11, 11, 11, 12, 11, 11, 11, 12, 11, 11, last: 10
string_test 10.1
# array_test 1.4, 2, 3, 3.8, 4.4, 5.3, 6.3, 7, 7.7, 8, 8.3, 8.5, last: 8.8
array_test 5.2
# function_test 2.7, 2.6, 2.8, 2.7, 2.9, 2.7, 2.7, 2.7, last: 2.6
function_test 2.7
# search_test 62, 122, 144, 171, 196, 218, 238, 259, last: 266
search_test 164.4


# Tests for zsh-5.0.2-osx
# string_test 2.5, 7.4, 8.9, 11, 11, 12, 11, 11, 11, 11, 12, 12, last: 10
string_test 9.9
# array_test 1.4, 2.2, 3, 4, 4.6, 5.3, 6.3, 7.4, 7.8, 8, 8.4, 8.7, last: 8.8
array_test 5.3
# function_test 2.6, 2.6, 2.6, 2.6, 2.6, 2.6, 2.6, last: 2.6
function_test 2.6
# search_test 59, 122, 152, 179, 204, 226, 245, last: 264
search_test 157.0


# Tests for zsh-head-both-patches
# string_test 40, 182, 318, 456, 589, 725, last: 9.7
string_test 317.0
# array_test 1.1, 2.5, 3, 3.8, 4.3, 5, 6, 7, 7.5, 7.8, 8.2, 8.3, last: 8.5
array_test 5.1
# function_test 2.6, 2.6, 2.6, 2.6, 2.5, 2.6, 2.6, last: 2.5
function_test 2.6
# search_test 122, 217, last: 266
search_test 122.0


# Tests for zsh-newheaps-three-patches
# string_test 44, 188, 331, 471, 612, last: 8.9
string_test 258.5
# array_test 1.1, 2, 3.1, 3.8, 4.4, 5.1, 6.2, 7.2, 7.7, 8, 8.2, 8.6, last: 8.7
array_test 5.2
# function_test 2.7, 2.7, 2.9, 2.8, 2.9, 2.7, 2.9, 2.6, last: 2.6
function_test 2.8
# search_test 116, 216, last: 265
search_test 116.0


# Tests for zsh-5.1.1-dev-0-clean
# string_test 2.6, 7.3, 8.8, 11, 11, 11, 10, 11, 12, 11, 12, 11, last: 10
string_test 9.8
# array_test 1.3, 2.2, 2.3, 3.4, 4.2, 5, 6.1, 6.9, 7.6, 7.8, 8.1, 8.4, last: 8.6
array_test 5.0
# function_test 2.6, 2.6, 2.6, 2.6, 2.6, 2.6, last: 2.6
function_test 2.6
# search_test 62, 121, 151, 177, 201, 223, 243, 264, last: 265
search_test 168.3



[-- Attachment #3: perf-test.txt --]
[-- Type: text/plain, Size: 1487 bytes --]

Running [zsh-empty-arena-else]: string_test 13749,47
Running [zsh-empty-arena-else]: array_test 12182,06
Running [zsh-empty-arena-else]: function_test 21345,66
Running [zsh-empty-arena-else]: search_test 3849,80


Running [zsh-newheaps-zhalloc]: string_test 9990,75
Running [zsh-newheaps-zhalloc]: array_test 12109,69
Running [zsh-newheaps-zhalloc]: function_test 21318,52
Running [zsh-newheaps-zhalloc]: search_test 6842,58


Running [zsh-newheaps-only]: string_test 9999,97
Running [zsh-newheaps-only]: array_test 11925,05
Running [zsh-newheaps-only]: function_test 21196,27
Running [zsh-newheaps-only]: search_test 11670,71


Running [zsh-5.0.2-osx]: string_test 9628,87
Running [zsh-5.0.2-osx]: array_test 12294,85
Running [zsh-5.0.2-osx]: function_test 18668,42
Running [zsh-5.0.2-osx]: search_test 11518,38


Running [zsh-head-both-patches]: string_test 4385,93
Running [zsh-head-both-patches]: array_test 11933,38
Running [zsh-head-both-patches]: function_test 18549,57
Running [zsh-head-both-patches]: search_test 3949,40


Running [zsh-newheaps-three-patches]: string_test 4351,58
Running [zsh-newheaps-three-patches]: array_test 12111,25
Running [zsh-newheaps-three-patches]: function_test 21356,30
Running [zsh-newheaps-three-patches]: search_test 4063,73


Running [zsh-5.1.1-dev-0-clean]: string_test 9651,08
Running [zsh-5.1.1-dev-0-clean]: array_test 12749,21
Running [zsh-5.1.1-dev-0-clean]: function_test 18667,25
Running [zsh-5.1.1-dev-0-clean]: search_test 11386,36



[-- Attachment #4: mem-test.zsh --]
[-- Type: application/octet-stream, Size: 4111 bytes --]

#!/bin/zsh

emulate -L zsh
setopt extendedglob

zshs=( zsh-empty-arena-else zsh-newheaps-zhalloc zsh-newheaps-only )
zshs+=( zsh-5.0.2-osx zsh-head-both-patches zsh-newheaps-three-patches zsh-5.1.1-dev-0-clean )

# Convert sizes to number of megabytes
to_mbytes() {
    local size="$1"
    #echo Converting: "$1"
    if [[ "$size" = [0-9]#[Mm]* ]]; then
        size="${size%[Mm]*}"
    elif [[ "$size" = [0-9]#[Kk]* ]]; then
        size="${size%[Kk]*}"
        (( size = size / 1024.0 ))
    elif [[ "$size" = [0-9]# ]]; then
        case $( uname ) in
            *Linux*)
                (( size = size / 1024.0 ))
                ;;
            *)
                (( size = size / (1024.0 * 1024.0) ))
                ;;
        esac
    else
        echo "Bad size occured: $size"
    fi

    REPLY="$size"
}

#
# Children administration
#

trap "finished" SIGUSR1

finished() {
    FINISHED=1
}

# Gets memory size of the zsh that runs the test
get_mem() {
    case $( uname ) in
        *Darwin*)
            output=( "${(@f)"$( top -pid "$SUB_PID" -stats mem -l 1 )"}" )
            to_mbytes "$output[-1]"
            ;;
        *Linux*)
            output=( "${(@f)"$( top -p "$SUB_PID" -bn 1 )"}" )
            output=$output[-1]
            output=( $=output )
            to_mbytes "$output[6]"
            ;;
    esac
}

# Waits for signal from child process
wait_get_mem() {
    local number
    float average=0.0
    integer count=0

    echo -n "# $TEST "

    sleep 1
    while [ "$FINISHED" -eq 0 ]; do
        get_mem
        number=`LANG=C printf "%.1f" "$REPLY"`
        echo -n "${number%.0}, "

        average+=number
        count+=1
        sleep 3
    done

    # Remove last result - to be certain that the average
    # is only above data from actively working test function
    if [ "$count" -gt 1 ]; then
        average=average-number
        count=count-1
    fi
    average=average/count

    # Take the explicit last result, it's telling
    # how zsh behaves when computation is stopped
    sleep 1
    get_mem
    number=`LANG=C printf "%.1f" "$REPLY"`
    echo "last: ${number%.0}"
    kill -15 "$SUB_PID"

    # Suitable for gnuplot - X Y
    LANG=C printf "$TEST %.1f\n" $average
}

_finished_signal_wait() {
    kill -SIGUSR1 "$MAIN_PID"
    sleep 60
}

#
# Tests
#

tests=( string_test array_test function_test search_test )

string_test() {
    local a=""
    integer i=150000
    repeat $i; do a+="$i"; done

    _finished_signal_wait
}

array_test() {
    typeset -a a
    integer i=25000
    repeat $i; do a+=( $i ); done

    _finished_signal_wait
}

function_test() {
    local count

    if [ -z "$1" ]; then
        repeat 10000; do function_test 100; done
        _finished_signal_wait
    else
        count="$1"
    fi

    if (( count -- > 0 )); then
        function_test "$count"
    fi
}

search_test() {
    integer elements=700000
    a="${(r:elements:: _:)b}"
    a=( $=a )
    a=( "${(@M)a:#(#i)*_*}" )
    a=( "${(@)a//(#mi)(_|a)/-${MATCH}-}" )
    a=( "${(@)a//(#bi)(_|-)/|${match[1]}|}" )

    _finished_signal_wait
}

#
# Main code
#

# Detect main vs. for-test invocation
if [ -z "$1" ]; then
    for current_zsh in "$zshs[@]"; do
        type "$current_zsh" 2>/dev/null 1>&2 || { echo >&2 "Skipping non-accessible $current_zsh"; continue }
        zsh_binary="${current_zsh##*/}"

        echo "# Tests for $zsh_binary"
        for test in "$tests[@]"; do
            FINISHED=0
            TEST="$test"

            "$current_zsh" -c "source ./$0 $$ \"$current_zsh\" $test" &

            SUB_PID=$!
            wait_get_mem
        done
        echo
        echo

    done

    # Example gnuplot invocation:
    #set style data histogram
    #set style fill solid border rgb "black"
    #plot "result" index 0 using 2: xtic(1), "result" index 1 using 2: xtic(1), "result" index 2 using 2: xtic(1)
else
    MAIN_PID="$1"
    zsh_binary="${2##*/}"
    shift
    shift
    # Echo status only when output is not to terminal
    [ ! -t 1 ] && echo >&2 "Running [$zsh_binary]: $@"

    # Run the test
    eval "run_test() { $@ }"
    run_test
fi

[-- Attachment #5: perf-test.zsh --]
[-- Type: application/octet-stream, Size: 2168 bytes --]

#!/bin/zsh

emulate -L zsh
setopt extendedglob

zmodload zsh/zprof

zshs=( zsh-empty-arena-else zsh-newheaps-zhalloc zsh-newheaps-only )
zshs+=( zsh-5.0.2-osx zsh-head-both-patches zsh-newheaps-three-patches zsh-5.1.1-dev-0-clean )

#
# Children administration
#

trap "finished" SIGUSR1

finished() {
    FINISHED=1
}

# Waits for signal from child process
wait_for_end_of_test() {
    while [ "$FINISHED" -eq 0 ]; do
        sleep 1
    done
    kill -15 "$SUB_PID"
}

_finished_signal_wait() {
    kill -SIGUSR1 "$MAIN_PID"
    sleep 60
}

#
# Tests
#

tests=( string_test array_test function_test search_test )

float multiplier=0.5

string_test() {
    local a=""
    integer i=$(( 150000*multiplier ))
    repeat $i; do a+="$i"; done
}

array_test() {
    typeset -a a
    integer i=$(( 25000*multiplier ))
    repeat $i; do a+=( $i ); done
}

function_test() {
    local count
    integer i=$(( 10000*multiplier ))

    if [ -z "$1" ]; then
        repeat $i; do function_test 100; done
    else
        count="$1"
    fi

    if (( count -- > 0 )); then
        function_test "$count"
    fi
}

search_test() {
    integer elements=$(( 800000 * multiplier ))
    a="${(r:elements:: _:)b}"
    a=( $=a )
    a=( "${(@M)a:#(#i)*_*}" )
    a=( "${(@)a//(#mi)(_|a)/-${MATCH}-}" )
    a=( "${(@)a//(#bi)(_|-)/|${match[1]}|}" )
}

#
# Main code
#

# Detect main vs. for-test invocation
if [ -z "$1" ]; then
    for current_zsh in "$zshs[@]"; do
        type "$current_zsh" 2>/dev/null 1>&2 || { echo >&2 "Skipping non-accessible $current_zsh"; continue }
        zsh_binary="${current_zsh##*/}"

        for test in "$tests[@]"; do
            FINISHED=0
            TEST="$test"

            "$current_zsh" -c "source ./$0 $$ \"$current_zsh\" $test" &

            SUB_PID=$!
            wait_for_end_of_test
        done
        echo
        echo

    done
else
    MAIN_PID="$1"
    zsh_binary="${2##*/}"
    shift
    shift
    echo -n "Running [$zsh_binary]: $@ "

    # Run the test
    zprof -c
    "$@"
    zprof_out=( "${(@f)"$( zprof )"}" )
    zprof_out="$zprof_out[3]"
    zprof_out=( $=zprof_out )
    echo "$zprof_out[3]"

    _finished_signal_wait
fi