async

#!/bin/bash
#
# Symbolic asynchronous tasks for devstack
#
# Usage:
#
#  async_runfunc my_shell_func foo bar baz
#
#  ... do other stuff ...
#
#  async_wait my_shell_func
#

DEVSTACK_PARALLEL=$(trueorfalse True DEVSTACK_PARALLEL)
_ASYNC_BG_TIME=0

# Keep track of how much total time was spent in background tasks
# Takes a job runtime in ms.
function _async_incr_bg_time {
    local elapsed_ms="$1"
    _ASYNC_BG_TIME=$(($_ASYNC_BG_TIME + $elapsed_ms))
}

# Get the PID of a named future to wait on
function async_pidof {
    local name="$1"
    local inifile="${DEST}/async/${name}.ini"

    if [ -f "$inifile" ]; then
        iniget $inifile job pid
    else
        echo 'UNKNOWN'
        return 1
    fi
}

# Log a message about a job. If the message contains "%command" then the
# full command line of the job will be substituted in the output
function async_log {
    local name="$1"
    shift
    local message="$*"
    local inifile=${DEST}/async/${name}.ini
    local pid
    local command

    pid=$(iniget $inifile job pid)
    command=$(iniget $inifile job command | tr '#' '-')
    message=$(echo "$message" | sed "s#%command#$command#g")

    echo "[$BASHPID Async ${name}:${pid}]: $message"
}

# Inner function that actually runs the requested task. We wrap it like this
# just so we can emit a finish message as soon as the work is done, to make
# it easier to find the tracking just before an error.
function async_inner {
    local name="$1"
    local rc
    local fifo="${DEST}/async/${name}.fifo"
    shift
    set -o xtrace
    if $* >${DEST}/async/${name}.log 2>&1; then
        rc=0
        set +o xtrace
        async_log "$name" "finished successfully"
    else
        rc=$?
        set +o xtrace
        async_log "$name" "FAILED with rc $rc"
    fi
    iniset ${DEST}/async/${name}.ini job end_time $(date "+%s%3N")
    # Block on the fifo until we are signaled to exit by the main process
    cat $fifo
    return $rc
}

# Run something async. Takes a symbolic name and a list of arguments of
# what to run. Ideally this would be rarely used and async_runfunc() would
# be used everywhere for readability.
#
# This spawns the work in a background worker, records a "future" to be
# collected by a later call to async_wait()
function async_run {
    local xtrace
    xtrace=$(set +o | grep xtrace)
    set +o xtrace

    local name="$1"
    shift
    local inifile=${DEST}/async/${name}.ini
    local fifo=${DEST}/async/${name}.fifo

    touch $inifile
    iniset $inifile job command "$*"
    iniset $inifile job start_time $(date +%s%3N)

    if [[ "$DEVSTACK_PARALLEL" = "True" ]]; then
        mkfifo $fifo
        async_inner $name $* &
        iniset $inifile job pid $!
        async_log "$name" "running: %command"
        $xtrace
    else
        iniset $inifile job pid "self"
        async_log "$name" "Running synchronously: %command"
        $xtrace
        $*
        return $?
    fi
}

# Shortcut for running a shell function async. Uses the function name as the
# async name.
function async_runfunc {
    async_run $1 $*
}

# Dump some information to help debug a failed wait
function async_wait_dump {
    local failpid=$1

    echo "=== Wait failure dump from $BASHPID ==="
    echo "Processes:"
    ps -f
    echo "Waiting jobs:"
    for name in $(ls ${DEST}/async/*.ini); do
        echo "Job $name :"
        cat "$name"
    done
    echo "Failed PID status:"
    sudo cat /proc/$failpid/status
    sudo cat /proc/$failpid/cmdline
    echo "=== End wait failure dump ==="
}

# Wait for an async future to complete. May return immediately if already
# complete, or of the future has already been waited on (avoid this). May
# block until the future completes.
function async_wait {
    local xtrace
    xtrace=$(set +o | grep xtrace)
    set +o xtrace

    local pid rc running inifile runtime fifo
    rc=0
    for name in $*; do
        running=$(ls ${DEST}/async/*.ini 2>/dev/null | wc -l)
        inifile="${DEST}/async/${name}.ini"
        fifo="${DEST}/async/${name}.fifo"

        if pid=$(async_pidof "$name"); then
            async_log "$name" "Waiting for completion of %command" \
                      "running on PID $pid ($running other jobs running)"
            time_start async_wait
            if [[ "$pid" != "self" ]]; then
                # Signal the child to go ahead and exit since we are about to
                # wait for it to collect its status.
                async_log "$name" "Signaling child to exit"
                echo WAKEUP > $fifo
                async_log "$name" "Signaled"
                # Do not actually call wait if we ran synchronously
                if wait $pid; then
                    rc=0
                else
                    rc=$?
                fi
                cat ${DEST}/async/${name}.log
                rm -f $fifo
            fi
            time_stop async_wait
            local start_time
            local end_time
            start_time=$(iniget $inifile job start_time)
            end_time=$(iniget $inifile job end_time)
            _async_incr_bg_time $(($end_time - $start_time))
            runtime=$((($end_time - $start_time) / 1000))
            async_log "$name" "finished %command with result" \
                      "$rc in $runtime seconds"
            rm -f $inifile
            if [ $rc -ne 0 ]; then
                async_wait_dump $pid
                echo Stopping async wait due to error: $*
                break
            fi
        else
            # This could probably be removed - it is really just here
            # to help notice if you wait for something by the wrong
            # name, but it also shows up for things we didn't start
            # because they were not enabled.
            echo Not waiting for async task $name that we never started or \
                 has already been waited for
        fi
    done

    $xtrace
    return $rc
}

# Check for uncollected futures and wait on them
function async_cleanup {
    local name

    if [[ "$DEVSTACK_PARALLEL" != "True" ]]; then
        return 0
    fi

    for inifile in $(find ${DEST}/async -name '*.ini'); do
        name=$(basename $pidfile .ini)
        echo "WARNING: uncollected async future $name"
        async_wait $name || true
    done
}

# Make sure our async dir is created and clean
function async_init {
    local async_dir=${DEST}/async

    # Clean any residue if present from previous runs
    rm -Rf $async_dir

    # Make sure we have a state directory
    mkdir -p $async_dir
}

function async_print_timing {
    local bg_time_minus_wait
    local elapsed_time
    local serial_time
    local speedup

    if [[ "$DEVSTACK_PARALLEL" != "True" ]]; then
        return 0
    fi

    # The logic here is: All the background task time would be
    # serialized if we did not do them in the background. So we can
    # add that to the elapsed time for the whole run. However, time we
    # spend waiting for async things to finish adds to the elapsed
    # time, but is time where we're not doing anything useful. Thus,
    # we substract that from the would-be-serialized time.

    bg_time_minus_wait=$((\
            ($_ASYNC_BG_TIME - ${_TIME_TOTAL[async_wait]}) / 1000))
    elapsed_time=$(($(date "+%s") - $_TIME_BEGIN))
    serial_time=$(($elapsed_time + $bg_time_minus_wait))

    echo
    echo "================="
    echo " Async summary"
    echo "================="
    echo " Time spent in the background minus waits: $bg_time_minus_wait sec"
    echo " Elapsed time: $elapsed_time sec"
    echo " Time if we did everything serially: $serial_time sec"
    echo " Speedup: " $(echo | awk "{print $serial_time / $elapsed_time}")
}