Message ID | 20200805100824.16817-3-den@openvz.org (mailing list archive) |
---|---|
State | New, archived |
Headers | show |
Series | block: add logging facility for long standing IO requests | expand |
On 8/5/20 12:08 PM, Denis V. Lunev wrote: > There are severe delays with IO requests processing if QEMU is running in > virtual machine or over software defined storage. Such delays potentially > results in unpredictable guest behavior. For example, guests over IDE or > SATA drive could remount filesystem read-only if write is performed > longer than 10 seconds. > > Such reports are very complex to process. Some good starting point for this > seems quite reasonable. This patch provides one. It adds logging of such > potentially dangerous long IO operations. > > Signed-off-by: Denis V. Lunev <den@openvz.org> > Reviewed-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> > CC: Stefan Hajnoczi <stefanha@redhat.com> > CC: Kevin Wolf <kwolf@redhat.com> > CC: Max Reitz <mreitz@redhat.com> > --- > block/accounting.c | 59 +++++++++++++++++++++++++++++++++++++- > blockdev.c | 7 ++++- > include/block/accounting.h | 5 +++- > slirp | 2 +- > 4 files changed, 69 insertions(+), 4 deletions(-) > ... > typedef struct BlockAcctCookie { > @@ -101,7 +104,7 @@ typedef struct BlockAcctCookie { > > void block_acct_init(BlockAcctStats *stats); > void block_acct_setup(BlockAcctStats *stats, bool account_invalid, > - bool account_failed); > + bool account_failed, unsigned latency_log_threshold_ms); > void block_acct_cleanup(BlockAcctStats *stats); > void block_acct_add_interval(BlockAcctStats *stats, unsigned interval_length); > BlockAcctTimedStats *block_acct_interval_next(BlockAcctStats *stats, > diff --git a/slirp b/slirp > index ce94eba204..2faae0f778 160000 > --- a/slirp > +++ b/slirp > @@ -1 +1 @@ > -Subproject commit ce94eba2042d52a0ba3d9e252ebce86715e94275 > +Subproject commit 2faae0f778f818fadc873308f983289df697eb93 SLiRP change unrelated I presume...
On 8/5/20 4:51 PM, Philippe Mathieu-Daudé wrote: > On 8/5/20 12:08 PM, Denis V. Lunev wrote: >> There are severe delays with IO requests processing if QEMU is running in >> virtual machine or over software defined storage. Such delays potentially >> results in unpredictable guest behavior. For example, guests over IDE or >> SATA drive could remount filesystem read-only if write is performed >> longer than 10 seconds. >> >> Such reports are very complex to process. Some good starting point for this >> seems quite reasonable. This patch provides one. It adds logging of such >> potentially dangerous long IO operations. >> >> Signed-off-by: Denis V. Lunev <den@openvz.org> >> Reviewed-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> >> CC: Stefan Hajnoczi <stefanha@redhat.com> >> CC: Kevin Wolf <kwolf@redhat.com> >> CC: Max Reitz <mreitz@redhat.com> >> --- >> block/accounting.c | 59 +++++++++++++++++++++++++++++++++++++- >> blockdev.c | 7 ++++- >> include/block/accounting.h | 5 +++- >> slirp | 2 +- >> 4 files changed, 69 insertions(+), 4 deletions(-) >> > ... > >> typedef struct BlockAcctCookie { >> @@ -101,7 +104,7 @@ typedef struct BlockAcctCookie { >> >> void block_acct_init(BlockAcctStats *stats); >> void block_acct_setup(BlockAcctStats *stats, bool account_invalid, >> - bool account_failed); >> + bool account_failed, unsigned latency_log_threshold_ms); >> void block_acct_cleanup(BlockAcctStats *stats); >> void block_acct_add_interval(BlockAcctStats *stats, unsigned interval_length); >> BlockAcctTimedStats *block_acct_interval_next(BlockAcctStats *stats, >> diff --git a/slirp b/slirp >> index ce94eba204..2faae0f778 160000 >> --- a/slirp >> +++ b/slirp >> @@ -1 +1 @@ >> -Subproject commit ce94eba2042d52a0ba3d9e252ebce86715e94275 >> +Subproject commit 2faae0f778f818fadc873308f983289df697eb93 > SLiRP change unrelated I presume... > yes :( subprojects comes into play.. I have not event changed this. Just a result from pull :((((
diff --git a/block/accounting.c b/block/accounting.c index 8d41c8a83a..24f48c84b8 100644 --- a/block/accounting.c +++ b/block/accounting.c @@ -27,7 +27,9 @@ #include "block/accounting.h" #include "block/block_int.h" #include "qemu/timer.h" +#include "qemu/log.h" #include "sysemu/qtest.h" +#include "sysemu/block-backend.h" static QEMUClockType clock_type = QEMU_CLOCK_REALTIME; static const int qtest_latency_ns = NANOSECONDS_PER_SECOND / 1000; @@ -41,10 +43,11 @@ void block_acct_init(BlockAcctStats *stats) } void block_acct_setup(BlockAcctStats *stats, bool account_invalid, - bool account_failed) + bool account_failed, unsigned latency_log_threshold_ms) { stats->account_invalid = account_invalid; stats->account_failed = account_failed; + stats->latency_log_threshold_ms = latency_log_threshold_ms; } void block_acct_cleanup(BlockAcctStats *stats) @@ -182,6 +185,58 @@ void block_latency_histograms_clear(BlockAcctStats *stats) } } +static const char *block_account_type(enum BlockAcctType type) +{ + switch (type) { + case BLOCK_ACCT_READ: + return "READ"; + case BLOCK_ACCT_WRITE: + return "WRITE"; + case BLOCK_ACCT_FLUSH: + return "DISCARD"; + case BLOCK_ACCT_UNMAP: + return "TRUNCATE"; + case BLOCK_ACCT_NONE: + return "NONE"; + case BLOCK_MAX_IOTYPE: + break; + } + return "UNKNOWN"; +} + +static void block_acct_report_long(BlockAcctStats *stats, + BlockAcctCookie *cookie, int64_t latency_ns) +{ + unsigned latency_ms = latency_ns / SCALE_MS; + int64_t start_time_host_s; + char buf[64]; + struct tm t; + BlockDriverState *bs; + + if (cookie->type == BLOCK_ACCT_NONE) { + return; + } + if (stats->latency_log_threshold_ms == 0) { + return; + } + if (latency_ms < stats->latency_log_threshold_ms) { + return; + } + + start_time_host_s = cookie->start_time_ns / NANOSECONDS_PER_SECOND; + strftime(buf, sizeof(buf), "%m-%d %H:%M:%S", + localtime_r(&start_time_host_s, &t)); + + bs = blk_bs(blk_stats2blk(stats)); + qemu_log("long %s[%ld] IO request: %d.03%d since %s.%03d bs: %s(%s, %s)\n", + block_account_type(cookie->type), cookie->bytes, + (int)(latency_ms / 1000), (int)(latency_ms % 1000), buf, + (int)((cookie->start_time_ns / 1000000) % 1000), + bs == NULL ? "unknown" : bdrv_get_node_name(bs), + bs == NULL ? "unknown" : bdrv_get_format_name(bs), + bs == NULL ? "unknown" : bs->filename); +} + static void block_account_one_io(BlockAcctStats *stats, BlockAcctCookie *cookie, bool failed) { @@ -222,6 +277,8 @@ static void block_account_one_io(BlockAcctStats *stats, BlockAcctCookie *cookie, qemu_mutex_unlock(&stats->lock); + block_acct_report_long(stats, cookie, latency_ns); + cookie->type = BLOCK_ACCT_NONE; } diff --git a/blockdev.c b/blockdev.c index 3848a9c8ab..66158d1292 100644 --- a/blockdev.c +++ b/blockdev.c @@ -622,7 +622,8 @@ static BlockBackend *blockdev_init(const char *file, QDict *bs_opts, bs->detect_zeroes = detect_zeroes; - block_acct_setup(blk_get_stats(blk), account_invalid, account_failed); + block_acct_setup(blk_get_stats(blk), account_invalid, account_failed, + qemu_opt_get_number(opts, "latency-log-threshold", 0)); if (!parse_stats_intervals(blk_get_stats(blk), interval_list, errp)) { blk_unref(blk); @@ -3727,6 +3728,10 @@ QemuOptsList qemu_common_drive_opts = { .type = QEMU_OPT_BOOL, .help = "whether to account for failed I/O operations " "in the statistics", + },{ + .name = "latency-log-threshold", + .type = QEMU_OPT_NUMBER, + .help = "threshold for long I/O report (disabled if <=0), in ms", }, { /* end of list */ } }, diff --git a/include/block/accounting.h b/include/block/accounting.h index 878b4c3581..c3ea25f9aa 100644 --- a/include/block/accounting.h +++ b/include/block/accounting.h @@ -91,6 +91,9 @@ struct BlockAcctStats { bool account_invalid; bool account_failed; BlockLatencyHistogram latency_histogram[BLOCK_MAX_IOTYPE]; + + /* Threshold for long I/O detection, ms */ + unsigned latency_log_threshold_ms; }; typedef struct BlockAcctCookie { @@ -101,7 +104,7 @@ typedef struct BlockAcctCookie { void block_acct_init(BlockAcctStats *stats); void block_acct_setup(BlockAcctStats *stats, bool account_invalid, - bool account_failed); + bool account_failed, unsigned latency_log_threshold_ms); void block_acct_cleanup(BlockAcctStats *stats); void block_acct_add_interval(BlockAcctStats *stats, unsigned interval_length); BlockAcctTimedStats *block_acct_interval_next(BlockAcctStats *stats, diff --git a/slirp b/slirp index ce94eba204..2faae0f778 160000 --- a/slirp +++ b/slirp @@ -1 +1 @@ -Subproject commit ce94eba2042d52a0ba3d9e252ebce86715e94275 +Subproject commit 2faae0f778f818fadc873308f983289df697eb93