nilfs2: rework error message subsystem
Subsystems (2)
Vyacheslav Dubeyko
maintainerPATCH 1/1 nilfs2: rework error message subsystem
From: Vyacheslav Dubeyko <[email protected]>
Subject: [PATCH] nilfs2: rework error message subsystem
There are situations when real error can emit huge amount of messages. As a result, system log contains many identical error messages. This patch changes printk on pr_[err|warn]_ratelimited version in proper places. Also printk was changed on pr_[err|warning|info] version in other places.
--- fs/nilfs2/alloc.c | 26 ++++++++------- fs/nilfs2/btree.c | 27 ++++++++-------- fs/nilfs2/cpfile.c | 13 ++++---- fs/nilfs2/dat.c | 8 ++--- fs/nilfs2/direct.c | 8 ++--- fs/nilfs2/inode.c | 10 ++---- fs/nilfs2/ioctl.c | 30 ++++++++--------- fs/nilfs2/page.c | 18 +++++------ fs/nilfs2/recovery.c | 49 ++++++++++------------------ fs/nilfs2/segbuf.c | 3 +- fs/nilfs2/segment.c | 18 ++++------- fs/nilfs2/sufile.c | 19 +++++------ fs/nilfs2/super.c | 85 ++++++++++++++++++++----------------------------- fs/nilfs2/the_nilfs.c | 80 +++++++++++++++++++--------------------------- 14 files changed, 170 insertions(+), 224 deletions(-)
fs/nilfs2/alloc.c +14 -12
@@ -581,10 +581,11 @@ void nilfs_palloc_commit_free_entry(struct inode *inode, bitmap = bitmap_kaddr +bh_offset (req->pr_bitmap_bh);if (!nilfs_clear_bit_atomic (nilfs_mdt_bgl_lock (inode, group), - group_offset, bitmap)) -printk (KERN_WARNING "%s: entry number %llu already freed\n" , - __func__, (unsigned long long )req->pr_entry_nr); -else + group_offset, bitmap)) { +pr_warn_ratelimited ("%s: entry number %llu already freed\n" , + __func__, + (unsigned long long )req->pr_entry_nr); + }else nilfs_palloc_group_desc_add_entries (inode, group, desc,1 );kunmap (req->pr_bitmap_bh->b_page);
@@ -618,10 +619,11 @@ void nilfs_palloc_abort_alloc_entry(struct inode *inode, bitmap_kaddr =kmap (req->pr_bitmap_bh->b_page); bitmap = bitmap_kaddr +bh_offset (req->pr_bitmap_bh);if (!nilfs_clear_bit_atomic (nilfs_mdt_bgl_lock (inode, group), - group_offset, bitmap)) -printk (KERN_WARNING "%s: entry number %llu already freed\n" , - __func__, (unsigned long long )req->pr_entry_nr); -else + group_offset, bitmap)) { +pr_warn_ratelimited ("%s: entry number %llu already freed\n" , + __func__, + (unsigned long long )req->pr_entry_nr); + }else nilfs_palloc_group_desc_add_entries (inode, group, desc,1 );kunmap (req->pr_bitmap_bh->b_page);
@@ -733,10 +735,10 @@ int nilfs_palloc_freev(struct inode *inode, __u64 *entry_nrs, size_t nitems)if (!nilfs_clear_bit_atomic (nilfs_mdt_bgl_lock (inode, group), group_offset, bitmap)) { -printk (KERN_WARNING -"%s: entry number %llu already freed\n" , - __func__, - (unsigned long long )entry_nrs[j]); +pr_warn_ratelimited ( +"%s: entry number %llu already freed\n" , + __func__, + (unsigned long long )entry_nrs[j]); }else { n++; }
fs/nilfs2/btree.c +13 -14
@@ -356,13 +356,13 @@ static int nilfs_btree_node_broken(const struct nilfs_btree_node *node, nchildren =nilfs_btree_node_get_nchildren (node);if (unlikely (level <NILFS_BTREE_LEVEL_NODE_MIN || - level >=NILFS_BTREE_LEVEL_MAX || - (flags &NILFS_BTREE_NODE_ROOT ) || - nchildren <0 || - nchildren >NILFS_BTREE_NODE_NCHILDREN_MAX (size))) { -printk (KERN_CRIT "NILFS: bad btree node (blocknr=%llu): " -"level = %d, flags = 0x%x, nchildren = %d\n" , - (unsigned long long )blocknr, level, flags, nchildren); + level >=NILFS_BTREE_LEVEL_MAX || + (flags &NILFS_BTREE_NODE_ROOT ) || + nchildren <0 || + nchildren >NILFS_BTREE_NODE_NCHILDREN_MAX (size))) { +pr_crit_ratelimited ("NILFS: bad btree node (blocknr=%llu): level = %d, flags = 0x%x, nchildren = %d\n" , + (unsigned long long )blocknr, level, + flags, nchildren); ret =1 ; }return ret;
@@ -427,8 +427,8 @@ nilfs_btree_bad_node(struct nilfs_btree_node *node, int level) {if (unlikely (nilfs_btree_node_get_level (node) != level)) {dump_stack (); -printk (KERN_CRIT "NILFS: btree level mismatch: %d != %d\n" , -nilfs_btree_node_get_level (node), level); +pr_crit_ratelimited ("NILFS: btree level mismatch: %d != %d\n" , +nilfs_btree_node_get_level (node), level);return 1 ; }return 0 ;
@@ -1989,8 +1989,9 @@ static int nilfs_btree_propagate(struct nilfs_bmap *btree, ret =nilfs_btree_do_lookup (btree, path, key,NULL , level +1 ,0 );if (ret <0 ) {if (unlikely (ret == -ENOENT )) -printk (KERN_CRIT "%s: key = %llu, level == %d\n" , - __func__, (unsigned long long )key, level); +pr_crit_ratelimited ("%s: key = %llu, level == %d\n" , + __func__, + (unsigned long long )key, level); goto out; }
@@ -2027,9 +2028,7 @@ static void nilfs_btree_add_dirty_buffer(struct nilfs_bmap *btree,if (level <NILFS_BTREE_LEVEL_NODE_MIN || level >=NILFS_BTREE_LEVEL_MAX ) {dump_stack (); -printk (KERN_WARNING -"%s: invalid btree level: %d (key=%llu, ino=%lu, " -"blocknr=%llu)\n" , +pr_warn_ratelimited ("%s: invalid btree level: %d (key=%llu, ino=%lu, blocknr=%llu)\n" , __func__, level, (unsigned long long )key,NILFS_BMAP_I (btree)->vfs_inode.i_ino, (unsigned long long )bh->b_blocknr);
fs/nilfs2/cpfile.c +7 -6
@@ -289,9 +289,10 @@ int nilfs_cpfile_delete_checkpoints(struct inode *cpfile,int ret, ncps, nicps, nss, count, i;if (unlikely (start ==0 || start > end)) { -printk (KERN_ERR "%s: invalid range of checkpoint numbers: " -"[%llu, %llu)\n" , __func__, - (unsigned long long )start, (unsigned long long )end); +pr_err_ratelimited ("%s: invalid range of checkpoint numbers: [%llu, %llu)\n" , + __func__, + (unsigned long long )start, + (unsigned long long )end);return -EINVAL ; }
@@ -343,9 +344,9 @@ int nilfs_cpfile_delete_checkpoints(struct inode *cpfile, cpfile, cno);if (ret ==0 )continue ; -printk (KERN_ERR -"%s: cannot delete block\n" , - __func__); +pr_err_ratelimited ( +"%s: cannot delete block\n" , + __func__);break ; } }
fs/nilfs2/dat.c +4 -4
@@ -355,10 +355,10 @@ int nilfs_dat_move(struct inode *dat, __u64 vblocknr, sector_t blocknr) kaddr =kmap_atomic (entry_bh->b_page); entry =nilfs_palloc_block_get_entry (dat, vblocknr, entry_bh, kaddr);if (unlikely (entry->de_blocknr ==cpu_to_le64 (0 ))) { -printk (KERN_CRIT "%s: vbn = %llu, [%llu, %llu)\n" , __func__, - (unsigned long long )vblocknr, - (unsigned long long )le64_to_cpu (entry->de_start), - (unsigned long long )le64_to_cpu (entry->de_end)); +pr_crit_ratelimited ("%s: vbn = %llu, [%llu, %llu)\n" , __func__, + (unsigned long long )vblocknr, + (unsigned long long )le64_to_cpu (entry->de_start), + (unsigned long long )le64_to_cpu (entry->de_end));kunmap_atomic (kaddr);brelse (entry_bh);return -EINVAL ;
fs/nilfs2/direct.c +4 -4
@@ -325,14 +325,14 @@ static int nilfs_direct_assign(struct nilfs_bmap *bmap, key =nilfs_bmap_data_get_key (bmap, *bh);if (unlikely (key >NILFS_DIRECT_KEY_MAX )) { -printk (KERN_CRIT "%s: invalid key: %llu\n" , __func__, - (unsigned long long )key); +pr_crit_ratelimited ("%s: invalid key: %llu\n" , __func__, + (unsigned long long )key);return -EINVAL ; } ptr =nilfs_direct_get_ptr (bmap, key);if (unlikely (ptr ==NILFS_BMAP_INVALID_PTR )) { -printk (KERN_CRIT "%s: invalid pointer: %llu\n" , __func__, - (unsigned long long )ptr); +pr_crit_ratelimited ("%s: invalid pointer: %llu\n" , __func__, + (unsigned long long )ptr);return -EINVAL ; }
fs/nilfs2/inode.c +3 -7
@@ -113,13 +113,9 @@ int nilfs_get_block(struct inode *inode, sector_t blkoff,* However, the page having this block must * be locked in this case. */ -printk (KERN_WARNING -"nilfs_get_block: a race condition " -"while inserting a data block. " -"(inode number=%lu, file block " -"offset=%llu)\n" , - inode->i_ino, - (unsigned long long )blkoff); +pr_warn_ratelimited ("nilfs_get_block: a race condition while inserting a data block. (inode number=%lu, file block offset=%llu)\n" , + inode->i_ino, + (unsigned long long )blkoff); err =0 ; }nilfs_transaction_abort (inode->i_sb);
fs/nilfs2/ioctl.c +15 -15
@@ -369,20 +369,20 @@ static int nilfs_ioctl_move_inode_block(struct inode *inode,if (unlikely (ret <0 )) {if (ret == -ENOENT ) -printk (KERN_CRIT -"%s: invalid virtual block address (%s): " -"ino=%llu, cno=%llu, offset=%llu, " -"blocknr=%llu, vblocknr=%llu\n" , - __func__, vdesc->vd_flags ?"node" :"data" , - (unsigned long long )vdesc->vd_ino, - (unsigned long long )vdesc->vd_cno, - (unsigned long long )vdesc->vd_offset, - (unsigned long long )vdesc->vd_blocknr, - (unsigned long long )vdesc->vd_vblocknr); +pr_crit_ratelimited ( +"%s: invalid virtual block address (%s): " +"ino=%llu, cno=%llu, offset=%llu, " +"blocknr=%llu, vblocknr=%llu\n" , + __func__, vdesc->vd_flags ?"node" :"data" , + (unsigned long long )vdesc->vd_ino, + (unsigned long long )vdesc->vd_cno, + (unsigned long long )vdesc->vd_offset, + (unsigned long long )vdesc->vd_blocknr, + (unsigned long long )vdesc->vd_vblocknr);return ret; }if (unlikely (!list_empty (&bh->b_assoc_buffers))) { - printk(KERN_CRIT "%s: conflicting %s buffer: ino=%llu, " + pr_crit_ratelimited("%s: conflicting %s buffer: ino=%llu, " "cno=%llu, offset=%llu, blocknr=%llu, vblocknr=%llu\n", __func__, vdesc->vd_flags ? "node" : "data", (unsigned long long)vdesc->vd_ino,
@@ -566,8 +566,8 @@ int nilfs_ioctl_prepare_clean_segments(struct the_nilfs *nilfs,return 0 ; failed: -printk (KERN_ERR "NILFS: GC failed during preparation: %s: err=%d\n" , - msg, ret); +pr_err_ratelimited ("NILFS: GC failed during preparation: %s: err=%d\n" , + msg, ret);return ret; }
@@ -662,8 +662,8 @@ static int nilfs_ioctl_clean_segments(struct inode *inode, struct file *filp, ret =nilfs_ioctl_move_blocks (inode->i_sb, &argv[0 ], kbufs[0 ]);if (ret <0 ) -printk (KERN_ERR "NILFS: GC failed during preparation: " -"cannot read source blocks: err=%d\n" , ret); +pr_err_ratelimited ("NILFS: GC failed during preparation: cannot read source blocks: err=%d\n" , + ret);else {if (nilfs_sb_need_update (nilfs))set_nilfs_discontinued (nilfs);
fs/nilfs2/page.c +9 -9
@@ -173,17 +173,17 @@ void nilfs_page_bug(struct page *page)unsigned long ino;if (unlikely (!page)) { -printk (KERN_CRIT "NILFS_PAGE_BUG(NULL)\n" ); +pr_crit_ratelimited ("NILFS_PAGE_BUG(NULL)\n" );return ; } m = page->mapping; ino = m ? m->host->i_ino :0 ; -printk (KERN_CRIT "NILFS_PAGE_BUG(%p): cnt=%d index#=%llu flags=0x%lx " -"mapping=%p ino=%lu\n" , - page,atomic_read (&page->_count), - (unsigned long long )page->index, page->flags, m, ino); +pr_crit_ratelimited ("NILFS_PAGE_BUG(%p): cnt=%d index#=%llu flags=0x%lx mapping=%p ino=%lu\n" , + page,atomic_read (&page->_count), + (unsigned long long )page->index, + page->flags, m, ino);if (page_has_buffers (page)) {struct buffer_head *bh, *head;
@@ -191,10 +191,10 @@ void nilfs_page_bug(struct page *page) bh = head =page_buffers (page);do { -printk (KERN_CRIT -" BH[%d] %p: cnt=%d block#=%llu state=0x%lx\n" , - i++, bh,atomic_read (&bh->b_count), - (unsigned long long )bh->b_blocknr, bh->b_state); +pr_crit_ratelimited (" BH[%d] %p: cnt=%d block#=%llu state=0x%lx\n" , + i++, bh,atomic_read (&bh->b_count), + (unsigned long long )bh->b_blocknr, + bh->b_state); bh = bh->b_this_page; }while (bh != head); }
fs/nilfs2/recovery.c +17 -32
109 lines not on this page · raw message
fs/nilfs2/segbuf.c +2 -1
@@ -528,7 +528,8 @@ static int nilfs_segbuf_wait(struct nilfs_segment_buffer *segbuf) }while (--segbuf->sb_nbio >0 );if (unlikely (atomic_read (&segbuf->sb_err) >0 )) { -printk (KERN_ERR "NILFS: IO error writing segment\n" ); +pr_err_ratelimited ("NILFS: IO error writing segment %llu\n" , + segbuf->sb_segnum); err = -EIO ; }return err;
fs/nilfs2/segment.c +6 -12
@@ -129,9 +129,7 @@ static int nilfs_prepare_segment_lock(struct nilfs_transaction_info *ti)* it is saved and will be restored on * nilfs_transaction_commit(). */ -printk (KERN_WARNING -"NILFS warning: journal info from a different " -"FS\n" ); +pr_warn_ratelimited ("NILFS warning: journal info from a different FS\n" ); save = current->journal_info; } }
@@ -2368,9 +2366,8 @@ int nilfs_clean_segments(struct super_block *sb, struct nilfs_argv *argv,int ret =nilfs_discard_segments (nilfs, sci->sc_freesegs, sci->sc_nfreesegs);if (ret) { -printk (KERN_WARNING -"NILFS warning: error %d on discard request, " -"turning discards off for the device\n" , ret); +pr_warn_ratelimited ("NILFS warning: error %d on discard request, turning discards off for the device\n" , + ret);nilfs_clear_opt (nilfs,DISCARD ); } }
@@ -2453,10 +2450,8 @@ static int nilfs_segctor_thread(void *arg)/* start sync. */ sci->sc_task = current;wake_up (&sci->sc_wait_task);/* for nilfs_segctor_start_thread() */ -printk (KERN_INFO -"segctord starting. Construction interval = %lu seconds, " -"CP frequency < %lu seconds\n" , - sci->sc_interval /HZ , sci->sc_mjcp_freq /HZ ); +pr_info ("segctord starting. Construction interval = %lu seconds, CP frequency < %lu seconds\n" , + sci->sc_interval /HZ , sci->sc_mjcp_freq /HZ );spin_lock (&sci->sc_state_lock); loop:
@@ -2530,8 +2525,7 @@ static int nilfs_segctor_start_thread(struct nilfs_sc_info *sci)if (IS_ERR (t)) {int err =PTR_ERR (t); -printk (KERN_ERR "NILFS: error %d creating segctord thread\n" , - err); +pr_err ("NILFS: error %d creating segctord thread\n" , err);return err; }wait_event (sci->sc_wait_task, sci->sc_task !=NULL );
fs/nilfs2/sufile.c +10 -9
@@ -181,9 +181,10 @@ int nilfs_sufile_updatev(struct inode *sufile, __u64 *segnumv, size_t nsegs,down_write (&NILFS_MDT (sufile)->mi_sem);for (seg = segnumv; seg < segnumv + nsegs; seg++) {if (unlikely (*seg >=nilfs_sufile_get_nsegments (sufile))) { -printk (KERN_WARNING -"%s: invalid segment number: %llu\n" , __func__, - (unsigned long long )*seg); +pr_warn_ratelimited ( +"%s: invalid segment number: %llu\n" , + __func__, + (unsigned long long )*seg); nerr++; } }
@@ -240,8 +241,8 @@ int nilfs_sufile_update(struct inode *sufile, __u64 segnum, int create,int ret;if (unlikely (segnum >=nilfs_sufile_get_nsegments (sufile))) { -printk (KERN_WARNING "%s: invalid segment number: %llu\n" , - __func__, (unsigned long long )segnum); +pr_warn_ratelimited ("%s: invalid segment number: %llu\n" , + __func__, (unsigned long long )segnum);return -EINVAL ; }down_write (&NILFS_MDT (sufile)->mi_sem);
@@ -416,8 +417,8 @@ void nilfs_sufile_do_cancel_free(struct inode *sufile, __u64 segnum, kaddr =kmap_atomic (su_bh->b_page); su =nilfs_sufile_block_get_segment_usage (sufile, segnum, su_bh, kaddr);if (unlikely (!nilfs_segment_usage_clean (su))) { -printk (KERN_WARNING "%s: segment %llu must be clean\n" , - __func__, (unsigned long long )segnum); +pr_warn_ratelimited ("%s: segment %llu must be clean\n" , + __func__, (unsigned long long )segnum);kunmap_atomic (kaddr);return ; }
@@ -473,8 +474,8 @@ void nilfs_sufile_do_free(struct inode *sufile, __u64 segnum, kaddr =kmap_atomic (su_bh->b_page); su =nilfs_sufile_block_get_segment_usage (sufile, segnum, su_bh, kaddr);if (nilfs_segment_usage_clean (su)) { -printk (KERN_WARNING "%s: segment %llu is already clean\n" , - __func__, (unsigned long long )segnum); +pr_warn_ratelimited ("%s: segment %llu is already clean\n" , + __func__, (unsigned long long )segnum);kunmap_atomic (kaddr);return ; }
fs/nilfs2/super.c +34 -51
230 lines not on this page · raw message
fs/nilfs2/the_nilfs.c +32 -48
203 lines not on this page · raw message
Signature · 1 line
1.7.9.5
Quoted 6 lines · On Mon, 02 Dec 2013 18:08:53 +0400 Vyacheslav Dubeyko <[email protected]> wrote:
There are situations when real error can emit huge amount of messages. As a result, system log contains many identical error messages. This patch changes printk on pr_[err|warn]_ratelimited version in proper places. Also printk was changed on pr_[err|warning|info] version in other places.
It converts every printk in nilfs2 into pr_foo_ratelimited (and bloats nilfs2.ko by 5k in the process). Isn't this rather overkill?
A message that is not in the archive (sent off-list or not yet received): 20131203162944.8f9ef3a08a3292a1959dd025-de/[email protected]
On Tue, 2013-12-03 at 16:29 -0800, Andrew Morton wrote:
[snip]
Quoted 4 lines
It converts every printk in nilfs2 into
pr_foo_ratelimited(and bloats nilfs2.ko by 5k in the process). Isn't this rather overkill?
I have converted not every printk() in nilfs2 but I agree that printk() was changed in many places by ratelimited version. So, yes, it can be not very good idea. But such replacement was made for code that can emit really many count of practically identical error messages. And there are situation of sophisticated issues in nilfs2 when huge amount of error messages simply hide an important information about the issue. As a result, my goal was to reduce amount of repeatable error messages.
So, what could you recommend as possible and proper solution?
Moreover, I cleaned up error messages subsystem of nilfs2 by change of printk on pr_foo version and by joining error strings that it was split. I believe that it makes sense. Of course, it is possible to leave nilfs2 error subsystem untouched. But from my point of view, there is the issue of hiding important information about an issue's reason by huge amount of repeatable error messages.
Thanks,
Vyacheslav Dubeyko.
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html
Quoted 14 lines · Vyacheslav Dubeyko
On Tue, 2013-12-03 at 16:29 -0800, Andrew Morton wrote:
[snip]
Quoted 3 lines
It converts every printk in nilfs2 into
pr_foo_ratelimited(and bloats nilfs2.ko by 5k in the process). Isn't this rather overkill?I have converted not every
printk()in nilfs2 but I agree thatprintk()was changed in many places by ratelimited version. So, yes, it can be not very good idea. But such replacement was made for code that can emit really many count of practically identical error messages. And there are situation of sophisticated issues in nilfs2 when huge amount of error messages simply hide an important information about the issue. As a result, my goal was to reduce amount of repeatable error messages.
Quoted 1 line
So, what could you recommend as possible and proper solution?
I think this will help. However, the idea I had in mind originally was for nilfs to "give up" sooner.
I suspect that my nilfs partition became corrupt for hardware or hardware-driver reasons. So lets ignore that part for now.
With the data on the drive being corrupt, it appeared that nilfs encountered an invalid directory (possibly just a long string of NUL bytes?) and emitted more than a million errors about invalid structures, triggering the soft-lockup watchdog and rebooting the system. When I recompiled my kernel with soft-lockup set to 5 minutes, it simply filled my log files.
[10796.519283] NILFS error (device sdf1): nilfs_check_page: bad entry in directory #2383620: rec_len is smaller than minimal - offset=1143304192, inode=0, rec_len=0, name_len=0
I haven't read the code involved, but what I think should happen is that on the very *first* error, it should return an I/O error to userland. Also, the partition was set to "errors=remount-ro", so the very first error should also make the filesystem read-only, correct?
-Mike
A message that is not in the archive (sent off-list or not yet received): [email protected]
Quoted 13 lines · Michael Conrad
I think this will help. However, the idea I had in mind originally was for nilfs to "give up" sooner.
I suspect that my nilfs partition became corrupt for hardware or hardware-driver reasons. So lets ignore that part for now.
With the data on the drive being corrupt, it appeared that nilfs encountered an invalid directory (possibly just a long string of NUL bytes?) and emitted more than a million errors about invalid structures, triggering the soft-lockup watchdog and rebooting the system. When I recompiled my kernel with soft-lockup set to 5 minutes, it simply filled my log files.
Quoted 9 lines
[10796.519283] NILFS error (device sdf1): nilfs_check_page: bad entry indirectory #2383620:
rec_lenis smaller than minimal - offset=1143304192, inode=0, rec_len=0, name_len=0I haven't read the code involved, but what I think should happen is that on the very *first* error, it should return an I/O error to userland. Also, the partition was set to "errors=remount-ro", so the very first error should also make the filesystem read-only, correct?
I think that your vision is correct. I am pondering about likewise solution too. But, anyway, likewise fixes can be made locally only for every concrete use-case. To change error messages correctly is easy. But to suggest proper fix without an issue reproducing is impossible.
Anyway, I'll try to elaborate some fix. But my hands on another task right now.
Thanks,
Vyacheslav Dubeyko.
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html