Received-SPF: pass (google.com: domain of linux-kernel+bounces-103152-linux.lists.archive=gmail.com@vger.kernel.org designates 2604:1380:4601:e00::3 as permitted sender) client-ip=2604:1380:4601:e00::3;
Message-ID: <9925a5bb-ebca-44d9-b73b-5593c66c0efd@redhat.com>
Date: Thu, 14 Mar 2024 12:00:28 +0100
Precedence: bulk
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: [PATCH] tracing/osnoise: init osnoise_instances list before
 registering tracer
To: Jerome Marchand <jmarchan@fedora.smtp.subspace.kernel.org>,
	Steven Rostedt <rostedt@goodmis.org>,
	Daniel Bristot de Oliveira <bristot@kernel.org>
Cc: Masami Hiramatsu <mhiramat@kernel.org>,
 Mathieu Desnoyers <mathieu.desnoyers@efficios.com>,
 linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org
References: <20240314104930.319754-1-jmarchan@redhat.com>
Content-Language: en-US
From: Jerome Marchand <jmarchan@redhat.com>
In-Reply-To: <20240314104930.319754-1-jmarchan@redhat.com>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit

On 14/03/2024 11:49, Jerome Marchand wrote:
> The kernel panic during the initialization of the osnoise tracer when
> booting with "ftrace=osnoise" or "ftrace=timerlat" option.

BTW, while this fixes this issue for osnoise and timerlat, another issue,
remains with timerlat which prevent to boot with "ftrace=timerlat" option.
It apparently related to hrtimers:

[    1.489168] Starting tracer 'timerlat'
[    1.506835] BUG: kernel NULL pointer dereference, address: 0000000000000000
[    1.507355] Loading compiled-in X.509 certificates
[    1.507652] #PF: supervisor write access in kernel mode
[    1.509639] #PF: error_code(0x0002) - not-present page
[    1.510425] PGD 0 P4D 0
[    1.510888] Oops: 0002 [#1] PREEMPT SMP NOPTI
[    1.511582] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.8.0-63.osnoiseinit.fc41.x86_64 #1
[    1.512819] Hardware name: Red Hat KVM/RHEL-AV, BIOS 1.13.0-2.module+el8.3.0+7353+9de0a3cc 04/01/2014
[    1.514175] RIP: 0010:rb_erase+0x18b/0x3a0
[    1.514871] Code: 48 83 c0 01 48 89 01 e9 b3 30 03 00 e9 ae 30 03 00 48 89 46 10 e9 17 ff ff ff 48 8b 56 10 48 8d 41 01 48 89 51 08 48 89 4e 10 <48> 89 02 48 8b 01 48 89 06 48 89 31 48 83 f8 03 0f 86 96 00 00 00
[    1.517486] RSP: 0018:ffffffff99403e08 EFLAGS: 00010046
[    1.521008] RAX: ffff95e06fa2de49 RBX: ffff95e06fa25050 RCX: ffff95e06fa2de48
[    1.522067] RDX: 0000000000000000 RSI: ffff95e06fa2de48 RDI: ffff95e06fa25050
[    1.523111] RBP: ffff95e06fa24b20 R08: ffff95e06fa24b20 R09: 0000000000000000
[    1.524151] R10: 0000000000000000 R11: ffffffff99464880 R12: 0000000000000001
[    1.525195] R13: ffff95e06fa24ac0 R14: ffff95e06fa24b00 R15: 0000000000024ac0
[    1.526230] FS:  0000000000000000(0000) GS:ffff95e06fa00000(0000) knlGS:0000000000000000
[    1.527433] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    1.528295] CR2: 0000000000000000 CR3: 000000014a422000 CR4: 0000000000350ef0
[    1.529331] Call Trace:
[    1.529783]  <TASK>
[    1.530192]  ? __die+0x23/0x70
[    1.530736]  ? page_fault_oops+0x174/0x530
[    1.531394]  ? srso_return_thunk+0x5/0x5f
[    1.532040]  ? srso_return_thunk+0x5/0x5f
[    1.532681]  ? ttwu_queue_wakelist+0xf1/0x110
[    1.533377]  ? exc_page_fault+0x7f/0x180
[    1.534007]  ? asm_exc_page_fault+0x26/0x30
[    1.534677]  ? rb_erase+0x18b/0x3a0
[    1.535251]  ? __schedule+0x3e9/0x1530
[    1.535863]  timerqueue_del+0x2e/0x50
[    1.536457]  __remove_hrtimer+0x39/0x90
[    1.537095]  hrtimer_start_range_ns+0x2a6/0x350
[    1.537918]  tick_nohz_idle_stop_tick+0x69/0xd0
[    1.538646]  do_idle+0x221/0x270
[    1.539195]  cpu_startup_entry+0x29/0x30
[    1.539829]  rest_init+0xcf/0xd0
[    1.540374]  arch_call_rest_init+0xe/0x30
[    1.541031]  start_kernel+0x717/0xa70
[    1.541623]  x86_64_start_reservations+0x18/0x30
[    1.542352]  x86_64_start_kernel+0x94/0xa0
[    1.543007]  secondary_startup_64_no_verify+0x184/0x18b
[    1.543813]  </TASK>
[    1.544217] Modules linked in:
[    1.544751] CR2: 0000000000000000
[    1.545300] ---[ end trace 0000000000000000 ]---
[    1.546015] RIP: 0010:rb_erase+0x18b/0x3a0
[    1.546674] Code: 48 83 c0 01 48 89 01 e9 b3 30 03 00 e9 ae 30 03 00 48 89 46 10 e9 17 ff ff ff 48 8b 56 10 48 8d 41 01 48 89 51 08 48 89 4e 10 <48> 89 02 48 8b 01 48 89 06 48 89 31 48 83 f8 03 0f 86 96 00 00 00
[    1.549271] RSP: 0018:ffffffff99403e08 EFLAGS: 00010046
[    1.550063] RAX: ffff95e06fa2de49 RBX: ffff95e06fa25050 RCX: ffff95e06fa2de48
[    1.551091] RDX: 0000000000000000 RSI: ffff95e06fa2de48 RDI: ffff95e06fa25050
[    1.552125] RBP: ffff95e06fa24b20 R08: ffff95e06fa24b20 R09: 0000000000000000
[    1.553157] R10: 0000000000000000 R11: ffffffff99464880 R12: 0000000000000001
[    1.554191] R13: ffff95e06fa24ac0 R14: ffff95e06fa24b00 R15: 0000000000024ac0
[    1.555226] FS:  0000000000000000(0000) GS:ffff95e06fa00000(0000) knlGS:0000000000000000
[    1.556433] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    1.557291] CR2: 0000000000000000 CR3: 000000014a422000 CR4: 0000000000350ef0
[    1.558322] Kernel panic - not syncing: Attempted to kill the idle task!
[    1.559602] Kernel Offset: 0x16000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[    1.561164] ---[ end Kernel panic - not syncing: Attempted to kill the idle task! ]---

Maybe a similar initialization issue that's easily fixed, or maybe the
timerlat option should be ignoreded at boot time, as mmiotrace is.

Regards,
Jerome Marchand

> 
> [    1.505256] Starting tracer 'osnoise'
> [    1.510214] BUG: kernel NULL pointer dereference, address: 0000000000000010
> [    1.511189] #PF: supervisor read access in kernel mode
> [    1.511938] #PF: error_code(0x0000) - not-present page
> [    1.512676] PGD 0 P4D 0
> [    1.513105] Oops: 0000 [#1] PREEMPT SMP NOPTI
> [    1.513763] CPU: 9 PID: 1 Comm: swapper/0 Not tainted 6.8.0-63.fc41.x86_64 #1
> [    1.515485] Hardware name: Red Hat KVM/RHEL-AV, BIOS 1.13.0-2.module+el8.3.0+7353+9de0a3cc 04/01/2014
> [    1.516765] RIP: 0010:osnoise_tracer_start+0x21/0x80
> [    1.517514] Code: 90 90 90 90 90 90 90 90 90 f3 0f 1e fa 55 48 89 fd 53 e8 62 2a f4 ff 48 8b 05 4b a1 ff 02 48 3d a0 32 28 b1 74 28 31 db 31 d2 <48> 39 68 10 48 8b 00 0f 94 c2 09 d3 48 3d a0 32 28 b1 75 ea e8 d6
> [    1.519975] RSP: 0018:ffffa35e40013d58 EFLAGS: 00010246
> [    1.520729] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000010
> [    1.521726] RDX: 0000000000000000 RSI: 0000000000000010 RDI: ffffffffb05ae000
> [    1.522700] RBP: ffffffffb05ae000 R08: ffff97624007a0b0 R09: 0000000000000000
> [    1.523671] R10: 0000000000000000 R11: ffffffffb0464880 R12: ffffffffb05ae000
> [    1.527337] R13: ffffffffafaa6652 R14: ffffffffb0727400 R15: 0000000000000000
> [    1.528329] FS:  0000000000000000(0000) GS:ffff9765afc40000(0000) knlGS:0000000000000000
> [    1.529476] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [    1.530281] CR2: 0000000000000010 CR3: 00000001c9422000 CR4: 0000000000350ef0
> [    1.531258] Call Trace:
> [    1.531690]  <TASK>
> [    1.532081]  ? __die+0x23/0x70
> [    1.532585]  ? page_fault_oops+0x174/0x530
> [    1.533209]  ? exc_page_fault+0x7f/0x180
> [    1.533828]  ? asm_exc_page_fault+0x26/0x30
> [    1.534459]  ? osnoise_tracer_start+0x21/0x80
> [    1.535104]  ? osnoise_tracer_start+0xe/0x80
> [    1.535746]  osnoise_tracer_init+0x1c/0x30
> [    1.536362]  tracing_set_tracer+0x17c/0x2b0
> [    1.536998]  register_tracer+0x165/0x260
> [    1.537615]  ? __pfx_init_osnoise_tracer+0x10/0x10
> [    1.538311]  init_osnoise_tracer+0x78/0x390
> [    1.538941]  ? __pfx_init_osnoise_tracer+0x10/0x10
> [    1.539637]  do_one_initcall+0x5b/0x320
> [    1.540224]  kernel_init_freeable+0x318/0x470
> [    1.540881]  ? __pfx_kernel_init+0x10/0x10
> [    1.541503]  kernel_init+0x1a/0x1c0
> [    1.542043]  ret_from_fork+0x34/0x50
> [    1.542603]  ? __pfx_kernel_init+0x10/0x10
> [    1.543240]  ret_from_fork_asm+0x1b/0x30
> [    1.543850]  </TASK>
> [    1.544237] Modules linked in:
> [    1.545395] CR2: 0000000000000010
> 
> Turns out, it's because osnoise tracer tries to access an
> uninitialized osnoise_instances list in osnoise_instance_registered(),
> called from osnoise_tracer_start(). Move the list initialization
> before calling register_tracer().
> 
> Signed-off-by: Jerome Marchand <jmarchan@redhat.com>
> ---
>   kernel/trace/trace_osnoise.c | 4 ++--
>   1 file changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/kernel/trace/trace_osnoise.c b/kernel/trace/trace_osnoise.c
> index a8e28f9b9271..122ef8a5c29d 100644
> --- a/kernel/trace/trace_osnoise.c
> +++ b/kernel/trace/trace_osnoise.c
> @@ -3110,6 +3110,8 @@ __init static int init_osnoise_tracer(void)
>   
>   	cpumask_copy(&osnoise_cpumask, cpu_all_mask);
>   
> +	INIT_LIST_HEAD_RCU(&osnoise_instances);
> +
>   	ret = register_tracer(&osnoise_tracer);
>   	if (ret) {
>   		pr_err(BANNER "Error registering osnoise!\n");
> @@ -3124,8 +3126,6 @@ __init static int init_osnoise_tracer(void)
>   
>   	osnoise_init_hotplug_support();
>   
> -	INIT_LIST_HEAD_RCU(&osnoise_instances);
> -
>   	init_tracefs();
>   
>   	return 0;