btrfs: scrub: refine the error messages output frequency

Currently when we increase the device statistics, it would always lead to an error message in the kernel log.

However this output is mostly duplicated with the existing ones:

- For scrub operations
We always have the following messages:
* "fixed up error at logical %llu"
* "unable to fixup (regular) error at logical %llu"

So no matter if the corruption is repaired or not, it scrub would output an error message to indicate the problem.

- For non-scrub read operations
We also have the following messages:
* "csum failed root %lld inode %llu off %llu" for data csum mismatch
* "bad (tree block start|fsid|tree block level)" for metadata
* "read error corrected: ino %llu off %llu" for repaired data/metadata

So the error message from btrfs_dev_stat_inc_and_print() is duplicated.

The real usage for the btrfs device statistics is for some user space daemon to check if there is any new errors, acting like some checks on SMART, thus we don't really need/want those messages in dmesg.

This patch would reduce the log level to debug (disabled by default) for btrfs_dev_stat_inc_and_print().
For users really want to utilize btrfs devices statistics, they should go check "btrfs device stats" periodically, and we should focus the kernel error messages to more important things.

Quoted 25 lines · Qu Wenruo

Currently when we increase the device statistics, it would always lead to an error message in the kernel log.

However this output is mostly duplicated with the existing ones:

- For scrub operations
We always have the following messages:
* "fixed up error at logical %llu"
* "unable to fixup (regular) error at logical %llu"

So no matter if the corruption is repaired or not, it scrub would output an error message to indicate the problem.

- For non-scrub read operations
We also have the following messages:
* "csum failed root %lld inode %llu off %llu" for data csum mismatch
* "bad (tree block start|fsid|tree block level)" for metadata
* "read error corrected: ino %llu off %llu" for repaired data/metadata

So the error message from btrfs_dev_stat_inc_and_print() is duplicated.

The real usage for the btrfs device statistics is for some user space daemon to check if there is any new errors, acting like some checks on SMART, thus we don't really need/want those messages in dmesg.

Quoted 5 lines

This patch would reduce the log level to debug (disabled by default) for btrfs_dev_stat_inc_and_print().
For users really want to utilize btrfs devices statistics, they should go check "btrfs device stats" periodically, and we should focus the kernel error messages to more important things.

I kind if disagree with each point.

The message is meant to be logged as it will happen in production and outside of development, so the debug level does not make sense.

The stats message is not duplicated for the individual causes, it additionally tracks the whole state.

Logging important messages to system log is a common thing and we do that a lot, this makes debugging and anlyzing things easier. We can't expect that there would always be a daemon collecting the stats, there's not standardized or recommended tool for that. A quick look to dmesg can show that something is wrong.

What we can do: reduce the number messages so the whole stats are printed once per transaction if there is a change.

We can also tune which events also print the stats, for example flush errors are more interesting than read/write, comparing the number of events that can happen in a batch.

The @stripe passed into scrub_stripe_report_errors() either has stripe->dev and stripe->physical properly populated (regular data stripes) or stripe->flags would have SCRUB_STRIPE_FLAG_NO_REPORT (RAID56 P/Q stripes).

Thus there is no need to go with btrfs_map_block() to get the dev/physical.

Just add an extra ASSERT() to make sure we get stripe->dev populated correctly.

Signed-off-by Qu Wenruo <[email protected]>

---
 fs/btrfs/scrub.c | 54 +++++++-----------------------------------------
 1 file changed, 7 insertions(+), 47 deletions(-)

fs/btrfs/scrub.c +7 -48

index a5a9fef2bdb2..ff952dd2b510 100644
@@ -863,7 +863,7 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
        static DEFINE_RATELIMIT_STATE(rs, DEFAULT_RATELIMIT_INTERVAL,
                                      DEFAULT_RATELIMIT_BURST);
        struct btrfs_fs_info *fs_info = sctx->fs_info;
-       struct btrfs_device *dev = NULL;
+       struct btrfs_device *dev = stripe->dev;
        u64 stripe_physical = stripe->physical;
        int nr_data_sectors = 0;
        int nr_meta_sectors = 0;

@@ -874,35 +874,7 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
        if (test_bit(SCRUB_STRIPE_FLAG_NO_REPORT, &stripe->state))
                return;
 
-       /*
-        * Init needed infos for error reporting.
-        *
-        * Although our scrub_stripe infrastructure is mostly based on btrfs_submit_bio()
-        * thus no need for dev/physical, error reporting still needs dev and physical.
-        */
-       if (!bitmap_empty(&stripe->init_error_bitmap, stripe->nr_sectors)) {
-               u64 mapped_len = fs_info->sectorsize;
-               struct btrfs_io_context *bioc = NULL;
-               int stripe_index = stripe->mirror_num - 1;
-               int ret;
-
-               /* For scrub, our mirror_num should always start at 1. */
-               ASSERT(stripe->mirror_num >= 1);
-               ret = btrfs_map_block(fs_info, BTRFS_MAP_GET_READ_MIRRORS,
-                                     stripe->logical, &mapped_len, &bioc,
-                                     NULL, NULL);
-               /*
-                * If we failed, dev will be NULL, and later detailed reports
-                * will just be skipped.
-                */
-               if (ret < 0)
-                       goto skip;
-               stripe_physical = bioc->stripes[stripe_index].physical;
-               dev = bioc->stripes[stripe_index].dev;
-               btrfs_put_bioc(bioc);
-       }
-
-skip:
+       ASSERT(dev);
        for_each_set_bit(sector_nr, &stripe->extent_sector_bitmap, stripe->nr_sectors) {
                const u64 logical = stripe->logical +
                                    (sector_nr << fs_info->sectorsize_bits);

@@ -933,41 +905,29 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
                 * output the message of repaired message.
                 */
                if (repaired) {
-                       if (dev) {
-                               btrfs_err_rl_in_rcu(fs_info,
+                       btrfs_err_rl_in_rcu(fs_info,
                        "fixed up error at logical %llu on dev %s physical %llu",
                                            logical, btrfs_dev_name(dev),
                                            physical);
-                       } else {
-                               btrfs_err_rl_in_rcu(fs_info,
-                       "fixed up error at logical %llu on mirror %u",
-                                           logical, stripe->mirror_num);
-                       }
                        continue;
                }
 
                /* The remaining are all for unrepaired. */
-               if (dev) {
-                       btrfs_err_rl_in_rcu(fs_info,
+               btrfs_err_rl_in_rcu(fs_info,
        "unable to fixup (regular) error at logical %llu on dev %s physical %llu",
                                            logical, btrfs_dev_name(dev),
                                            physical);
-               } else {
-                       btrfs_err_rl_in_rcu(fs_info,
-       "unable to fixup (regular) error at logical %llu on mirror %u",
-                                           logical, stripe->mirror_num);
-               }
 
                if (test_bit(sector_nr, &stripe->io_error_bitmap))
-                       if (__ratelimit(&rs) && dev)
+                       if (__ratelimit(&rs))
                                scrub_print_common_warning("i/o error", dev,
                                                     logical, physical);
                if (test_bit(sector_nr, &stripe->csum_error_bitmap))
-                       if (__ratelimit(&rs) && dev)
+                       if (__ratelimit(&rs))
                                scrub_print_common_warning("checksum error", dev,
                                                     logical, physical);
                if (test_bit(sector_nr, &stripe->meta_error_bitmap))
-                       if (__ratelimit(&rs) && dev)
+                       if (__ratelimit(&rs))
                                scrub_print_common_warning("header error", dev,
                                                     logical, physical);
        }
--

2.44.0

For btrfs scrub error messages, I have hit a lot of support cases on older kernels where no filename is outputted at all, with only error messages like:

BTRFS error (device dm-0): bdev /dev/mapper/sys-rootlv errs: wr 0, rd 0, flush 0, corrupt 2823, gen 0 BTRFS error (device dm-0): unable to fixup (regular) error at logical 1563504640 on dev /dev/mapper/sys-rootlv BTRFS error (device dm-0): bdev /dev/mapper/sys-rootlv errs: wr 0, rd 0, flush 0, corrupt 2824, gen 0 BTRFS error (device dm-0): unable to fixup (regular) error at logical 1579016192 on dev /dev/mapper/sys-rootlv BTRFS error (device dm-0): bdev /dev/mapper/sys-rootlv errs: wr 0, rd 0, flush 0, corrupt 2825, gen 0

The "unable to fixup (regular) error" line shows we hit an unrepairable error, then normally we would do data/metadata backref walk to grab the correct info.

But we can hit cases like the inode is already orphan (unlinked from any parent inode), or even the subvolume is orphan (unlinked and waiting to be deleted).

In that case we're not sure what's the proper way to continue (Is it some critical data/metadata? Would it prevent the system from booting?)

To improve the situation, this patch would:

- Ensure we at least output one message for each unrepairable error If by somehow we didn't output any error message for the error, we always fallback to the basic logical/physical error output, with its type (data or metadata).

Signed-off-by Qu Wenruo <[email protected]>

---
 fs/btrfs/scrub.c | 25 ++++++++++++++++++-------
 1 file changed, 18 insertions(+), 7 deletions(-)

fs/btrfs/scrub.c +7 -7

index 85f321e3e37c..0d2b042d75c2 100644
@@ -226,6 +226,7 @@ struct scrub_warning {
        u64                     physical;
        u64                     logical;
        struct btrfs_device     *dev;
+       bool                    message_printed;
 };
 
 static void release_scrub_stripe(struct scrub_stripe *stripe)

@@ -425,7 +426,7 @@ static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
         * we deliberately ignore the bit ipath might have been too small to
         * hold all of the paths here
         */
-       for (i = 0; i < ipath->fspath->elem_cnt; ++i)
+       for (i = 0; i < ipath->fspath->elem_cnt; ++i) {
                btrfs_warn_in_rcu(fs_info,
 "%s at logical %llu on dev %s, physical %llu, root %llu, inode %llu, offset %llu, path: %s",
                                  swarn->errstr, swarn->logical,

@@ -433,6 +434,8 @@ static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
                                  swarn->physical,
                                  root, inum, offset,
                                  (char *)(unsigned long)ipath->fspath->val[i]);
+               swarn->message_printed = true;
+       }
 
        btrfs_put_root(local_root);
        free_ipath(ipath);

@@ -445,7 +448,7 @@ static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
                          btrfs_dev_name(swarn->dev),
                          swarn->physical,
                          root, inum, offset, ret);
-
+       swarn->message_printed = true;
        free_ipath(ipath);
        return 0;
 }

@@ -471,6 +474,7 @@ static void scrub_print_common_warning(const char *errstr, struct btrfs_device *
        swarn.logical = logical;
        swarn.errstr = errstr;
        swarn.dev = NULL;
+       swarn.message_printed = false;
 
        ret = extent_from_logical(fs_info, swarn.logical, path, &found_key,
                                  &flags);

@@ -492,12 +496,8 @@ static void scrub_print_common_warning(const char *errstr, struct btrfs_device *
                        ret = tree_backref_for_extent(&ptr, eb, &found_key, ei,
                                                      item_size, &ref_root,
                                                      &ref_level);
-                       if (ret < 0) {
-                               btrfs_warn(fs_info,
-                               "failed to resolve tree backref for logical %llu: %d",
-                                                 swarn.logical, ret);
+                       if (ret < 0)
                                break;
-                       }
                        if (ret > 0)
                                break;
                        btrfs_warn_in_rcu(fs_info,

fs/btrfs/scrub.c +5 -1

                btrfs_release_path(path);
        } else {
                struct btrfs_backref_walk_ctx ctx = { 0 };

@@ -520,6 +526,11 @@ static void scrub_print_common_warning(const char *errstr, struct btrfs_device *
                swarn.dev = dev;
 
                iterate_extent_inodes(&ctx, true, scrub_print_warning_inode, &swarn);
+               if (!swarn.message_printed)
+                       btrfs_warn_in_rcu(fs_info,
+       "%s at data, filename unresolved, logical %llu on dev %s physical %llu",
+                                         errstr, swarn.logical,
+                                         btrfs_dev_name(dev), swarn.physical);
        }
 
 out:
--

2.44.0

Currently scrub goes different ways to rate limits its error messages:

- regular btrfs_err_rl_in_rcu() helper for repaired sectors and the initial message for unrepaired sectors

- Manually rate limits scrub_print_common_warning()

I'd say the different rate limits could lead to cases where we only got the "unable to fixup (regular) error" messages but the detailed report about that corruption is ratelimited.

To make the whole rate limit works more consistently, change the rate limit by:

- Always using btrfs_*_rl() helpers

- Remove the initial "unable to fixup (regular) error" message Since we're ensured to have at least one error message for each unrepaired sector (before rate limit), there is no need for a duplicated line.

And if we hit rate limits, we will rate limit all the error messages together, not treating different error messages differently.

Signed-off-by Qu Wenruo <[email protected]>

---
 fs/btrfs/scrub.c | 26 ++++++++------------------
 1 file changed, 8 insertions(+), 18 deletions(-)

fs/btrfs/scrub.c +8 -19

index 0d2b042d75c2..f942c9e3f121 100644
@@ -427,7 +427,7 @@ static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
         * hold all of the paths here
         */
        for (i = 0; i < ipath->fspath->elem_cnt; ++i) {
-               btrfs_warn_in_rcu(fs_info,
+               btrfs_warn_rl_in_rcu(fs_info,
 "%s at logical %llu on dev %s, physical %llu, root %llu, inode %llu, offset %llu, path: %s",
                                  swarn->errstr, swarn->logical,
                                  btrfs_dev_name(swarn->dev),

@@ -442,7 +442,7 @@ static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
        return 0;
 
 err:
-       btrfs_warn_in_rcu(fs_info,
+       btrfs_warn_rl_in_rcu(fs_info,
                          "%s at logical %llu on dev %s, physical %llu, root %llu, inode %llu, offset %llu: path resolving failed with ret=%d",
                          swarn->errstr, swarn->logical,
                          btrfs_dev_name(swarn->dev),

@@ -500,7 +500,7 @@ static void scrub_print_common_warning(const char *errstr, struct btrfs_device *
                                break;
                        if (ret > 0)
                                break;
-                       btrfs_warn_in_rcu(fs_info,
+                       btrfs_warn_rl_in_rcu(fs_info,
 "%s at logical %llu on dev %s, physical %llu: metadata %s (level %d) in tree %llu",
                                errstr, swarn.logical, btrfs_dev_name(dev),
                                swarn.physical, (ref_level ? "node" : "leaf"),

@@ -508,7 +508,7 @@ static void scrub_print_common_warning(const char *errstr, struct btrfs_device *
                        swarn.message_printed = true;
                }
                if (!swarn.message_printed)
-                       btrfs_warn_in_rcu(fs_info,
+                       btrfs_warn_rl_in_rcu(fs_info,
                        "%s at metadata, logical %llu on dev %s physical %llu",
                                          errstr, swarn.logical,
                                          btrfs_dev_name(dev), swarn.physical);

@@ -527,7 +527,7 @@ static void scrub_print_common_warning(const char *errstr, struct btrfs_device *
 
                iterate_extent_inodes(&ctx, true, scrub_print_warning_inode, &swarn);
                if (!swarn.message_printed)
-                       btrfs_warn_in_rcu(fs_info,
+                       btrfs_warn_rl_in_rcu(fs_info,
        "%s at data, filename unresolved, logical %llu on dev %s physical %llu",
                                          errstr, swarn.logical,
                                          btrfs_dev_name(dev), swarn.physical);

@@ -846,8 +846,6 @@ static void scrub_stripe_submit_repair_read(struct scrub_stripe *stripe,
 static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
                                       struct scrub_stripe *stripe)
 {
-       static DEFINE_RATELIMIT_STATE(rs, DEFAULT_RATELIMIT_INTERVAL,
-                                     DEFAULT_RATELIMIT_BURST);
        struct btrfs_fs_info *fs_info = sctx->fs_info;
        struct btrfs_device *dev = stripe->dev;
        u64 stripe_physical = stripe->physical;

@@ -899,22 +897,14 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
                }
 
                /* The remaining are all for unrepaired. */
-               btrfs_err_rl_in_rcu(fs_info,
-       "unable to fixup (regular) error at logical %llu on dev %s physical %llu",
-                                           logical, btrfs_dev_name(dev),
-                                           physical);
-
                if (test_bit(sector_nr, &stripe->io_error_bitmap))
-                       if (__ratelimit(&rs))
-                               scrub_print_common_warning("i/o error", dev,
+                       scrub_print_common_warning("i/o error", dev,
                                                     logical, physical);
                if (test_bit(sector_nr, &stripe->csum_error_bitmap))
-                       if (__ratelimit(&rs))
-                               scrub_print_common_warning("checksum error", dev,
+                       scrub_print_common_warning("checksum error", dev,
                                                     logical, physical);
                if (test_bit(sector_nr, &stripe->meta_error_bitmap))
-                       if (__ratelimit(&rs))
-                               scrub_print_common_warning("header error", dev,
+                       scrub_print_common_warning("header error", dev,
                                                     logical, physical);
        }
 
--

2.44.0