Whamcloud - gitweb
LU-16314 debug: Enable optional unhashed pointers 77/51877/15
authorShaun Tancheff <shaun.tancheff@hpe.com>
Wed, 18 Oct 2023 09:27:10 +0000 (04:27 -0500)
committerOleg Drokin <green@whamcloud.com>
Thu, 15 Feb 2024 07:05:55 +0000 (07:05 +0000)
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 <shaun.tancheff@hpe.com>
Change-Id: I63d90d614ce4435b07f5e84991a12ae7351ac2bb
Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/51877
Tested-by: jenkins <devops@whamcloud.com>
Tested-by: Maloo <maloo@whamcloud.com>
Reviewed-by: Oleg Drokin <green@whamcloud.com>
Reviewed-by: Andreas Dilger <adilger@whamcloud.com>
Reviewed-by: Petros Koutoupis <petros.koutoupis@hpe.com>
libcfs/include/libcfs/libcfs_debug.h
libcfs/libcfs/tracefile.c
lustre/obdclass/obd_sysfs.c
lustre/tests/test-framework.sh

index 404bc45..12a61e6 100644 (file)
@@ -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: */
index 00a68b3..1085e14 100644 (file)
@@ -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);
 
index d0f09aa..2da1aa7 100644 (file)
@@ -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)) {
index 430e1ea..8317560 100755 (executable)
@@ -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