hulk inclusion category: feature bugzilla: https://atomgit.com/openeuler/kernel/issues/10109 ---------------------------------------- Add a dyn_threaded_debug module parameter that enables debug instrumentation of the scheduler. The messages are recorded with trace_printk(), so that the periodic sampling, the status transitions and the decisions on the IRQ affinity, the NAPI thread masks and the napi thread CPU count can be followed from tracefs without flooding the console; without tracing support the messages fall back to dynamic debug. The switch is off by default. This adds the per-branch decisions of bind_napi_threaded(), the IRQ binding results, the napi thread CPU resize and the status transitions, matching the instrumentation that was used during the development of the module. Assisted-by: opencode:deepseek-v4.1-flash Signed-off-by: Cai Xinchen <caixinchen1@huawei.com> --- net/dynthread/net_dynthread.c | 101 ++++++++++++++++++++++++++++++++-- 1 file changed, 97 insertions(+), 4 deletions(-) diff --git a/net/dynthread/net_dynthread.c b/net/dynthread/net_dynthread.c index 3752be272c96..feb0f79e0a61 100644 --- a/net/dynthread/net_dynthread.c +++ b/net/dynthread/net_dynthread.c @@ -292,6 +292,30 @@ module_param(dyn_threaded_cpuload_upper_limit, uint, 0644); MODULE_PARM_DESC(dyn_threaded_cpuload_upper_limit, "napi cpu load percent to grow for, default 90"); +static bool dyn_threaded_debug; +module_param(dyn_threaded_debug, bool, 0644); +MODULE_PARM_DESC(dyn_threaded_debug, + "enable the ftrace based debug instrumentation, default 0"); + +/* Debug instrumentation of the scheduler. It is controlled by the + * dyn_threaded_debug module parameter and recorded in the ftrace buffer, + * so that it can be read from tracefs without flooding the console. + * Without tracing support it falls back to dynamic debug. + */ +#ifdef CONFIG_TRACING +#define dyn_threaded_dbg(fmt, ...) \ + do { \ + if (dyn_threaded_debug) \ + trace_printk(fmt, ##__VA_ARGS__); \ + } while (0) +#else +#define dyn_threaded_dbg(fmt, ...) \ + do { \ + if (dyn_threaded_debug) \ + pr_debug(fmt, ##__VA_ARGS__); \ + } while (0) +#endif + /** * struct sched_netdev_queue_info - IRQ information of one RX queue * @irq: Linux IRQ number of the queue @@ -468,6 +492,9 @@ static void get_netdev_queue_info(struct sched_netdev *sched_dev) rxq_info = &sched_dev->rxq[sched_dev->rxq_num++]; rxq_info->irq = irq; rxq_info->affinity_cpu = cpu; + dyn_threaded_dbg("dev %s: irq=%d [%s] rxq_id=%d affinity_cpu=%d\n", + sched_dev->dev_name, irq, name, + sched_dev->rxq_num - 1, cpu); } rcu_read_unlock(); } @@ -514,22 +541,27 @@ static int init_dev(const char *if_name, size_t length) strscpy(dev_name, if_name, min_t(size_t, length + 1, IFNAMSIZ)); netdev = netdev_get_by_name(&init_net, dev_name, &dev_tracker, GFP_KERNEL); - if (!netdev) + if (!netdev) { + dyn_threaded_dbg("dev [%s] does not exist\n", dev_name); return -ENODEV; + } if (!(netdev->flags & IFF_UP)) { ret = -ENETDOWN; + dyn_threaded_dbg("dev [%s] is not up, flags=%u\n", dev_name, netdev->flags); goto err_dev_put; } if (netdev->flags & IFF_LOOPBACK) { ret = -EOPNOTSUPP; + dyn_threaded_dbg("loopback devices are not supported\n"); goto err_dev_put; } sched_dev = alloc_sched_netdev(); if (!sched_dev) { ret = -ENOMEM; + dyn_threaded_dbg("too many devices\n"); goto err_dev_put; } @@ -632,6 +664,11 @@ static int sched_task_runtime_avg_snapshot(const char *target_comm, cpumask_copy(&target_cpumask, &masks); WRITE_ONCE(target_cpucnt, cpumask_weight(&target_cpumask)); + dyn_threaded_dbg("target tasks '%s': cpumask %*pb (%u cpus), runtime %llu ns, switches %llu, threads %u\n", + infos->comm, cpumask_pr_args(&masks), + READ_ONCE(target_cpucnt), infos->total_runtime_ns, + infos->total_switches, infos->thread_cnt); + return 0; } @@ -730,14 +767,20 @@ static void bind_irq_in_cpumask(int irq, int index, const struct cpumask *bind_m unsigned int len = cpumask_weight(bind_mask); int cpu; - if (!len) + if (!len) { + dyn_threaded_dbg("empty bind mask for irq %d\n", irq); return; + } cpu = cpumask_nth(index % len, bind_mask); - if (cpu >= nr_cpu_ids) + if (cpu >= nr_cpu_ids) { + dyn_threaded_dbg("no cpu for index %u of irq %d\n", index % len, irq); return; + } irq_set_affinity(irq, cpumask_of(cpu)); + dyn_threaded_dbg("bind irq %d to cpu %d of %*pb\n", + irq, cpu, cpumask_pr_args(bind_mask)); } /* Spread the RX queue IRQs of every monitored device over the CPUs of @@ -852,6 +895,8 @@ static void set_irq_node_affinity(const struct cpumask *tasks_cpumask) cpumask_weight(&irq_prefer_mask) < dyn_threaded_irq_cpucore_limit) return; + dyn_threaded_dbg("irq affinity mask: %*pb\n", cpumask_pr_args(&irq_prefer_mask)); + cpu = cpumask_first(&irq_prefer_mask); for (dev_id = 0; dev_id < sched_netdev_num; dev_id++) { sched_dev = get_sched_netdev(dev_id); @@ -867,8 +912,15 @@ static void set_irq_node_affinity(const struct cpumask *tasks_cpumask) cpu = cpumask_first(&irq_prefer_mask); } /* set irq affinity to all irq_prefer_mask failed */ - if (cpu_idx == cpu_cnt) + if (cpu_idx == cpu_cnt) { + dyn_threaded_dbg("failed to set irq %d affinity to mask %*pb\n", + sched_dev->rxq[rxq_id].irq, + cpumask_pr_args(&irq_prefer_mask)); return; + } + + dyn_threaded_dbg("set irq %d affinity to cpu %d\n", + sched_dev->rxq[rxq_id].irq, cpu); cpu = cpumask_next(cpu, &irq_prefer_mask); if (cpu >= nr_cpu_ids) @@ -992,6 +1044,8 @@ static void bind_napi_threaded(struct sched_netdev *sched_dev) if (cpumask_empty(&check_mask)) { cpumask_or(&napi_cpumask, &napi_cpumask, node_mask); set_cpus_allowed_ptr(napi->thread, node_mask); + dyn_threaded_dbg("%s: napi %u, no target cpu in node, use %*pb\n", + dev->name, napi->napi_id, cpumask_pr_args(node_mask)); continue; } @@ -1000,6 +1054,9 @@ static void bind_napi_threaded(struct sched_netdev *sched_dev) if (!cpumask_empty(&napi_allowed_mask)) { cpumask_or(&napi_cpumask, &napi_cpumask, &napi_allowed_mask); set_cpus_allowed_ptr(napi->thread, &napi_allowed_mask); + dyn_threaded_dbg("%s: napi %u, use target-free cpus %*pb\n", + dev->name, napi->napi_id, + cpumask_pr_args(&napi_allowed_mask)); continue; } @@ -1010,6 +1067,9 @@ static void bind_napi_threaded(struct sched_netdev *sched_dev) if (cpumask_weight(napi->thread->cpus_ptr) == dyn_threaded_corenum && cpumask_subset(napi->thread->cpus_ptr, &napi_allowed_mask)) { cpumask_or(&napi_cpumask, &napi_cpumask, napi->thread->cpus_ptr); + dyn_threaded_dbg("%s: napi %u, keep mask %*pb\n", + dev->name, napi->napi_id, + cpumask_pr_args(napi->thread->cpus_ptr)); continue; } @@ -1019,6 +1079,9 @@ static void bind_napi_threaded(struct sched_netdev *sched_dev) cpumask_or(&napi_cpumask, &napi_cpumask, &bind_mask); set_cpus_allowed_ptr(napi->thread, &bind_mask); + dyn_threaded_dbg("%s: napi %u, use first %u cpus %*pb\n", + dev->name, napi->napi_id, dyn_threaded_corenum, + cpumask_pr_args(&bind_mask)); if (dyn_threaded_bindirq && irq >= 0) bind_irq_in_cpumask(irq, idx++, &bind_mask); } @@ -1039,6 +1102,8 @@ static void set_all_napi_threaded(bool threaded) continue; dev_set_threaded(sched_dev->netdev, threaded); + dyn_threaded_dbg("%s: set threaded napi %d\n", + sched_dev->dev_name, threaded); if (threaded) bind_napi_threaded(sched_dev); } @@ -1164,6 +1229,11 @@ static void change_dyn_threaded_corenum(void) /* percentual load of the napi cpus */ cal_cpustat_per(&napi_cpustat, &snapshot_napi_cpustat, &napi_per); + dyn_threaded_dbg("napi cpu user %llu system %llu softirq %llu irq %llu idle %llu iowait %llu\n", + napi_per.cpustat[CPUTIME_USER], napi_per.cpustat[CPUTIME_SYSTEM], + napi_per.cpustat[CPUTIME_SOFTIRQ], napi_per.cpustat[CPUTIME_IRQ], + napi_per.cpustat[CPUTIME_IDLE], napi_per.cpustat[CPUTIME_IOWAIT]); + spin_lock(&dyn_threaded_corenum_lock); corenum = dyn_threaded_corenum; spin_unlock(&dyn_threaded_corenum_lock); @@ -1216,11 +1286,15 @@ static void change_dyn_threaded_corenum(void) dynamic_corenum_changed = true; } spin_unlock(&dyn_threaded_corenum_lock); + dyn_threaded_dbg("resize napi thread cpus %u -> %u\n", + last_threaded_corenum, dyn_threaded_corenum); } else { dynamic_corenum_keep = true; } out: + dyn_threaded_dbg("napi threads use %u cpus of %*pb\n", + dyn_threaded_corenum, cpumask_pr_args(&napi_cpumask)); snapshot_napi_cpustat = napi_cpustat; } @@ -1260,6 +1334,8 @@ static void dyn_threaded_handler(struct work_struct *work) dyn_threaded_bindirq) set_irq_node_affinity(&target_cpumask); + dyn_threaded_dbg("target task status %d\n", info.status); + switch (info.status) { case NO_TASK: /* no target tasks: back to softirq mode and restore the @@ -1309,6 +1385,7 @@ static void dyn_threaded_handler(struct work_struct *work) take_napi_cpustat_snapshot(); break; default: + dyn_threaded_dbg("unexpected status %d\n", info.status); break; } @@ -1318,6 +1395,14 @@ static void dyn_threaded_handler(struct work_struct *work) else info.last_status = snapshot.status; + if (info.status != snapshot.status) + dyn_threaded_dbg("status %d -> %d\n", + snapshot.status, info.status); + + dyn_threaded_dbg("%s: avg_runtime %llu nvcsw_per %llu cpuload %llu status %d last %d irq_node %d\n", + __func__, info.avg_runtime, info.nvcsw_per, info.cpuload, + info.status, info.last_status, affinity_to_one_node); + snapshot = info; } @@ -1347,6 +1432,8 @@ static void start_worker(void) hrtimer_init(&dyn_threaded_timer, CLOCK_MONOTONIC, HRTIMER_MODE_REL); dyn_threaded_timer.function = dyn_threaded_hrtimer_callback; hrtimer_start(&dyn_threaded_timer, interval, HRTIMER_MODE_REL); + + dyn_threaded_dbg("worker started, interval %u ms\n", dyn_threaded_interval); } static void stop_worker(void) @@ -1357,6 +1444,8 @@ static void stop_worker(void) recover_irq_affinity(); cpumask_clear(&napi_cpumask); clear_corenum_napi(); + + dyn_threaded_dbg("worker stopped\n"); } /* enable/disable the scheduler through the dynthreaded module parameter */ @@ -1475,6 +1564,8 @@ static int __init dynthread_init(void) start_worker(); mutex_unlock(&dynthreaded_lock); + dyn_threaded_dbg("module loaded\n"); + return 0; } @@ -1488,6 +1579,8 @@ static void __exit dynthread_exit(void) recover_irq_affinity(); deinit_netdevinfo(); + + dyn_threaded_dbg("module unloaded\n"); } module_init(dynthread_init); -- 2.18.0.huawei.25