btrfs: scrub: refine the error messages

[BUG]
Scrub is not reporting the correct logical/physical address, it can be verified by the following script:

  # mkfs.btrfs -f $dev1
  # mount $dev1 $mnt
  # xfs_io -f -c "pwrite -S 0xaa 0 128k" $mnt/file1
  # umount $mnt
  # xfs_io -f -c "pwrite -S 0xff 13647872 4k" $dev1
  # mount $dev1 $mnt
  # btrfs scrub start -fB $mnt
  # umount $mnt

Note above 13647872 is the physical address for logical 13631488 + 4K.

Scrub would report the following error:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13631488 on dev /dev/mapper/test-scratch1 physical 13631488
BTRFS warning (device dm-2): checksum error at logical 13631488 on dev /dev/mapper/test-scratch1, physical 13631488, root 5, inode 257, offset 0, length 4096, links 1 (path: file1)

On the other hand, "btrfs check --check-data-csum" is reporting the correct logical/physical address:

Checking filesystem on /dev/test/scratch1
UUID: db2eb621-b09d-4f24-8199-da17dc7b3201
[5/7] checking csums against data
mirror 1 bytenr 13647872 csum 0x13fec125 expected csum 0x656bd64e
ERROR: errors found in csum tree

[CAUSE]
In the function scrub_stripe_report_errors(), we always use the stripe->logical and its physical address to print the error message, not taking the sector number into consideration at all.

[FIX]
Fix the error reporting function by calculating logical/physical with the sector number.

Now the scrub report is correct:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872 on dev /dev/mapper/test-scratch1 physical 13647872
BTRFS warning (device dm-2): checksum error at logical 13647872 on dev /dev/mapper/test-scratch1, physical 13647872, root 5, inode 257, offset 16384, length 4096, links 1 (path: file1)

Fixes 0096580713ff ("btrfs: scrub: introduce error reporting functionality for scrub_stripe")

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

---
  fs/btrfs/scrub.c | 22 +++++++++++++---------
  1 file changed, 13 insertions(+), 9 deletions(-)

fs/btrfs/scrub.c +13 -9

index fa25004ab04e..119e98797b21 100644
@@ -870,7 +870,7 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
  				      DEFAULT_RATELIMIT_BURST);
  	struct btrfs_fs_info *fs_info = sctx->fs_info;
  	struct btrfs_device *dev = NULL;
-	u64 physical = 0;
+	u64 stripe_physical = stripe->physical;
  	int nr_data_sectors = 0;
  	int nr_meta_sectors = 0;
  	int nr_nodatacsum_sectors = 0;

@@ -903,13 +903,17 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
  		 */
  		if (ret < 0)
  			goto skip;
-		physical = bioc->stripes[stripe_index].physical;
+		stripe_physical = bioc->stripes[stripe_index].physical;
  		dev = bioc->stripes[stripe_index].dev;
  		btrfs_put_bioc(bioc);
  	}
 
  skip:
  	for_each_set_bit(sector_nr, &stripe->extent_sector_bitmap, stripe->nr_sectors) {
+		u64 logical = stripe->logical +
+			      (sector_nr << fs_info->sectorsize_bits);
+		u64 physical = stripe_physical +
+			      (sector_nr << fs_info->sectorsize_bits);
  		bool repaired = false;
 
  		if (stripe->sectors[sector_nr].is_metadata) {

@@ -938,12 +942,12 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
  			if (dev) {
  				btrfs_err_rl_in_rcu(fs_info,
  			"fixed up error at logical %llu on dev %s physical %llu",
-					    stripe->logical, btrfs_dev_name(dev),
+					    logical, btrfs_dev_name(dev),
  					    physical);
  			} else {
  				btrfs_err_rl_in_rcu(fs_info,
  			"fixed up error at logical %llu on mirror %u",
-					    stripe->logical, stripe->mirror_num);
+					    logical, stripe->mirror_num);
  			}
  			continue;
  		}

@@ -952,26 +956,26 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
  		if (dev) {
  			btrfs_err_rl_in_rcu(fs_info,
  	"unable to fixup (regular) error at logical %llu on dev %s physical %llu",
-					    stripe->logical, btrfs_dev_name(dev),
+					    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",
-					    stripe->logical, stripe->mirror_num);
+					    logical, stripe->mirror_num);
  		}
 
  		if (test_bit(sector_nr, &stripe->io_error_bitmap))
  			if (__ratelimit(&rs) && dev)
  				scrub_print_common_warning("i/o error", dev, false,
-						     stripe->logical, physical);
+						     logical, physical);
  		if (test_bit(sector_nr, &stripe->csum_error_bitmap))
  			if (__ratelimit(&rs) && dev)
  				scrub_print_common_warning("checksum error", dev, false,
-						     stripe->logical, physical);
+						     logical, physical);
  		if (test_bit(sector_nr, &stripe->meta_error_bitmap))
  			if (__ratelimit(&rs) && dev)
  				scrub_print_common_warning("header error", dev, false,
-						     stripe->logical, physical);
+						     logical, physical);
  	}
 
  	spin_lock(&sctx->stat_lock);

[BUG]
Scrub is not reporting the correct logical/physical address, it can be verified by the following script:

 # mkfs.btrfs -f $dev1
 # mount $dev1 $mnt
 # xfs_io -f -c "pwrite -S 0xaa 0 128k" $mnt/file1
 # umount $mnt
 # xfs_io -f -c "pwrite -S 0xff 13647872 4k" $dev1
 # mount $dev1 $mnt
 # btrfs scrub start -fB $mnt
 # umount $mnt

Note above 13647872 is the physical address for logical 13631488 + 4K.

Scrub would report the following error:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13631488 on dev /dev/mapper/test-scratch1 physical 13631488
BTRFS warning (device dm-2): checksum error at logical 13631488 on dev /dev/mapper/test-scratch1, physical 13631488, root 5, inode 257, offset 0, length 4096, links 1 (path: file1)

On the other hand, "btrfs check --check-data-csum" is reporting the correct logical/physical address:

Checking filesystem on /dev/test/scratch1
UUID: db2eb621-b09d-4f24-8199-da17dc7b3201
[5/7] checking csums against data
mirror 1 bytenr 13647872 csum 0x13fec125 expected csum 0x656bd64e
ERROR: errors found in csum tree

[CAUSE]
In the function scrub_stripe_report_errors(), we always use the stripe->logical and its physical address to print the error message, not taking the sector number into consideration at all.

[FIX]
Fix the error reporting function by calculating logical/physical with the sector number.

Now the scrub report is correct:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872 on dev /dev/mapper/test-scratch1 physical 13647872
BTRFS warning (device dm-2): checksum error at logical 13647872 on dev /dev/mapper/test-scratch1, physical 13647872, root 5, inode 257, offset 16384, length 4096, links 1 (path: file1)

Fixes 0096580713ff ("btrfs: scrub: introduce error reporting functionality for scrub_stripe")

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

---
 fs/btrfs/scrub.c | 22 +++++++++++++---------
 1 file changed, 13 insertions(+), 9 deletions(-)

fs/btrfs/scrub.c +2 -2

index fa25004ab04e..119e98797b21 100644
@@ -870,7 +870,7 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
                                      DEFAULT_RATELIMIT_BURST);
        struct btrfs_fs_info *fs_info = sctx->fs_info;
        struct btrfs_device *dev = NULL;
-       u64 physical = 0;
+       u64 stripe_physical = stripe->physical;
        int nr_data_sectors = 0;
        int nr_meta_sectors = 0;
        int nr_nodatacsum_sectors = 0;

@@ -903,13 +903,17 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
                 */
                if (ret < 0)
                        goto skip;
-               physical = bioc->stripes[stripe_index].physical;
+               stripe_physical = bioc->stripes[stripe_index].physical;

fs/btrfs/scrub.c +7 -8

                bool repaired = false;
 
                if (stripe->sectors[sector_nr].is_metadata) {

@@ -938,12 +942,12 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
                        if (dev) {
                                btrfs_err_rl_in_rcu(fs_info,
                        "fixed up error at logical %llu on dev %s physical %llu",
-                                           stripe->logical, btrfs_dev_name(dev),
+                                           logical, btrfs_dev_name(dev),
                                            physical);
                        } else {
                                btrfs_err_rl_in_rcu(fs_info,
                        "fixed up error at logical %llu on mirror %u",
-                                           stripe->logical, stripe->mirror_num);
+                                           logical, stripe->mirror_num);
                        }
                        continue;
                }

@@ -952,26 +956,26 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
                if (dev) {
                        btrfs_err_rl_in_rcu(fs_info,
        "unable to fixup (regular) error at logical %llu on dev %s physical %llu",
-                                           stripe->logical, btrfs_dev_name(dev),
+                                           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",
-                                           stripe->logical, stripe->mirror_num);
+                                           logical, stripe->mirror_num);
                }
 
                if (test_bit(sector_nr, &stripe->io_error_bitmap))
                        if (__ratelimit(&rs) && dev)
                                scrub_print_common_warning("i/o error", dev, false,
-                                                    stripe->logical, physical);
+                                                    logical, physical);
                if (test_bit(sector_nr, &stripe->csum_error_bitmap))
                        if (__ratelimit(&rs) && dev)
                                scrub_print_common_warning("checksum error", dev, false,
-                                                    stripe->logical, physical);
+                                                    logical, physical);
                if (test_bit(sector_nr, &stripe->meta_error_bitmap))
                        if (__ratelimit(&rs) && dev)
                                scrub_print_common_warning("header error", dev, false,
-                                                    stripe->logical, physical);
+                                                    logical, physical);
        }
 
        spin_lock(&sctx->stat_lock);
--

2.44.0

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

I would argue this behavior is not ideal:

- It would flood the dmesg and bury real important messages One common scenario is scrub.
If scrub hit some errors, it would cause both scrub and btrfs_dev_stat_inc_and_print() to print error messages.

And in that case, btrfs_dev_stat_inc_and_print() is completely useless.

- The results of btrfs_dev_stat_inc_and_print() is mostly for history monitoring, doesn't has enough details

If we trigger the errors during regular read, such messages from btrfs_dev_stat_inc_and_print() won't help us to locate the cause either.

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.

CC [email protected]

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

---
 fs/btrfs/volumes.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

fs/btrfs/volumes.c +1 -2

index e49935a54da0..126145950ed3 100644
@@ -7828,7 +7828,7 @@ void btrfs_dev_stat_inc_and_print(struct btrfs_device *dev, int index)
 
        if (!dev->dev_stats_valid)
                return;
-       btrfs_err_rl_in_rcu(dev->fs_info,
+       btrfs_debug_rl_in_rcu(dev->fs_info,
                "bdev %s errs: wr %u, rd %u, flush %u, corrupt %u, gen %u",
                           btrfs_dev_name(dev),
                           btrfs_dev_stat_read(dev, BTRFS_DEV_STAT_WRITE_ERRS),
--

2.44.0

Since commit 2a2dc22f7e9d ("btrfs: scrub: use dedicated super block verification function to scrub one super block"), the super block scrubbing is handled in a dedicated helper, thus scrub_print_common_warning() no longer needs to print warning for super block errors.

Just remove the parameter.

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

---
 fs/btrfs/scrub.c | 14 ++++----------
 1 file changed, 4 insertions(+), 10 deletions(-)

fs/btrfs/scrub.c +4 -11

index 119e98797b21..5e371ffdb37b 100644
@@ -476,7 +476,7 @@ static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
 }
 
 static void scrub_print_common_warning(const char *errstr, struct btrfs_device *dev,
-                                      bool is_super, u64 logical, u64 physical)
+                                      u64 logical, u64 physical)
 {
        struct btrfs_fs_info *fs_info = dev->fs_info;
        struct btrfs_path *path;

@@ -488,12 +488,6 @@ static void scrub_print_common_warning(const char *errstr, struct btrfs_device *
        u32 item_size;
        int ret;
 
-       /* Super block error, no need to search extent tree. */
-       if (is_super) {
-               btrfs_warn_in_rcu(fs_info, "%s on device %s, physical %llu",
-                                 errstr, btrfs_dev_name(dev), physical);
-               return;
-       }
        path = btrfs_alloc_path();
        if (!path)
                return;

@@ -966,15 +960,15 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
 
                if (test_bit(sector_nr, &stripe->io_error_bitmap))
                        if (__ratelimit(&rs) && dev)
-                               scrub_print_common_warning("i/o error", dev, false,
+                               scrub_print_common_warning("i/o error", dev,
                                                     logical, physical);
                if (test_bit(sector_nr, &stripe->csum_error_bitmap))
                        if (__ratelimit(&rs) && dev)
-                               scrub_print_common_warning("checksum error", dev, false,
+                               scrub_print_common_warning("checksum error", dev,
                                                     logical, physical);
                if (test_bit(sector_nr, &stripe->meta_error_bitmap))
                        if (__ratelimit(&rs) && dev)
-                               scrub_print_common_warning("header error", dev, false,
+                               scrub_print_common_warning("header error", dev,
                                                     logical, physical);
        }
 
--

2.44.0

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 | 59 ++++++------------------------------------------
 1 file changed, 7 insertions(+), 52 deletions(-)

fs/btrfs/scrub.c +5 -48

index 5e371ffdb37b..277583464371 100644
@@ -860,10 +860,8 @@ 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 = NULL;
+       struct btrfs_device *dev = stripe->dev;
        u64 stripe_physical = stripe->physical;
        int nr_data_sectors = 0;
        int nr_meta_sectors = 0;

@@ -874,35 +872,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) {
                u64 logical = stripe->logical +
                              (sector_nr << fs_info->sectorsize_bits);

@@ -933,42 +903,27 @@ 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)
-                               scrub_print_common_warning("i/o error", dev,
+                       scrub_print_common_warning("i/o error", dev,

fs/btrfs/scrub.c +0 -1

                                                     logical, physical);
        }
 
--

2.44.0

The following two output are not really needed:

- nlinks
Normally file inodes should have nlinks as 1, for those inodes have multiple hard links, the inode/root number is still enough to pin it down to certain inode.

- size
The size is always fixed to sector size.

By removing the nlinks output, we can reduce one inode item lookup.

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

---
 fs/btrfs/scrub.c | 27 +--------------------------
 1 file changed, 1 insertion(+), 26 deletions(-)

fs/btrfs/scrub.c +1 -27

index 277583464371..18b2ee3b1616 100644
@@ -388,17 +388,13 @@ static noinline_for_stack struct scrub_ctx *scrub_setup_ctx(
 static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
                                     u64 root, void *warn_ctx)
 {
-       u32 nlink;
        int ret;
        int i;
        unsigned nofs_flag;
-       struct extent_buffer *eb;
-       struct btrfs_inode_item *inode_item;
        struct scrub_warning *swarn = warn_ctx;
        struct btrfs_fs_info *fs_info = swarn->dev->fs_info;
        struct inode_fs_paths *ipath = NULL;
        struct btrfs_root *local_root;
-       struct btrfs_key key;
 
        local_root = btrfs_get_fs_root(fs_info, root, true);
        if (IS_ERR(local_root)) {

@@ -406,26 +402,6 @@ static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
                goto err;
        }
 
-       /*
-        * this makes the path point to (inum INODE_ITEM ioff)
-        */
-       key.objectid = inum;
-       key.type = BTRFS_INODE_ITEM_KEY;
-       key.offset = 0;
-
-       ret = btrfs_search_slot(NULL, local_root, &key, swarn->path, 0, 0);
-       if (ret) {
-               btrfs_put_root(local_root);
-               btrfs_release_path(swarn->path);
-               goto err;
-       }
-
-       eb = swarn->path->nodes[0];
-       inode_item = btrfs_item_ptr(eb, swarn->path->slots[0],
-                                       struct btrfs_inode_item);
-       nlink = btrfs_inode_nlink(eb, inode_item);
-       btrfs_release_path(swarn->path);
-
        /*
         * init_path might indirectly call vmalloc, or use GFP_KERNEL. Scrub
         * uses GFP_NOFS in this context, so we keep it consistent but it does

@@ -451,12 +427,11 @@ static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
         */
        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, length %u, links %u (path: %s)",
+"%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),
                                  swarn->physical,
                                  root, inum, offset,
-                                 fs_info->sectorsize, nlink,
                                  (char *)(unsigned long)ipath->fspath->val[i]);
 
        btrfs_put_root(local_root);
--

2.44.0

During some support sessions, I found older kernels are always report very unuseful scrub 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

There are two problems:
- No proper details about the corruption
No metadata or data indication, nor the filename or the tree id. Even the involved kernel (and newer kernels after the scrub rework) has the ability to do backref walk and find out the file path or the tree backref.

My guess is, for data sometimes the corrupted sector is no longer referred by any data extent.

- Too noisy and useless error message from btrfs_dev_stat_inc_and_print()
I'd argue we should not output any error message just for btrfs_dev_stat_inc_and_print().

After the series, the error message would look like this:

BTRFS warning (device dm-2): checksum error at inode 5/257(file1) fileoff 16384, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872

This involves the following enhancement:

- Single line
And we ensure we output at least one line for the error we hit. No more unrelated btrfs_dev_stat_inc_and_print() output.

- Proper fall backs
We have the following different fall back options
* Repaired
Just a line of something repaired for logical/physical address.

* Detailed data info
Including the following elements (if possible), and if higher priority ones can not be fetched, it would be skipped and try lower priority items:
+ file path (can have multiple ones)
+ root/inode number and offset
+ logical/physical address (always output)

* Detaile metadata info
The priority list is:
+ root ref/level
+ logical/physical address (always output)

For the worst case of data corruption, we would still have some like:

BTRFS warning (device dm-2): checksum error at data, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872

And similar ones for metadata:

BTRFS warning (device dm-2): checksum error at meta, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872

The first patch is fixing a regression in the error message, which leads to bad logical/physical bytenr.
The second one would reduce the log level for btrfs_dev_stat_inc_and_print().

Path 3~4 are cleanups to remove unnecessary parameters.

The remaining reworks the format and refine the error message frequency.

Qu Wenruo (7):
btrfs: scrub: fix incorrectly reported logical/physical address
btrfs: reduce the log level for btrfs_dev_stat_inc_and_print()
btrfs: scrub: remove unused is_super parameter from
scrub_print_common_warning()
btrfs: scrub: remove unnecessary dev/physical lookup for
scrub_stripe_report_errors()
btrfs: scrub: simplify the inode iteration output
btrfs: scrub: unify and shorten the error message
btrfs: scrub: fix the frequency of error messages

 fs/btrfs/scrub.c   | 185 ++++++++++++++++-----------------------------
 fs/btrfs/volumes.c |   2 +-
 2 files changed, 66 insertions(+), 121 deletions(-)

Signature · 1 line

2.44.0

Currently the scrub error report is pretty long:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872 on dev /dev/mapper/test-scratch1 physical 13647872
BTRFS warning (device dm-2): checksum error at logical 13647872 on dev /dev/mapper/test-scratch1, physical 13647872, root 5, inode 257, offset 16384, length 4096, links 1 (path: file1)

Since we have so many things to output, it's not a surprise we got long error lines.

To make the lines a little shorter, and make important info more obvious, change the unify output to something like this:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872 BTRFS warning (device dm-2): checksum error at inode 5/257(file1) fileoff 16384, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872

The idea is, to put large values/small values/string separated meanwhile skip the some descriptor directly:

- "logical LOGICAL(MIRROR)"
LOGICAL is always a large value, meanwhile MIRROR is always a single digit.
Thus combining them together, human can still split them instinctively.

- "physical DEVID(DEVPATH)PHYSICAL"
DEVID is normally a short number, DEVPATH is a long string, and PHYSICAL is a normally a large number.
And for most end users, the most important device path is still easy to catch, even surrounded by some large numbers.

- inode ROOT/INO(PATH)
To locate a btrfs inode, we have to provide both root and inode number. Normally ROOT should be a much smaller number (3 digits) meanwhile the INO can be pretty large.

However for the end user, the most important thing is the PATH, which is still not hard to locate.

Any better ideas would be appreciated to make those lines shorter.

However what we really need is a proper way to report all those info (maybe put the file/dev name resolution into the user space) to user space reliably (without rate limit).

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

---
 fs/btrfs/scrub.c | 55 +++++++++++++++++++++++++++---------------------
 1 file changed, 31 insertions(+), 24 deletions(-)

fs/btrfs/scrub.c +31 -25

index 18b2ee3b1616..17e492076bf8 100644
@@ -226,6 +226,7 @@ struct scrub_warning {
        u64                     physical;
        u64                     logical;
        struct btrfs_device     *dev;
+       int                     mirror_num;
 };
 
 static void release_scrub_stripe(struct scrub_stripe *stripe)

@@ -427,12 +428,12 @@ static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
         */
        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,
-                                 btrfs_dev_name(swarn->dev),
-                                 swarn->physical,
-                                 root, inum, offset,
-                                 (char *)(unsigned long)ipath->fspath->val[i]);
+"%s at inode %lld/%llu(%s) fileoff %llu, logical %llu(%u) physical %llu(%s)%llu",
+                                 swarn->errstr, root, inum,
+                                 (char *)ipath->fspath->val[i], offset,
+                                 swarn->logical, swarn->mirror_num,
+                                 swarn->dev->devid, btrfs_dev_name(swarn->dev),
+                                 swarn->physical);
 
        btrfs_put_root(local_root);
        free_ipath(ipath);

@@ -440,18 +441,17 @@ static int scrub_print_warning_inode(u64 inum, u64 offset, u64 num_bytes,
 
 err:
        btrfs_warn_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),
-                         swarn->physical,
-                         root, inum, offset, ret);
-
+       "%s at inode %lld/%llu fileoff %llu, logical %llu(%u) physical %llu(%s)%llu",
+                         swarn->errstr, root, inum, offset,
+                         swarn->logical, swarn->mirror_num,
+                         swarn->dev->devid, btrfs_dev_name(swarn->dev),
+                         swarn->physical);
        free_ipath(ipath);
        return 0;
 }
 
 static void scrub_print_common_warning(const char *errstr, struct btrfs_device *dev,
-                                      u64 logical, u64 physical)
+                                      u64 logical, u64 physical, int mirror_num)
 {
        struct btrfs_fs_info *fs_info = dev->fs_info;
        struct btrfs_path *path;

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

@@ -501,10 +502,11 @@ static void scrub_print_common_warning(const char *errstr, struct btrfs_device *
                        if (ret > 0)
                                break;
                        btrfs_warn_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"),
-                               ref_level, ref_root);
+"%s at metadata in tree %llu(%u), logical %llu(%u) physical %llu(%s)%llu",
+                               errstr, ref_root, ref_level,
+                               swarn.logical, swarn.mirror_num,
+                               dev->devid, btrfs_dev_name(dev),
+                               swarn.physical);
                }
                btrfs_release_path(path);
        } else {

@@ -879,27 +881,32 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
                 */
                if (repaired) {
                        btrfs_err_rl_in_rcu(fs_info,
-                       "fixed up error at logical %llu on dev %s physical %llu",
-                                           logical, btrfs_dev_name(dev),
+                       "fixed up error at logical %llu(%u) physical %llu(%s)%llu",
+                                           logical, stripe->mirror_num,
+                                           dev->devid, btrfs_dev_name(dev),
                                            physical);
                        continue;
                }
 
                /* 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),
+       "unable to fixup (regular) error at logical %llu(%u) physical %llu(%s)%llu",
+                                           logical, stripe->mirror_num,
+                                           dev->devid, btrfs_dev_name(dev),
                                            physical);
 
                if (test_bit(sector_nr, &stripe->io_error_bitmap))
                        scrub_print_common_warning("i/o error", dev,
-                                                    logical, physical);
+                                                    logical, physical,
+                                                    stripe->mirror_num);
                if (test_bit(sector_nr, &stripe->csum_error_bitmap))
                        scrub_print_common_warning("checksum error", dev,
-                                                    logical, physical);
+                                                    logical, physical,
+                                                    stripe->mirror_num);
                if (test_bit(sector_nr, &stripe->meta_error_bitmap))
                        scrub_print_common_warning("header error", dev,
-                                                    logical, physical);
+                                                    logical, physical,
+                                                    stripe->mirror_num);
        }
 
        spin_lock(&sctx->stat_lock);
--

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

- Remove the "unable to fixup" error message
Since we have ensured at least one error message is outputted for each unrepairable corruption, there is no need for that fallback one.

Now one unrepairable corruption would output a more refined and less duplicated error message:

BTRFS info (device dm-2): scrub: started on devid 1
BTRFS warning (device dm-2): checksum error at inode 5/257(file1) fileoff 16384, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872 BTRFS info (device dm-2): scrub: finished on devid 1 with status: 0

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

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

fs/btrfs/scrub.c +19 -9

index 17e492076bf8..84617a64b2d4 100644
@@ -227,6 +227,7 @@ struct scrub_warning {
        u64                     logical;
        struct btrfs_device     *dev;
        int                     mirror_num;
+       bool                    message_printed;
 };
 
 static void release_scrub_stripe(struct scrub_stripe *stripe)

@@ -426,26 +427,29 @@ 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)
-               btrfs_warn_in_rcu(fs_info,
+       for (i = 0; i < ipath->fspath->elem_cnt; ++i) {
+               btrfs_warn_rl_in_rcu(fs_info,
 "%s at inode %lld/%llu(%s) fileoff %llu, logical %llu(%u) physical %llu(%s)%llu",
                                  swarn->errstr, root, inum,
                                  (char *)ipath->fspath->val[i], offset,
                                  swarn->logical, swarn->mirror_num,
                                  swarn->dev->devid, btrfs_dev_name(swarn->dev),
                                  swarn->physical);
+               swarn->message_printed = true;
+       }
 
        btrfs_put_root(local_root);
        free_ipath(ipath);
        return 0;
 
 err:
-       btrfs_warn_in_rcu(fs_info,
+       btrfs_warn_rl_in_rcu(fs_info,
        "%s at inode %lld/%llu fileoff %llu, logical %llu(%u) physical %llu(%s)%llu",
                          swarn->errstr, root, inum, offset,
                          swarn->logical, swarn->mirror_num,
                          swarn->dev->devid, btrfs_dev_name(swarn->dev),
                          swarn->physical);
+       swarn->message_printed = true;
        free_ipath(ipath);
        return 0;
 }

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

@@ -488,26 +493,31 @@ static void scrub_print_common_warning(const char *errstr, struct btrfs_device *
                unsigned long ptr = 0;
                u8 ref_level;
                u64 ref_root;
+               bool message_printed = false;
 
                while (true) {
                        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,
+                       btrfs_warn_rl_in_rcu(fs_info,
 "%s at metadata in tree %llu(%u), logical %llu(%u) physical %llu(%s)%llu",
                                errstr, ref_root, ref_level,
                                swarn.logical, swarn.mirror_num,
                                dev->devid, btrfs_dev_name(dev),
                                swarn.physical);
+                       message_printed = true;
                }
+               if (!message_printed)
+                       btrfs_warn_rl_in_rcu(fs_info,
+"%s at metadata, logical %llu(%u) physical %llu(%s)%llu",
+                               errstr, swarn.logical, swarn.mirror_num,
+                               dev->devid, btrfs_dev_name(dev),
+                               swarn.physical);
+
                btrfs_release_path(path);
        } else {
                struct btrfs_backref_walk_ctx ctx = { 0 };

fs/btrfs/scrub.c +0 -1

        }
-
 out:
        btrfs_free_path(path);
 }

fs/btrfs/scrub.c +0 -1

                if (test_bit(sector_nr, &stripe->io_error_bitmap))
                        scrub_print_common_warning("i/o error", dev,
                                                     logical, physical,
--

2.44.0

Quoted 43 lines · Qu Wenruo

[BUG]
Scrub is not reporting the correct logical/physical address, it can be verified by the following script:

  # mkfs.btrfs -f $dev1
  # mount $dev1 $mnt
  # xfs_io -f -c "pwrite -S 0xaa 0 128k" $mnt/file1
  # umount $mnt
  # xfs_io -f -c "pwrite -S 0xff 13647872 4k" $dev1
  # mount $dev1 $mnt
  # btrfs scrub start -fB $mnt
  # umount $mnt

Note above 13647872 is the physical address for logical 13631488 + 4K.

Scrub would report the following error:

  BTRFS error (device dm-2): unable to fixup (regular) error at logical 13631488 on dev /dev/mapper/test-scratch1 physical 13631488
  BTRFS warning (device dm-2): checksum error at logical 13631488 on dev /dev/mapper/test-scratch1, physical 13631488, root 5, inode 257, offset 0, length 4096, links 1 (path: file1)

On the other hand, "btrfs check --check-data-csum" is reporting the correct logical/physical address:

  Checking filesystem on /dev/test/scratch1
  UUID: db2eb621-b09d-4f24-8199-da17dc7b3201
  [5/7] checking csums against data
  mirror 1 bytenr 13647872 csum 0x13fec125 expected csum 0x656bd64e
  ERROR: errors found in csum tree

[CAUSE]
In the function scrub_stripe_report_errors(), we always use the stripe->logical and its physical address to print the error message, not taking the sector number into consideration at all.

[FIX]
Fix the error reporting function by calculating logical/physical with the sector number.

Now the scrub report is correct:

  BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872 on dev /dev/mapper/test-scratch1 physical 13647872
  BTRFS warning (device dm-2): checksum error at logical 13647872 on dev /dev/mapper/test-scratch1, physical 13647872, root 5, inode 257, offset 16384, length 4096, links 1 (path: file1)

Quoted 2 lines

Fixes 0096580713ff ("btrfs: scrub: introduce error reporting functionality for scrub_stripe")

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

To help accurate debug on stable kernel, we could also add
CC: [email protected] #6.4+

Not too particular though.

Reviewed-by Anand Jain <[email protected]>

Thanks.

Quoted 83 lines

---
  fs/btrfs/scrub.c | 22 +++++++++++++---------

  1 file changed, 13 insertions(+), 9 deletions(-)

fs/btrfs/scrub.c +1 -1

index fa25004ab04e..119e98797b21 100644
@@ -870,7 +870,7 @@ static void scrub_stripe_report_errors(struct 
 scrub_ctx *sctx,
                         DEFAULT_RATELIMIT_BURST);
       struct btrfs_fs_info *fs_info = sctx->fs_info;
       struct btrfs_device *dev = NULL;
-    u64 physical = 0;
+    u64 stripe_physical = stripe->physical;
       int nr_data_sectors = 0;
       int nr_meta_sectors = 0;

      int nr_nodatacsum_sectors = 0;

fs/btrfs/scrub.c +1 -1

@@ -903,13 +903,17 @@ static void scrub_stripe_report_errors(struct 
 scrub_ctx *sctx,
            */
           if (ret < 0)
               goto skip;
-        physical = bioc->stripes[stripe_index].physical;
+        stripe_physical = bioc->stripes[stripe_index].physical;
           dev = bioc->stripes[stripe_index].dev;
           btrfs_put_bioc(bioc);
       }

  skip:
      for_each_set_bit(sector_nr, &stripe->extent_sector_bitmap, stripe->nr_sectors) { +        u64 logical = stripe->logical +
+                  (sector_nr << fs_info->sectorsize_bits);
+        u64 physical = stripe_physical +
+                  (sector_nr << fs_info->sectorsize_bits);
          bool repaired = false;
          if (stripe->sectors[sector_nr].is_metadata) {

fs/btrfs/scrub.c +2 -2

@@ -938,12 +942,12 @@ static void scrub_stripe_report_errors(struct 
 scrub_ctx *sctx,
               if (dev) {
                   btrfs_err_rl_in_rcu(fs_info,
               "fixed up error at logical %llu on dev %s physical %llu",
-                        stripe->logical, btrfs_dev_name(dev),
+                        logical, btrfs_dev_name(dev),
                           physical);
               } else {
                   btrfs_err_rl_in_rcu(fs_info,
               "fixed up error at logical %llu on mirror %u",
-                        stripe->logical, stripe->mirror_num);
+                        logical, stripe->mirror_num);
               }
               continue;

          }

fs/btrfs/scrub.c +5 -5

@@ -952,26 +956,26 @@ static void scrub_stripe_report_errors(struct 
 scrub_ctx *sctx,
           if (dev) {
               btrfs_err_rl_in_rcu(fs_info,
       "unable to fixup (regular) error at logical %llu on dev %s physical %llu",
-                        stripe->logical, btrfs_dev_name(dev),
+                        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",
-                        stripe->logical, stripe->mirror_num);
+                        logical, stripe->mirror_num);
           }
           if (test_bit(sector_nr, &stripe->io_error_bitmap))
               if (__ratelimit(&rs) && dev)
                   scrub_print_common_warning("i/o error", dev, false,
-                             stripe->logical, physical);
+                             logical, physical);
           if (test_bit(sector_nr, &stripe->csum_error_bitmap))
               if (__ratelimit(&rs) && dev)
                   scrub_print_common_warning("checksum error", dev, false,
-                             stripe->logical, physical);
+                             logical, physical);
           if (test_bit(sector_nr, &stripe->meta_error_bitmap))
               if (__ratelimit(&rs) && dev)
                   scrub_print_common_warning("header error", dev, false,
-                             stripe->logical, physical);
+                             logical, physical);
       }
       spin_lock(&sctx->stat_lock);

Quoted 25 lines · Qu Wenruo

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

I would argue this behavior is not ideal:

- It would flood the dmesg and bury real important messages One common scenario is scrub.
If scrub hit some errors, it would cause both scrub and btrfs_dev_stat_inc_and_print() to print error messages.

And in that case, btrfs_dev_stat_inc_and_print() is completely useless.

- The results of btrfs_dev_stat_inc_and_print() is mostly for history monitoring, doesn't has enough details

If we trigger the errors during regular read, such messages from btrfs_dev_stat_inc_and_print() won't help us to locate the cause either.

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.

Not sure if this is the right thing to do.

In the scrub context it can be annoying for sure.
Other cases I'm not so sure about, because having error messages in dmesg/syslog may help notice issues more quickly.

Quoted 25 lines

CC [email protected]

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

---
  fs/btrfs/volumes.c | 2 +-
  1 file changed, 1 insertion(+), 1 deletion(-)

fs/btrfs/volumes.c +1 -2

index e49935a54da0..126145950ed3 100644
@@ -7828,7 +7828,7 @@ void btrfs_dev_stat_inc_and_print(struct btrfs_device *dev, int index)
 
         if (!dev->dev_stats_valid)
                 return;
-       btrfs_err_rl_in_rcu(dev->fs_info,
+       btrfs_debug_rl_in_rcu(dev->fs_info,
                 "bdev %s errs: wr %u, rd %u, flush %u, corrupt %u, gen %u",
                            btrfs_dev_name(dev),
                            btrfs_dev_stat_read(dev, BTRFS_DEV_STAT_WRITE_ERRS),
--

2.44.0

Quoted 110 lines · Qu Wenruo

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 | 59 ++++++------------------------------------------
  1 file changed, 7 insertions(+), 52 deletions(-)

fs/btrfs/scrub.c +6 -50

index 5e371ffdb37b..277583464371 100644
@@ -860,10 +860,8 @@ 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 = NULL;
+       struct btrfs_device *dev = stripe->dev;
         u64 stripe_physical = stripe->physical;
         int nr_data_sectors = 0;
         int nr_meta_sectors = 0;

@@ -874,35 +872,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) {
                 u64 logical = stripe->logical +
                               (sector_nr << fs_info->sectorsize_bits);

@@ -933,42 +903,27 @@ 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)
-                               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) && dev)
-                               scrub_print_common_warning("checksum error", dev,
+                       scrub_print_common_warning("checksum error", dev,

fs/btrfs/scrub.c static void scrub_stripe_report_errors(struct scrub_ctx *sctx, · line 926

Quoted 5 lines

fs/btrfs/scrub.c +1 -2

                                                      logical, physical);
                 if (test_bit(sector_nr, &stripe->meta_error_bitmap))
-                       if (__ratelimit(&rs) && dev)
-                               scrub_print_common_warning("header error", dev,
+                       scrub_print_common_warning("header error", dev,

Why are we removing the rate limiting?
This seems like an unrelated change.

Everything else looks ok.

Thanks.

Quoted 7 lines

fs/btrfs/scrub.c +0 -1

                                                      logical, physical);
         }
 
--

2.44.0

Quoted 25 lines · Qu Wenruo

During some support sessions, I found older kernels are always report very unuseful scrub 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

There are two problems:
- No proper details about the corruption
No metadata or data indication, nor the filename or the tree id. Even the involved kernel (and newer kernels after the scrub rework) has the ability to do backref walk and find out the file path or the tree backref.

My guess is, for data sometimes the corrupted sector is no longer referred by any data extent.

- Too noisy and useless error message from btrfs_dev_stat_inc_and_print()
I'd argue we should not output any error message just for btrfs_dev_stat_inc_and_print().

After the series, the error message would look like this:

Quoted 1 line

BTRFS warning (device dm-2): checksum error at inode 5/257(file1) fileoff 16384, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872

Stoked on this series, thanks for doing it!

qq: would it be helpful to also include the actual/expected csum? I think it's particularly helpful when one or the other is either zeros or the checksum of the zero block.

Quoted 61 lines

This involves the following enhancement:

- Single line
And we ensure we output at least one line for the error we hit. No more unrelated btrfs_dev_stat_inc_and_print() output.

- Proper fall backs
We have the following different fall back options
* Repaired
Just a line of something repaired for logical/physical address.

* Detailed data info
Including the following elements (if possible), and if higher priority ones can not be fetched, it would be skipped and try lower priority items:
+ file path (can have multiple ones)
+ root/inode number and offset
+ logical/physical address (always output)

* Detaile metadata info
The priority list is:
+ root ref/level
+ logical/physical address (always output)

For the worst case of data corruption, we would still have some like:

    BTRFS warning (device dm-2): checksum error at data, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872

And similar ones for metadata:

    BTRFS warning (device dm-2): checksum error at meta, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872

The first patch is fixing a regression in the error message, which leads to bad logical/physical bytenr.
The second one would reduce the log level for btrfs_dev_stat_inc_and_print().

Path 3~4 are cleanups to remove unnecessary parameters.

The remaining reworks the format and refine the error message frequency.

Qu Wenruo (7):
btrfs: scrub: fix incorrectly reported logical/physical address
btrfs: reduce the log level for btrfs_dev_stat_inc_and_print()
btrfs: scrub: remove unused is_super parameter from
scrub_print_common_warning()
btrfs: scrub: remove unnecessary dev/physical lookup for
scrub_stripe_report_errors()
btrfs: scrub: simplify the inode iteration output
btrfs: scrub: unify and shorten the error message
btrfs: scrub: fix the frequency of error messages

  fs/btrfs/scrub.c   | 185 ++++++++++++++++-----------------------------
  fs/btrfs/volumes.c |   2 +-
  2 files changed, 66 insertions(+), 121 deletions(-)

--
2.44.0

Quoted 1 line

+ }

No need for the curly braces here, it's a single statement, so we follow the style of dropping them.

Quoted 8 lines

         }

fs/btrfs/scrub.c +0 -1

-
  out:
         btrfs_free_path(path);
  }

@@ -889,12 +905,6 @@ static void scrub_stripe_report_errors(struct scrub_ctx *sctx,
                 }
 

fs/btrfs/scrub.c static void scrub_stripe_report_errors(struct scrub_ctx *sctx, · line 897

Quoted 7 lines

fs/btrfs/scrub.c +0 -6

                 /* The remaining are all for unrepaired. */
-               btrfs_err_rl_in_rcu(fs_info,
-       "unable to fixup (regular) error at logical %llu(%u) physical %llu(%s)%llu",
-                                           logical, stripe->mirror_num,
-                                           dev->devid, btrfs_dev_name(dev),
-                                           physical);
-

This hunk seems unintentional?

Thanks.

Quoted 7 lines

fs/btrfs/scrub.c +0 -1

                 if (test_bit(sector_nr, &stripe->io_error_bitmap))
                         scrub_print_common_warning("i/o error", dev,
                                                      logical, physical,
--

2.44.0

Quoted 6 lines · Qu Wenruo

Currently the scrub error report is pretty long:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872 on dev /dev/mapper/test-scratch1 physical 13647872
BTRFS warning (device dm-2): checksum error at logical 13647872 on dev /dev/mapper/test-scratch1, physical 13647872, root 5, inode 257, offset 16384, length 4096, links 1 (path: file1)

Quoted 8 lines

Since we have so many things to output, it's not a surprise we got long error lines.

To make the lines a little shorter, and make important info more obvious, change the unify output to something like this:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872 BTRFS warning (device dm-2): checksum error at inode 5/257(file1) fileoff 16384, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872

I find that hard to read because:

1) Please leave spaces before opening parenthesis.
That makes things less cluttered and easier to the eyes, more
consistent with what we generally do and it's the formal way to do things in English (see
https://www.scribens.com/grammar-rules/typography/spacing.html);

2) Instead of "inode 5/257(file1)", something a lot easier to understand like "inode 5 root 257 path \"file1\"", which leaves no margin for doubt about what each number is;

3) Same with "logical 13647872(1)" - what is the 1? That will be the question anyone reading such a log message will likely have.

     Something like "logical 13647872 mirror 1" makes it clear;

4) Same with "physical 1(/dev/mapper/test-scratch1)13647872". Something like "physical 13647872 device ID 1 device path
\"/dev/mapper/test-scratch1\"", makes it clear what each number is and easier to read.

Thanks.

Quoted 111 lines · Filipe Manana

Quoted 110 lines · Qu Wenruo

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 | 59 ++++++------------------------------------------
  1 file changed, 7 insertions(+), 52 deletions(-)

fs/btrfs/scrub.c +6 -50

index 5e371ffdb37b..277583464371 100644
@@ -860,10 +860,8 @@ 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 = NULL;
+       struct btrfs_device *dev = stripe->dev;
         u64 stripe_physical = stripe->physical;
         int nr_data_sectors = 0;
         int nr_meta_sectors = 0;

@@ -874,35 +872,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) {
                 u64 logical = stripe->logical +
                               (sector_nr << fs_info->sectorsize_bits);

@@ -933,42 +903,27 @@ 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)
-                               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) && dev)
-                               scrub_print_common_warning("checksum error", dev,
+                       scrub_print_common_warning("checksum error", dev,

Quoted 8 lines

fs/btrfs/scrub.c static void scrub_stripe_report_errors(struct scrub_ctx *sctx, · line 926

Quoted 5 lines

fs/btrfs/scrub.c +1 -2

                                                      logical, physical);
                 if (test_bit(sector_nr, &stripe->meta_error_bitmap))
-                       if (__ratelimit(&rs) && dev)
-                               scrub_print_common_warning("header error", dev,
+                       scrub_print_common_warning("header error", dev,

Why are we removing the rate limiting?
This seems like an unrelated change.

Because the ratelimit is not consistent.

E.g. the "fixed up error" line is not rated limited by @rs, but by btrfs_err_rl_in_rcu().

And we would have scrub_print_common_warning() to go btrfs_*_rl() helper in the coming patches.

Thanks,
Qu

Quoted 13 lines

Everything else looks ok.

Thanks.

Quoted 7 lines

fs/btrfs/scrub.c +0 -1

                                                      logical, physical);
         }
 
--

2.44.0

Quoted 16 lines · Filipe Manana

Quoted 6 lines · Qu Wenruo

Currently the scrub error report is pretty long:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872 on dev /dev/mapper/test-scratch1 physical 13647872
BTRFS warning (device dm-2): checksum error at logical 13647872 on dev /dev/mapper/test-scratch1, physical 13647872, root 5, inode 257, offset 16384, length 4096, links 1 (path: file1)

Quoted 8 lines

Since we have so many things to output, it's not a surprise we got long error lines.

To make the lines a little shorter, and make important info more obvious, change the unify output to something like this:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872 BTRFS warning (device dm-2): checksum error at inode 5/257(file1) fileoff 16384, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872

Quoted 7 lines

I find that hard to read because:

1) Please leave spaces before opening parenthesis.
That makes things less cluttered and easier to the eyes, more
consistent with what we generally do and it's the formal way to do things in English (see
https://www.scribens.com/grammar-rules/typography/spacing.html);

Yep, I can do that, but I also want to keep the involved members together thus closer.

Not sure if adding spaces would still keep the close relationships between the values.

E.g: inode 5/256 (file1) fileoff 16384, logical 123456 (1) physical 1 (scratch1) 123456

It makes it a little harder to indicate that "(1)" is related to logical address (thus mirror number).

Quoted 5 lines

2) Instead of "inode 5/257(file1)", something a lot easier to understand like "inode 5 root 257 path \"file1\"", which leaves no margin for doubt about what each number is;

Quoted 8 lines

3) Same with "logical 13647872(1)" - what is the 1? That will be the question anyone reading such a log message will likely have.

     Something like "logical 13647872 mirror 1" makes it clear;

4) Same with "physical 1(/dev/mapper/test-scratch1)13647872". Something like "physical 13647872 device ID 1 device path
\"/dev/mapper/test-scratch1\"", makes it clear what each number is and easier to read.

I totally understand the original output format is much easier to read on its own.

However if we have hundreds lines of similar output, it's a different story, a small change in any of the value is much harder to catch, and the extra helpful prompt is in fact a burden other than a bless.

(That's why things like spreadsheet is much easier to reader for multiple similarly structured data, and in that case it's much better to craft a script to convert the lines into a csv)

Unfortunately we don't have the benefit (at least yet) to structure all these info into a structured output.

But what I'm doing here is to reduce the prompts to minimal (at most 4 prompts, "inode", "fileoff", "logical", "physical"), so less duplicated strings for multiple lines of similar error messages.

The patchset is in the middle ground between fully detailed output (the old one, focusing on single line) and the fully script orient output (no prompt at all, just all numbers/strings, focusing on CSV like output).

Furthermore, I would also argue that, for entry level end users, they can still catch the critical info (like file path and device path) without much difficult, and those info is enough for them to take action. (E.g. deleting the file, or replace the disk)

Yes, they would get confused on the devid or rootid, but that's fine and everyone can learn something new.

For experienced users who understand basics of btrfs, or us developers, the split in values are already arranged in a way similar sized values are never close together (aka, string/large/small value split).

Thanks,
Qu

Quoted 3 lines

Thanks.

Quoted 124 lines · Qu Wenruo

Quoted 111 lines · Filipe Manana

Quoted 110 lines · Qu Wenruo

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 | 59 ++++++------------------------------------------
   1 file changed, 7 insertions(+), 52 deletions(-)

fs/btrfs/scrub.c +6 -50

index 5e371ffdb37b..277583464371 100644
@@ -860,10 +860,8 @@ 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 = NULL;
+       struct btrfs_device *dev = stripe->dev;
          u64 stripe_physical = stripe->physical;
          int nr_data_sectors = 0;
          int nr_meta_sectors = 0;

@@ -874,35 +872,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) {
                  u64 logical = stripe->logical +
                                (sector_nr << fs_info->sectorsize_bits);

@@ -933,42 +903,27 @@ 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)
-                               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) && dev)
-                               scrub_print_common_warning("checksum error", dev,
+                       scrub_print_common_warning("checksum error", dev,

Quoted 8 lines

fs/btrfs/scrub.c static void scrub_stripe_report_errors(struct scrub_ctx *sctx, · line 926

Quoted 5 lines

fs/btrfs/scrub.c +1 -2

                                                       logical, physical);
                  if (test_bit(sector_nr, &stripe->meta_error_bitmap))
-                       if (__ratelimit(&rs) && dev)
-                               scrub_print_common_warning("header error", dev,
+                       scrub_print_common_warning("header error", dev,

Why are we removing the rate limiting?
This seems like an unrelated change.

Quoted 4 lines

Because the ratelimit is not consistent.

E.g. the "fixed up error" line is not rated limited by @rs, but by btrfs_err_rl_in_rcu().

That I don't understand.

What I see is that scrub_print_common_warning() calls btrfs_warn_in_rcu() or btrfs_warn() or scrub_print_warning_inode() (which calls btrfs_warn_in_rcu()).
I don't see where btrfs_err_rl_in_rcu() is called. So to me it seems @rs is doing the rate limiting.

Quoted 1 line

Quoted 2 lines

And we would have scrub_print_common_warning() to go btrfs_*_rl() helper in the coming patches.

Ok, but if @rs is indeed doing the rate limiting here, then from an organization point of view, it should be removed in the later patch that makes scrub_print_common_warning() use the btrfs_*_rl() helpers.

Thanks.

Quoted 16 lines

Thanks,
Qu

Quoted 13 lines

Everything else looks ok.

Thanks.

Quoted 7 lines

fs/btrfs/scrub.c +0 -1

                                                       logical, physical);
          }
 
--

2.44.0

Quoted 32 lines · Filipe Manana

Quoted 25 lines · Qu Wenruo

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

I would argue this behavior is not ideal:

- It would flood the dmesg and bury real important messages One common scenario is scrub.
If scrub hit some errors, it would cause both scrub and btrfs_dev_stat_inc_and_print() to print error messages.

And in that case, btrfs_dev_stat_inc_and_print() is completely useless.

- The results of btrfs_dev_stat_inc_and_print() is mostly for history monitoring, doesn't has enough details

If we trigger the errors during regular read, such messages from btrfs_dev_stat_inc_and_print() won't help us to locate the cause either.

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.

Quoted 5 lines

Not sure if this is the right thing to do.

In the scrub context it can be annoying for sure.
Other cases I'm not so sure about, because having error messages in dmesg/syslog may help notice issues more quickly.

For non-scrub cases, I'd argue we already have enough output:

No matter if the error is fixed or not, every time a mirror got csum mismatch or other errors, we already have error message output:

Data: btrfs_print_data_csum_error()
Meta: btrfs_validate_extent_buffer()

For repaired ones, we have extra output from bio layer for both metadata and data:
btrfs_repair_io_failure()

So I'd say the dev_stat ones are already duplicated.

Thanks,
Qu

Quoted 26 lines

Quoted 25 lines

CC [email protected]

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

---
  fs/btrfs/volumes.c | 2 +-
  1 file changed, 1 insertion(+), 1 deletion(-)

fs/btrfs/volumes.c +1 -2

index e49935a54da0..126145950ed3 100644
@@ -7828,7 +7828,7 @@ void btrfs_dev_stat_inc_and_print(struct btrfs_device *dev, int index)
 
         if (!dev->dev_stats_valid)
                 return;
-       btrfs_err_rl_in_rcu(dev->fs_info,
+       btrfs_debug_rl_in_rcu(dev->fs_info,
                 "bdev %s errs: wr %u, rd %u, flush %u, corrupt %u, gen %u",
                            btrfs_dev_name(dev),
                            btrfs_dev_stat_read(dev, BTRFS_DEV_STAT_WRITE_ERRS),
--

2.44.0

Quoted 83 lines · Qu Wenruo

Quoted 16 lines · Filipe Manana

Quoted 6 lines · Qu Wenruo

Currently the scrub error report is pretty long:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872 on dev /dev/mapper/test-scratch1 physical 13647872
BTRFS warning (device dm-2): checksum error at logical 13647872 on dev /dev/mapper/test-scratch1, physical 13647872, root 5, inode 257, offset 16384, length 4096, links 1 (path: file1)

Quoted 8 lines

Since we have so many things to output, it's not a surprise we got long error lines.

To make the lines a little shorter, and make important info more obvious, change the unify output to something like this:

BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872 BTRFS warning (device dm-2): checksum error at inode 5/257(file1) fileoff 16384, logical 13647872(1) physical 1(/dev/mapper/test-scratch1)13647872

Quoted 7 lines

I find that hard to read because:

1) Please leave spaces before opening parenthesis.
That makes things less cluttered and easier to the eyes, more
consistent with what we generally do and it's the formal way to do things in English (see
https://www.scribens.com/grammar-rules/typography/spacing.html);

Yep, I can do that, but I also want to keep the involved members together thus closer.

Not sure if adding spaces would still keep the close relationships between the values.

E.g: inode 5/256 (file1) fileoff 16384, logical 123456 (1) physical 1 (scratch1) 123456

It makes it a little harder to indicate that "(1)" is related to logical address (thus mirror number).

Quoted 5 lines

2) Instead of "inode 5/257(file1)", something a lot easier to understand like "inode 5 root 257 path \"file1\"", which leaves no margin for doubt about what each number is;

Quoted 8 lines

3) Same with "logical 13647872(1)" - what is the 1? That will be the question anyone reading such a log message will likely have.

      Something like "logical 13647872 mirror 1" makes it clear;

4) Same with "physical 1(/dev/mapper/test-scratch1)13647872". Something like "physical 13647872 device ID 1 device path
\"/dev/mapper/test-scratch1\"", makes it clear what each number is and easier to read.

I totally understand the original output format is much easier to read on its own.

However if we have hundreds lines of similar output, it's a different story, a small change in any of the value is much harder to catch, and the extra helpful prompt is in fact a burden other than a bless.

(That's why things like spreadsheet is much easier to reader for multiple similarly structured data, and in that case it's much better to craft a script to convert the lines into a csv)

Unfortunately we don't have the benefit (at least yet) to structure all these info into a structured output.

But what I'm doing here is to reduce the prompts to minimal (at most 4 prompts, "inode", "fileoff", "logical", "physical"), so less duplicated strings for multiple lines of similar error messages.

The patchset is in the middle ground between fully detailed output (the old one, focusing on single line) and the fully script orient output (no prompt at all, just all numbers/strings, focusing on CSV like output).

Furthermore, I would also argue that, for entry level end users, they can still catch the critical info (like file path and device path) without much difficult, and those info is enough for them to take action. (E.g. deleting the file, or replace the disk)

Quoted 6 lines

Yes, they would get confused on the devid or rootid, but that's fine and everyone can learn something new.

For experienced users who understand basics of btrfs, or us developers, the split in values are already arranged in a way similar sized values are never close together (aka, string/large/small value split).

Well, I'm a developer and I can tell you if I ever see such log messages, I'll have to go to the source code to figure out what each value is supposed to be.
I'll be able to memorize for some hours or even a few days, but after that I'll forget again and have to look at the source code again.

Quoted 9 lines

Thanks,
Qu

Quoted 3 lines

Thanks.

Quoted 55 lines · Anand Jain

Quoted 52 lines · Qu Wenruo

[BUG]
Scrub is not reporting the correct logical/physical address, it can be verified by the following script:

  # mkfs.btrfs -f $dev1
  # mount $dev1 $mnt
  # xfs_io -f -c "pwrite -S 0xaa 0 128k" $mnt/file1
  # umount $mnt
  # xfs_io -f -c "pwrite -S 0xff 13647872 4k" $dev1
  # mount $dev1 $mnt
  # btrfs scrub start -fB $mnt
  # umount $mnt

Note above 13647872 is the physical address for logical 13631488 + 4K.

Scrub would report the following error:

  BTRFS error (device dm-2): unable to fixup (regular) error at logical 13631488 on dev /dev/mapper/test-scratch1 physical 13631488 BTRFS warning (device dm-2): checksum error at logical 13631488 on dev /dev/mapper/test-scratch1, physical 13631488, root 5, inode 257, offset 0, length 4096, links 1 (path: file1)

On the other hand, "btrfs check --check-data-csum" is reporting the correct logical/physical address:

  Checking filesystem on /dev/test/scratch1
  UUID: db2eb621-b09d-4f24-8199-da17dc7b3201
  [5/7] checking csums against data
  mirror 1 bytenr 13647872 csum 0x13fec125 expected csum 0x656bd64e
  ERROR: errors found in csum tree

[CAUSE]
In the function scrub_stripe_report_errors(), we always use the stripe->logical and its physical address to print the error message, not taking the sector number into consideration at all.

[FIX]
Fix the error reporting function by calculating logical/physical with the sector number.

Now the scrub report is correct:

  BTRFS error (device dm-2): unable to fixup (regular) error at logical 13647872 on dev /dev/mapper/test-scratch1 physical 13647872 BTRFS warning (device dm-2): checksum error at logical 13647872 on dev /dev/mapper/test-scratch1, physical 13647872, root 5, inode 257, offset 16384, length 4096, links 1 (path: file1)

Fixes 0096580713ff ("btrfs: scrub: introduce error reporting

functionality for scrub_stripe")

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

Quoted 2 lines

To help accurate debug on stable kernel, we could also add
CC: [email protected] #6.4+

IIRC Fixes: tag is more accurate than just CC stable, as stable has the correct bots catching the fixes line.