| Message ID | 20200710172711.8059-3-den@openvz.org |
|---|---|
| State | New |
| Headers | show |
| Series | block: add logging facility for long standing IO requests | expand |
10.07.2020 20:27, 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> > CC: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.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 +++- > 3 files changed, 68 insertions(+), 3 deletions(-) > > diff --git a/block/accounting.c b/block/accounting.c > index 8d41c8a83a..3002444fa5 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 / 1000000; > + 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 / 1000000000ull; > + 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", Better use PRId64 for cookie->bytes s/.03%d/.%03d/ with this fixed: Reviewed-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> > + 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); may add blk_name as well > +} > + > 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 31d5eaf6bf..d87260958c 100644 > --- a/blockdev.c > +++ b/blockdev.c > @@ -625,7 +625,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)); Could we use non-zero default, so the option to be enabled by default? > > if (!parse_stats_intervals(blk_get_stats(blk), interval_list, errp)) { > blk_unref(blk); > @@ -3740,6 +3741,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_STRING, > + .help = "threshold for long I/O report (disabled if <=0), in ms", I'd say if ==0. Anyway it's unsigned.. > }, > { /* 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, >
On Fri, Jul 10, 2020 at 08:27:11PM +0300, Denis V. Lunev wrote: > +static void block_acct_report_long(BlockAcctStats *stats, > + BlockAcctCookie *cookie, int64_t latency_ns) > +{ > + unsigned latency_ms = latency_ns / 1000000; Please use 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 / 1000000000ull; Please use NANOSECONDS_PER_SECOND. > diff --git a/blockdev.c b/blockdev.c > index 31d5eaf6bf..d87260958c 100644 > --- a/blockdev.c > +++ b/blockdev.c > @@ -625,7 +625,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); > @@ -3740,6 +3741,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_STRING, QEMU_OPT_NUMBER?
On 7/29/20 1:30 PM, Stefan Hajnoczi wrote: > On Fri, Jul 10, 2020 at 08:27:11PM +0300, Denis V. Lunev wrote: >> +static void block_acct_report_long(BlockAcctStats *stats, >> + BlockAcctCookie *cookie, int64_t latency_ns) >> +{ >> + unsigned latency_ms = latency_ns / 1000000; > Please use SCALE_MS. sure > >> + 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 / 1000000000ull; > Please use NANOSECONDS_PER_SECOND. sure >> diff --git a/blockdev.c b/blockdev.c >> index 31d5eaf6bf..d87260958c 100644 >> --- a/blockdev.c >> +++ b/blockdev.c >> @@ -625,7 +625,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); >> @@ -3740,6 +3741,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_STRING, > QEMU_OPT_NUMBER? good catch! we have this parameter on by default (10 seconds) and never passed it from the command line :) Thus should we keep this off be default or on? :) Den
On Wed, Jul 29, 2020 at 02:06:43PM +0300, Denis V. Lunev wrote: > On 7/29/20 1:30 PM, Stefan Hajnoczi wrote: > > On Fri, Jul 10, 2020 at 08:27:11PM +0300, Denis V. Lunev wrote: > >> @@ -3740,6 +3741,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_STRING, > > QEMU_OPT_NUMBER? > good catch! we have this parameter on by default (10 seconds) and never > passed it from the command line :) > > Thus should we keep this off be default or on? :) On by default sounds good. It adds useful information. Stefan
diff --git a/block/accounting.c b/block/accounting.c index 8d41c8a83a..3002444fa5 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 / 1000000; + 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 / 1000000000ull; + 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 31d5eaf6bf..d87260958c 100644 --- a/blockdev.c +++ b/blockdev.c @@ -625,7 +625,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); @@ -3740,6 +3741,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_STRING, + .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,
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> CC: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.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 +++- 3 files changed, 68 insertions(+), 3 deletions(-)