Re: [Qemu-devel] [Qemu-block] [PATCH v2] blkdebug: Add support for latency rules

[John Snow]

On 09/13/2018 12:48 PM, Marc Olson wrote:
> Are there further thoughts on this patch?
> 

The CI tools may have missed it since it appears to have been sent in
reply to the V1 instead of as a new thread. When you send a revision
out, can you send it as its own thread?

(We're also in a bit of a logjam at the moment with no pull requests
having been processed recently, so we're a bit gummed up.)

Some comments below.

> 
> On 09/04/2018 05:24 PM, Marc Olson wrote:
>> Sometimes storage devices can be slow to respond, due to media errors,
>> firmware
>> issues, SSD garbage collection, etc. This patch adds a new rule type to
>> blkdebug that allows injection of latency to I/O operations. Similar
>> to error
>> injection rules, latency rules can be specified with or without an
>> offset, and
>> can also apply upon state transitions.
>>
>> Signed-off-by: Marc Olson <address@hidden>
>>
>> ---
>> v2:
>> - Change so that delay rules are executed before error rules
>> - Add QMP support
>> - Add tests
>> ---
>>   block/blkdebug.c           | 119
>> +++++++++++++++++++++++++++++++++++----------
>>   docs/devel/blkdebug.txt    |  30 +++++++++---
>>   qapi/block-core.json       |  39 +++++++++++++--
>>   tests/qemu-iotests/071     |  63 ++++++++++++++++++++++++
>>   tests/qemu-iotests/071.out |  31 ++++++++++++
>>   5 files changed, 244 insertions(+), 38 deletions(-)
>>
>> diff --git a/block/blkdebug.c b/block/blkdebug.c
>> index 0759452..1785fe3 100644
>> --- a/block/blkdebug.c
>> +++ b/block/blkdebug.c
>> @@ -65,6 +65,7 @@ typedef struct BlkdebugSuspendedReq {
>>     enum {
>>       ACTION_INJECT_ERROR,
>> +    ACTION_DELAY,
>>       ACTION_SET_STATE,
>>       ACTION_SUSPEND,
>>   };
>> @@ -73,14 +74,17 @@ typedef struct BlkdebugRule {
>>       BlkdebugEvent event;
>>       int action;
>>       int state;
>> +    int once;
>> +    int64_t offset;

Hm, I guess we're just promoting these to universal values that might
exist for any of the rule types, but not allowing the user to set them
for rules where it doesn't make sense.

>>       union {
>>           struct {
>>               int error;
>>               int immediately;
>> -            int once;
>> -            int64_t offset;
>>           } inject;
>>           struct {
>> +            int64_t latency;
>> +        } delay;
>> +        struct {
>>               int new_state;
>>           } set_state;
>>           struct {
>> @@ -123,6 +127,33 @@ static QemuOptsList inject_error_opts = {
>>       },
>>   };
>>   +static QemuOptsList delay_opts = {
>> +    .name = "delay",
>> +    .head = QTAILQ_HEAD_INITIALIZER(delay_opts.head),
>> +    .desc = {
>> +        {
>> +            .name = "event",
>> +        },
>> +        {
>> +            .name = "state",
>> +            .type = QEMU_OPT_NUMBER,
>> +        },
>> +        {
>> +            .name = "latency",
>> +            .type = QEMU_OPT_NUMBER,
>> +        },
>> +        {
>> +            .name = "sector",
>> +            .type = QEMU_OPT_NUMBER,
>> +        },
>> +        {
>> +            .name = "once",
>> +            .type = QEMU_OPT_BOOL,
>> +        },
>> +        { /* end of list */ }
>> +    },
>> +};
>> +
>>   static QemuOptsList set_state_opts = {
>>       .name = "set-state",
>>       .head = QTAILQ_HEAD_INITIALIZER(set_state_opts.head),
>> @@ -145,6 +176,7 @@ static QemuOptsList set_state_opts = {
>>     static QemuOptsList *config_groups[] = {
>>       &inject_error_opts,
>> +    &delay_opts,
>>       &set_state_opts,
>>       NULL
>>   };
>> @@ -182,16 +214,21 @@ static int add_rule(void *opaque, QemuOpts
>> *opts, Error **errp)
>>           .state  = qemu_opt_get_number(opts, "state", 0),
>>       };
>>   +    rule->once  = qemu_opt_get_bool(opts, "once", 0);
>> +    sector = qemu_opt_get_number(opts, "sector", -1);
>> +    rule->offset = sector == -1 ? -1 : sector * BDRV_SECTOR_SIZE;
>> +
>>       /* Parse action-specific options */
>>       switch (d->action) {
>>       case ACTION_INJECT_ERROR:
>>           rule->options.inject.error = qemu_opt_get_number(opts,
>> "errno", EIO);
>> -        rule->options.inject.once  = qemu_opt_get_bool(opts, "once", 0);
>>           rule->options.inject.immediately =
>>               qemu_opt_get_bool(opts, "immediately", 0);
>> -        sector = qemu_opt_get_number(opts, "sector", -1);
>> -        rule->options.inject.offset =
>> -            sector == -1 ? -1 : sector * BDRV_SECTOR_SIZE;
>> +        break;
>> +
>> +    case ACTION_DELAY:
>> +        rule->options.delay.latency =
>> +            qemu_opt_get_number(opts, "latency", 100) * SCALE_US;
>>           break;
>>         case ACTION_SET_STATE:
>> @@ -264,6 +301,14 @@ static int read_config(BDRVBlkdebugState *s,
>> const char *filename,
>>           goto fail;
>>       }
>>   +    d.action = ACTION_DELAY;
>> +    qemu_opts_foreach(&delay_opts, add_rule, &d, &local_err);
>> +    if (local_err) {
>> +        error_propagate(errp, local_err);
>> +        ret = -EINVAL;
>> +        goto fail;
>> +    }
>> +
>>       d.action = ACTION_SET_STATE;
>>       qemu_opts_foreach(&set_state_opts, add_rule, &d, &local_err);
>>       if (local_err) {
>> @@ -275,6 +320,7 @@ static int read_config(BDRVBlkdebugState *s, const
>> char *filename,
>>       ret = 0;
>>   fail:
>>       qemu_opts_reset(&inject_error_opts);
>> +    qemu_opts_reset(&delay_opts);
>>       qemu_opts_reset(&set_state_opts);
>>       if (f) {
>>           fclose(f);
>> @@ -473,39 +519,61 @@ out:
>>   static int rule_check(BlockDriverState *bs, uint64_t offset,
>> uint64_t bytes)
>>   {
>>       BDRVBlkdebugState *s = bs->opaque;
>> -    BlkdebugRule *rule = NULL;
>> +    BlkdebugRule *rule = NULL, *delay_rule = NULL, *error_rule = NULL;
>> +    int64_t latency;
>>       int error;
>>       bool immediately;
>> +    int ret = 0;
>>         QSIMPLEQ_FOREACH(rule, &s->active_rules, active_next) {
>> -        uint64_t inject_offset = rule->options.inject.offset;
>> -
>> -        if (inject_offset == -1 ||
>> -            (bytes && inject_offset >= offset &&
>> -             inject_offset < offset + bytes))
>> +        if (rule->offset == -1 ||
>> +            (bytes && rule->offset >= offset &&
>> +             rule->offset < offset + bytes))
>>           {
>> -            break;
>> +            if (!error_rule && rule->action == ACTION_INJECT_ERROR) {
>> +                error_rule = rule;
>> +            } else if (!delay_rule && rule->action == ACTION_DELAY) {
>> +                delay_rule = rule;
>> +            }
>> +
>> +            if (error_rule && delay_rule) {
>> +                break;
>> +            }
>>           }
>>       }
>>   -    if (!rule || !rule->options.inject.error) {
>> -        return 0;
>> -    }
>> +    if (delay_rule) {
>> +        latency = delay_rule->options.delay.latency;
>>   -    immediately = rule->options.inject.immediately;
>> -    error = rule->options.inject.error;
>> +        if (delay_rule->once) {
>> +            QSIMPLEQ_REMOVE(&s->active_rules, delay_rule,
>> BlkdebugRule, active_next);
>> +            remove_rule(delay_rule);
>> +        }
>>   -    if (rule->options.inject.once) {
>> -        QSIMPLEQ_REMOVE(&s->active_rules, rule, BlkdebugRule,
>> active_next);
>> -        remove_rule(rule);
>> +        if (latency != 0) {
>> +            qemu_co_sleep_ns(QEMU_CLOCK_REALTIME, latency);
>> +        }
>>       }
>>   -    if (!immediately) {
>> -        aio_co_schedule(qemu_get_current_aio_context(),
>> qemu_coroutine_self());
>> -        qemu_coroutine_yield();
>> +    if (error_rule) {
>> +        error = error_rule->options.inject.error;
>> +        immediately = error_rule->options.inject.immediately;
>> +
>> +        if (error_rule->once) {
>> +            QSIMPLEQ_REMOVE(&s->active_rules, error_rule,
>> BlkdebugRule, active_next);
>> +            remove_rule(error_rule);
>> +        }
>> +
>> +        if (error && !immediately) {
>> +            aio_co_schedule(qemu_get_current_aio_context(),
>> +                            qemu_coroutine_self());
>> +            qemu_coroutine_yield();
>> +        }
>> +
>> +        ret = -error;
>>       }
>>   -    return -error;
>> +    return ret;
>>   }

That's a big hunk of stuff all changing at once, it might have been nice
to do this in two passes:

1. refactor the loop to look for error rules, then
2. add login in for the delay rules.

It looks like we change the handling of error rules just a little bit;
before if (!rule->options.inject.error) we return 0 immediately, but now
we actually check for `once` and remove the the rule first.

I think that's probably fine; isn't it? It's not as if the error will
show up if it wasn't there already, so that's probably an improvement.

The delay rule looks fine.

>>     static int coroutine_fn
>> @@ -694,6 +762,7 @@ static bool process_rule(BlockDriverState *bs,
>> struct BlkdebugRule *rule,
>>       /* Take the action */
>>       switch (rule->action) {
>>       case ACTION_INJECT_ERROR:
>> +    case ACTION_DELAY:
>>           if (!injected) {
>>               QSIMPLEQ_INIT(&s->active_rules);
>>               injected = true;
>> diff --git a/docs/devel/blkdebug.txt b/docs/devel/blkdebug.txt
>> index 43d8e8f..1befcf8 100644
>> --- a/docs/devel/blkdebug.txt
>> +++ b/docs/devel/blkdebug.txt
>> @@ -24,7 +24,7 @@ This way, all error paths can be tested to make sure
>> they are correct.
>>   Rules
>>   -----
>>   The blkdebug block driver takes a list of "rules" that tell the
>> error injection
>> -engine when to fail an I/O request.
>> +engine when to fail (inject-error) or add latency to (delay) an I/O
>> request.
>>     Each I/O request is evaluated against the rules.  If a rule
>> matches the request
>>   then its "action" is executed.
>> @@ -33,17 +33,25 @@ Rules can be placed in a configuration file; the
>> configuration file
>>   follows the same .ini-like format used by QEMU's -readconfig option,
>> and
>>   each section of the file represents a rule.
>>   -The following configuration file defines a single rule:
>> +The following configuration file defines multiple rules:
>>       $ cat blkdebug.conf
>>     [inject-error]
>>     event = "read_aio"
>>     errno = "28"
>>   -This rule fails all aio read requests with ENOSPC (28).  Note that
>> the errno
>> -value depends on the host.  On Linux, see
>> +  [delay]
>> +  event = "read_aio"
>> +  sector = "2048"
>> +  latency = "500000"
>> +
>> +The error rule fails all aio read requests with ENOSPC (28).  Note
>> that the
>> +errno value depends on the host.  On Linux, see
>>   /usr/include/asm-generic/errno-base.h for errno values.
>>   +The delay rule adds 500 ms of latency to a read I/O request
>> containing sector
>> +2048.
>> +
>>   Invoke QEMU as follows:
>>       $ qemu-system-x86_64
>> @@ -60,21 +68,27 @@ Rules support the following attributes:
>>             rule to match.  See the "State transitions" section for
>> information
>>             on states.
>>   -  errno - the numeric errno value to return when a request matches
>> this rule.
>> -          The errno values depend on the host since the numeric
>> values are not
>> -          standarized in the POSIX specification.
>> -
>>     sector - (optional) a sector number that the request must overlap
>> in order to
>>              match this rule
>>       once - (optional, default "off") only execute this action on the
>> first
>>            matching request
>>   +Error injection rules support the following attributes:

The section rewrite here actually makes it a little less clear which
rules support which attributes, it might be time for a heavier rewrite.

This is OK for now, though, I think...

>> +
>> +  errno - the numeric errno value to return when a request matches
>> this rule.
>> +          The errno values depend on the host since the numeric
>> values are not
>> +          standarized in the POSIX specification.
>> +
>>     immediately - (optional, default "off") return a NULL BlockAIOCB
>>                   pointer and fail without an errno instead.  This
>>                   exercises the code path where BlockAIOCB fails and the
>>                   caller's BlockCompletionFunc is not invoked.
>>   +Delay rules support the following attribute:
>> +
>> +  latency - the delay to add to an I/O request, in microseconds.
>> +
>>   Events
>>   ------
>>   Block drivers provide information about the type of I/O request they
>> are about
>> diff --git a/qapi/block-core.json b/qapi/block-core.json
>> index 4c7a37a..819e3f9 100644
>> --- a/qapi/block-core.json
>> +++ b/qapi/block-core.json
>> @@ -2941,11 +2941,11 @@
>>               'refblock_alloc_write_blocks',
>> 'refblock_alloc_write_table',
>>               'refblock_alloc_switch_table', 'cluster_alloc',
>>               'cluster_alloc_bytes', 'cluster_free', 'flush_to_os',
>> -            'flush_to_disk', 'pwritev_rmw_head',
>> 'pwritev_rmw_after_head',
>> -            'pwritev_rmw_tail', 'pwritev_rmw_after_tail', 'pwritev',
>> -            'pwritev_zero', 'pwritev_done', 'empty_image_prepare',
>> -            'l1_shrink_write_table', 'l1_shrink_free_l2_clusters',
>> -            'cor_write'] }
>> +            'flush_to_disk', 'preadv', 'pwritev_rmw_head',
>> +            'pwritev_rmw_after_head', 'pwritev_rmw_tail',
>> +            'pwritev_rmw_after_tail', 'pwritev', 'pwritev_zero',
>> 'pwritev_done',
>> +            'empty_image_prepare', 'l1_shrink_write_table',
>> +            'l1_shrink_free_l2_clusters', 'cor_write'] }

Is this an unrelated change that snuck in? If it's intentional, you
ought to justify it in a standalone commit with a commit message
containing the rationale.

>>     ##
>>   # @BlkdebugInjectErrorOptions:
>> @@ -2980,6 +2980,34 @@
>>               '*immediately': 'bool' } }
>>     ##
>> +# @BlkdebugDelayOptions:
>> +#
>> +# Describes a single latency injection for blkdebug.
>> +#
>> +# @event:       trigger event
>> +#
>> +# @state:       the state identifier blkdebug needs to be in to
>> +#               actually trigger the event; defaults to "any"
>> +#
>> +# @latency:     The delay to add to an I/O, in microseconds.
>> +#
>> +# @sector:      specifies the sector index which has to be affected
>> +#               in order to actually trigger the event; defaults to "any
>> +#               sector"
>> +#
>> +# @once:        disables further events after this one has been
>> +#               triggered; defaults to false
>> +#
>> +# Since: 3.0

3.1, sorry :)

>> +##
>> +{ 'struct': 'BlkdebugDelayOptions',
>> +  'data': { 'event': 'BlkdebugEvent',
>> +            '*state': 'int',
>> +            '*latency': 'int',
>> +            '*sector': 'int',
>> +            '*once': 'bool' } }
>> +
>> +##
>>   # @BlkdebugSetStateOptions:
>>   #
>>   # Describes a single state-change event for blkdebug.
>> @@ -3049,6 +3077,7 @@
>>               '*opt-write-zero': 'int32', '*max-write-zero': 'int32',
>>               '*opt-discard': 'int32', '*max-discard': 'int32',
>>               '*inject-error': ['BlkdebugInjectErrorOptions'],
>> +            '*delay': ['BlkdebugDelayOptions'],
>>               '*set-state': ['BlkdebugSetStateOptions'] } }
>>     ##
>> diff --git a/tests/qemu-iotests/071 b/tests/qemu-iotests/071
>> index 48b4955..3d0610c 100755
>> --- a/tests/qemu-iotests/071
>> +++ b/tests/qemu-iotests/071
>> @@ -100,6 +100,69 @@ $QEMU_IO -c "open -o
>> driver=$IMGFMT,file.driver=blkdebug,file.inject-error.event
>>            -c 'read -P 42 0x38000 512'
>>     echo
>> +echo "=== Testing blkdebug latency through filename ==="
>> +echo
>> +
>> +$QEMU_IO -c "open -o
>> file.driver=blkdebug,file.delay.event=write_aio,file.delay.latency=10000
>> $TEST_IMG" \
>> +         -c 'aio_write -P 42 0x28000 512' \
>> +         -c 'aio_read -P 42 0x38000 512' \
>> +         | _filter_qemu_io
>> +
>> +echo
>> +echo "=== Testing blkdebug latency through file blockref ==="
>> +echo
>> +
>> +$QEMU_IO -c "open -o
>> driver=$IMGFMT,file.driver=blkdebug,file.delay.event=write_aio,file.delay.latency=10000,file.image.filename=$TEST_IMG"
>> \
>> +         -c 'aio_write -P 42 0x28000 512' \
>> +         -c 'aio_read -P 42 0x38000 512' \
>> +         | _filter_qemu_io
>> +
>> +# Using QMP is synchronous by default, so even though we would
>> +# expect reordering due to using the aio_* commands, they are
>> +# not. The purpose of this test is to verify that the driver
>> +# can be setup via QMP, and IO can complete. See the qemu-io
>> +# test above to prove delay functionality
>> +echo
>> +echo "=== Testing blkdebug on existing block device ==="
>> +echo
>> +
>> +run_qemu <<EOF
>> +{ "execute": "qmp_capabilities" }
>> +{ "execute": "blockdev-add",
>> +    "arguments": {
>> +        "node-name": "drive0",
>> +        "driver": "file",
>> +        "filename": "$TEST_IMG"
>> +    }
>> +}
>> +{ "execute": "blockdev-add",
>> +    "arguments": {
>> +        "driver": "$IMGFMT",
>> +        "node-name": "drive0-debug",
>> +        "file": {
>> +            "driver": "blkdebug",
>> +            "image": "drive0",
>> +            "delay": [{
>> +                "event": "write_aio",
>> +                "latency": 10000
>> +            }]
>> +        }
>> +    }
>> +}
>> +{ "execute": "human-monitor-command",
>> +    "arguments": {
>> +        "command-line": 'qemu-io drive0-debug "aio_write 0 512"'
>> +    }
>> +}
>> +{ "execute": "human-monitor-command",
>> +    "arguments": {
>> +        "command-line": 'qemu-io drive0-debug "aio_read 0 512"'
>> +    }
>> +}
>> +{ "execute": "quit" }
>> +EOF
>> +
>> +echo
>>   echo "=== Testing blkdebug on existing block device ==="
>>   echo
>>   diff --git a/tests/qemu-iotests/071.out b/tests/qemu-iotests/071.out
>> index 1d5e28d..1952990 100644
>> --- a/tests/qemu-iotests/071.out
>> +++ b/tests/qemu-iotests/071.out
>> @@ -36,6 +36,37 @@ read failed: Input/output error
>>     read failed: Input/output error
>>   +=== Testing blkdebug latency through filename ===
>> +
>> +read 512/512 bytes at offset 229376
>> +512 bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>> +wrote 512/512 bytes at offset 163840
>> +512 bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>> +
>> +=== Testing blkdebug latency through file blockref ===
>> +
>> +read 512/512 bytes at offset 229376
>> +512 bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>> +wrote 512/512 bytes at offset 163840
>> +512 bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>> +
>> +=== Testing blkdebug on existing block device ===
>> +
>> +Testing:
>> +QMP_VERSION
>> +{"return": {}}
>> +{"return": {}}
>> +{"return": {}}
>> +wrote 512/512 bytes at offset 0
>> +512 bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>> +{"return": ""}
>> +read 512/512 bytes at offset 0
>> +512 bytes, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
>> +{"return": ""}
>> +{"return": {}}
>> +{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP},
>> "event": "SHUTDOWN", "data": {"guest": false}}
>> +
>> +
>>   === Testing blkdebug on existing block device ===
>>     Testing:
> 
> 

Thanks, this seems like a good addition to have.

--js