* [PATCH V4 1/3] ocfs2: add last unlock times in locking_state @ 2019-06-11 1:54 Gang He 2019-06-11 1:54 ` [PATCH V4 2/3] ocfs2: add locking filter debugfs file Gang He 2019-06-11 1:54 ` [PATCH V4 3/3] ocfs2: add first lock wait time in locking_state Gang He 0 siblings, 2 replies; 6+ messages in thread From: Gang He @ 2019-06-11 1:54 UTC (permalink / raw) To: mark, jlbec, joseph.qi; +Cc: Gang He, linux-kernel, ocfs2-devel, akpm ocfs2 file system uses locking_state file under debugfs to dump each ocfs2 file system's dlm lock resources, but the dlm lock resources in memory are becoming more and more after the files were touched by the user. it will become a bit difficult to analyze these dlm lock resource records in locking_state file by the upper scripts, though some files are not active for now, which were accessed long time ago. Then, I'd like to add last pr/ex unlock times in locking_state file for each dlm lock resource record, the the upper scripts can use last unlock time to filter inactive dlm lock resource record. Compared with v1, the main change is to use wall time in microsecond for last pr/ex unlock time. Signed-off-by: Gang He <ghe@suse.com> Reviewed-by: Joseph Qi <joseph.qi@linux.alibaba.com> --- fs/ocfs2/dlmglue.c | 18 +++++++++++++++--- fs/ocfs2/ocfs2.h | 1 + 2 files changed, 16 insertions(+), 3 deletions(-) diff --git a/fs/ocfs2/dlmglue.c b/fs/ocfs2/dlmglue.c index af405586c5b1..3b0e7d399df2 100644 --- a/fs/ocfs2/dlmglue.c +++ b/fs/ocfs2/dlmglue.c @@ -474,6 +474,8 @@ static void ocfs2_update_lock_stats(struct ocfs2_lock_res *res, int level, if (ret) stats->ls_fail++; + + stats->ls_last = ktime_to_us(ktime_get_real()); } static inline void ocfs2_track_lock_refresh(struct ocfs2_lock_res *lockres) @@ -3093,8 +3095,10 @@ static void *ocfs2_dlm_seq_next(struct seq_file *m, void *v, loff_t *pos) * - Lock stats printed * New in version 3 * - Max time in lock stats is in usecs (instead of nsecs) + * New in version 4 + * - Add last pr/ex unlock times in usecs */ -#define OCFS2_DLM_DEBUG_STR_VERSION 3 +#define OCFS2_DLM_DEBUG_STR_VERSION 4 static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) { int i; @@ -3145,6 +3149,8 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) # define lock_max_prmode(_l) ((_l)->l_lock_prmode.ls_max) # define lock_max_exmode(_l) ((_l)->l_lock_exmode.ls_max) # define lock_refresh(_l) ((_l)->l_lock_refresh) +# define lock_last_prmode(_l) ((_l)->l_lock_prmode.ls_last) +# define lock_last_exmode(_l) ((_l)->l_lock_exmode.ls_last) #else # define lock_num_prmode(_l) (0) # define lock_num_exmode(_l) (0) @@ -3155,6 +3161,8 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) # define lock_max_prmode(_l) (0) # define lock_max_exmode(_l) (0) # define lock_refresh(_l) (0) +# define lock_last_prmode(_l) (0ULL) +# define lock_last_exmode(_l) (0ULL) #endif /* The following seq_print was added in version 2 of this output */ seq_printf(m, "%u\t" @@ -3165,7 +3173,9 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) "%llu\t" "%u\t" "%u\t" - "%u\t", + "%u\t" + "%llu\t" + "%llu\t", lock_num_prmode(lockres), lock_num_exmode(lockres), lock_num_prmode_failed(lockres), @@ -3174,7 +3184,9 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) lock_total_exmode(lockres), lock_max_prmode(lockres), lock_max_exmode(lockres), - lock_refresh(lockres)); + lock_refresh(lockres), + lock_last_prmode(lockres), + lock_last_exmode(lockres)); /* End the line */ seq_printf(m, "\n"); diff --git a/fs/ocfs2/ocfs2.h b/fs/ocfs2/ocfs2.h index 1f029fbe8b8d..6f43651f01b3 100644 --- a/fs/ocfs2/ocfs2.h +++ b/fs/ocfs2/ocfs2.h @@ -164,6 +164,7 @@ struct ocfs2_lock_stats { /* Storing max wait in usecs saves 24 bytes per inode */ u32 ls_max; /* Max wait in USEC */ + u64 ls_last; /* Last unlock time in USEC */ }; #endif -- 2.21.0 ^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH V4 2/3] ocfs2: add locking filter debugfs file 2019-06-11 1:54 [PATCH V4 1/3] ocfs2: add last unlock times in locking_state Gang He @ 2019-06-11 1:54 ` Gang He 2019-06-11 1:54 ` [PATCH V4 3/3] ocfs2: add first lock wait time in locking_state Gang He 1 sibling, 0 replies; 6+ messages in thread From: Gang He @ 2019-06-11 1:54 UTC (permalink / raw) To: mark, jlbec, joseph.qi; +Cc: Gang He, linux-kernel, ocfs2-devel, akpm Add locking filter debugfs file, which is used to filter lock resources dump from locking_state debugfs file. We use d_filter_secs field to filter lock resources dump, the default d_filter_secs(0) value filters nothing, otherwise, only dump the last N seconds active lock resources. This enhancement can avoid dumping lots of old records. The d_filter_secs value can be changed via locking_filter file. Compared with v3, I need to do the related change since last lock/unlock uses wall time in microsecond. secondly, adjust CONFIG_OCFS2_FS_STATS macro positions. Compared with v2, ocfs2_dlm_init_debug() returns directly with error when creating locking filter debugfs file is failed, since ocfs2_dlm_shutdown_debug() will handle this failure perfectly. Compared with v1, the main change is to add CONFIG_OCFS2_FS_STATS macro definition judgment. Signed-off-by: Gang He <ghe@suse.com> Reviewed-by: Joseph Qi <joseph.qi@linux.alibaba.com> --- fs/ocfs2/dlmglue.c | 38 ++++++++++++++++++++++++++++++++++++++ fs/ocfs2/ocfs2.h | 2 ++ 2 files changed, 40 insertions(+) diff --git a/fs/ocfs2/dlmglue.c b/fs/ocfs2/dlmglue.c index 3b0e7d399df2..d4caa6d117c6 100644 --- a/fs/ocfs2/dlmglue.c +++ b/fs/ocfs2/dlmglue.c @@ -3005,6 +3005,8 @@ struct ocfs2_dlm_debug *ocfs2_new_dlm_debug(void) kref_init(&dlm_debug->d_refcnt); INIT_LIST_HEAD(&dlm_debug->d_lockres_tracking); dlm_debug->d_locking_state = NULL; + dlm_debug->d_locking_filter = NULL; + dlm_debug->d_filter_secs = 0; out: return dlm_debug; } @@ -3104,10 +3106,34 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) int i; char *lvb; struct ocfs2_lock_res *lockres = v; +#ifdef CONFIG_OCFS2_FS_STATS + u64 now, last; + struct ocfs2_dlm_debug *dlm_debug = + ((struct ocfs2_dlm_seq_priv *)m->private)->p_dlm_debug; +#endif if (!lockres) return -EINVAL; +#ifdef CONFIG_OCFS2_FS_STATS + if (dlm_debug->d_filter_secs) { + now = ktime_to_us(ktime_get_real()); + if (lockres->l_lock_prmode.ls_last > + lockres->l_lock_exmode.ls_last) + last = lockres->l_lock_prmode.ls_last; + else + last = lockres->l_lock_exmode.ls_last; + /* + * Use d_filter_secs field to filter lock resources dump, + * the default d_filter_secs(0) value filters nothing, + * otherwise, only dump the last N seconds active lock + * resources. + */ + if ((now - last) / 1000000 > dlm_debug->d_filter_secs) + return 0; + } +#endif + seq_printf(m, "0x%x\t", OCFS2_DLM_DEBUG_STR_VERSION); if (lockres->l_type == OCFS2_LOCK_TYPE_DENTRY) @@ -3257,6 +3283,17 @@ static int ocfs2_dlm_init_debug(struct ocfs2_super *osb) goto out; } + dlm_debug->d_locking_filter = debugfs_create_u32("locking_filter", + 0600, + osb->osb_debug_root, + &dlm_debug->d_filter_secs); + if (!dlm_debug->d_locking_filter) { + ret = -EINVAL; + mlog(ML_ERROR, + "Unable to create locking filter debugfs file.\n"); + goto out; + } + ocfs2_get_dlm_debug(dlm_debug); out: return ret; @@ -3268,6 +3305,7 @@ static void ocfs2_dlm_shutdown_debug(struct ocfs2_super *osb) if (dlm_debug) { debugfs_remove(dlm_debug->d_locking_state); + debugfs_remove(dlm_debug->d_locking_filter); ocfs2_put_dlm_debug(dlm_debug); } } diff --git a/fs/ocfs2/ocfs2.h b/fs/ocfs2/ocfs2.h index 6f43651f01b3..6d0a77703d0e 100644 --- a/fs/ocfs2/ocfs2.h +++ b/fs/ocfs2/ocfs2.h @@ -237,6 +237,8 @@ struct ocfs2_orphan_scan { struct ocfs2_dlm_debug { struct kref d_refcnt; struct dentry *d_locking_state; + struct dentry *d_locking_filter; + u32 d_filter_secs; struct list_head d_lockres_tracking; }; -- 2.21.0 ^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH V4 3/3] ocfs2: add first lock wait time in locking_state 2019-06-11 1:54 [PATCH V4 1/3] ocfs2: add last unlock times in locking_state Gang He 2019-06-11 1:54 ` [PATCH V4 2/3] ocfs2: add locking filter debugfs file Gang He @ 2019-06-11 1:54 ` Gang He 2019-06-12 7:03 ` Joseph Qi 1 sibling, 1 reply; 6+ messages in thread From: Gang He @ 2019-06-11 1:54 UTC (permalink / raw) To: mark, jlbec, joseph.qi; +Cc: Gang He, linux-kernel, ocfs2-devel, akpm ocfs2 file system uses locking_state file under debugfs to dump each ocfs2 file system's dlm lock resources, but the users ever encountered some hang(deadlock) problems in ocfs2 file system. I'd like to add first lock wait time in locking_state file, which can help the upper scripts detect these deadlock problems via comparing the first lock wait time with the current time. Signed-off-by: Gang He <ghe@suse.com> --- fs/ocfs2/dlmglue.c | 32 +++++++++++++++++++++++++++++--- fs/ocfs2/ocfs2.h | 1 + 2 files changed, 30 insertions(+), 3 deletions(-) diff --git a/fs/ocfs2/dlmglue.c b/fs/ocfs2/dlmglue.c index d4caa6d117c6..8ce4b76f81ee 100644 --- a/fs/ocfs2/dlmglue.c +++ b/fs/ocfs2/dlmglue.c @@ -440,6 +440,7 @@ static void ocfs2_remove_lockres_tracking(struct ocfs2_lock_res *res) static void ocfs2_init_lock_stats(struct ocfs2_lock_res *res) { res->l_lock_refresh = 0; + res->l_lock_wait = 0; memset(&res->l_lock_prmode, 0, sizeof(struct ocfs2_lock_stats)); memset(&res->l_lock_exmode, 0, sizeof(struct ocfs2_lock_stats)); } @@ -483,6 +484,21 @@ static inline void ocfs2_track_lock_refresh(struct ocfs2_lock_res *lockres) lockres->l_lock_refresh++; } +static inline void ocfs2_track_lock_wait(struct ocfs2_lock_res *lockres) +{ + struct ocfs2_mask_waiter *mw; + + if (list_empty(&lockres->l_mask_waiters)) { + lockres->l_lock_wait = 0; + return; + } + + mw = list_first_entry(&lockres->l_mask_waiters, + struct ocfs2_mask_waiter, mw_item); + lockres->l_lock_wait = + ktime_to_us(ktime_mono_to_real(mw->mw_lock_start)); +} + static inline void ocfs2_init_start_time(struct ocfs2_mask_waiter *mw) { mw->mw_lock_start = ktime_get(); @@ -498,6 +514,9 @@ static inline void ocfs2_update_lock_stats(struct ocfs2_lock_res *res, static inline void ocfs2_track_lock_refresh(struct ocfs2_lock_res *lockres) { } +static inline void ocfs2_track_lock_wait(struct ocfs2_lock_res *lockres) +{ +} static inline void ocfs2_init_start_time(struct ocfs2_mask_waiter *mw) { } @@ -891,6 +910,7 @@ static void lockres_set_flags(struct ocfs2_lock_res *lockres, list_del_init(&mw->mw_item); mw->mw_status = 0; complete(&mw->mw_complete); + ocfs2_track_lock_wait(lockres); } } static void lockres_or_flags(struct ocfs2_lock_res *lockres, unsigned long or) @@ -1402,6 +1422,7 @@ static void lockres_add_mask_waiter(struct ocfs2_lock_res *lockres, list_add_tail(&mw->mw_item, &lockres->l_mask_waiters); mw->mw_mask = mask; mw->mw_goal = goal; + ocfs2_track_lock_wait(lockres); } /* returns 0 if the mw that was removed was already satisfied, -EBUSY @@ -1418,6 +1439,7 @@ static int __lockres_remove_mask_waiter(struct ocfs2_lock_res *lockres, list_del_init(&mw->mw_item); init_completion(&mw->mw_complete); + ocfs2_track_lock_wait(lockres); } return ret; @@ -3098,7 +3120,7 @@ static void *ocfs2_dlm_seq_next(struct seq_file *m, void *v, loff_t *pos) * New in version 3 * - Max time in lock stats is in usecs (instead of nsecs) * New in version 4 - * - Add last pr/ex unlock times in usecs + * - Add last pr/ex unlock times and first lock wait time in usecs */ #define OCFS2_DLM_DEBUG_STR_VERSION 4 static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) @@ -3116,7 +3138,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) return -EINVAL; #ifdef CONFIG_OCFS2_FS_STATS - if (dlm_debug->d_filter_secs) { + if (!lockres->l_lock_wait && dlm_debug->d_filter_secs) { now = ktime_to_us(ktime_get_real()); if (lockres->l_lock_prmode.ls_last > lockres->l_lock_exmode.ls_last) @@ -3177,6 +3199,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) # define lock_refresh(_l) ((_l)->l_lock_refresh) # define lock_last_prmode(_l) ((_l)->l_lock_prmode.ls_last) # define lock_last_exmode(_l) ((_l)->l_lock_exmode.ls_last) +# define lock_wait(_l) ((_l)->l_lock_wait) #else # define lock_num_prmode(_l) (0) # define lock_num_exmode(_l) (0) @@ -3189,6 +3212,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) # define lock_refresh(_l) (0) # define lock_last_prmode(_l) (0ULL) # define lock_last_exmode(_l) (0ULL) +# define lock_wait(_l) (0ULL) #endif /* The following seq_print was added in version 2 of this output */ seq_printf(m, "%u\t" @@ -3201,6 +3225,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) "%u\t" "%u\t" "%llu\t" + "%llu\t" "%llu\t", lock_num_prmode(lockres), lock_num_exmode(lockres), @@ -3212,7 +3237,8 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) lock_max_exmode(lockres), lock_refresh(lockres), lock_last_prmode(lockres), - lock_last_exmode(lockres)); + lock_last_exmode(lockres), + lock_wait(lockres)); /* End the line */ seq_printf(m, "\n"); diff --git a/fs/ocfs2/ocfs2.h b/fs/ocfs2/ocfs2.h index 6d0a77703d0e..99ce40063da6 100644 --- a/fs/ocfs2/ocfs2.h +++ b/fs/ocfs2/ocfs2.h @@ -206,6 +206,7 @@ struct ocfs2_lock_res { #ifdef CONFIG_OCFS2_FS_STATS struct ocfs2_lock_stats l_lock_prmode; /* PR mode stats */ u32 l_lock_refresh; /* Disk refreshes */ + u64 l_lock_wait; /* First lock wait time */ struct ocfs2_lock_stats l_lock_exmode; /* EX mode stats */ #endif #ifdef CONFIG_DEBUG_LOCK_ALLOC -- 2.21.0 ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH V4 3/3] ocfs2: add first lock wait time in locking_state 2019-06-11 1:54 ` [PATCH V4 3/3] ocfs2: add first lock wait time in locking_state Gang He @ 2019-06-12 7:03 ` Joseph Qi 2019-06-12 7:29 ` Gang He 0 siblings, 1 reply; 6+ messages in thread From: Joseph Qi @ 2019-06-12 7:03 UTC (permalink / raw) To: Gang He, mark, jlbec; +Cc: linux-kernel, ocfs2-devel, akpm Hi Gang, On 19/6/11 09:54, Gang He wrote: > ocfs2 file system uses locking_state file under debugfs to dump > each ocfs2 file system's dlm lock resources, but the users ever > encountered some hang(deadlock) problems in ocfs2 file system. > I'd like to add first lock wait time in locking_state file, which > can help the upper scripts detect these deadlock problems via > comparing the first lock wait time with the current time. > > Signed-off-by: Gang He <ghe@suse.com> > --- > fs/ocfs2/dlmglue.c | 32 +++++++++++++++++++++++++++++--- > fs/ocfs2/ocfs2.h | 1 + > 2 files changed, 30 insertions(+), 3 deletions(-) > > diff --git a/fs/ocfs2/dlmglue.c b/fs/ocfs2/dlmglue.c > index d4caa6d117c6..8ce4b76f81ee 100644 > --- a/fs/ocfs2/dlmglue.c > +++ b/fs/ocfs2/dlmglue.c > @@ -440,6 +440,7 @@ static void ocfs2_remove_lockres_tracking(struct ocfs2_lock_res *res) > static void ocfs2_init_lock_stats(struct ocfs2_lock_res *res) > { > res->l_lock_refresh = 0; > + res->l_lock_wait = 0; > memset(&res->l_lock_prmode, 0, sizeof(struct ocfs2_lock_stats)); > memset(&res->l_lock_exmode, 0, sizeof(struct ocfs2_lock_stats)); > } > @@ -483,6 +484,21 @@ static inline void ocfs2_track_lock_refresh(struct ocfs2_lock_res *lockres) > lockres->l_lock_refresh++; > } > > +static inline void ocfs2_track_lock_wait(struct ocfs2_lock_res *lockres) > +{ > + struct ocfs2_mask_waiter *mw; > + > + if (list_empty(&lockres->l_mask_waiters)) { > + lockres->l_lock_wait = 0; > + return; > + } > + > + mw = list_first_entry(&lockres->l_mask_waiters, > + struct ocfs2_mask_waiter, mw_item); > + lockres->l_lock_wait = > + ktime_to_us(ktime_mono_to_real(mw->mw_lock_start)); I wonder why ktime_mono_to_real() here? Thanks, Joseph > +} > + > static inline void ocfs2_init_start_time(struct ocfs2_mask_waiter *mw) > { > mw->mw_lock_start = ktime_get(); > @@ -498,6 +514,9 @@ static inline void ocfs2_update_lock_stats(struct ocfs2_lock_res *res, > static inline void ocfs2_track_lock_refresh(struct ocfs2_lock_res *lockres) > { > } > +static inline void ocfs2_track_lock_wait(struct ocfs2_lock_res *lockres) > +{ > +} > static inline void ocfs2_init_start_time(struct ocfs2_mask_waiter *mw) > { > } > @@ -891,6 +910,7 @@ static void lockres_set_flags(struct ocfs2_lock_res *lockres, > list_del_init(&mw->mw_item); > mw->mw_status = 0; > complete(&mw->mw_complete); > + ocfs2_track_lock_wait(lockres); > } > } > static void lockres_or_flags(struct ocfs2_lock_res *lockres, unsigned long or) > @@ -1402,6 +1422,7 @@ static void lockres_add_mask_waiter(struct ocfs2_lock_res *lockres, > list_add_tail(&mw->mw_item, &lockres->l_mask_waiters); > mw->mw_mask = mask; > mw->mw_goal = goal; > + ocfs2_track_lock_wait(lockres); > } > > /* returns 0 if the mw that was removed was already satisfied, -EBUSY > @@ -1418,6 +1439,7 @@ static int __lockres_remove_mask_waiter(struct ocfs2_lock_res *lockres, > > list_del_init(&mw->mw_item); > init_completion(&mw->mw_complete); > + ocfs2_track_lock_wait(lockres); > } > > return ret; > @@ -3098,7 +3120,7 @@ static void *ocfs2_dlm_seq_next(struct seq_file *m, void *v, loff_t *pos) > * New in version 3 > * - Max time in lock stats is in usecs (instead of nsecs) > * New in version 4 > - * - Add last pr/ex unlock times in usecs > + * - Add last pr/ex unlock times and first lock wait time in usecs > */ > #define OCFS2_DLM_DEBUG_STR_VERSION 4 > static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) > @@ -3116,7 +3138,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) > return -EINVAL; > > #ifdef CONFIG_OCFS2_FS_STATS > - if (dlm_debug->d_filter_secs) { > + if (!lockres->l_lock_wait && dlm_debug->d_filter_secs) { > now = ktime_to_us(ktime_get_real()); > if (lockres->l_lock_prmode.ls_last > > lockres->l_lock_exmode.ls_last) > @@ -3177,6 +3199,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) > # define lock_refresh(_l) ((_l)->l_lock_refresh) > # define lock_last_prmode(_l) ((_l)->l_lock_prmode.ls_last) > # define lock_last_exmode(_l) ((_l)->l_lock_exmode.ls_last) > +# define lock_wait(_l) ((_l)->l_lock_wait) > #else > # define lock_num_prmode(_l) (0) > # define lock_num_exmode(_l) (0) > @@ -3189,6 +3212,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) > # define lock_refresh(_l) (0) > # define lock_last_prmode(_l) (0ULL) > # define lock_last_exmode(_l) (0ULL) > +# define lock_wait(_l) (0ULL) > #endif > /* The following seq_print was added in version 2 of this output */ > seq_printf(m, "%u\t" > @@ -3201,6 +3225,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) > "%u\t" > "%u\t" > "%llu\t" > + "%llu\t" > "%llu\t", > lock_num_prmode(lockres), > lock_num_exmode(lockres), > @@ -3212,7 +3237,8 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) > lock_max_exmode(lockres), > lock_refresh(lockres), > lock_last_prmode(lockres), > - lock_last_exmode(lockres)); > + lock_last_exmode(lockres), > + lock_wait(lockres)); > > /* End the line */ > seq_printf(m, "\n"); > diff --git a/fs/ocfs2/ocfs2.h b/fs/ocfs2/ocfs2.h > index 6d0a77703d0e..99ce40063da6 100644 > --- a/fs/ocfs2/ocfs2.h > +++ b/fs/ocfs2/ocfs2.h > @@ -206,6 +206,7 @@ struct ocfs2_lock_res { > #ifdef CONFIG_OCFS2_FS_STATS > struct ocfs2_lock_stats l_lock_prmode; /* PR mode stats */ > u32 l_lock_refresh; /* Disk refreshes */ > + u64 l_lock_wait; /* First lock wait time */ > struct ocfs2_lock_stats l_lock_exmode; /* EX mode stats */ > #endif > #ifdef CONFIG_DEBUG_LOCK_ALLOC > ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH V4 3/3] ocfs2: add first lock wait time in locking_state 2019-06-12 7:03 ` Joseph Qi @ 2019-06-12 7:29 ` Gang He 2019-06-12 7:45 ` Joseph Qi 0 siblings, 1 reply; 6+ messages in thread From: Gang He @ 2019-06-12 7:29 UTC (permalink / raw) To: jlbec, mark, Joseph Qi; +Cc: akpm, ocfs2-devel, linux-kernel Hello Joseph, >>> On 6/12/2019 at 3:03 pm, in message <fe52ae81-2140-9f68-8ec2-cc7c1fb3bc1a@linux.alibaba.com>, Joseph Qi <joseph.qi@linux.alibaba.com> wrote: > Hi Gang, > > On 19/6/11 09:54, Gang He wrote: >> ocfs2 file system uses locking_state file under debugfs to dump >> each ocfs2 file system's dlm lock resources, but the users ever >> encountered some hang(deadlock) problems in ocfs2 file system. >> I'd like to add first lock wait time in locking_state file, which >> can help the upper scripts detect these deadlock problems via >> comparing the first lock wait time with the current time. >> >> Signed-off-by: Gang He <ghe@suse.com> >> --- >> fs/ocfs2/dlmglue.c | 32 +++++++++++++++++++++++++++++--- >> fs/ocfs2/ocfs2.h | 1 + >> 2 files changed, 30 insertions(+), 3 deletions(-) >> >> diff --git a/fs/ocfs2/dlmglue.c b/fs/ocfs2/dlmglue.c >> index d4caa6d117c6..8ce4b76f81ee 100644 >> --- a/fs/ocfs2/dlmglue.c >> +++ b/fs/ocfs2/dlmglue.c >> @@ -440,6 +440,7 @@ static void ocfs2_remove_lockres_tracking(struct > ocfs2_lock_res *res) >> static void ocfs2_init_lock_stats(struct ocfs2_lock_res *res) >> { >> res->l_lock_refresh = 0; >> + res->l_lock_wait = 0; >> memset(&res->l_lock_prmode, 0, sizeof(struct ocfs2_lock_stats)); >> memset(&res->l_lock_exmode, 0, sizeof(struct ocfs2_lock_stats)); >> } >> @@ -483,6 +484,21 @@ static inline void ocfs2_track_lock_refresh(struct > ocfs2_lock_res *lockres) >> lockres->l_lock_refresh++; >> } >> >> +static inline void ocfs2_track_lock_wait(struct ocfs2_lock_res *lockres) >> +{ >> + struct ocfs2_mask_waiter *mw; >> + >> + if (list_empty(&lockres->l_mask_waiters)) { >> + lockres->l_lock_wait = 0; >> + return; >> + } >> + >> + mw = list_first_entry(&lockres->l_mask_waiters, >> + struct ocfs2_mask_waiter, mw_item); >> + lockres->l_lock_wait = >> + ktime_to_us(ktime_mono_to_real(mw->mw_lock_start)); > > I wonder why ktime_mono_to_real() here? The new item l_lock_wait is a statistic (or debugging) related, which will be dumping to the user-space via debugfs file locking_state for the further analysis if need. As the last comments from Wengang, the dumping is from different nodes in the cluster, it is better to use wall time (instead of mono or boot time) to display the related absolute times. Of course, the existing delta time (use mono time) will not affected. Thanks Gang > > Thanks, > Joseph > >> +} >> + >> static inline void ocfs2_init_start_time(struct ocfs2_mask_waiter *mw) >> { >> mw->mw_lock_start = ktime_get(); >> @@ -498,6 +514,9 @@ static inline void ocfs2_update_lock_stats(struct > ocfs2_lock_res *res, >> static inline void ocfs2_track_lock_refresh(struct ocfs2_lock_res *lockres) >> { >> } >> +static inline void ocfs2_track_lock_wait(struct ocfs2_lock_res *lockres) >> +{ >> +} >> static inline void ocfs2_init_start_time(struct ocfs2_mask_waiter *mw) >> { >> } >> @@ -891,6 +910,7 @@ static void lockres_set_flags(struct ocfs2_lock_res > *lockres, >> list_del_init(&mw->mw_item); >> mw->mw_status = 0; >> complete(&mw->mw_complete); >> + ocfs2_track_lock_wait(lockres); >> } >> } >> static void lockres_or_flags(struct ocfs2_lock_res *lockres, unsigned long > or) >> @@ -1402,6 +1422,7 @@ static void lockres_add_mask_waiter(struct > ocfs2_lock_res *lockres, >> list_add_tail(&mw->mw_item, &lockres->l_mask_waiters); >> mw->mw_mask = mask; >> mw->mw_goal = goal; >> + ocfs2_track_lock_wait(lockres); >> } >> >> /* returns 0 if the mw that was removed was already satisfied, -EBUSY >> @@ -1418,6 +1439,7 @@ static int __lockres_remove_mask_waiter(struct > ocfs2_lock_res *lockres, >> >> list_del_init(&mw->mw_item); >> init_completion(&mw->mw_complete); >> + ocfs2_track_lock_wait(lockres); >> } >> >> return ret; >> @@ -3098,7 +3120,7 @@ static void *ocfs2_dlm_seq_next(struct seq_file *m, > void *v, loff_t *pos) >> * New in version 3 >> * - Max time in lock stats is in usecs (instead of nsecs) >> * New in version 4 >> - * - Add last pr/ex unlock times in usecs >> + * - Add last pr/ex unlock times and first lock wait time in usecs >> */ >> #define OCFS2_DLM_DEBUG_STR_VERSION 4 >> static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) >> @@ -3116,7 +3138,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void > *v) >> return -EINVAL; >> >> #ifdef CONFIG_OCFS2_FS_STATS >> - if (dlm_debug->d_filter_secs) { >> + if (!lockres->l_lock_wait && dlm_debug->d_filter_secs) { >> now = ktime_to_us(ktime_get_real()); >> if (lockres->l_lock_prmode.ls_last > >> lockres->l_lock_exmode.ls_last) >> @@ -3177,6 +3199,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void > *v) >> # define lock_refresh(_l) ((_l)->l_lock_refresh) >> # define lock_last_prmode(_l) ((_l)->l_lock_prmode.ls_last) >> # define lock_last_exmode(_l) ((_l)->l_lock_exmode.ls_last) >> +# define lock_wait(_l) ((_l)->l_lock_wait) >> #else >> # define lock_num_prmode(_l) (0) >> # define lock_num_exmode(_l) (0) >> @@ -3189,6 +3212,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void > *v) >> # define lock_refresh(_l) (0) >> # define lock_last_prmode(_l) (0ULL) >> # define lock_last_exmode(_l) (0ULL) >> +# define lock_wait(_l) (0ULL) >> #endif >> /* The following seq_print was added in version 2 of this output */ >> seq_printf(m, "%u\t" >> @@ -3201,6 +3225,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void > *v) >> "%u\t" >> "%u\t" >> "%llu\t" >> + "%llu\t" >> "%llu\t", >> lock_num_prmode(lockres), >> lock_num_exmode(lockres), >> @@ -3212,7 +3237,8 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void > *v) >> lock_max_exmode(lockres), >> lock_refresh(lockres), >> lock_last_prmode(lockres), >> - lock_last_exmode(lockres)); >> + lock_last_exmode(lockres), >> + lock_wait(lockres)); >> >> /* End the line */ >> seq_printf(m, "\n"); >> diff --git a/fs/ocfs2/ocfs2.h b/fs/ocfs2/ocfs2.h >> index 6d0a77703d0e..99ce40063da6 100644 >> --- a/fs/ocfs2/ocfs2.h >> +++ b/fs/ocfs2/ocfs2.h >> @@ -206,6 +206,7 @@ struct ocfs2_lock_res { >> #ifdef CONFIG_OCFS2_FS_STATS >> struct ocfs2_lock_stats l_lock_prmode; /* PR mode stats */ >> u32 l_lock_refresh; /* Disk refreshes */ >> + u64 l_lock_wait; /* First lock wait time */ >> struct ocfs2_lock_stats l_lock_exmode; /* EX mode stats */ >> #endif >> #ifdef CONFIG_DEBUG_LOCK_ALLOC >> ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH V4 3/3] ocfs2: add first lock wait time in locking_state 2019-06-12 7:29 ` Gang He @ 2019-06-12 7:45 ` Joseph Qi 0 siblings, 0 replies; 6+ messages in thread From: Joseph Qi @ 2019-06-12 7:45 UTC (permalink / raw) To: Gang He, jlbec, mark; +Cc: akpm, ocfs2-devel, linux-kernel On 19/6/12 15:29, Gang He wrote: > Hello Joseph, > >>>> On 6/12/2019 at 3:03 pm, in message > <fe52ae81-2140-9f68-8ec2-cc7c1fb3bc1a@linux.alibaba.com>, Joseph Qi > <joseph.qi@linux.alibaba.com> wrote: >> Hi Gang, >> >> On 19/6/11 09:54, Gang He wrote: >>> ocfs2 file system uses locking_state file under debugfs to dump >>> each ocfs2 file system's dlm lock resources, but the users ever >>> encountered some hang(deadlock) problems in ocfs2 file system. >>> I'd like to add first lock wait time in locking_state file, which >>> can help the upper scripts detect these deadlock problems via >>> comparing the first lock wait time with the current time. >>> >>> Signed-off-by: Gang He <ghe@suse.com> >>> --- >>> fs/ocfs2/dlmglue.c | 32 +++++++++++++++++++++++++++++--- >>> fs/ocfs2/ocfs2.h | 1 + >>> 2 files changed, 30 insertions(+), 3 deletions(-) >>> >>> diff --git a/fs/ocfs2/dlmglue.c b/fs/ocfs2/dlmglue.c >>> index d4caa6d117c6..8ce4b76f81ee 100644 >>> --- a/fs/ocfs2/dlmglue.c >>> +++ b/fs/ocfs2/dlmglue.c >>> @@ -440,6 +440,7 @@ static void ocfs2_remove_lockres_tracking(struct >> ocfs2_lock_res *res) >>> static void ocfs2_init_lock_stats(struct ocfs2_lock_res *res) >>> { >>> res->l_lock_refresh = 0; >>> + res->l_lock_wait = 0; >>> memset(&res->l_lock_prmode, 0, sizeof(struct ocfs2_lock_stats)); >>> memset(&res->l_lock_exmode, 0, sizeof(struct ocfs2_lock_stats)); >>> } >>> @@ -483,6 +484,21 @@ static inline void ocfs2_track_lock_refresh(struct >> ocfs2_lock_res *lockres) >>> lockres->l_lock_refresh++; >>> } >>> >>> +static inline void ocfs2_track_lock_wait(struct ocfs2_lock_res *lockres) >>> +{ >>> + struct ocfs2_mask_waiter *mw; >>> + >>> + if (list_empty(&lockres->l_mask_waiters)) { >>> + lockres->l_lock_wait = 0; >>> + return; >>> + } >>> + >>> + mw = list_first_entry(&lockres->l_mask_waiters, >>> + struct ocfs2_mask_waiter, mw_item); >>> + lockres->l_lock_wait = >>> + ktime_to_us(ktime_mono_to_real(mw->mw_lock_start)); >> >> I wonder why ktime_mono_to_real() here? > The new item l_lock_wait is a statistic (or debugging) related, which will be dumping to the user-space via debugfs file locking_state for the further analysis if need. > As the last comments from Wengang, the dumping is from different nodes in the cluster, it is better to use wall time (instead of mono or boot time) to display the related absolute times. > Of course, the existing delta time (use mono time) will not affected. > > Thanks > Gang > Got it, Reviewed-by: Joseph Qi <joseph.qi@linux.alibaba.com> >> >> Thanks, >> Joseph >> >>> +} >>> + >>> static inline void ocfs2_init_start_time(struct ocfs2_mask_waiter *mw) >>> { >>> mw->mw_lock_start = ktime_get(); >>> @@ -498,6 +514,9 @@ static inline void ocfs2_update_lock_stats(struct >> ocfs2_lock_res *res, >>> static inline void ocfs2_track_lock_refresh(struct ocfs2_lock_res *lockres) >>> { >>> } >>> +static inline void ocfs2_track_lock_wait(struct ocfs2_lock_res *lockres) >>> +{ >>> +} >>> static inline void ocfs2_init_start_time(struct ocfs2_mask_waiter *mw) >>> { >>> } >>> @@ -891,6 +910,7 @@ static void lockres_set_flags(struct ocfs2_lock_res >> *lockres, >>> list_del_init(&mw->mw_item); >>> mw->mw_status = 0; >>> complete(&mw->mw_complete); >>> + ocfs2_track_lock_wait(lockres); >>> } >>> } >>> static void lockres_or_flags(struct ocfs2_lock_res *lockres, unsigned long >> or) >>> @@ -1402,6 +1422,7 @@ static void lockres_add_mask_waiter(struct >> ocfs2_lock_res *lockres, >>> list_add_tail(&mw->mw_item, &lockres->l_mask_waiters); >>> mw->mw_mask = mask; >>> mw->mw_goal = goal; >>> + ocfs2_track_lock_wait(lockres); >>> } >>> >>> /* returns 0 if the mw that was removed was already satisfied, -EBUSY >>> @@ -1418,6 +1439,7 @@ static int __lockres_remove_mask_waiter(struct >> ocfs2_lock_res *lockres, >>> >>> list_del_init(&mw->mw_item); >>> init_completion(&mw->mw_complete); >>> + ocfs2_track_lock_wait(lockres); >>> } >>> >>> return ret; >>> @@ -3098,7 +3120,7 @@ static void *ocfs2_dlm_seq_next(struct seq_file *m, >> void *v, loff_t *pos) >>> * New in version 3 >>> * - Max time in lock stats is in usecs (instead of nsecs) >>> * New in version 4 >>> - * - Add last pr/ex unlock times in usecs >>> + * - Add last pr/ex unlock times and first lock wait time in usecs >>> */ >>> #define OCFS2_DLM_DEBUG_STR_VERSION 4 >>> static int ocfs2_dlm_seq_show(struct seq_file *m, void *v) >>> @@ -3116,7 +3138,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void >> *v) >>> return -EINVAL; >>> >>> #ifdef CONFIG_OCFS2_FS_STATS >>> - if (dlm_debug->d_filter_secs) { >>> + if (!lockres->l_lock_wait && dlm_debug->d_filter_secs) { >>> now = ktime_to_us(ktime_get_real()); >>> if (lockres->l_lock_prmode.ls_last > >>> lockres->l_lock_exmode.ls_last) >>> @@ -3177,6 +3199,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void >> *v) >>> # define lock_refresh(_l) ((_l)->l_lock_refresh) >>> # define lock_last_prmode(_l) ((_l)->l_lock_prmode.ls_last) >>> # define lock_last_exmode(_l) ((_l)->l_lock_exmode.ls_last) >>> +# define lock_wait(_l) ((_l)->l_lock_wait) >>> #else >>> # define lock_num_prmode(_l) (0) >>> # define lock_num_exmode(_l) (0) >>> @@ -3189,6 +3212,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void >> *v) >>> # define lock_refresh(_l) (0) >>> # define lock_last_prmode(_l) (0ULL) >>> # define lock_last_exmode(_l) (0ULL) >>> +# define lock_wait(_l) (0ULL) >>> #endif >>> /* The following seq_print was added in version 2 of this output */ >>> seq_printf(m, "%u\t" >>> @@ -3201,6 +3225,7 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void >> *v) >>> "%u\t" >>> "%u\t" >>> "%llu\t" >>> + "%llu\t" >>> "%llu\t", >>> lock_num_prmode(lockres), >>> lock_num_exmode(lockres), >>> @@ -3212,7 +3237,8 @@ static int ocfs2_dlm_seq_show(struct seq_file *m, void >> *v) >>> lock_max_exmode(lockres), >>> lock_refresh(lockres), >>> lock_last_prmode(lockres), >>> - lock_last_exmode(lockres)); >>> + lock_last_exmode(lockres), >>> + lock_wait(lockres)); >>> >>> /* End the line */ >>> seq_printf(m, "\n"); >>> diff --git a/fs/ocfs2/ocfs2.h b/fs/ocfs2/ocfs2.h >>> index 6d0a77703d0e..99ce40063da6 100644 >>> --- a/fs/ocfs2/ocfs2.h >>> +++ b/fs/ocfs2/ocfs2.h >>> @@ -206,6 +206,7 @@ struct ocfs2_lock_res { >>> #ifdef CONFIG_OCFS2_FS_STATS >>> struct ocfs2_lock_stats l_lock_prmode; /* PR mode stats */ >>> u32 l_lock_refresh; /* Disk refreshes */ >>> + u64 l_lock_wait; /* First lock wait time */ >>> struct ocfs2_lock_stats l_lock_exmode; /* EX mode stats */ >>> #endif >>> #ifdef CONFIG_DEBUG_LOCK_ALLOC >>> ^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2019-06-12 7:45 UTC | newest] Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2019-06-11 1:54 [PATCH V4 1/3] ocfs2: add last unlock times in locking_state Gang He 2019-06-11 1:54 ` [PATCH V4 2/3] ocfs2: add locking filter debugfs file Gang He 2019-06-11 1:54 ` [PATCH V4 3/3] ocfs2: add first lock wait time in locking_state Gang He 2019-06-12 7:03 ` Joseph Qi 2019-06-12 7:29 ` Gang He 2019-06-12 7:45 ` Joseph Qi
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox
all inboxes | Powered by JetHome®