From mboxrd@z Thu Jan 1 00:00:00 1970 From: Bob Peterson Date: Fri, 8 Dec 2017 10:30:48 -0500 (EST) Subject: [Cluster-devel] [GFS2 PATCH] GFS2: Log the reason for log flushes in every log header In-Reply-To: <353387775.37200223.1512156899106.JavaMail.zimbra@redhat.com> Message-ID: <94557090.39942461.1512747048003.JavaMail.zimbra@redhat.com> List-Id: To: cluster-devel.redhat.com MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Hi, This is a version 2 replacement for this patch, with some improvements. --- This patch just adds the capability for GFS2 to track which function called gfs2_log_flush. This should make it easier to diagnose problems based on the sequence of events found in the journals. Signed-off-by: Bob Peterson --- fs/gfs2/aops.c | 2 +- fs/gfs2/file.c | 2 +- fs/gfs2/glops.c | 12 ++++---- fs/gfs2/incore.h | 1 + fs/gfs2/log.c | 61 +++++++++++++++++++++++++++++++++------- fs/gfs2/log.h | 8 +----- fs/gfs2/ops_fstype.c | 2 +- fs/gfs2/quota.c | 2 +- fs/gfs2/rgrp.c | 2 +- fs/gfs2/super.c | 8 +++--- fs/gfs2/trace_gfs2.h | 11 +++++--- fs/gfs2/trans.c | 2 +- include/uapi/linux/gfs2_ondisk.h | 36 ++++++++++++++++++++++++ 13 files changed, 112 insertions(+), 37 deletions(-) diff --git a/fs/gfs2/aops.c b/fs/gfs2/aops.c index 658ca027cab9..4ef09ad463d4 100644 --- a/fs/gfs2/aops.c +++ b/fs/gfs2/aops.c @@ -445,7 +445,7 @@ static int gfs2_jdata_writepages(struct address_space *mapping, ret = gfs2_write_cache_jdata(mapping, wbc); if (ret == 0 && wbc->sync_mode == WB_SYNC_ALL) { - gfs2_log_flush(sdp, ip->i_gl, NORMAL_FLUSH); + gfs2_log_flush(sdp, ip->i_gl, LHF_JDATA_WPAGES); ret = gfs2_write_cache_jdata(mapping, wbc); } return ret; diff --git a/fs/gfs2/file.c b/fs/gfs2/file.c index 58705ef8643a..68fee09efdf2 100644 --- a/fs/gfs2/file.c +++ b/fs/gfs2/file.c @@ -246,7 +246,7 @@ static int do_gfs2_set_flags(struct file *filp, u32 reqflags, u32 mask) } if ((flags ^ new_flags) & GFS2_DIF_JDATA) { if (new_flags & GFS2_DIF_JDATA) - gfs2_log_flush(sdp, ip->i_gl, NORMAL_FLUSH); + gfs2_log_flush(sdp, ip->i_gl, LHF_SET_FLAGS); error = filemap_fdatawrite(inode->i_mapping); if (error) goto out; diff --git a/fs/gfs2/glops.c b/fs/gfs2/glops.c index cdd1c5f06f45..1e95c0bdbc3b 100644 --- a/fs/gfs2/glops.c +++ b/fs/gfs2/glops.c @@ -107,7 +107,7 @@ static void gfs2_ail_empty_gl(struct gfs2_glock *gl) __gfs2_ail_flush(gl, 0, tr.tr_revokes); gfs2_trans_end(sdp); - gfs2_log_flush(sdp, NULL, NORMAL_FLUSH); + gfs2_log_flush(sdp, NULL, LHF_AIL_EMPTY_GL); } void gfs2_ail_flush(struct gfs2_glock *gl, bool fsync) @@ -128,7 +128,7 @@ void gfs2_ail_flush(struct gfs2_glock *gl, bool fsync) return; __gfs2_ail_flush(gl, fsync, max_revokes); gfs2_trans_end(sdp); - gfs2_log_flush(sdp, NULL, NORMAL_FLUSH); + gfs2_log_flush(sdp, NULL, LHF_AIL_FLUSH); } /** @@ -157,7 +157,7 @@ static void rgrp_go_sync(struct gfs2_glock *gl) return; GLOCK_BUG_ON(gl, gl->gl_state != LM_ST_EXCLUSIVE); - gfs2_log_flush(sdp, gl, NORMAL_FLUSH); + gfs2_log_flush(sdp, gl, LHF_RGRP_GO_SYNC); filemap_fdatawrite_range(mapping, gl->gl_vm.start, gl->gl_vm.end); error = filemap_fdatawait_range(mapping, gl->gl_vm.start, gl->gl_vm.end); mapping_set_error(mapping, error); @@ -252,7 +252,7 @@ static void inode_go_sync(struct gfs2_glock *gl) GLOCK_BUG_ON(gl, gl->gl_state != LM_ST_EXCLUSIVE); - gfs2_log_flush(gl->gl_name.ln_sbd, gl, NORMAL_FLUSH); + gfs2_log_flush(gl->gl_name.ln_sbd, gl, LHF_INODE_GO_SYNC); filemap_fdatawrite(metamapping); if (isreg) { struct address_space *mapping = ip->i_inode.i_mapping; @@ -303,7 +303,7 @@ static void inode_go_inval(struct gfs2_glock *gl, int flags) } if (ip == GFS2_I(gl->gl_name.ln_sbd->sd_rindex)) { - gfs2_log_flush(gl->gl_name.ln_sbd, NULL, NORMAL_FLUSH); + gfs2_log_flush(gl->gl_name.ln_sbd, NULL, LHF_INODE_GO_INVAL); gl->gl_name.ln_sbd->sd_rindex_uptodate = 0; } if (ip && S_ISREG(ip->i_inode.i_mode)) @@ -495,7 +495,7 @@ static void freeze_go_sync(struct gfs2_glock *gl) gfs2_assert_withdraw(sdp, 0); } queue_work(gfs2_freeze_wq, &sdp->sd_freeze_work); - gfs2_log_flush(sdp, NULL, FREEZE_FLUSH); + gfs2_log_flush(sdp, NULL, LHF_FREEZE_GO_SYNC); } } diff --git a/fs/gfs2/incore.h b/fs/gfs2/incore.h index 6e18e9793ec4..4a45c2590b1b 100644 --- a/fs/gfs2/incore.h +++ b/fs/gfs2/incore.h @@ -844,6 +844,7 @@ struct gfs2_sbd { struct dentry *debugfs_dentry_glocks; struct dentry *debugfs_dentry_glstats; struct dentry *debugfs_dentry_sbstats; + unsigned long sd_log_flushers; }; static inline void gfs2_glstats_inc(struct gfs2_glock *gl, int which) diff --git a/fs/gfs2/log.c b/fs/gfs2/log.c index 508b6edefab7..b64b15c0f1eb 100644 --- a/fs/gfs2/log.c +++ b/fs/gfs2/log.c @@ -33,6 +33,35 @@ #include "dir.h" #include "trace_gfs2.h" +enum gfs2_flush_type { + NORMAL_FLUSH = 0, + SYNC_FLUSH, + SHUTDOWN_FLUSH, + FREEZE_FLUSH +}; + +static const enum gfs2_flush_type log_flush_types[LHF_LOG_FLUSHERS] = { + NORMAL_FLUSH, /* LHF_SHUTDOWN */ + NORMAL_FLUSH, /* LHF_JDATA_WPAGES */ + NORMAL_FLUSH, /* LHF_SET_FLAGS */ + NORMAL_FLUSH, /* LHF_AIL_EMPTY_GL */ + NORMAL_FLUSH, /* LHF_AIL_FLUSH */ + NORMAL_FLUSH, /* LHF_RGRP_GO_SYNC */ + NORMAL_FLUSH, /* LHF_INODE_GO_SYNC */ + NORMAL_FLUSH, /* LHF_INODE_GO_INVAL */ + FREEZE_FLUSH, /* LHF_FREEZE_GO_SYNC */ + SYNC_FLUSH, /* LHF_KILL_SB */ + NORMAL_FLUSH, /* LHF_DO_SYNC */ + NORMAL_FLUSH, /* LHF_INPLACE_RESERVE */ + NORMAL_FLUSH, /* LHF_WRITE_INODE */ + SHUTDOWN_FLUSH, /* LHF_MAKE_FS_RO */ + NORMAL_FLUSH, /* LHF_SYNC_FS */ + NORMAL_FLUSH, /* LHF_EVICT_INODE */ + NORMAL_FLUSH, /* LHF_TRANS_END */ + NORMAL_FLUSH, /* LHF_LOGD_JFLUSH_REQD */ + NORMAL_FLUSH, /* LHF_LOGD_AIL_FLUSH_REQD */ +}; + /** * gfs2_struct2blk - compute stuff * @sdp: the filesystem @@ -654,7 +683,8 @@ void gfs2_write_revokes(struct gfs2_sbd *sdp) * Returns: the initialized log buffer descriptor */ -static void log_write_header(struct gfs2_sbd *sdp, u32 flags) +static void log_write_header(struct gfs2_sbd *sdp, + enum gfs2_log_flushers flusher) { struct gfs2_log_header_v2 *lh2; struct gfs2_log_header *lh; @@ -665,6 +695,14 @@ static void log_write_header(struct gfs2_sbd *sdp, u32 flags) enum gfs2_freeze_state state = atomic_read(&sdp->sd_freeze_state); struct gfs2_statfs_change_host *l_sc = &sdp->sd_statfs_local; struct timespec64 tv; + u32 flags = (flusher == LHF_SHUTDOWN) ? GFS2_LOG_HEAD_UNMOUNT : 0; + + BUG_ON(flusher >= LHF_LOG_FLUSHERS); + /* Although not necessary, we funnel the flusher passed to this func + through a common superblock variable in sdp. That way, if we have + competing calls to this function, we ought to see multiple bits + set in the resulting LH, and maybe in multiple LH blocks. */ + set_bit(flusher, &sdp->sd_log_flushers); lh2 = page_address(page); clear_page(lh2); @@ -692,6 +730,8 @@ static void log_write_header(struct gfs2_sbd *sdp, u32 flags) lh2->lh_jinode = cpu_to_be64(GFS2_I(sdp->sd_jdesc->jd_inode)->i_no_addr); lh2->lh_statfs_addr = cpu_to_be64(GFS2_I(sdp->sd_sc_inode)->i_no_addr); lh2->lh_quota_addr = cpu_to_be64(GFS2_I(sdp->sd_qc_inode)->i_no_addr); + lh2->lh_log_flushers = cpu_to_be32(sdp->sd_log_flushers); + sdp->sd_log_flushers = 0; spin_lock(&sdp->sd_statfs_spin); lh2->lh_local_total = cpu_to_be64(l_sc->sc_total); @@ -724,10 +764,11 @@ static void log_write_header(struct gfs2_sbd *sdp, u32 flags) */ void gfs2_log_flush(struct gfs2_sbd *sdp, struct gfs2_glock *gl, - enum gfs2_flush_type type) + enum gfs2_log_flushers flusher) { struct gfs2_trans *tr; enum gfs2_freeze_state state = atomic_read(&sdp->sd_freeze_state); + u32 type = log_flush_types[flusher]; down_write(&sdp->sd_log_flush_lock); @@ -736,7 +777,7 @@ void gfs2_log_flush(struct gfs2_sbd *sdp, struct gfs2_glock *gl, up_write(&sdp->sd_log_flush_lock); return; } - trace_gfs2_log_flush(sdp, 1); + trace_gfs2_log_flush(sdp, 1, flusher); if (type == SHUTDOWN_FLUSH) clear_bit(SDF_JOURNAL_LIVE, &sdp->sd_flags); @@ -763,11 +804,11 @@ void gfs2_log_flush(struct gfs2_sbd *sdp, struct gfs2_glock *gl, if (sdp->sd_log_head != sdp->sd_log_flush_head) { log_flush_wait(sdp); - log_write_header(sdp, 0); + log_write_header(sdp, flusher); } else if (sdp->sd_log_tail != current_tail(sdp) && !sdp->sd_log_idle){ atomic_dec(&sdp->sd_log_blks_free); /* Adjust for unreserved buffer */ trace_gfs2_log_blocks(sdp, -1); - log_write_header(sdp, 0); + log_write_header(sdp, flusher); } lops_after_commit(sdp, tr); @@ -794,7 +835,7 @@ void gfs2_log_flush(struct gfs2_sbd *sdp, struct gfs2_glock *gl, } atomic_dec(&sdp->sd_log_blks_free); /* Adjust for unreserved buffer */ trace_gfs2_log_blocks(sdp, -1); - log_write_header(sdp, 0); + log_write_header(sdp, flusher); sdp->sd_log_head = sdp->sd_log_flush_head; } if (type == SHUTDOWN_FLUSH || type == FREEZE_FLUSH) @@ -803,7 +844,7 @@ void gfs2_log_flush(struct gfs2_sbd *sdp, struct gfs2_glock *gl, atomic_set(&sdp->sd_freeze_state, SFS_FROZEN); } - trace_gfs2_log_flush(sdp, 0); + trace_gfs2_log_flush(sdp, 0, flusher); up_write(&sdp->sd_log_flush_lock); kfree(tr); @@ -899,7 +940,7 @@ void gfs2_log_shutdown(struct gfs2_sbd *sdp) sdp->sd_log_flush_head = sdp->sd_log_head; - log_write_header(sdp, GFS2_LOG_HEAD_UNMOUNT); + log_write_header(sdp, LHF_SHUTDOWN); gfs2_assert_warn(sdp, sdp->sd_log_head == sdp->sd_log_tail); gfs2_assert_warn(sdp, list_empty(&sdp->sd_ail2_list)); @@ -955,7 +996,7 @@ int gfs2_logd(void *data) did_flush = false; if (gfs2_jrnl_flush_reqd(sdp) || t == 0) { gfs2_ail1_empty(sdp); - gfs2_log_flush(sdp, NULL, NORMAL_FLUSH); + gfs2_log_flush(sdp, NULL, LHF_LOGD_JFLUSH_REQD); did_flush = true; } @@ -963,7 +1004,7 @@ int gfs2_logd(void *data) gfs2_ail1_start(sdp); gfs2_ail1_wait(sdp); gfs2_ail1_empty(sdp); - gfs2_log_flush(sdp, NULL, NORMAL_FLUSH); + gfs2_log_flush(sdp, NULL, LHF_LOGD_AIL_FLUSH_REQD); did_flush = true; } diff --git a/fs/gfs2/log.h b/fs/gfs2/log.h index 9499a6049212..aad2b2c69d54 100644 --- a/fs/gfs2/log.h +++ b/fs/gfs2/log.h @@ -65,14 +65,8 @@ extern unsigned int gfs2_struct2blk(struct gfs2_sbd *sdp, unsigned int nstruct, extern void gfs2_log_release(struct gfs2_sbd *sdp, unsigned int blks); extern int gfs2_log_reserve(struct gfs2_sbd *sdp, unsigned int blks); -enum gfs2_flush_type { - NORMAL_FLUSH = 0, - SYNC_FLUSH, - SHUTDOWN_FLUSH, - FREEZE_FLUSH -}; extern void gfs2_log_flush(struct gfs2_sbd *sdp, struct gfs2_glock *gl, - enum gfs2_flush_type type); + enum gfs2_log_flushers flusher); extern void gfs2_log_commit(struct gfs2_sbd *sdp, struct gfs2_trans *trans); extern void gfs2_remove_from_ail(struct gfs2_bufdata *bd); extern void gfs2_ail1_flush(struct gfs2_sbd *sdp, struct writeback_control *wbc); diff --git a/fs/gfs2/ops_fstype.c b/fs/gfs2/ops_fstype.c index a3711f543405..b53cf3e111e1 100644 --- a/fs/gfs2/ops_fstype.c +++ b/fs/gfs2/ops_fstype.c @@ -1382,7 +1382,7 @@ static void gfs2_kill_sb(struct super_block *sb) return; } - gfs2_log_flush(sdp, NULL, SYNC_FLUSH); + gfs2_log_flush(sdp, NULL, LHF_KILL_SB); dput(sdp->sd_root_dir); dput(sdp->sd_master_dir); sdp->sd_root_dir = NULL; diff --git a/fs/gfs2/quota.c b/fs/gfs2/quota.c index e700fb162664..a90ccd8855aa 100644 --- a/fs/gfs2/quota.c +++ b/fs/gfs2/quota.c @@ -955,7 +955,7 @@ static int do_sync(unsigned int num_qd, struct gfs2_quota_data **qda) gfs2_glock_dq_uninit(&ghs[qx]); inode_unlock(&ip->i_inode); kfree(ghs); - gfs2_log_flush(ip->i_gl->gl_name.ln_sbd, ip->i_gl, NORMAL_FLUSH); + gfs2_log_flush(ip->i_gl->gl_name.ln_sbd, ip->i_gl, LHF_DO_SYNC); return error; } diff --git a/fs/gfs2/rgrp.c b/fs/gfs2/rgrp.c index b52c5c3ac445..f9b00836ce1a 100644 --- a/fs/gfs2/rgrp.c +++ b/fs/gfs2/rgrp.c @@ -2072,7 +2072,7 @@ int gfs2_inplace_reserve(struct gfs2_inode *ip, struct gfs2_alloc_parms *ap) } /* Flushing the log may release space */ if (loops == 2) - gfs2_log_flush(sdp, NULL, NORMAL_FLUSH); + gfs2_log_flush(sdp, NULL, LHF_INPLACE_RESERVE); } return -ENOSPC; diff --git a/fs/gfs2/super.c b/fs/gfs2/super.c index 9cb5c9a97d69..5bf53ac15ab3 100644 --- a/fs/gfs2/super.c +++ b/fs/gfs2/super.c @@ -757,7 +757,7 @@ static int gfs2_write_inode(struct inode *inode, struct writeback_control *wbc) bool flush_all = (wbc->sync_mode == WB_SYNC_ALL || gfs2_is_jdata(ip)); if (flush_all) - gfs2_log_flush(GFS2_SB(inode), ip->i_gl, NORMAL_FLUSH); + gfs2_log_flush(GFS2_SB(inode), ip->i_gl, LHF_WRITE_INODE); if (bdi->wb.dirty_exceeded) gfs2_ail1_flush(sdp, wbc); else @@ -853,7 +853,7 @@ static int gfs2_make_fs_ro(struct gfs2_sbd *sdp) gfs2_quota_sync(sdp->sd_vfs, 0); gfs2_statfs_sync(sdp->sd_vfs, 0); - gfs2_log_flush(sdp, NULL, SHUTDOWN_FLUSH); + gfs2_log_flush(sdp, NULL, LHF_MAKE_FS_RO); wait_event(sdp->sd_reserving_log_wait, atomic_read(&sdp->sd_reserving_log) == 0); gfs2_assert_warn(sdp, atomic_read(&sdp->sd_log_blks_free) == sdp->sd_jdesc->jd_blocks); @@ -946,7 +946,7 @@ static int gfs2_sync_fs(struct super_block *sb, int wait) gfs2_quota_sync(sb, -1); if (wait) - gfs2_log_flush(sdp, NULL, NORMAL_FLUSH); + gfs2_log_flush(sdp, NULL, LHF_SYNC_FS); return sdp->sd_log_error; } @@ -1650,7 +1650,7 @@ static void gfs2_evict_inode(struct inode *inode) goto out_unlock; out_truncate: - gfs2_log_flush(sdp, ip->i_gl, NORMAL_FLUSH); + gfs2_log_flush(sdp, ip->i_gl, LHF_EVICT_INODE); metamapping = gfs2_glock2aspace(ip->i_gl); if (test_bit(GLF_DIRTY, &ip->i_gl->gl_flags)) { filemap_fdatawrite(metamapping); diff --git a/fs/gfs2/trace_gfs2.h b/fs/gfs2/trace_gfs2.h index f67a709589d3..62ada4847250 100644 --- a/fs/gfs2/trace_gfs2.h +++ b/fs/gfs2/trace_gfs2.h @@ -353,26 +353,29 @@ TRACE_EVENT(gfs2_pin, /* Flushing the log */ TRACE_EVENT(gfs2_log_flush, - TP_PROTO(const struct gfs2_sbd *sdp, int start), + TP_PROTO(const struct gfs2_sbd *sdp, int start, u32 flusher), - TP_ARGS(sdp, start), + TP_ARGS(sdp, start, flusher), TP_STRUCT__entry( __field( dev_t, dev ) __field( int, start ) __field( u64, log_seq ) + __field( u32, flusher ) ), TP_fast_assign( __entry->dev = sdp->sd_vfs->s_dev; __entry->start = start; __entry->log_seq = sdp->sd_log_sequence; + __entry->flusher = flusher; ), - TP_printk("%u,%u log flush %s %llu", + TP_printk("%u,%u log flush %s %llu %llx", MAJOR(__entry->dev), MINOR(__entry->dev), __entry->start ? "start" : "end", - (unsigned long long)__entry->log_seq) + (unsigned long long)__entry->log_seq, + (unsigned long long)__entry->flusher) ); /* Reserving/releasing blocks in the log */ diff --git a/fs/gfs2/trans.c b/fs/gfs2/trans.c index a85ca8b2c9ba..9842778e32d1 100644 --- a/fs/gfs2/trans.c +++ b/fs/gfs2/trans.c @@ -118,7 +118,7 @@ void gfs2_trans_end(struct gfs2_sbd *sdp) up_read(&sdp->sd_log_flush_lock); if (sdp->sd_vfs->s_flags & MS_SYNCHRONOUS) - gfs2_log_flush(sdp, NULL, NORMAL_FLUSH); + gfs2_log_flush(sdp, NULL, LHF_TRANS_END); if (alloced) sb_end_intwrite(sdp->sd_vfs); } diff --git a/include/uapi/linux/gfs2_ondisk.h b/include/uapi/linux/gfs2_ondisk.h index 96d9676ac354..cf867896436d 100644 --- a/include/uapi/linux/gfs2_ondisk.h +++ b/include/uapi/linux/gfs2_ondisk.h @@ -406,6 +406,42 @@ struct gfs2_log_header { __be32 lh_hash; }; +/* + * Log Header version 2 constants - actor who wrote a log header + */ + +enum gfs2_log_flushers { + /* Constants reserved for kernel space */ + LHF_SHUTDOWN = 0, + LHF_JDATA_WPAGES = 1, + LHF_SET_FLAGS = 2, + LHF_AIL_EMPTY_GL = 3, + LHF_AIL_FLUSH = 4, + LHF_RGRP_GO_SYNC = 5, + LHF_INODE_GO_SYNC = 6, + LHF_INODE_GO_INVAL = 7, + LHF_FREEZE_GO_SYNC = 8, + LHF_KILL_SB = 9, + LHF_DO_SYNC = 10, + LHF_INPLACE_RESERVE = 11, + LHF_WRITE_INODE = 12, + LHF_MAKE_FS_RO = 13, + LHF_SYNC_FS = 14, + LHF_EVICT_INODE = 15, + LHF_TRANS_END = 16, + LHF_LOGD_JFLUSH_REQD = 17, + LHF_LOGD_AIL_FLUSH_REQD = 18, + LHF_LOG_FLUSHERS = 19, /* number of kernel log flushers */ + + /* Constants reserved for user space / gfs2-utils */ + LHF_GFS2_CONVERT = 26, + LHF_GFS2_EDIT = 27, + LHF_GFS2_FSCK = 28, + LHF_GFS2_FSCK_JREPLAY = 29, + LHF_GFS2_MKFS = 30, + LHF_GFS2_JADD = 31 +}; + struct gfs2_log_header_v2 { struct gfs2_log_header lhv1;