[Cluster-devel] [PATCH dlm/next 1/3] fs: change ast and bast trace order

[Cluster-devel] [PATCH dlm/next 1/3] fs: change ast and bast trace order

[Alexander Aring]

This patch changes the order to call trace functionality before calling
the traced callback. The intention is always to see at first that a dlm
callback occurred and then optionally see dlm user traces in the ast or
bast callback. Currently the behaviour is vice versa, the user sees that
dlm ast or bast callback occurred after the dlm user callback for ast or
bast was called.

Signed-off-by: Alexander Aring <aahringo@redhat.com>
---
 fs/dlm/ast.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/fs/dlm/ast.c b/fs/dlm/ast.c
index bfac462dd3e8..df25c3e785cf 100644
--- a/fs/dlm/ast.c
+++ b/fs/dlm/ast.c
@@ -255,13 +255,13 @@ void dlm_callback_work(struct work_struct *work)
 		if (callbacks[i].flags & DLM_CB_SKIP) {
 			continue;
 		} else if (callbacks[i].flags & DLM_CB_BAST) {
-			bastfn(lkb->lkb_astparam, callbacks[i].mode);
 			trace_dlm_bast(ls, lkb, callbacks[i].mode);
+			bastfn(lkb->lkb_astparam, callbacks[i].mode);
 		} else if (callbacks[i].flags & DLM_CB_CAST) {
 			lkb->lkb_lksb->sb_status = callbacks[i].sb_status;
 			lkb->lkb_lksb->sb_flags = callbacks[i].sb_flags;
-			castfn(lkb->lkb_astparam);
 			trace_dlm_ast(ls, lkb, lkb->lkb_lksb);
+			castfn(lkb->lkb_astparam);
 		}
 	}
 
-- 
2.31.1

[Cluster-devel] [PATCH dlm/next 2/3] fs: remove additional dereference of lkbsb

[Alexander Aring]

This patch removes a dereference of lkbsb of lkb when calling ast
tracepoint. First it reduces additional overhead, even if traces are not
acitivated. Second we can deference it in TP_fast_assign over the
already passed lkb parameter.

Signed-off-by: Alexander Aring <aahringo@redhat.com>
---
 fs/dlm/ast.c               | 2 +-
 include/trace/events/dlm.h | 8 ++++----
 2 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/fs/dlm/ast.c b/fs/dlm/ast.c
index df25c3e785cf..19ef136f9e4f 100644
--- a/fs/dlm/ast.c
+++ b/fs/dlm/ast.c
@@ -260,7 +260,7 @@ void dlm_callback_work(struct work_struct *work)
 		} else if (callbacks[i].flags & DLM_CB_CAST) {
 			lkb->lkb_lksb->sb_status = callbacks[i].sb_status;
 			lkb->lkb_lksb->sb_flags = callbacks[i].sb_flags;
-			trace_dlm_ast(ls, lkb, lkb->lkb_lksb);
+			trace_dlm_ast(ls, lkb);
 			castfn(lkb->lkb_astparam);
 		}
 	}
diff --git a/include/trace/events/dlm.h b/include/trace/events/dlm.h
index 32088c603244..e333176ecfaf 100644
--- a/include/trace/events/dlm.h
+++ b/include/trace/events/dlm.h
@@ -138,9 +138,9 @@ TRACE_EVENT(dlm_bast,
 
 TRACE_EVENT(dlm_ast,
 
-	TP_PROTO(struct dlm_ls *ls, struct dlm_lkb *lkb, struct dlm_lksb *lksb),
+	TP_PROTO(struct dlm_ls *ls, struct dlm_lkb *lkb),
 
-	TP_ARGS(ls, lkb, lksb),
+	TP_ARGS(ls, lkb),
 
 	TP_STRUCT__entry(
 		__field(__u32, ls_id)
@@ -152,8 +152,8 @@ TRACE_EVENT(dlm_ast,
 	TP_fast_assign(
 		__entry->ls_id = ls->ls_global_id;
 		__entry->lkb_id = lkb->lkb_id;
-		__entry->sb_flags = lksb->sb_flags;
-		__entry->sb_status = lksb->sb_status;
+		__entry->sb_flags = lkb->lkb_lksb->sb_flags;
+		__entry->sb_status = lkb->lkb_lksb->sb_status;
 	),
 
 	TP_printk("ls_id=%u lkb_id=%x sb_flags=%s sb_status=%d",
-- 
2.31.1

[Cluster-devel] [PATCH dlm/next 3/3] fs: dlm: add resource name to tracepoints

[Alexander Aring]

This patch adds the resource name to dlm tracepoints. In case of
dlm_lock() we might end in a short time situation (if flags is not
convert) that a lkb is not associated with a resource at the time
when the tracepoint is called. Therefore we have a a prioritzation of
getting the resource name. If the resource in a lkb isn't set we use the
name and namelen passed as parameter as fallback.

The dlm resource name can be decoded as a string representated ascii
codec. DLM itself stores the name with as a null terminated array but
the user does not required to pass a null terminated resource name. To
have somehow a similar behaviour and the user knows that the resource
name of the dlm user is ascii codec we store the resource name array in
a null terminated array but pass the array length for the trace user
without the null terminated byte. The advantage here is that the user
can run directly a printf() on the resource name array with a optional
check on isascii().

The TP_printk() call however use always a hexadecimal string
representation for the resource name array.

Signed-off-by: Alexander Aring <aahringo@redhat.com>
---
 fs/dlm/lock.c              |   4 +-
 include/trace/events/dlm.h | 134 ++++++++++++++++++++++++++++++++-----
 2 files changed, 118 insertions(+), 20 deletions(-)

diff --git a/fs/dlm/lock.c b/fs/dlm/lock.c
index 226822f49d30..e80d42ba64ae 100644
--- a/fs/dlm/lock.c
+++ b/fs/dlm/lock.c
@@ -3472,7 +3472,7 @@ int dlm_lock(dlm_lockspace_t *lockspace,
 	if (error)
 		goto out;
 
-	trace_dlm_lock_start(ls, lkb, mode, flags);
+	trace_dlm_lock_start(ls, lkb, name, namelen, mode, flags);
 
 	error = set_lock_args(mode, lksb, flags, namelen, 0, ast,
 			      astarg, bast, &args);
@@ -3487,7 +3487,7 @@ int dlm_lock(dlm_lockspace_t *lockspace,
 	if (error == -EINPROGRESS)
 		error = 0;
  out_put:
-	trace_dlm_lock_end(ls, lkb, mode, flags, error);
+	trace_dlm_lock_end(ls, lkb, name, namelen, mode, flags, error);
 
 	if (convert || error)
 		__put_lkb(ls, lkb);
diff --git a/include/trace/events/dlm.h b/include/trace/events/dlm.h
index e333176ecfaf..180a24481929 100644
--- a/include/trace/events/dlm.h
+++ b/include/trace/events/dlm.h
@@ -49,38 +49,56 @@
 /* note: we begin tracing dlm_lock_start() only if ls and lkb are found */
 TRACE_EVENT(dlm_lock_start,
 
-	TP_PROTO(struct dlm_ls *ls, struct dlm_lkb *lkb, int mode,
-		 __u32 flags),
+	TP_PROTO(struct dlm_ls *ls, struct dlm_lkb *lkb, void *name,
+		 unsigned int namelen, int mode, __u32 flags),
 
-	TP_ARGS(ls, lkb, mode, flags),
+	TP_ARGS(ls, lkb, name, namelen, mode, flags),
 
 	TP_STRUCT__entry(
 		__field(__u32, ls_id)
 		__field(__u32, lkb_id)
 		__field(int, mode)
 		__field(__u32, flags)
+		__dynamic_array(unsigned char, res_name,
+				lkb->lkb_resource ? lkb->lkb_resource->res_length + 1 : namelen + 1)
 	),
 
 	TP_fast_assign(
+		struct dlm_rsb *r;
+		char *c;
+
 		__entry->ls_id = ls->ls_global_id;
 		__entry->lkb_id = lkb->lkb_id;
 		__entry->mode = mode;
 		__entry->flags = flags;
+
+		r = lkb->lkb_resource;
+		if (r)
+			memcpy(__get_dynamic_array(res_name), r->res_name,
+			       __get_dynamic_array_len(res_name));
+		else if (name)
+			memcpy(__get_dynamic_array(res_name), name,
+			       __get_dynamic_array_len(res_name));
+
+		c = __get_dynamic_array(res_name);
+		c[__get_dynamic_array_len(res_name) - 1] = '\0';
 	),
 
-	TP_printk("ls_id=%u lkb_id=%x mode=%s flags=%s",
+	TP_printk("ls_id=%u lkb_id=%x mode=%s flags=%s res_name=%s",
 		  __entry->ls_id, __entry->lkb_id,
 		  show_lock_mode(__entry->mode),
-		  show_lock_flags(__entry->flags))
+		  show_lock_flags(__entry->flags),
+		  __print_hex_str(__get_dynamic_array(res_name),
+				  __get_dynamic_array_len(res_name)))
 
 );
 
 TRACE_EVENT(dlm_lock_end,
 
-	TP_PROTO(struct dlm_ls *ls, struct dlm_lkb *lkb, int mode, __u32 flags,
-		 int error),
+	TP_PROTO(struct dlm_ls *ls, struct dlm_lkb *lkb, void *name,
+		 unsigned int namelen, int mode, __u32 flags, int error),
 
-	TP_ARGS(ls, lkb, mode, flags, error),
+	TP_ARGS(ls, lkb, name, namelen, mode, flags, error),
 
 	TP_STRUCT__entry(
 		__field(__u32, ls_id)
@@ -88,14 +106,30 @@ TRACE_EVENT(dlm_lock_end,
 		__field(int, mode)
 		__field(__u32, flags)
 		__field(int, error)
+		__dynamic_array(unsigned char, res_name,
+				lkb->lkb_resource ? lkb->lkb_resource->res_length + 1 : namelen + 1)
 	),
 
 	TP_fast_assign(
+		struct dlm_rsb *r;
+		char *c;
+
 		__entry->ls_id = ls->ls_global_id;
 		__entry->lkb_id = lkb->lkb_id;
 		__entry->mode = mode;
 		__entry->flags = flags;
 
+		r = lkb->lkb_resource;
+		if (r)
+			memcpy(__get_dynamic_array(res_name), r->res_name,
+			       __get_dynamic_array_len(res_name));
+		else if (name)
+			memcpy(__get_dynamic_array(res_name), name,
+			       __get_dynamic_array_len(res_name));
+
+		c = __get_dynamic_array(res_name);
+		c[__get_dynamic_array_len(res_name) - 1] = '\0';
+
 		/* return value will be zeroed in those cases by dlm_lock()
 		 * we do it here again to not introduce more overhead if
 		 * trace isn't running and error reflects the return value.
@@ -104,12 +138,15 @@ TRACE_EVENT(dlm_lock_end,
 			__entry->error = 0;
 		else
 			__entry->error = error;
+
 	),
 
-	TP_printk("ls_id=%u lkb_id=%x mode=%s flags=%s error=%d",
+	TP_printk("ls_id=%u lkb_id=%x mode=%s flags=%s error=%d res_name=%s",
 		  __entry->ls_id, __entry->lkb_id,
 		  show_lock_mode(__entry->mode),
-		  show_lock_flags(__entry->flags), __entry->error)
+		  show_lock_flags(__entry->flags), __entry->error,
+		  __print_hex_str(__get_dynamic_array(res_name),
+				  __get_dynamic_array_len(res_name)))
 
 );
 
@@ -123,16 +160,32 @@ TRACE_EVENT(dlm_bast,
 		__field(__u32, ls_id)
 		__field(__u32, lkb_id)
 		__field(int, mode)
+		__dynamic_array(unsigned char, res_name,
+				lkb->lkb_resource ? lkb->lkb_resource->res_length + 1 : 1)
 	),
 
 	TP_fast_assign(
+		struct dlm_rsb *r;
+		char *c;
+
 		__entry->ls_id = ls->ls_global_id;
 		__entry->lkb_id = lkb->lkb_id;
 		__entry->mode = mode;
+
+		r = lkb->lkb_resource;
+		if (r)
+			memcpy(__get_dynamic_array(res_name), r->res_name,
+			       __get_dynamic_array_len(res_name));
+
+		c = __get_dynamic_array(res_name);
+		c[__get_dynamic_array_len(res_name) - 1] = '\0';
 	),
 
-	TP_printk("ls_id=%u lkb_id=%x mode=%s", __entry->ls_id,
-		  __entry->lkb_id, show_lock_mode(__entry->mode))
+	TP_printk("ls_id=%u lkb_id=%x mode=%s res_name=%s",
+		  __entry->ls_id, __entry->lkb_id,
+		  show_lock_mode(__entry->mode),
+		  __print_hex_str(__get_dynamic_array(res_name),
+				  __get_dynamic_array_len(res_name)))
 
 );
 
@@ -147,18 +200,33 @@ TRACE_EVENT(dlm_ast,
 		__field(__u32, lkb_id)
 		__field(u8, sb_flags)
 		__field(int, sb_status)
+		__dynamic_array(unsigned char, res_name,
+				lkb->lkb_resource ? lkb->lkb_resource->res_length + 1 : 1)
 	),
 
 	TP_fast_assign(
+		struct dlm_rsb *r;
+		char *c;
+
 		__entry->ls_id = ls->ls_global_id;
 		__entry->lkb_id = lkb->lkb_id;
 		__entry->sb_flags = lkb->lkb_lksb->sb_flags;
 		__entry->sb_status = lkb->lkb_lksb->sb_status;
+
+		r = lkb->lkb_resource;
+		if (r)
+			memcpy(__get_dynamic_array(res_name), r->res_name,
+			       __get_dynamic_array_len(res_name));
+
+		c = __get_dynamic_array(res_name);
+		c[__get_dynamic_array_len(res_name) - 1] = '\0';
 	),
 
-	TP_printk("ls_id=%u lkb_id=%x sb_flags=%s sb_status=%d",
+	TP_printk("ls_id=%u lkb_id=%x sb_flags=%s sb_status=%d res_name=%s",
 		  __entry->ls_id, __entry->lkb_id,
-		  show_dlm_sb_flags(__entry->sb_flags), __entry->sb_status)
+		  show_dlm_sb_flags(__entry->sb_flags), __entry->sb_status,
+		  __print_hex_str(__get_dynamic_array(res_name),
+				  __get_dynamic_array_len(res_name)))
 
 );
 
@@ -173,17 +241,32 @@ TRACE_EVENT(dlm_unlock_start,
 		__field(__u32, ls_id)
 		__field(__u32, lkb_id)
 		__field(__u32, flags)
+		__dynamic_array(unsigned char, res_name,
+				lkb->lkb_resource ? lkb->lkb_resource->res_length + 1 : 1)
 	),
 
 	TP_fast_assign(
+		struct dlm_rsb *r;
+		char *c;
+
 		__entry->ls_id = ls->ls_global_id;
 		__entry->lkb_id = lkb->lkb_id;
 		__entry->flags = flags;
+
+		r = lkb->lkb_resource;
+		if (r)
+			memcpy(__get_dynamic_array(res_name), r->res_name,
+			       __get_dynamic_array_len(res_name));
+
+		c = __get_dynamic_array(res_name);
+		c[__get_dynamic_array_len(res_name) - 1] = '\0';
 	),
 
-	TP_printk("ls_id=%u lkb_id=%x flags=%s",
+	TP_printk("ls_id=%u lkb_id=%x flags=%s res_name=%s",
 		  __entry->ls_id, __entry->lkb_id,
-		  show_lock_flags(__entry->flags))
+		  show_lock_flags(__entry->flags),
+		  __print_hex_str(__get_dynamic_array(res_name),
+				  __get_dynamic_array_len(res_name)))
 
 );
 
@@ -199,18 +282,33 @@ TRACE_EVENT(dlm_unlock_end,
 		__field(__u32, lkb_id)
 		__field(__u32, flags)
 		__field(int, error)
+		__dynamic_array(unsigned char, res_name,
+				lkb->lkb_resource ? lkb->lkb_resource->res_length + 1 : 1)
 	),
 
 	TP_fast_assign(
+		struct dlm_rsb *r;
+		char *c;
+
 		__entry->ls_id = ls->ls_global_id;
 		__entry->lkb_id = lkb->lkb_id;
 		__entry->flags = flags;
 		__entry->error = error;
+
+		r = lkb->lkb_resource;
+		if (r)
+			memcpy(__get_dynamic_array(res_name), r->res_name,
+			       __get_dynamic_array_len(res_name));
+
+		c = __get_dynamic_array(res_name);
+		c[__get_dynamic_array_len(res_name) - 1] = '\0';
 	),
 
-	TP_printk("ls_id=%u lkb_id=%x flags=%s error=%d",
+	TP_printk("ls_id=%u lkb_id=%x flags=%s error=%d res_name=%s",
 		  __entry->ls_id, __entry->lkb_id,
-		  show_lock_flags(__entry->flags), __entry->error)
+		  show_lock_flags(__entry->flags), __entry->error,
+		  __print_hex_str(__get_dynamic_array(res_name),
+				  __get_dynamic_array_len(res_name)))
 
 );
 
-- 
2.31.1

[Cluster-devel] [PATCH dlm/next 3/3] fs: dlm: add resource name to tracepoints

[Alexander Aring]

Hi,

On Mon, May 30, 2022 at 10:55 AM Alexander Aring <aahringo@redhat.com> wrote:
>
> This patch adds the resource name to dlm tracepoints. In case of
> dlm_lock() we might end in a short time situation (if flags is not
> convert) that a lkb is not associated with a resource at the time
> when the tracepoint is called. Therefore we have a a prioritzation of
> getting the resource name. If the resource in a lkb isn't set we use the
> name and namelen passed as parameter as fallback.
>
> The dlm resource name can be decoded as a string representated ascii
> codec. DLM itself stores the name with as a null terminated array but
> the user does not required to pass a null terminated resource name. To
> have somehow a similar behaviour and the user knows that the resource
> name of the dlm user is ascii codec we store the resource name array in
> a null terminated array but pass the array length for the trace user
> without the null terminated byte. The advantage here is that the user
> can run directly a printf() on the resource name array with a optional
> check on isascii().
>
> The TP_printk() call however use always a hexadecimal string
> representation for the resource name array.
>

I forgot to mention here to say something about the rsb lock and
refcount. Regarding the refcount it's stimple, if it's associated with
a lkb, it can't be freed at this time... and the rsb lock, we access
the name here only and I think this should never be changed.

- Alex

[Cluster-devel] [PATCH dlm/next 3/3] fs: dlm: add resource name to tracepoints

[Alexander Aring]

Hi,

On Mon, May 30, 2022 at 10:55 AM Alexander Aring <aahringo@redhat.com> wrote:
>
> This patch adds the resource name to dlm tracepoints. In case of
> dlm_lock() we might end in a short time situation (if flags is not
> convert) that a lkb is not associated with a resource at the time
> when the tracepoint is called. Therefore we have a a prioritzation of
> getting the resource name. If the resource in a lkb isn't set we use the
> name and namelen passed as parameter as fallback.
>
> The dlm resource name can be decoded as a string representated ascii
> codec. DLM itself stores the name with as a null terminated array but
> the user does not required to pass a null terminated resource name. To
> have somehow a similar behaviour and the user knows that the resource
> name of the dlm user is ascii codec we store the resource name array in
> a null terminated array but pass the array length for the trace user
> without the null terminated byte. The advantage here is that the user
> can run directly a printf() on the resource name array with a optional
> check on isascii().
>
> The TP_printk() call however use always a hexadecimal string
> representation for the resource name array.
>
> Signed-off-by: Alexander Aring <aahringo@redhat.com>
> ---
>  fs/dlm/lock.c              |   4 +-
>  include/trace/events/dlm.h | 134 ++++++++++++++++++++++++++++++++-----
>  2 files changed, 118 insertions(+), 20 deletions(-)
>
> diff --git a/fs/dlm/lock.c b/fs/dlm/lock.c
> index 226822f49d30..e80d42ba64ae 100644
> --- a/fs/dlm/lock.c
> +++ b/fs/dlm/lock.c
> @@ -3472,7 +3472,7 @@ int dlm_lock(dlm_lockspace_t *lockspace,
>         if (error)
>                 goto out;
>
> -       trace_dlm_lock_start(ls, lkb, mode, flags);
> +       trace_dlm_lock_start(ls, lkb, name, namelen, mode, flags);
>
>         error = set_lock_args(mode, lksb, flags, namelen, 0, ast,
>                               astarg, bast, &args);
> @@ -3487,7 +3487,7 @@ int dlm_lock(dlm_lockspace_t *lockspace,
>         if (error == -EINPROGRESS)
>                 error = 0;
>   out_put:
> -       trace_dlm_lock_end(ls, lkb, mode, flags, error);
> +       trace_dlm_lock_end(ls, lkb, name, namelen, mode, flags, error);
>
>         if (convert || error)
>                 __put_lkb(ls, lkb);
> diff --git a/include/trace/events/dlm.h b/include/trace/events/dlm.h
> index e333176ecfaf..180a24481929 100644
> --- a/include/trace/events/dlm.h
> +++ b/include/trace/events/dlm.h
> @@ -49,38 +49,56 @@
>  /* note: we begin tracing dlm_lock_start() only if ls and lkb are found */
>  TRACE_EVENT(dlm_lock_start,
>
> -       TP_PROTO(struct dlm_ls *ls, struct dlm_lkb *lkb, int mode,
> -                __u32 flags),
> +       TP_PROTO(struct dlm_ls *ls, struct dlm_lkb *lkb, void *name,
> +                unsigned int namelen, int mode, __u32 flags),
>
> -       TP_ARGS(ls, lkb, mode, flags),
> +       TP_ARGS(ls, lkb, name, namelen, mode, flags),
>
>         TP_STRUCT__entry(
>                 __field(__u32, ls_id)
>                 __field(__u32, lkb_id)
>                 __field(int, mode)
>                 __field(__u32, flags)
> +               __dynamic_array(unsigned char, res_name,
> +                               lkb->lkb_resource ? lkb->lkb_resource->res_length + 1 : namelen + 1)

I will send a v2 series for this. I think we should remove the
additional byte here and let the user handle it to parse it in some
way and add a null termination on its own (if necessary).
The array length in trace api is encoded in their trace UAPI/data
structure, we can't make it ending '\0' and make the array length
without the null termination. Or we add another field for the length
and have two lengths there, whereas one is -1 of the other... sounds
not right.

However..., I will change that again.

The user should not assume to have a '\0' terminated array here,
_whereas_ in dlm_rsb kernel the user can assume it... but can't assume
it's ascii code.

>         ),
>
>         TP_fast_assign(
> +               struct dlm_rsb *r;
> +               char *c;
> +
>                 __entry->ls_id = ls->ls_global_id;
>                 __entry->lkb_id = lkb->lkb_id;
>                 __entry->mode = mode;
>                 __entry->flags = flags;
> +
> +               r = lkb->lkb_resource;
> +               if (r)
> +                       memcpy(__get_dynamic_array(res_name), r->res_name,
> +                              __get_dynamic_array_len(res_name));
> +               else if (name)
> +                       memcpy(__get_dynamic_array(res_name), name,
> +                              __get_dynamic_array_len(res_name));
> +
> +               c = __get_dynamic_array(res_name);
> +               c[__get_dynamic_array_len(res_name) - 1] = '\0';

Hopefully we can remove this then...

>         ),
>
> -       TP_printk("ls_id=%u lkb_id=%x mode=%s flags=%s",
> +       TP_printk("ls_id=%u lkb_id=%x mode=%s flags=%s res_name=%s",
>                   __entry->ls_id, __entry->lkb_id,
>                   show_lock_mode(__entry->mode),
> -                 show_lock_flags(__entry->flags))
> +                 show_lock_flags(__entry->flags),
> +                 __print_hex_str(__get_dynamic_array(res_name),
> +                                 __get_dynamic_array_len(res_name)))

also wrong that it will always print the 00 byte at the end. :-/

- Alex