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

[PATCH 0/2] 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>
CC: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
CC: Kevin Wolf <kwolf@redhat.com>
CC: Max Reitz <mreitz@redhat.com>

[PATCH 1/2] 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>
CC: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.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 6936b25c83..e77a7e468e 100644
--- a/block/block-backend.c
+++ b/block/block-backend.c
@@ -2143,6 +2143,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

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

[Vladimir Sementsov-Ogievskiy]

10.07.2020 20:27, 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>
> CC: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.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 6936b25c83..e77a7e468e 100644
> --- a/block/block-backend.c
> +++ b/block/block-backend.c
> @@ -2143,6 +2143,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);
> 

Reviewed-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>

-- 
Best regards,
Vladimir

[PATCH 2/2] 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>
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",
+             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,
-- 
2.17.1

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

[Vladimir Sementsov-Ogievskiy]

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


-- 
Best regards,
Vladimir

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

[Stefan Hajnoczi]

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

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?

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

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

[Denis V. Lunev]

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

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

[Stefan Hajnoczi]

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

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

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

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

[Stefan Hajnoczi]

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

On Fri, Jul 10, 2020 at 08:27:09PM +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.
> 
> 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>

This looks useful. It is indeed hard to diagnose soft lockups, I/O
timeouts, etc inside the guest :). QEMU should print more info. Thanks
for doing this!

Stefan

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

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

[Stefan Hajnoczi]

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

On Fri, Jul 10, 2020 at 08:27:09PM +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.
> 
> 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>

If I understand correctly this only reports completed I/Os, so if the
host hasn't given up on an I/O request yet then QEMU will not report it
is taking a long time. In the meantime the guest could start printing
timeout errors.

I think this patch series is good as it is. In the future maybe a QMP
command that lists in-flight I/O requests would be nice. That helps
when troubleshooting I/Os that are hung.

Stefan

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

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

[Denis V. Lunev]

On 7/31/20 1:25 PM, Stefan Hajnoczi wrote:
> On Fri, Jul 10, 2020 at 08:27:09PM +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.
>>
>> 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>
> If I understand correctly this only reports completed I/Os, so if the
> host hasn't given up on an I/O request yet then QEMU will not report it
> is taking a long time. In the meantime the guest could start printing
> timeout errors.
>
> I think this patch series is good as it is. In the future maybe a QMP
> command that lists in-flight I/O requests would be nice. That helps
> when troubleshooting I/Os that are hung.
We could dump requests at block level, we do have proper lists,
but the would be a little bit different.

Anyway, I __DO__ like this idea, I have missed this somehow :)

Thank you for the suggestion,
    Den