From 50baa82e334c7e5c2323d6e01309d922d67e01fd Mon Sep 17 00:00:00 2001 From: Shaun Tancheff Date: Wed, 18 Oct 2023 04:27:10 -0500 Subject: [PATCH] LU-16314 debug: Enable optional unhashed pointers This patch takes a page out of the kernel trace debug playbook to rewrite format strings and change %p -> %px on-the-fly when: libcfs_debug_raw_pointers is enabled. The module parameter can be viewed and modified by root via lctl: lctl get_param debug_raw_pointers lctl set_param debug_raw_pointers=1 Since nothing uses the return value from libcfs_debug_msg change it to void. Use percpu pre-allocated buffers for holding modified format strings to avoid kmalloc/kfree as well as avoid bloating stack usage. HPE-bug-id: LUS-10945 Signed-off-by: Shaun Tancheff Change-Id: I63d90d614ce4435b07f5e84991a12ae7351ac2bb Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/51877 Tested-by: jenkins Tested-by: Maloo Reviewed-by: Oleg Drokin Reviewed-by: Andreas Dilger Reviewed-by: Petros Koutoupis --- libcfs/include/libcfs/libcfs_debug.h | 10 +- libcfs/libcfs/tracefile.c | 192 +++++++++++++++++++++++++++++++++-- lustre/obdclass/obd_sysfs.c | 50 +++++++-- lustre/tests/test-framework.sh | 11 +- 4 files changed, 247 insertions(+), 16 deletions(-) diff --git a/libcfs/include/libcfs/libcfs_debug.h b/libcfs/include/libcfs/libcfs_debug.h index 404bc45..12a61e6 100644 --- a/libcfs/include/libcfs/libcfs_debug.h +++ b/libcfs/include/libcfs/libcfs_debug.h @@ -64,6 +64,12 @@ void libcfs_debug_dumpstack(struct task_struct *tsk); /* Has there been an LBUG? */ extern unsigned int libcfs_catastrophe; extern unsigned int libcfs_panic_on_lbug; +extern bool libcfs_debug_raw_pointers; + +int debug_format_buffer_alloc_buffers(void); +void debug_format_buffer_free_buffers(void); +bool get_debug_raw_pointers(void); +void set_debug_raw_pointers(bool value); #ifndef DEBUG_SUBSYSTEM # define DEBUG_SUBSYSTEM S_UNDEFINED @@ -176,8 +182,8 @@ static inline int cfs_cdebug_show(unsigned int mask, unsigned int subsystem) #define LCONSOLE_EMERG(format, ...) \ CDEBUG(D_CONSOLE | D_EMERG, format, ## __VA_ARGS__) -int libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, - const char *format1, ...) +void libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, + const char *format1, ...) __printf(2, 3); /* other external symbols that tracefile provides: */ diff --git a/libcfs/libcfs/tracefile.c b/libcfs/libcfs/tracefile.c index 00a68b3..1085e14 100644 --- a/libcfs/libcfs/tracefile.c +++ b/libcfs/libcfs/tracefile.c @@ -374,8 +374,185 @@ static void cfs_print_to_console(struct ptldebug_header *hdr, int mask, cfs_vprint_to_console(hdr, mask, &vaf, file, fn); } -int libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, - const char *format, ...) +#define DEBUG_FORMAT_BUFFER_SIZE (256 - sizeof(unsigned long)) + +struct debug_format_buffer { + unsigned long dfb_flags; + char dfb_buf[DEBUG_FORMAT_BUFFER_SIZE]; +}; +struct pcpu_format_pool { + struct debug_format_buffer pf_dfb[4096 / DEBUG_FORMAT_BUFFER_SIZE]; +}; + +enum pool_flags { + PF_INUSE, +}; + +static struct pcpu_format_pool __percpu *debug_format_pool; + +int debug_format_buffer_alloc_buffers(void) +{ + struct pcpu_format_pool __percpu *obj; + struct pcpu_format_pool *pbuf; + int cpu; + + obj = alloc_percpu(struct pcpu_format_pool); + if (!obj) + return -ENOMEM; + for_each_possible_cpu(cpu) { + pbuf = per_cpu_ptr(obj, cpu); + memset(pbuf, 0, sizeof(*pbuf)); + } + debug_format_pool = obj; + + return 0; +} +EXPORT_SYMBOL(debug_format_buffer_alloc_buffers); + +void debug_format_buffer_free_buffers(void) +{ + struct pcpu_format_pool __percpu *tmp = debug_format_pool; + struct pcpu_format_pool *pbuf; + int cpu; + int i; + + if (!debug_format_pool) + return; + + debug_format_pool = NULL; + synchronize_rcu(); + + for_each_possible_cpu(cpu) { + pbuf = per_cpu_ptr(tmp, cpu); + for (i = 0; i < ARRAY_SIZE(pbuf->pf_dfb); i++) + set_bit(PF_INUSE, &pbuf->pf_dfb[i].dfb_flags); + } + free_percpu(tmp); +} +EXPORT_SYMBOL(debug_format_buffer_free_buffers); + +bool libcfs_debug_raw_pointers; + +bool get_debug_raw_pointers(void) +{ + return libcfs_debug_raw_pointers; +} +EXPORT_SYMBOL(get_debug_raw_pointers); + +void set_debug_raw_pointers(bool value) +{ + libcfs_debug_raw_pointers = value; +} +EXPORT_SYMBOL(set_debug_raw_pointers); + +#ifndef raw_cpu_ptr +#define raw_cpu_ptr(p) this_cpu_ptr(p) +#endif + +static struct debug_format_buffer *debug_format_buffer_get_locked(void) +{ + struct debug_format_buffer *dfb = NULL; + struct pcpu_format_pool *pbuf; + int i; + + if (!debug_format_pool) + return NULL; + + pbuf = raw_cpu_ptr(debug_format_pool); + for (i = 0; i < ARRAY_SIZE(pbuf->pf_dfb); i++) { + if (!test_and_set_bit(PF_INUSE, &pbuf->pf_dfb[i].dfb_flags)) { + dfb = &pbuf->pf_dfb[i]; + break; + } + } + return dfb; +} + +static void debug_format_buffer_put_locked(struct debug_format_buffer *dfb) +{ + if (!debug_format_pool || !dfb) + return; + clear_bit(PF_INUSE, &dfb->dfb_flags); +} + +/* return number of %p to %px replacements or < 0 on error */ +static bool rewrite_format(const char *fmt, size_t nfsz, char *new_fmt) +{ + const char *p = fmt; + char *q = new_fmt; + int written = 0; + int unhashed = 0; + + if (WARN_ON_ONCE(!fmt)) + return 0; + + p = fmt; + q = new_fmt; + while (*p) { + if (written + 2 >= nfsz) + return false; + + *q++ = *p++; + written++; + + /* Replace %p with %px */ + if (p[-1] == '%') { + if (p[0] == '%') { + if (written + 2 >= nfsz) + return false; + *q++ = *p++; + written++; + } else if (p[0] == 'p' && !isalnum(p[1])) { + if (written + 3 >= nfsz) + return false; + *q++ = *p++; + *q++ = 'x'; + written += 2; + unhashed++; + } + } + } + *q = '\0'; + + return unhashed > 0; +} + +/* + * @fmt: caller provided format string + * @m: if non-null points to per-cpu object + * + * return result is format string to use, it will be either: + * fmt: when no changes need to be made to original format + * *m->dfb_buf: when percpu pre-allocated is sufficient to hold updated format + */ +static inline const char *debug_format(const char *fmt, + struct debug_format_buffer **m) +{ + struct debug_format_buffer *dfb_fmt; + + *m = NULL; + if (likely(!libcfs_debug_raw_pointers)) + return fmt; + if (!strstr(fmt, "%p")) + return fmt; + + /* try to rewrite format into buf */ + dfb_fmt = debug_format_buffer_get_locked(); + if (dfb_fmt) { + size_t len = sizeof(dfb_fmt->dfb_buf) - 1; + + if (rewrite_format(fmt, len, dfb_fmt->dfb_buf)) { + *m = dfb_fmt; + return dfb_fmt->dfb_buf; + } + debug_format_buffer_put_locked(dfb_fmt); + } + + return fmt; +} + +void libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, + const char *format, ...) { struct cfs_trace_cpu_data *tcd = NULL; struct ptldebug_header header = {0}; @@ -391,6 +568,9 @@ int libcfs_debug_msg(struct libcfs_debug_msg_data *msgdata, int mask = msgdata->msg_mask; char *file = (char *)msgdata->msg_file; struct cfs_debug_limit_state *cdls = msgdata->msg_cdls; + struct debug_format_buffer *dfb = NULL; + + format = debug_format(format, &dfb); if (strchr(file, '/')) file = strrchr(file, '/') + 1; @@ -500,7 +680,7 @@ console: /* no console output requested */ if (tcd != NULL) cfs_trace_put_tcd(tcd); - return 1; + goto out; } if (cdls != NULL) { @@ -511,7 +691,7 @@ console: cdls->cdls_count++; if (tcd != NULL) cfs_trace_put_tcd(tcd); - return 1; + goto out; } if (time_after(jiffies, cdls->cdls_next + @@ -556,8 +736,8 @@ console: cdls->cdls_count = 0; } - - return 0; +out: + debug_format_buffer_put_locked(dfb); } EXPORT_SYMBOL(libcfs_debug_msg); diff --git a/lustre/obdclass/obd_sysfs.c b/lustre/obdclass/obd_sysfs.c index d0f09aa..2da1aa7 100644 --- a/lustre/obdclass/obd_sysfs.c +++ b/lustre/obdclass/obd_sysfs.c @@ -423,6 +423,41 @@ static ssize_t timeout_store(struct kobject *kobj, return count; } +static ssize_t debug_raw_pointers_show(struct kobject *kobj, + struct attribute *attr, + char *buf) +{ + return scnprintf(buf, PAGE_SIZE, "%d\n", get_debug_raw_pointers()); +} + +static ssize_t debug_raw_pointers_store(struct kobject *kobj, + struct attribute *attr, + const char *buffer, + size_t count) +{ + bool initial = get_debug_raw_pointers(); + bool val; + int rc; + + rc = kstrtobool(buffer, &val); + if (rc) + return rc; + + if ((initial && val) || (!initial && !val)) + return count; + + if (val) { + rc = debug_format_buffer_alloc_buffers(); + if (rc) + return rc; + } else { + debug_format_buffer_free_buffers(); + } + set_debug_raw_pointers(val); + + return count; +} + /* Root for /sys/kernel/debug/lustre */ struct dentry *debugfs_lustre_root; EXPORT_SYMBOL_GPL(debugfs_lustre_root); @@ -442,6 +477,7 @@ LUSTRE_RW_ATTR(jobid_var); LUSTRE_RW_ATTR(jobid_name); LUSTRE_RW_ATTR(jobid_this_session); LUSTRE_RW_ATTR(timeout); +LUSTRE_RW_ATTR(debug_raw_pointers); static struct attribute *lustre_attrs[] = { &lustre_attr_version.attr, @@ -452,6 +488,7 @@ static struct attribute *lustre_attrs[] = { &lustre_attr_jobid_var.attr, &lustre_attr_jobid_this_session.attr, &lustre_attr_timeout.attr, + &lustre_attr_debug_raw_pointers.attr, &lustre_attr_max_dirty_mb.attr, &lustre_sattr_debug_peer_on_timeout.u.attr, &lustre_sattr_dump_on_timeout.u.attr, @@ -702,7 +739,6 @@ ssize_t class_set_global(const char *param) int class_procfs_init(void) { struct proc_dir_entry *entry; - struct dentry *file; int rc = -ENOMEM; ENTRY; @@ -726,14 +762,14 @@ int class_procfs_init(void) debugfs_lustre_root = debugfs_create_dir("lustre", NULL); - file = debugfs_create_file("devices", 0444, debugfs_lustre_root, NULL, - &obd_device_list_fops); + debugfs_create_file("devices", 0444, debugfs_lustre_root, NULL, + &obd_device_list_fops); - file = debugfs_create_file("health_check", 0444, debugfs_lustre_root, - NULL, &health_check_fops); + debugfs_create_file("health_check", 0444, debugfs_lustre_root, + NULL, &health_check_fops); - file = debugfs_create_file("checksum_speed", 0444, debugfs_lustre_root, - NULL, &checksum_speed_fops); + debugfs_create_file("checksum_speed", 0444, debugfs_lustre_root, + NULL, &checksum_speed_fops); entry = lprocfs_register("fs/lustre", NULL, NULL, NULL); if (IS_ERR(entry)) { diff --git a/lustre/tests/test-framework.sh b/lustre/tests/test-framework.sh index 430e1ea..8317560 100755 --- a/lustre/tests/test-framework.sh +++ b/lustre/tests/test-framework.sh @@ -7332,11 +7332,15 @@ run_one_logged() { local rc=0 local node declare -A kptr_restrict + declare -A debug_raw umask 0022 for node in $(all_nodes); do kptr_restrict[$node]=$(do_node $node "sysctl --values kernel/kptr_restrict") do_node $node "sysctl -wq kernel/kptr_restrict=1" + # Enable %p to be unhashed (if supported) + debug_raw[$node]=$(do_node $node "$LCTL get_param -n debug_raw_pointers" || echo 0) + do_node $node "$LCTL set_param debug_raw_pointers=Y || true" done rm -f $LOGDIR/err $LOGDIR/ignore $LOGDIR/skip @@ -7385,8 +7389,13 @@ run_one_logged() { [[ $rc != 0 || "$TEST_STATUS" != "PASS" ]] && break done + local param for node in $(all_nodes); do - do_node $node "sysctl -wq kernel/kptr_restrict=${kptr_restrict[$node]}" + param="kernel/kptr_restrict=${kptr_restrict[$node]}" + do_node $node "sysctl -wq ${param} || true" + # Restore %p to initial state + param="debug_raw_pointers=${debug_raw[$node]}" + do_node $node "$LCTL set_param ${param} || true" done if [[ "$TEST_STATUS" != "SKIP" && -f $TF_SKIP ]]; then -- 1.8.3.1