[PATCH 0/5] block, migration: improve debugging of migration bdrv_flush failure

[PATCH 0/5] block, migration: improve debugging of migration bdrv_flush failure

[Daniel P. Berrangé]

I spent a while debugging a tricky migration failure today which was
ultimately caused by fdatasync() getting EACCESS. The existing probes
were not sufficient to diagnose this, so I had to resort to GDB. This
improves probes and block error reporting to make future diagnosis
possible without GDB.

Daniel P. Berrangé (5):
  migration: add trace point when vm_stop_force_state fails
  softmmu: add trace point when bdrv_flush_all fails
  block: preserve errno from fdatasync failures
  block: add trace point when fdatasync fails
  block: remove duplicate trace.h include

 block/file-posix.c     | 10 +++++-----
 block/trace-events     |  1 +
 migration/migration.c  |  1 +
 migration/trace-events |  1 +
 softmmu/cpus.c         |  7 ++++++-
 softmmu/trace-events   |  3 +++
 6 files changed, 17 insertions(+), 6 deletions(-)

-- 
2.30.2

[PATCH 1/5] migration: add trace point when vm_stop_force_state fails

[Daniel P. Berrangé]

This is a critical failure scenario for migration that is hard to
diagnose from existing probes. Most likely it is caused by an error
from bdrv_flush(), but we're not logging the errno anywhere, hence
this new probe.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 migration/migration.c  | 1 +
 migration/trace-events | 1 +
 2 files changed, 2 insertions(+)

diff --git a/migration/migration.c b/migration/migration.c
index 8ca034136b..bee0dcd501 100644
--- a/migration/migration.c
+++ b/migration/migration.c
@@ -3121,6 +3121,7 @@ static void migration_completion(MigrationState *s)
         if (!ret) {
             bool inactivate = !migrate_colo_enabled();
             ret = vm_stop_force_state(RUN_STATE_FINISH_MIGRATE);
+            trace_migration_completion_vm_stop(ret);
             if (ret >= 0) {
                 ret = migration_maybe_pause(s, &current_active_state,
                                             MIGRATION_STATUS_DEVICE);
diff --git a/migration/trace-events b/migration/trace-events
index 668c562fed..8ec28432eb 100644
--- a/migration/trace-events
+++ b/migration/trace-events
@@ -149,6 +149,7 @@ migrate_pending(uint64_t size, uint64_t max, uint64_t pre, uint64_t compat, uint
 migrate_send_rp_message(int msg_type, uint16_t len) "%d: len %d"
 migrate_send_rp_recv_bitmap(char *name, int64_t size) "block '%s' size 0x%"PRIi64
 migration_completion_file_err(void) ""
+migration_completion_vm_stop(int ret) "ret %d"
 migration_completion_postcopy_end(void) ""
 migration_completion_postcopy_end_after_complete(void) ""
 migration_rate_limit_pre(int ms) "%d ms"
-- 
2.30.2

Re: [PATCH 1/5] migration: add trace point when vm_stop_force_state fails

[Dr. David Alan Gilbert]

* Daniel P. Berrangé (berrange@redhat.com) wrote:
> This is a critical failure scenario for migration that is hard to
> diagnose from existing probes. Most likely it is caused by an error
> from bdrv_flush(), but we're not logging the errno anywhere, hence
> this new probe.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>

Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>

> ---
>  migration/migration.c  | 1 +
>  migration/trace-events | 1 +
>  2 files changed, 2 insertions(+)
> 
> diff --git a/migration/migration.c b/migration/migration.c
> index 8ca034136b..bee0dcd501 100644
> --- a/migration/migration.c
> +++ b/migration/migration.c
> @@ -3121,6 +3121,7 @@ static void migration_completion(MigrationState *s)
>          if (!ret) {
>              bool inactivate = !migrate_colo_enabled();
>              ret = vm_stop_force_state(RUN_STATE_FINISH_MIGRATE);
> +            trace_migration_completion_vm_stop(ret);
>              if (ret >= 0) {
>                  ret = migration_maybe_pause(s, &current_active_state,
>                                              MIGRATION_STATUS_DEVICE);
> diff --git a/migration/trace-events b/migration/trace-events
> index 668c562fed..8ec28432eb 100644
> --- a/migration/trace-events
> +++ b/migration/trace-events
> @@ -149,6 +149,7 @@ migrate_pending(uint64_t size, uint64_t max, uint64_t pre, uint64_t compat, uint
>  migrate_send_rp_message(int msg_type, uint16_t len) "%d: len %d"
>  migrate_send_rp_recv_bitmap(char *name, int64_t size) "block '%s' size 0x%"PRIi64
>  migration_completion_file_err(void) ""
> +migration_completion_vm_stop(int ret) "ret %d"
>  migration_completion_postcopy_end(void) ""
>  migration_completion_postcopy_end_after_complete(void) ""
>  migration_rate_limit_pre(int ms) "%d ms"
> -- 
> 2.30.2
> 
-- 
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

[PATCH 2/5] softmmu: add trace point when bdrv_flush_all fails

[Daniel P. Berrangé]

The VM stop process has to flush outstanding I/O and this is a critical
failure scenario that is hard to diagnose. Add a probe point that
records the flush return code.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 softmmu/cpus.c       | 7 ++++++-
 softmmu/trace-events | 3 +++
 2 files changed, 9 insertions(+), 1 deletion(-)

diff --git a/softmmu/cpus.c b/softmmu/cpus.c
index a7ee431187..c3caaeb26e 100644
--- a/softmmu/cpus.c
+++ b/softmmu/cpus.c
@@ -44,6 +44,7 @@
 #include "sysemu/whpx.h"
 #include "hw/boards.h"
 #include "hw/hw.h"
+#include "trace.h"
 
 #ifdef CONFIG_LINUX
 
@@ -266,6 +267,7 @@ static int do_vm_stop(RunState state, bool send_stop)
 
     bdrv_drain_all();
     ret = bdrv_flush_all();
+    trace_vm_stop_flush_all(ret);
 
     return ret;
 }
@@ -704,12 +706,15 @@ int vm_stop_force_state(RunState state)
     if (runstate_is_running()) {
         return vm_stop(state);
     } else {
+        int ret;
         runstate_set(state);
 
         bdrv_drain_all();
         /* Make sure to return an error if the flush in a previous vm_stop()
          * failed. */
-        return bdrv_flush_all();
+        ret = bdrv_flush_all();
+        trace_vm_stop_flush_all(ret);
+        return ret;
     }
 }
 
diff --git a/softmmu/trace-events b/softmmu/trace-events
index b80ca042e1..f11b427544 100644
--- a/softmmu/trace-events
+++ b/softmmu/trace-events
@@ -19,6 +19,9 @@ flatview_new(void *view, void *root) "%p (root %p)"
 flatview_destroy(void *view, void *root) "%p (root %p)"
 flatview_destroy_rcu(void *view, void *root) "%p (root %p)"
 
+# softmmu.c
+vm_stop_flush_all(int ret) "ret %d"
+
 # vl.c
 vm_state_notify(int running, int reason, const char *reason_str) "running %d reason %d (%s)"
 load_file(const char *name, const char *path) "name %s location %s"
-- 
2.30.2

Re: [PATCH 2/5] softmmu: add trace point when bdrv_flush_all fails

[Dr. David Alan Gilbert]

* Daniel P. Berrangé (berrange@redhat.com) wrote:
> The VM stop process has to flush outstanding I/O and this is a critical
> failure scenario that is hard to diagnose. Add a probe point that
> records the flush return code.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>

Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>

> ---
>  softmmu/cpus.c       | 7 ++++++-
>  softmmu/trace-events | 3 +++
>  2 files changed, 9 insertions(+), 1 deletion(-)
> 
> diff --git a/softmmu/cpus.c b/softmmu/cpus.c
> index a7ee431187..c3caaeb26e 100644
> --- a/softmmu/cpus.c
> +++ b/softmmu/cpus.c
> @@ -44,6 +44,7 @@
>  #include "sysemu/whpx.h"
>  #include "hw/boards.h"
>  #include "hw/hw.h"
> +#include "trace.h"
>  
>  #ifdef CONFIG_LINUX
>  
> @@ -266,6 +267,7 @@ static int do_vm_stop(RunState state, bool send_stop)
>  
>      bdrv_drain_all();
>      ret = bdrv_flush_all();
> +    trace_vm_stop_flush_all(ret);
>  
>      return ret;
>  }
> @@ -704,12 +706,15 @@ int vm_stop_force_state(RunState state)
>      if (runstate_is_running()) {
>          return vm_stop(state);
>      } else {
> +        int ret;
>          runstate_set(state);
>  
>          bdrv_drain_all();
>          /* Make sure to return an error if the flush in a previous vm_stop()
>           * failed. */
> -        return bdrv_flush_all();
> +        ret = bdrv_flush_all();
> +        trace_vm_stop_flush_all(ret);
> +        return ret;
>      }
>  }
>  
> diff --git a/softmmu/trace-events b/softmmu/trace-events
> index b80ca042e1..f11b427544 100644
> --- a/softmmu/trace-events
> +++ b/softmmu/trace-events
> @@ -19,6 +19,9 @@ flatview_new(void *view, void *root) "%p (root %p)"
>  flatview_destroy(void *view, void *root) "%p (root %p)"
>  flatview_destroy_rcu(void *view, void *root) "%p (root %p)"
>  
> +# softmmu.c
> +vm_stop_flush_all(int ret) "ret %d"
> +
>  # vl.c
>  vm_state_notify(int running, int reason, const char *reason_str) "running %d reason %d (%s)"
>  load_file(const char *name, const char *path) "name %s location %s"
> -- 
> 2.30.2
> 
-- 
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

[PATCH 3/5] block: preserve errno from fdatasync failures

[Daniel P. Berrangé]

When fdatasync() fails on a file backend we set a flag that
short-circuits any future attempts to call fdatasync(). The
first failure returns the true errno, but the later short-
circuited calls return a generic EIO. The latter is unhelpful
because fdatasync() can return a variety of errnos, including
EACCESS.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 block/file-posix.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/block/file-posix.c b/block/file-posix.c
index 20e14f8e96..99cf452f84 100644
--- a/block/file-posix.c
+++ b/block/file-posix.c
@@ -160,7 +160,7 @@ typedef struct BDRVRawState {
     bool discard_zeroes:1;
     bool use_linux_aio:1;
     bool use_linux_io_uring:1;
-    bool page_cache_inconsistent:1;
+    int page_cache_inconsistent; /* errno from fdatasync failure */
     bool has_fallocate;
     bool needs_alignment;
     bool drop_cache;
@@ -1357,7 +1357,7 @@ static int handle_aiocb_flush(void *opaque)
     int ret;
 
     if (s->page_cache_inconsistent) {
-        return -EIO;
+        return -s->page_cache_inconsistent;
     }
 
     ret = qemu_fdatasync(aiocb->aio_fildes);
@@ -1376,7 +1376,7 @@ static int handle_aiocb_flush(void *opaque)
          * Obviously, this doesn't affect O_DIRECT, which bypasses the page
          * cache. */
         if ((s->open_flags & O_DIRECT) == 0) {
-            s->page_cache_inconsistent = true;
+            s->page_cache_inconsistent = errno;
         }
         return -errno;
     }
-- 
2.30.2

[PATCH 4/5] block: add trace point when fdatasync fails

[Daniel P. Berrangé]

A flush failure is a critical failure scenario for some operations.
For example, it will prevent migration from completing, as it will
make vm_stop() report an error. Thus it is important to have a
trace point present for debugging.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 block/file-posix.c | 2 ++
 block/trace-events | 1 +
 2 files changed, 3 insertions(+)

diff --git a/block/file-posix.c b/block/file-posix.c
index 99cf452f84..6aafeda44f 100644
--- a/block/file-posix.c
+++ b/block/file-posix.c
@@ -1362,6 +1362,8 @@ static int handle_aiocb_flush(void *opaque)
 
     ret = qemu_fdatasync(aiocb->aio_fildes);
     if (ret == -1) {
+        trace_file_flush_fdatasync_failed(errno);
+
         /* There is no clear definition of the semantics of a failing fsync(),
          * so we may have to assume the worst. The sad truth is that this
          * assumption is correct for Linux. Some pages are now probably marked
diff --git a/block/trace-events b/block/trace-events
index 1a12d634e2..c8a943e992 100644
--- a/block/trace-events
+++ b/block/trace-events
@@ -206,6 +206,7 @@ file_copy_file_range(void *bs, int src, int64_t src_off, int dst, int64_t dst_of
 file_FindEjectableOpticalMedia(const char *media) "Matching using %s"
 file_setup_cdrom(const char *partition) "Using %s as optical disc"
 file_hdev_is_sg(int type, int version) "SG device found: type=%d, version=%d"
+file_flush_fdatasync_failed(int err) "errno %d"
 
 # sheepdog.c
 sheepdog_reconnect_to_sdog(void) "Wait for connection to be established"
-- 
2.30.2

Re: [PATCH 4/5] block: add trace point when fdatasync fails

[Dr. David Alan Gilbert]

* Daniel P. Berrangé (berrange@redhat.com) wrote:
> A flush failure is a critical failure scenario for some operations.
> For example, it will prevent migration from completing, as it will
> make vm_stop() report an error. Thus it is important to have a
> trace point present for debugging.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>

I'd have had to admit to not having thought that would fail; the fact
we're debugging something where it does, suggests it's a good idea!


Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>

> ---
>  block/file-posix.c | 2 ++
>  block/trace-events | 1 +
>  2 files changed, 3 insertions(+)
> 
> diff --git a/block/file-posix.c b/block/file-posix.c
> index 99cf452f84..6aafeda44f 100644
> --- a/block/file-posix.c
> +++ b/block/file-posix.c
> @@ -1362,6 +1362,8 @@ static int handle_aiocb_flush(void *opaque)
>  
>      ret = qemu_fdatasync(aiocb->aio_fildes);
>      if (ret == -1) {
> +        trace_file_flush_fdatasync_failed(errno);
> +
>          /* There is no clear definition of the semantics of a failing fsync(),
>           * so we may have to assume the worst. The sad truth is that this
>           * assumption is correct for Linux. Some pages are now probably marked
> diff --git a/block/trace-events b/block/trace-events
> index 1a12d634e2..c8a943e992 100644
> --- a/block/trace-events
> +++ b/block/trace-events
> @@ -206,6 +206,7 @@ file_copy_file_range(void *bs, int src, int64_t src_off, int dst, int64_t dst_of
>  file_FindEjectableOpticalMedia(const char *media) "Matching using %s"
>  file_setup_cdrom(const char *partition) "Using %s as optical disc"
>  file_hdev_is_sg(int type, int version) "SG device found: type=%d, version=%d"
> +file_flush_fdatasync_failed(int err) "errno %d"
>  
>  # sheepdog.c
>  sheepdog_reconnect_to_sdog(void) "Wait for connection to be established"
> -- 
> 2.30.2
> 
-- 
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

[PATCH 5/5] block: remove duplicate trace.h include

[Daniel P. Berrangé]

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 block/file-posix.c | 2 --
 1 file changed, 2 deletions(-)

diff --git a/block/file-posix.c b/block/file-posix.c
index 6aafeda44f..2538e43299 100644
--- a/block/file-posix.c
+++ b/block/file-posix.c
@@ -106,8 +106,6 @@
 #include <xfs/xfs.h>
 #endif
 
-#include "trace.h"
-
 /* OS X does not have O_DSYNC */
 #ifndef O_DSYNC
 #ifdef O_SYNC
-- 
2.30.2

Re: [PATCH 5/5] block: remove duplicate trace.h include

[Dr. David Alan Gilbert]

* Daniel P. Berrangé (berrange@redhat.com) wrote:
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>

Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>

> ---
>  block/file-posix.c | 2 --
>  1 file changed, 2 deletions(-)
> 
> diff --git a/block/file-posix.c b/block/file-posix.c
> index 6aafeda44f..2538e43299 100644
> --- a/block/file-posix.c
> +++ b/block/file-posix.c
> @@ -106,8 +106,6 @@
>  #include <xfs/xfs.h>
>  #endif
>  
> -#include "trace.h"
> -
>  /* OS X does not have O_DSYNC */
>  #ifndef O_DSYNC
>  #ifdef O_SYNC
> -- 
> 2.30.2
> 
-- 
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: [PATCH 0/5] block, migration: improve debugging of migration bdrv_flush failure

[Connor Kuehl]

On 4/15/21 8:58 AM, Daniel P. Berrangé wrote:
> I spent a while debugging a tricky migration failure today which was
> ultimately caused by fdatasync() getting EACCESS. The existing probes
> were not sufficient to diagnose this, so I had to resort to GDB. This
> improves probes and block error reporting to make future diagnosis
> possible without GDB.
> 
> Daniel P. Berrangé (5):
>    migration: add trace point when vm_stop_force_state fails
>    softmmu: add trace point when bdrv_flush_all fails
>    block: preserve errno from fdatasync failures
>    block: add trace point when fdatasync fails
>    block: remove duplicate trace.h include
> 
>   block/file-posix.c     | 10 +++++-----
>   block/trace-events     |  1 +
>   migration/migration.c  |  1 +
>   migration/trace-events |  1 +
>   softmmu/cpus.c         |  7 ++++++-
>   softmmu/trace-events   |  3 +++
>   6 files changed, 17 insertions(+), 6 deletions(-)
> 

For the series:

Reviewed-by: Connor Kuehl <ckuehl@redhat.com>