[PATCH v8 41/43] dyndbg: add +c flag to count advantage of classmaps for DRM

[Jim Cromie via B4 Relay <devnull+jim.cromie.gmail.com@kernel.org>]

From: Jim Cromie <jim.cromie@gmail.com>

Introduce a +c flag, to increment a per-cpu counter: ddebug_count
when a flagged pr_debug() is called.

Reset the counter with:
  echo reset_stats > /proc/dynamic_debug/control

and see the count value with:
  tail -n1 /proc/dynamic_debug/control
  #: total count: 2295401

This counter lets us count drm*dbg() callrate without doing the
printk; it counts how often upstream drm_debug_enabled() would read
main memory, evict a cache-line, and test a bit.

CONFIG_DRM_USE_DYNAMIC_DEBUG=y gives drm a per callsite static-key to
avoid that cache-line insult.  On my amdgpu + nvidia laptop, thats
~3200 of them.

The benchmarks below are from a recent build running on my asus
amdgpu + nouveau laptop, using scripts from below the snip.

  #> count_hits 30 hammer_vk --
  Banging on: hammer_vk (&)
  [1] 100847
  [1]+  Done                       hammer_vk
  #: total hits: 2295401

  #> count_hits 30 hammer_vk -- DRM_UT_CORE
  Banging on: hammer_vk (&)
  [1] 99910
  [1]+  Done                       hammer_vk
  #: total hits: 2204406

Notably, the DRM_UT_CORE category dominates the call traffic, not
DRM_UT_VBL or any others, which contribute little extra to the above.

To see the distribution of debug categories (for vkcube load)

  #> isolate_drm_hits 2> /dev/null
  Starting isolation study: 10s per class using vkcube
  ----------------------------------------------------------
  DRM CLASS            | TOTAL HITS
  ----------------------------------------------------------
  DRM_UT_CORE          | 85305
  DRM_UT_DRIVER        | 0
  DRM_UT_KMS           | 1435
  DRM_UT_PRIME         | 0
  DRM_UT_ATOMIC        | 13645
  DRM_UT_VBL           | 4071
  DRM_UT_STATE         | 1780
  DRM_UT_LEASE         | 0
  DRM_UT_DP            | 0
  DRM_UT_DRMRES        | 0
  FOO                  | 0

REVIEW:

In every minute, 12 vkcubes issue ~4.6M drm_debug_enabled(__drm_debug)
macro-calls.  To test the bits, they all *may* go out to main memory,
though __drm_debug is ro-mostly.  Still, theres significant cache-line
eviction, and potentially meaningful costs we can avoid.

With CONFIG_DRM_USE_DYNAMIC_DEBUG=y, each pr_debug call-site is
replaced by a static-key, with the off-cost of few NOOPs, avoiding all
the unpredictable downsides.

NOTES:

The +c flag invokes the callsite, but avoids the heavy syslog writing.
It is currently independent of +p, but it could be compressed into a
state-machine, and the bit recovered, but not til we need to do so.

The +c flag has no predictive quality; to count usr_dbg() callsites,
you must have reimplemnted them already with pr_debug.  This just
gives DRM some numbers to consider, to balance against the work needed
o test this series.

Assisted-by: Gemini-CLI:gemini-2.5-pro
Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---

function ddcmd () {
    local cmd="$*"
    # Direct write - assume the parent script is run with 'sudo' or as root
    [ -f /proc/dynamic_debug/control ] || return 1;
    if ! echo "$cmd" > /proc/dynamic_debug/control 2>/tmp/dd_err; then
        local ret=$?
        echo "ERROR ($ret): $(cat /tmp/dd_err)" #>&2
        # Check dmesg for the "!" syntax error on wk-baseline
        dmesg | grep -i "dyndbg" | tail -n 2 #>&2
        return $ret
    fi
}

function _get_cal_count() {
    if [ ! -f /proc/interrupts ]; then
        echo 0
        return
    fi
    # sum all CPU columns for any line starting with CAL:
    # the awk starts at $2 to skip the label (CAL:)
    # NF-2 skips the trailing text "Function call interrupts"
    grep "^ *CAL:" /proc/interrupts | \
        awk '{ for(i=2; i<=NF-2; i++) sum+=$i } END { print sum+0 }'
}

function wrap_cal_count() {
    local cal_before
    cal_before=$(_get_cal_count)
    printf " wrapping: %s\n" "$*" #>&2
    #time \
	"$@" || return 1
    local cal_after
    cal_after=$(_get_cal_count)
    local delta=$(( ${cal_after:-0} - ${cal_before:-0} ))
    printf "Delta-CAL (IPI): %d\n" "$delta" #>&2
}

TEST_CLASSES_LIST="D2_CORE D2_DRIVER D2_KMS D2_PRIME D2_ATOMIC D2_VBL D2_STATE D2_LEASE D2_DP D2_DRMRES V0 V1 V2 V3 V4 V5 V6 V7"

DRM_CLASSES_LIST="DRM_UT_CORE DRM_UT_DRIVER DRM_UT_KMS DRM_UT_PRIME DRM_UT_ATOMIC DRM_UT_VBL DRM_UT_STATE DRM_UT_LEASE DRM_UT_DP DRM_UT_DRMRES"

function dd_setup_() {
    local flags="${1:-+p}"
    # Use $2 if provided, otherwise fallback to the full list
    local CLASSES_LIST="$2"
    local q=""
    local C

    # Safeguard: if list is empty, don't do anything
    [[ -z "$CLASSES_LIST" ]] && echo "no classes!" && return 0

    for C in $CLASSES_LIST; do
        q+="class $C $flags ; "
    done
    #echo "sending: $q"
    ddcmd "$q"
}

function dd_setup_test() {
    modprobe test_dynamic_debug || return 1
    dd_setup_ $1 "${2:-$TEST_CLASSES_LIST}"
}

function dd_setup_drm() {
    dd_setup_ $1 "${2:-$DRM_CLASSES_LIST}"
}

function count_hits() {
    local duration=60
    [[ "$1" =~ ^[0-9]+$ ]] && { duration=$1; shift; }

    local cmd_to_run=()
    local custom_classes=""
    while [[ $# -gt 0 ]]; do
        if [[ "$1" == "--" ]]; then
            shift
            custom_classes="$*"
            break
        fi
        cmd_to_run+=("$1")
        shift
    done

    ddcmd reset_stats
    dd_setup_drm "+c" "$custom_classes"

    if [[ ${#cmd_to_run[@]} -gt 0 ]]; then
        echo "Banging on: ${cmd_to_run[*]} (&)"
        # Use eval so bash functions work
        eval "${cmd_to_run[*]} &"
        local cmd_pid=$!
        sleep "$duration"
        killall vkcube 2>/dev/null
        kill "$cmd_pid" 2>/dev/null
    else
        sleep "$duration"
    fi

    dd_setup_drm "-c" "$custom_classes"
    tail -n1 /proc/dynamic_debug/control
}

function hammer_vk() {
    for i in {1..12}; do vkcube >/dev/null 2>&1 & done
}

function isolate_drm_hits() {
    local duration=${1:-10}
    local cmd=${2:-vkcube}

    echo "Starting isolation study: ${duration}s per class using ${cmd}"
    echo "----------------------------------------------------------"
    printf "%-20s | %-10s\n" "DRM CLASS" "TOTAL HITS"
    echo "----------------------------------------------------------"

    for class in $DRM_CLASSES_LIST FOO; do
        # Run count_hits for the specific class
        # Use 'capture' logic to grab only the hit count from the tail output
        result=$(count_hits "$duration" "$cmd" -- "$class" | grep "total hits" | awk '{print $NF}')

        printf "%-20s | %-10s\n" "$class" "$result"
    done
    #result=$(count_hits "$duration" "$cmd" -- "FOO" | grep "total hits" | awk '{print $NF}')
    #printf "%-20s | %-10s\n" "$class" "$result"
}

[ $SHLVL == 2 -a -n "$*" ] && echo " doing: $* in $PWD" #>&2

if [ $SHLVL == 2 ]; then
    # run args as cmd
    $@
fi
---
 include/linux/dynamic_debug.h | 25 +++++++++++++++++++++----
 lib/dynamic_debug.c           | 40 ++++++++++++++++++++++++++++++++++++----
 2 files changed, 57 insertions(+), 8 deletions(-)

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 82cde8e6b46c..0e3af8948a56 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -54,6 +54,10 @@ struct _ddebug {
 #define _DPRINTK_FLAGS_INCL_TID		(1<<4)
 #define _DPRINTK_FLAGS_INCL_SOURCENAME	(1<<5)
 #define _DPRINTK_FLAGS_INCL_STACK	(1<<6)
+#define _DPRINTK_FLAGS_COUNT		(1<<7)
+
+#define _DPRINTK_FLAGS_ENABLED (_DPRINTK_FLAGS_PRINT | _DPRINTK_FLAGS_COUNT)
+#define _DPRINTK_FLAGS_ACTIVE  (_DPRINTK_FLAGS_PRINT)
 
 #define _DPRINTK_FLAGS_INCL_ANY		\
 	(_DPRINTK_FLAGS_INCL_MODNAME | _DPRINTK_FLAGS_INCL_FUNCNAME |\
@@ -409,6 +413,12 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 
 #endif /* CONFIG_JUMP_LABEL */
 
+void ddebug_increment_call_count(void);
+#define DYNAMIC_DEBUG_COUNT(descriptor) {			\
+	if (unlikely(descriptor.flags & _DPRINTK_FLAGS_COUNT))	\
+		ddebug_increment_call_count();			\
+	}
+
 /*
  * Factory macros: ($prefix)dynamic_func_call($suffix)
  *
@@ -420,11 +430,15 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
  * (|_cls):	adds in _DPRINT_CLASS_DFLT as needed
  * (|_no_desc):	former gets callsite descriptor as 1st arg (for prdbgs)
  */
+
 #define __dynamic_func_call_cls(id, cls, fmt, func, ...) do {	\
 	DEFINE_DYNAMIC_DEBUG_METADATA_CLS(id, cls, fmt);	\
 	if (DYNAMIC_DEBUG_BRANCH(id)) {				\
-		func(&id, ##__VA_ARGS__);			\
-		__dynamic_dump_stack(id);			\
+		DYNAMIC_DEBUG_COUNT(id);			\
+		if (id.flags & _DPRINTK_FLAGS_ACTIVE) {		\
+			func(&id, ##__VA_ARGS__);		\
+			__dynamic_dump_stack(id);		\
+		}						\
 	}							\
 } while (0)
 #define __dynamic_func_call(id, fmt, func, ...)				\
@@ -434,8 +448,11 @@ void __dynamic_ibdev_dbg(struct _ddebug *descriptor,
 #define __dynamic_func_call_cls_no_desc(id, cls, fmt, func, ...) do {	\
 	DEFINE_DYNAMIC_DEBUG_METADATA_CLS(id, cls, fmt);		\
 	if (DYNAMIC_DEBUG_BRANCH(id)) {					\
-		func(__VA_ARGS__);					\
-		__dynamic_dump_stack(id);				\
+		DYNAMIC_DEBUG_COUNT(id);				\
+		if (id.flags & _DPRINTK_FLAGS_ACTIVE) {			\
+			func(__VA_ARGS__);				\
+			__dynamic_dump_stack(id);			\
+		}							\
 	}								\
 } while (0)
 #define __dynamic_func_call_no_desc(id, fmt, func, ...)			\
diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index d098afe8d340..154ae947f4a6 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -19,12 +19,14 @@
 #include <linux/kallsyms.h>
 #include <linux/types.h>
 #include <linux/mutex.h>
+#include <linux/percpu.h>
 #include <linux/proc_fs.h>
 #include <linux/seq_file.h>
 #include <linux/list.h>
 #include <linux/sysctl.h>
 #include <linux/ctype.h>
 #include <linux/string.h>
+
 #include <linux/parser.h>
 #include <linux/string_helpers.h>
 #include <linux/uaccess.h>
@@ -71,6 +73,13 @@ struct flag_settings {
 	unsigned int mask;
 };
 
+static DEFINE_PER_CPU(unsigned long, ddebug_call_count);
+void ddebug_increment_call_count(void)
+{
+	this_cpu_inc(ddebug_call_count);
+}
+EXPORT_SYMBOL(ddebug_increment_call_count);
+
 static bool ddebug_class_map_in_range(const int class_id,
 				      const struct ddebug_class_map *map);
 static bool ddebug_class_user_in_range(const int class_id,
@@ -101,6 +110,7 @@ static const struct { unsigned flag:8; char opt_char; } opt_array[] = {
 	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
 	{ _DPRINTK_FLAGS_INCL_TID, 't' },
 	{ _DPRINTK_FLAGS_INCL_STACK, 'd' },
+	{ _DPRINTK_FLAGS_COUNT, 'c' },
 	{ _DPRINTK_FLAGS_NONE, '_' },
 };
 
@@ -365,10 +375,10 @@ static int ddebug_change(const struct ddebug_query *query, struct flag_settings
 			if (newflags == dp->flags)
 				continue;
 #ifdef CONFIG_JUMP_LABEL
-			if (dp->flags & _DPRINTK_FLAGS_PRINT) {
-				if (!(newflags & _DPRINTK_FLAGS_PRINT))
+			if (dp->flags & _DPRINTK_FLAGS_ENABLED) {
+				if (!(newflags & _DPRINTK_FLAGS_ENABLED))
 					static_branch_disable(&dp->key.dd_key_true);
-			} else if (newflags & _DPRINTK_FLAGS_PRINT) {
+			} else if (newflags & _DPRINTK_FLAGS_ENABLED) {
 				static_branch_enable(&dp->key.dd_key_true);
 			}
 #endif
@@ -1083,6 +1093,14 @@ static __init int dyndbg_setup(char *str)
 
 __setup("dyndbg=", dyndbg_setup);
 
+static void reset_ddebug_call_count(void)
+{
+	int cpu;
+
+	for_each_possible_cpu(cpu)
+		per_cpu(ddebug_call_count, cpu) = 0;
+}
+
 /*
  * File_ops->write method for <debugfs>/dynamic_debug/control.  Gathers the
  * command text from userspace, parses and executes it.
@@ -1105,6 +1123,10 @@ static ssize_t ddebug_proc_write(struct file *file, const char __user *ubuf,
 		return PTR_ERR(tmpbuf);
 	v2pr_info("read %zu bytes from userspace\n", len);
 
+	if (len >= 11 && !strncmp(tmpbuf, "reset_stats", 11)) {
+		reset_ddebug_call_count();
+		return len;
+	}
 	ret = ddebug_exec_queries(tmpbuf, NULL);
 	kfree(tmpbuf);
 	if (ret < 0)
@@ -1238,6 +1260,16 @@ static const char *ddebug_class_name(struct _ddebug_info *di, struct _ddebug *dp
 	return NULL;
 }
 
+static unsigned long get_ddebug_call_count(void)
+{
+	unsigned long total = 0;
+	int cpu;
+
+	for_each_online_cpu(cpu)
+		total += per_cpu(ddebug_call_count, cpu);
+	return total;
+}
+
 /*
  * Seq_ops show method.  Called several times within a read()
  * call from userspace, with ddebug_lock held.  Formats the
@@ -1257,7 +1289,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
 		return 0;
 	}
 	if (p == EPILOGUE_TOKEN) {
-		/* use this soon */
+		seq_printf(m, "#: total call-counts: %lu\n", get_ddebug_call_count());
 		return 0;
 	}
 

-- 
2.55.0