[PATCH sched_ext/for-6.12] sched_ext: Improve logging around enable/disable

[PATCH sched_ext/for-6.12] sched_ext: Improve logging around enable/disable

[Tejun Heo]

sched_ext currently doesn't generate messages when the BPF scheduler is
enabled and disabled unless there are errors. It is useful to have paper
trail. Improve logging around enable/disable:

- Generate info messages on enable and non-error disable.

- Update error exit message formatting so that it's consistent with
  non-error message. Also, prefix ei->msg with the BPF scheduler's name to
  make it clear where the message is coming from.

- Shorten scx_exit_reason() strings for SCX_EXIT_UNREG* for brevity and
  consistency.

Signed-off-by: Tejun Heo <tj@kernel.org>
Suggested-by: Phil Auld <pauld@redhat.com>
---
 kernel/sched/ext.c |   21 +++++++++++++--------
 1 file changed, 13 insertions(+), 8 deletions(-)

diff --git a/kernel/sched/ext.c b/kernel/sched/ext.c
index 60a7eb7d8a9e..eea2fda8e099 100644
--- a/kernel/sched/ext.c
+++ b/kernel/sched/ext.c
@@ -4004,11 +4004,11 @@ static const char *scx_exit_reason(enum scx_exit_kind kind)
 {
 	switch (kind) {
 	case SCX_EXIT_UNREG:
-		return "Scheduler unregistered from user space";
+		return "unregistered from user space";
 	case SCX_EXIT_UNREG_BPF:
-		return "Scheduler unregistered from BPF";
+		return "unregistered from BPF";
 	case SCX_EXIT_UNREG_KERN:
-		return "Scheduler unregistered from the main kernel";
+		return "unregistered from the main kernel";
 	case SCX_EXIT_SYSRQ:
 		return "disabled by sysrq-S";
 	case SCX_EXIT_ERROR:
@@ -4126,14 +4126,17 @@ static void scx_ops_disable_workfn(struct kthread_work *work)
 	percpu_up_write(&scx_fork_rwsem);
 
 	if (ei->kind >= SCX_EXIT_ERROR) {
-		printk(KERN_ERR "sched_ext: BPF scheduler \"%s\" errored, disabling\n", scx_ops.name);
+		pr_err("sched_ext: BPF scheduler \"%s\" disabled (%s)\n",
+		       scx_ops.name, ei->reason);
 
-		if (ei->msg[0] == '\0')
-			printk(KERN_ERR "sched_ext: %s\n", ei->reason);
-		else
-			printk(KERN_ERR "sched_ext: %s (%s)\n", ei->reason, ei->msg);
+		if (ei->msg[0] != '\0')
+			printk(KERN_ERR "sched_ext: %s: %s\n",
+			       scx_ops.name, ei->msg);
 
 		stack_trace_print(ei->bt, ei->bt_len, 2);
+	} else {
+		pr_info("sched_ext: BPF scheduler \"%s\" disabled (%s)\n",
+			scx_ops.name, ei->reason);
 	}
 
 	if (scx_ops.exit)
@@ -4808,6 +4811,8 @@ static int scx_ops_enable(struct sched_ext_ops *ops, struct bpf_link *link)
 	if (!(ops->flags & SCX_OPS_SWITCH_PARTIAL))
 		static_branch_enable(&__scx_switched_all);
 
+	pr_info("sched_ext: BPF scheduler \"%s\" enabled%s\n",
+		scx_ops.name, scx_switched_all() ? "" : " (partial)");
 	kobject_uevent(scx_root_kobj, KOBJ_ADD);
 	mutex_unlock(&scx_ops_enable_mutex);
 

Re: [PATCH sched_ext/for-6.12] sched_ext: Improve logging around enable/disable

[Phil Auld]

On Wed, Aug 07, 2024 at 02:52:50PM -1000 Tejun Heo wrote:
> sched_ext currently doesn't generate messages when the BPF scheduler is
> enabled and disabled unless there are errors. It is useful to have paper
> trail. Improve logging around enable/disable:
> 
> - Generate info messages on enable and non-error disable.
> 
> - Update error exit message formatting so that it's consistent with
>   non-error message. Also, prefix ei->msg with the BPF scheduler's name to
>   make it clear where the message is coming from.
> 
> - Shorten scx_exit_reason() strings for SCX_EXIT_UNREG* for brevity and
>   consistency.
>

Thanks! That looks very helpful.


Reviewed-by: Phil Auld <pauld@redhat.com>


> Signed-off-by: Tejun Heo <tj@kernel.org>
> Suggested-by: Phil Auld <pauld@redhat.com>
> ---
>  kernel/sched/ext.c |   21 +++++++++++++--------
>  1 file changed, 13 insertions(+), 8 deletions(-)
> 
> diff --git a/kernel/sched/ext.c b/kernel/sched/ext.c
> index 60a7eb7d8a9e..eea2fda8e099 100644
> --- a/kernel/sched/ext.c
> +++ b/kernel/sched/ext.c
> @@ -4004,11 +4004,11 @@ static const char *scx_exit_reason(enum scx_exit_kind kind)
>  {
>  	switch (kind) {
>  	case SCX_EXIT_UNREG:
> -		return "Scheduler unregistered from user space";
> +		return "unregistered from user space";
>  	case SCX_EXIT_UNREG_BPF:
> -		return "Scheduler unregistered from BPF";
> +		return "unregistered from BPF";
>  	case SCX_EXIT_UNREG_KERN:
> -		return "Scheduler unregistered from the main kernel";
> +		return "unregistered from the main kernel";
>  	case SCX_EXIT_SYSRQ:
>  		return "disabled by sysrq-S";
>  	case SCX_EXIT_ERROR:
> @@ -4126,14 +4126,17 @@ static void scx_ops_disable_workfn(struct kthread_work *work)
>  	percpu_up_write(&scx_fork_rwsem);
>  
>  	if (ei->kind >= SCX_EXIT_ERROR) {
> -		printk(KERN_ERR "sched_ext: BPF scheduler \"%s\" errored, disabling\n", scx_ops.name);
> +		pr_err("sched_ext: BPF scheduler \"%s\" disabled (%s)\n",
> +		       scx_ops.name, ei->reason);
>  
> -		if (ei->msg[0] == '\0')
> -			printk(KERN_ERR "sched_ext: %s\n", ei->reason);
> -		else
> -			printk(KERN_ERR "sched_ext: %s (%s)\n", ei->reason, ei->msg);
> +		if (ei->msg[0] != '\0')
> +			printk(KERN_ERR "sched_ext: %s: %s\n",
> +			       scx_ops.name, ei->msg);
>  
>  		stack_trace_print(ei->bt, ei->bt_len, 2);
> +	} else {
> +		pr_info("sched_ext: BPF scheduler \"%s\" disabled (%s)\n",
> +			scx_ops.name, ei->reason);
>  	}
>  
>  	if (scx_ops.exit)
> @@ -4808,6 +4811,8 @@ static int scx_ops_enable(struct sched_ext_ops *ops, struct bpf_link *link)
>  	if (!(ops->flags & SCX_OPS_SWITCH_PARTIAL))
>  		static_branch_enable(&__scx_switched_all);
>  
> +	pr_info("sched_ext: BPF scheduler \"%s\" enabled%s\n",
> +		scx_ops.name, scx_switched_all() ? "" : " (partial)");
>  	kobject_uevent(scx_root_kobj, KOBJ_ADD);
>  	mutex_unlock(&scx_ops_enable_mutex);
>  
> 

-- 

Re: [PATCH sched_ext/for-6.12] sched_ext: Improve logging around enable/disable

[David Vernet]

[-- Attachment #1: Type: text/plain, Size: 2437 bytes --]

On Wed, Aug 07, 2024 at 02:52:50PM -1000, Tejun Heo wrote:

Hi Tejun,

> sched_ext currently doesn't generate messages when the BPF scheduler is
> enabled and disabled unless there are errors. It is useful to have paper
> trail. Improve logging around enable/disable:
> 
> - Generate info messages on enable and non-error disable.
> 
> - Update error exit message formatting so that it's consistent with
>   non-error message. Also, prefix ei->msg with the BPF scheduler's name to
>   make it clear where the message is coming from.
> 
> - Shorten scx_exit_reason() strings for SCX_EXIT_UNREG* for brevity and
>   consistency.
> 
> Signed-off-by: Tejun Heo <tj@kernel.org>
> Suggested-by: Phil Auld <pauld@redhat.com>
> ---
>  kernel/sched/ext.c |   21 +++++++++++++--------
>  1 file changed, 13 insertions(+), 8 deletions(-)
> 
> diff --git a/kernel/sched/ext.c b/kernel/sched/ext.c
> index 60a7eb7d8a9e..eea2fda8e099 100644
> --- a/kernel/sched/ext.c
> +++ b/kernel/sched/ext.c
> @@ -4004,11 +4004,11 @@ static const char *scx_exit_reason(enum scx_exit_kind kind)
>  {
>  	switch (kind) {
>  	case SCX_EXIT_UNREG:
> -		return "Scheduler unregistered from user space";
> +		return "unregistered from user space";
>  	case SCX_EXIT_UNREG_BPF:
> -		return "Scheduler unregistered from BPF";
> +		return "unregistered from BPF";
>  	case SCX_EXIT_UNREG_KERN:
> -		return "Scheduler unregistered from the main kernel";
> +		return "unregistered from the main kernel";
>  	case SCX_EXIT_SYSRQ:
>  		return "disabled by sysrq-S";
>  	case SCX_EXIT_ERROR:
> @@ -4126,14 +4126,17 @@ static void scx_ops_disable_workfn(struct kthread_work *work)
>  	percpu_up_write(&scx_fork_rwsem);
>  
>  	if (ei->kind >= SCX_EXIT_ERROR) {
> -		printk(KERN_ERR "sched_ext: BPF scheduler \"%s\" errored, disabling\n", scx_ops.name);
> +		pr_err("sched_ext: BPF scheduler \"%s\" disabled (%s)\n",
> +		       scx_ops.name, ei->reason);
>  
> -		if (ei->msg[0] == '\0')
> -			printk(KERN_ERR "sched_ext: %s\n", ei->reason);
> -		else
> -			printk(KERN_ERR "sched_ext: %s (%s)\n", ei->reason, ei->msg);
> +		if (ei->msg[0] != '\0')
> +			printk(KERN_ERR "sched_ext: %s: %s\n",
> +			       scx_ops.name, ei->msg);

Was it intentional to use pr_err() above, and printk() here? If not,
let's make them consistent?

Looks good otherwise.

Acked-by: David Vernet <void@manifault.com>

Thanks,
David

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

[PATCH v2 sched_ext/for-6.12] sched_ext: Improve logging around enable/disable

[Tejun Heo]

From 344576fa6a69ce1292ef669c8d50c2088c36dc1e Mon Sep 17 00:00:00 2001
From: Tejun Heo <tj@kernel.org>
Date: Wed, 7 Aug 2024 14:52:50 -1000
Subject: [PATCH] sched_ext: Improve logging around enable/disable

sched_ext currently doesn't generate messages when the BPF scheduler is
enabled and disabled unless there are errors. It is useful to have paper
trail. Improve logging around enable/disable:

- Generate info messages on enable and non-error disable.

- Update error exit message formatting so that it's consistent with
  non-error message. Also, prefix ei->msg with the BPF scheduler's name to
  make it clear where the message is coming from.

- Shorten scx_exit_reason() strings for SCX_EXIT_UNREG* for brevity and
  consistency.

v2: Use pr_*() instead of KERN_* consistently. (David)

Signed-off-by: Tejun Heo <tj@kernel.org>
Suggested-by: Phil Auld <pauld@redhat.com>
Reviewed-by: Phil Auld <pauld@redhat.com>
Acked-by: David Vernet <void@manifault.com>
---

Applied to sched_ext/for-6.12 w/ the pr_err() update.

Thanks.

 kernel/sched/ext.c | 20 ++++++++++++--------
 1 file changed, 12 insertions(+), 8 deletions(-)

diff --git a/kernel/sched/ext.c b/kernel/sched/ext.c
index 17af9c46d891..143c4207a826 100644
--- a/kernel/sched/ext.c
+++ b/kernel/sched/ext.c
@@ -4013,11 +4013,11 @@ static const char *scx_exit_reason(enum scx_exit_kind kind)
 {
 	switch (kind) {
 	case SCX_EXIT_UNREG:
-		return "Scheduler unregistered from user space";
+		return "unregistered from user space";
 	case SCX_EXIT_UNREG_BPF:
-		return "Scheduler unregistered from BPF";
+		return "unregistered from BPF";
 	case SCX_EXIT_UNREG_KERN:
-		return "Scheduler unregistered from the main kernel";
+		return "unregistered from the main kernel";
 	case SCX_EXIT_SYSRQ:
 		return "disabled by sysrq-S";
 	case SCX_EXIT_ERROR:
@@ -4135,14 +4135,16 @@ static void scx_ops_disable_workfn(struct kthread_work *work)
 	percpu_up_write(&scx_fork_rwsem);
 
 	if (ei->kind >= SCX_EXIT_ERROR) {
-		printk(KERN_ERR "sched_ext: BPF scheduler \"%s\" errored, disabling\n", scx_ops.name);
+		pr_err("sched_ext: BPF scheduler \"%s\" disabled (%s)\n",
+		       scx_ops.name, ei->reason);
 
-		if (ei->msg[0] == '\0')
-			printk(KERN_ERR "sched_ext: %s\n", ei->reason);
-		else
-			printk(KERN_ERR "sched_ext: %s (%s)\n", ei->reason, ei->msg);
+		if (ei->msg[0] != '\0')
+			pr_err("sched_ext: %s: %s\n", scx_ops.name, ei->msg);
 
 		stack_trace_print(ei->bt, ei->bt_len, 2);
+	} else {
+		pr_info("sched_ext: BPF scheduler \"%s\" disabled (%s)\n",
+			scx_ops.name, ei->reason);
 	}
 
 	if (scx_ops.exit)
@@ -4817,6 +4819,8 @@ static int scx_ops_enable(struct sched_ext_ops *ops, struct bpf_link *link)
 	if (!(ops->flags & SCX_OPS_SWITCH_PARTIAL))
 		static_branch_enable(&__scx_switched_all);
 
+	pr_info("sched_ext: BPF scheduler \"%s\" enabled%s\n",
+		scx_ops.name, scx_switched_all() ? "" : " (partial)");
 	kobject_uevent(scx_root_kobj, KOBJ_ADD);
 	mutex_unlock(&scx_ops_enable_mutex);
 
-- 
2.46.0