[PATCH v2 for 5.2 0/3] block: add logging facility for long standing IO requests

[PATCH v2 for 5.2 0/3] block: add logging facility for long standing IO requests

[Denis V. Lunev]

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.

Changed from v2:
- removed accidentally added slirp subproject ID
- added comment describing timeout selection to patch 3

Changes from v1:
- fixed conversions using macros suggested by Stefan
- fixed option declaration
- enabled by default with patch 3

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>
CC: Stefan Hajnoczi <stefanha@redhat.com>

[PATCH 1/3] block/block-backend: add converter from BlockAcctStats to BlockBackend

[Denis V. Lunev]

Right now BlockAcctStats is always reside on BlockBackend. This structure
is not used in any other place. Thus we are able to create a converter
from one pointer to another.

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/block-backend.c          | 5 +++++
 include/sysemu/block-backend.h | 1 +
 2 files changed, 6 insertions(+)

diff --git a/block/block-backend.c b/block/block-backend.c
index 3a13cb5f0b..88e531df98 100644
--- a/block/block-backend.c
+++ b/block/block-backend.c
@@ -2153,6 +2153,11 @@ BlockAcctStats *blk_get_stats(BlockBackend *blk)
     return &blk->stats;
 }
 
+BlockBackend *blk_stats2blk(BlockAcctStats *s)
+{
+    return container_of(s, BlockBackend, stats);
+}
+
 void *blk_aio_get(const AIOCBInfo *aiocb_info, BlockBackend *blk,
                   BlockCompletionFunc *cb, void *opaque)
 {
diff --git a/include/sysemu/block-backend.h b/include/sysemu/block-backend.h
index 8203d7f6f9..bd4694e7bc 100644
--- a/include/sysemu/block-backend.h
+++ b/include/sysemu/block-backend.h
@@ -227,6 +227,7 @@ void blk_add_insert_bs_notifier(BlockBackend *blk, Notifier *notify);
 void blk_io_plug(BlockBackend *blk);
 void blk_io_unplug(BlockBackend *blk);
 BlockAcctStats *blk_get_stats(BlockBackend *blk);
+BlockBackend *blk_stats2blk(BlockAcctStats *stats);
 BlockBackendRootState *blk_get_root_state(BlockBackend *blk);
 void blk_update_root_state(BlockBackend *blk);
 bool blk_get_detect_zeroes_from_root_state(BlockBackend *blk);
-- 
2.17.1

[PATCH 2/3] block: add logging facility for long standing IO requests

[Denis V. Lunev]

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 +++-
 3 files changed, 68 insertions(+), 3 deletions(-)

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,
-- 
2.17.1

[PATCH 3/3] block: enable long IO requests report by default

[Denis V. Lunev]

Latency threshold is set to 10 seconds following guest request timeout
on legacy storage controller.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
CC: Stefan Hajnoczi <stefanha@redhat.com>
CC: Kevin Wolf <kwolf@redhat.com>
CC: Max Reitz <mreitz@redhat.com>
---
 blockdev.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/blockdev.c b/blockdev.c
index 66158d1292..733fdd36da 100644
--- a/blockdev.c
+++ b/blockdev.c
@@ -622,8 +622,13 @@ static BlockBackend *blockdev_init(const char *file, QDict *bs_opts,
 
         bs->detect_zeroes = detect_zeroes;
 
+        /*
+         * Set log threshold to 10 seconds. Timeout choosen by observation
+         * of the guest behavior with legacy storage controllers. Linux
+         * could remount FS read-only if journal write takes this time.
+         */
         block_acct_setup(blk_get_stats(blk), account_invalid, account_failed,
-                qemu_opt_get_number(opts, "latency-log-threshold", 0));
+                qemu_opt_get_number(opts, "latency-log-threshold", 10000));
 
         if (!parse_stats_intervals(blk_get_stats(blk), interval_list, errp)) {
             blk_unref(blk);
-- 
2.17.1

Re: [PATCH v2 for 5.2 0/3] block: add logging facility for long standing IO requests

[Stefan Hajnoczi]

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

On Mon, Aug 10, 2020 at 01:14:44PM +0300, 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.
> 
> Changed from v2:
> - removed accidentally added slirp subproject ID
> - added comment describing timeout selection to patch 3
> 
> Changes from v1:
> - fixed conversions using macros suggested by Stefan
> - fixed option declaration
> - enabled by default with patch 3
> 
> 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>
> CC: Stefan Hajnoczi <stefanha@redhat.com>

Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH v2 for 5.2 0/3] block: add logging facility for long standing IO requests

[Denis V. Lunev]

On 8/12/20 5:00 PM, Stefan Hajnoczi wrote:
> On Mon, Aug 10, 2020 at 01:14:44PM +0300, 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.
>>
>> Changed from v2:
>> - removed accidentally added slirp subproject ID
>> - added comment describing timeout selection to patch 3
>>
>> Changes from v1:
>> - fixed conversions using macros suggested by Stefan
>> - fixed option declaration
>> - enabled by default with patch 3
>>
>> 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>
>> CC: Stefan Hajnoczi <stefanha@redhat.com>
> Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>
ping

Re: [PATCH 2/3] block: add logging facility for long standing IO requests

[David Edmondson]

On Monday, 2020-08-10 at 13:14:46 +03, Denis V. Lunev wrote:

> +    strftime(buf, sizeof(buf), "%m-%d %H:%M:%S",

"%F %T" would include the year, which can be useful.

> +             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),

Is there a reason not to use %u rather than casting?

dme.
-- 
We wanna wait, but here we go again.

Re: [PATCH 2/3] block: add logging facility for long standing IO requests

[Denis V. Lunev]

On 8/20/20 11:03 AM, David Edmondson wrote:
> On Monday, 2020-08-10 at 13:14:46 +03, Denis V. Lunev wrote:
>
>> +    strftime(buf, sizeof(buf), "%m-%d %H:%M:%S",
> "%F %T" would include the year, which can be useful.
ok

>
>> +             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),
> Is there a reason not to use %u rather than casting?
no, we could use unsigned.

Will resend shortly.

Re: [PATCH 2/3] block: add logging facility for long standing IO requests

[Max Reitz]

[-- Attachment #1.1: Type: text/plain, Size: 5160 bytes --]

On 10.08.20 12:14, 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 +++-
>  3 files changed, 68 insertions(+), 3 deletions(-)
> 
> diff --git a/block/accounting.c b/block/accounting.c
> index 8d41c8a83a..24f48c84b8 100644
> --- a/block/accounting.c
> +++ b/block/accounting.c

[...]

> @@ -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";

I don’t understand how FLUSH translates to DISCARD, and UNMAP to 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,

Why not just latency_ms * .001f and %.3f?

> +             (int)((cookie->start_time_ns / 1000000) % 1000),

s/1000000/SCALE_MS/? (But I’m not sure whether that’s what the SCALE_?S
are for.)

> +             bs == NULL ? "unknown" : bdrv_get_node_name(bs),
> +             bs == NULL ? "unknown" : bdrv_get_format_name(bs),
> +             bs == NULL ? "unknown" : bs->filename);

Now that I’m writing this response already, I wonder whether a QMP event
wouldn’t be nice.  (But considering that accounting apparently just
doesn’t with -blockdev, I suppose that’s not that big of a worry.)

> +}
> +
>  static void block_account_one_io(BlockAcctStats *stats, BlockAcctCookie *cookie,
>                                   bool failed)
>  {

[...]

> 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));

latency_log_threshold_ms is an unsigned int and so this will silently
overflow for values >= 2^32.

(Or for user-specified values < 0, which are wrapped around.)

>  
>          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",

Because of that overflow, negative values will not necessarily disable
reporting, because truncating them to 32 bit may make them small
absolute values again.

In any case, I’d just say “disabled if 0”, and not mention anything
about <0.

Max


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH 1/3] block/block-backend: add converter from BlockAcctStats to BlockBackend

[Max Reitz]

[-- Attachment #1.1: Type: text/plain, Size: 2052 bytes --]

On 10.08.20 12:14, Denis V. Lunev wrote:
> Right now BlockAcctStats is always reside on BlockBackend. This structure
> is not used in any other place. Thus we are able to create a converter
> from one pointer to another.
> 
> 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/block-backend.c          | 5 +++++
>  include/sysemu/block-backend.h | 1 +
>  2 files changed, 6 insertions(+)

(Note: I’m just writing this mail because I already responded to patch
2.  I wouldn’t have if I didn’t have anything to say regarding the other
patches in this series, so nothing I say here is backed by a strong
opinion from me.)

> diff --git a/block/block-backend.c b/block/block-backend.c
> index 3a13cb5f0b..88e531df98 100644
> --- a/block/block-backend.c
> +++ b/block/block-backend.c
> @@ -2153,6 +2153,11 @@ BlockAcctStats *blk_get_stats(BlockBackend *blk)
>      return &blk->stats;
>  }
>  
> +BlockBackend *blk_stats2blk(BlockAcctStats *s)

(Extreme bikeshedding: I’d prefer something like blk_from_stats().)

> +{
> +    return container_of(s, BlockBackend, stats);
> +}

Works, but I get all itchy, especially given the reasoning in the commit
message, which is basically “Right now this works”.

That sounds to me like maybe in the future someone could get the idea of
moving BlockAcctStats somewhere else and then this is something that we
absolutely must not forget about, lest horrible accidents occur.

Would a back pointer from BlockAcctStats to the BlockBackend work or do
you find that just too ugly and unnecessary?  (I think it would help at
least so that we do not forget this place here.)

Or maybe just a comment above BlockAcctStats would help quench my itch,
too, like “Note: blk_stats2blk() expects objects of this type only to
occur as part of a BlockBackend”.

Max


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH 3/3] block: enable long IO requests report by default

[Max Reitz]

[-- Attachment #1.1: Type: text/plain, Size: 1322 bytes --]

On 10.08.20 12:14, Denis V. Lunev wrote:
> Latency threshold is set to 10 seconds following guest request timeout
> on legacy storage controller.
> 
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> CC: Kevin Wolf <kwolf@redhat.com>
> CC: Max Reitz <mreitz@redhat.com>
> ---
>  blockdev.c | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
> 
> diff --git a/blockdev.c b/blockdev.c
> index 66158d1292..733fdd36da 100644
> --- a/blockdev.c
> +++ b/blockdev.c
> @@ -622,8 +622,13 @@ static BlockBackend *blockdev_init(const char *file, QDict *bs_opts,
>  
>          bs->detect_zeroes = detect_zeroes;
>  
> +        /*
> +         * Set log threshold to 10 seconds. Timeout choosen by observation

*chosen

> +         * of the guest behavior with legacy storage controllers. Linux
> +         * could remount FS read-only if journal write takes this time.
> +         */
>          block_acct_setup(blk_get_stats(blk), account_invalid, account_failed,
> -                qemu_opt_get_number(opts, "latency-log-threshold", 0));
> +                qemu_opt_get_number(opts, "latency-log-threshold", 10000));

Yeah, why not.

Reviewed-by: Max Reitz <mreitz@redhat.com>


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH 2/3] block: add logging facility for long standing IO requests

[Denis V. Lunev]

On 9/17/20 4:56 PM, Max Reitz wrote:
> On 10.08.20 12:14, 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 +++-
>>  3 files changed, 68 insertions(+), 3 deletions(-)
>>
>> diff --git a/block/accounting.c b/block/accounting.c
>> index 8d41c8a83a..24f48c84b8 100644
>> --- a/block/accounting.c
>> +++ b/block/accounting.c
> [...]
>
>> @@ -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";
> I don’t understand how FLUSH translates to DISCARD, and UNMAP to TRUNCATE.
>

Ha, seems I have made copy/pasted and missed this.
Nice catch.

>> +    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,
> Why not just latency_ms * .001f and %.3f?
I personally dislike floating point, this leads to
a bit strange output.


>
>> +             (int)((cookie->start_time_ns / 1000000) % 1000),
> s/1000000/SCALE_MS/? (But I’m not sure whether that’s what the SCALE_?S
> are for.)
yes, you right.

>> +             bs == NULL ? "unknown" : bdrv_get_node_name(bs),
>> +             bs == NULL ? "unknown" : bdrv_get_format_name(bs),
>> +             bs == NULL ? "unknown" : bs->filename);
> Now that I’m writing this response already, I wonder whether a QMP event
> wouldn’t be nice.  (But considering that accounting apparently just
> doesn’t with -blockdev, I suppose that’s not that big of a worry.)
may be. Why not?

Though there is some note. Usually after the stall there
is a bunch of requests completed at the same time
once the storage is unfrozen, thus some aggregation
would be required.

I think that this should be made separately.
>> +}
>> +
>>  static void block_account_one_io(BlockAcctStats *stats, BlockAcctCookie *cookie,
>>                                   bool failed)
>>  {
> [...]
>
>> 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));
> latency_log_threshold_ms is an unsigned int and so this will silently
> overflow for values >= 2^32.
>
> (Or for user-specified values < 0, which are wrapped around.)
>
>>  
>>          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",
> Because of that overflow, negative values will not necessarily disable
> reporting, because truncating them to 32 bit may make them small
> absolute values again.
>
> In any case, I’d just say “disabled if 0”, and not mention anything
> about <0.
will do.

Thanks for review!

Den

Re: [PATCH 2/3] block: add logging facility for long standing IO requests

[Denis V. Lunev]

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 :((((

Re: [PATCH 2/3] block: add logging facility for long standing IO requests

[Philippe Mathieu-Daudé]

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...

[PATCH 2/3] block: add logging facility for long standing IO requests

[Denis V. Lunev]

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(-)

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
-- 
2.17.1