* How to trace serial console init during boot-time?
@ 2022-10-07 13:30 Paul Menzel
2022-10-08 20:43 ` Steven Rostedt
0 siblings, 1 reply; 3+ messages in thread
From: Paul Menzel @ 2022-10-07 13:30 UTC (permalink / raw)
To: Steven Rostedt, Ingo Molnar
Cc: Greg Kroah-Hartman, linux-serial, Petr Mladek, Sergey Senozhatsky, LKML
Dear Linux folks,
I am trying to do boot-time tracing of `univ8250_console_init()`:
[ 0.126636] ftrace: allocating 41793 entries in 164 pages
[ 0.132446] ftrace: allocated 164 pages with 3 groups
[…]
[ 0.167334] calling con_init+0x0/0x239 @ 0
[ 0.170217] Console: colour VGA+ 80x25
[ 0.190381] printk: console [tty0] enabled
[ 0.190484] initcall con_init+0x0/0x239 returned 0 after 0 usecs
[ 0.190487] calling hvc_console_init+0x0/0x18 @ 0
[ 0.190489] initcall hvc_console_init+0x0/0x18 returned 0 after
0 usecs
[ 0.190491] calling univ8250_console_init+0x0/0x2b @ 0
[ 1.488645] printk: console [ttyS0] enabled
[ 1.492945] initcall univ8250_console_init+0x0/0x2b returned 0
after 0 usecs
[…]
[ 1.670397] calling trace_init_perf_perm_irq_work_exit+0x0/0x17 @ 1
[ 1.670399] initcall trace_init_perf_perm_irq_work_exit+0x0/0x17
returned 0 after 0 usecs
[…]
[ 1.673339] calling trace_init_flags_sys_enter+0x0/0x13 @ 1
[ 1.673342] initcall trace_init_flags_sys_enter+0x0/0x13
returned 0 after 0 usecs
[ 1.673344] calling trace_init_flags_sys_exit+0x0/0x13 @ 1
[ 1.673346] initcall trace_init_flags_sys_exit+0x0/0x13 returned
0 after 0 usecs
[ 1.673348] calling cpu_stop_init+0x0/0x87 @ 1
[ 1.673364] initcall cpu_stop_init+0x0/0x87 returned 0 after 0 usecs
[ 1.673366] calling init_kprobes+0x0/0x149 @ 1
[ 1.673495] initcall init_kprobes+0x0/0x149 returned 0 after 0 usecs
[ 1.673497] calling init_events+0x0/0x4d @ 1
[ 1.673502] initcall init_events+0x0/0x4d returned 0 after 0 usecs
[ 1.673504] calling init_trace_printk+0x0/0xc @ 1
[ 1.673505] initcall init_trace_printk+0x0/0xc returned 0 after
0 usecs
[ 1.673507] calling event_trace_enable_again+0x0/0x23 @ 1
[ 1.673508] initcall event_trace_enable_again+0x0/0x23 returned
0 after 0 usecs
The function `univ8250_console_init()` is not available in
`/sys/kernel/debug/tracing/available_filter_functions`, so I’d like to
trace `univ8250_console_setup()`:
initcall_debug log_buf_len=32M trace_buf_size=262144K
trace_clock=global
trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,funcgraph-duration,funcgraph-proc,funcgraph-tail,nofuncgraph-overhead,context-info,graph-time
ftrace=fun
ction_graph ftrace_graph_max_depth=2
ftrace_graph_filter=univ8250_console_setup tp_printk
Unfortunately, `/sys/kernel/debug/tracing/trace` is empty, so I guess
the console happens before ftrace is available?
Is there another way to trace the serial console init, without having to
add print statements?
Kind regards,
Paul
PS: We boot our systems generally with the serial console enabled
`console=ttyS0`, and noticed that initializing the console takes at
least one second.
$ dmesg | grep -e 'DMI:' -e 'printk: console'
[ 0.000000] DMI: Dell Inc. PowerEdge R7525/05Y13N, BIOS 2.7.3 03/30/2022
[ 2.691432] printk: console [tty0] enabled
[ 5.414384] printk: console [ttyS0] enabled
$ dmesg | grep -e 'DMI:' -e 'printk:'
[ 0.000000] DMI: Dell Inc. Precision Tower 3620/0MWYPT, BIOS 2.22.0
07/13/2022
[ 0.146953] printk: console [tty0] enabled
[ 1.374382] printk: console [ttyS0] enabled
$ dmesg | grep -e 'DMI:' -e 'printk: console'
[ 0.000000] DMI: Dell Inc. PowerEdge R7425/08V001, BIOS 1.6.7 10/29/2018
[ 1.589543] printk: console [tty0] enabled
[ 3.057770] printk: console [ttyS0] enabled
$ dmesg | grep -e 'DMI:' -e 'printk: console'
[ 0.000000] DMI: HPE ProLiant DL385 Gen10 Plus/ProLiant DL385 Gen10
Plus, BIOS A42 12/03/2021
[ 5.171202] printk: console [tty0] enabled
[ 8.066602] printk: console [ttyS0] enabled
^ permalink raw reply [flat|nested] 3+ messages in thread* Re: How to trace serial console init during boot-time?
2022-10-07 13:30 How to trace serial console init during boot-time? Paul Menzel
@ 2022-10-08 20:43 ` Steven Rostedt
2022-10-11 9:13 ` Paul Menzel
0 siblings, 1 reply; 3+ messages in thread
From: Steven Rostedt @ 2022-10-08 20:43 UTC (permalink / raw)
To: Paul Menzel
Cc: Ingo Molnar, Greg Kroah-Hartman, linux-serial, Petr Mladek,
Sergey Senozhatsky, LKML
On Fri, 7 Oct 2022 15:30:56 +0200
Paul Menzel <pmenzel@molgen.mpg.de> wrote:
> Dear Linux folks,
>
>
> I am trying to do boot-time tracing of `univ8250_console_init()`:
>
> [ 0.126636] ftrace: allocating 41793 entries in 164 pages
> [ 0.132446] ftrace: allocated 164 pages with 3 groups
> […]
> [ 0.167334] calling con_init+0x0/0x239 @ 0
> [ 0.170217] Console: colour VGA+ 80x25
> [ 0.190381] printk: console [tty0] enabled
> [ 0.190484] initcall con_init+0x0/0x239 returned 0 after 0 usecs
> [ 0.190487] calling hvc_console_init+0x0/0x18 @ 0
> [ 0.190489] initcall hvc_console_init+0x0/0x18 returned 0 after
> 0 usecs
> [ 0.190491] calling univ8250_console_init+0x0/0x2b @ 0
> [ 1.488645] printk: console [ttyS0] enabled
> [ 1.492945] initcall univ8250_console_init+0x0/0x2b returned 0
> after 0 usecs
> […]
> [ 1.670397] calling trace_init_perf_perm_irq_work_exit+0x0/0x17 @ 1
> [ 1.670399] initcall trace_init_perf_perm_irq_work_exit+0x0/0x17
> returned 0 after 0 usecs
> […]
> [ 1.673339] calling trace_init_flags_sys_enter+0x0/0x13 @ 1
> [ 1.673342] initcall trace_init_flags_sys_enter+0x0/0x13
> returned 0 after 0 usecs
> [ 1.673344] calling trace_init_flags_sys_exit+0x0/0x13 @ 1
> [ 1.673346] initcall trace_init_flags_sys_exit+0x0/0x13 returned
> 0 after 0 usecs
> [ 1.673348] calling cpu_stop_init+0x0/0x87 @ 1
> [ 1.673364] initcall cpu_stop_init+0x0/0x87 returned 0 after 0 usecs
> [ 1.673366] calling init_kprobes+0x0/0x149 @ 1
> [ 1.673495] initcall init_kprobes+0x0/0x149 returned 0 after 0 usecs
> [ 1.673497] calling init_events+0x0/0x4d @ 1
> [ 1.673502] initcall init_events+0x0/0x4d returned 0 after 0 usecs
> [ 1.673504] calling init_trace_printk+0x0/0xc @ 1
> [ 1.673505] initcall init_trace_printk+0x0/0xc returned 0 after
> 0 usecs
> [ 1.673507] calling event_trace_enable_again+0x0/0x23 @ 1
> [ 1.673508] initcall event_trace_enable_again+0x0/0x23 returned
> 0 after 0 usecs
>
> The function `univ8250_console_init()` is not available in
> `/sys/kernel/debug/tracing/available_filter_functions`, so I’d like to
> trace `univ8250_console_setup()`:
>
> initcall_debug log_buf_len=32M trace_buf_size=262144K
> trace_clock=global
> trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,funcgraph-duration,funcgraph-proc,funcgraph-tail,nofuncgraph-overhead,context-info,graph-time
> ftrace=fun
> ction_graph ftrace_graph_max_depth=2
> ftrace_graph_filter=univ8250_console_setup tp_printk
>
> Unfortunately, `/sys/kernel/debug/tracing/trace` is empty, so I guess
> the console happens before ftrace is available?
"function" tracing is enabled by then (I just tested it), but
"function_graph" is not. Function graph requires trace events enabled,
but I could see what happens if I do enabled it ;-)
>
> Is there another way to trace the serial console init, without having to
> add print statements?
>
Use "ftrace=function" but then you will get everything. You could add a
"set_filter=<func>:traceoff" to set a trigger that would disable
tracing, if you can find a function that would be good to stop tracing
with.
Otherwise, I could take a look to see what it takes to get function
graph tracing working that early.
-- Steve
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: How to trace serial console init during boot-time?
2022-10-08 20:43 ` Steven Rostedt
@ 2022-10-11 9:13 ` Paul Menzel
0 siblings, 0 replies; 3+ messages in thread
From: Paul Menzel @ 2022-10-11 9:13 UTC (permalink / raw)
To: Steven Rostedt
Cc: Ingo Molnar, Greg Kroah-Hartman, linux-serial, Petr Mladek,
Sergey Senozhatsky, LKML
Dear Steven,
Thank you very much for the quick reply.
Am 08.10.22 um 22:43 schrieb Steven Rostedt:
> On Fri, 7 Oct 2022 15:30:56 +0200 Paul Menzel wrote:
>> I am trying to do boot-time tracing of `univ8250_console_init()`:
>>
>> [ 0.126636] ftrace: allocating 41793 entries in 164 pages
>> [ 0.132446] ftrace: allocated 164 pages with 3 groups
>> […]
>> [ 0.167334] calling con_init+0x0/0x239 @ 0
>> [ 0.170217] Console: colour VGA+ 80x25
>> [ 0.190381] printk: console [tty0] enabled
>> [ 0.190484] initcall con_init+0x0/0x239 returned 0 after 0 usecs
>> [ 0.190487] calling hvc_console_init+0x0/0x18 @ 0
>> [ 0.190489] initcall hvc_console_init+0x0/0x18 returned 0 after 0 usecs
>> [ 0.190491] calling univ8250_console_init+0x0/0x2b @ 0
>> [ 1.488645] printk: console [ttyS0] enabled
>> [ 1.492945] initcall univ8250_console_init+0x0/0x2b returned 0 after 0 usecs
>> […]
>> [ 1.670397] calling trace_init_perf_perm_irq_work_exit+0x0/0x17 @ 1
>> [ 1.670399] initcall trace_init_perf_perm_irq_work_exit+0x0/0x17 returned 0 after 0 usecs
>> […]
>> [ 1.673339] calling trace_init_flags_sys_enter+0x0/0x13 @ 1
>> [ 1.673342] initcall trace_init_flags_sys_enter+0x0/0x13 returned 0 after 0 usecs
>> [ 1.673344] calling trace_init_flags_sys_exit+0x0/0x13 @ 1
>> [ 1.673346] initcall trace_init_flags_sys_exit+0x0/0x13 returned 0 after 0 usecs
>> [ 1.673348] calling cpu_stop_init+0x0/0x87 @ 1
>> [ 1.673364] initcall cpu_stop_init+0x0/0x87 returned 0 after 0 usecs
>> [ 1.673366] calling init_kprobes+0x0/0x149 @ 1
>> [ 1.673495] initcall init_kprobes+0x0/0x149 returned 0 after 0 usecs
>> [ 1.673497] calling init_events+0x0/0x4d @ 1
>> [ 1.673502] initcall init_events+0x0/0x4d returned 0 after 0 usecs
>> [ 1.673504] calling init_trace_printk+0x0/0xc @ 1
>> [ 1.673505] initcall init_trace_printk+0x0/0xc returned 0 after 0 usecs
>> [ 1.673507] calling event_trace_enable_again+0x0/0x23 @ 1
>> [ 1.673508] initcall event_trace_enable_again+0x0/0x23 returned 0 after 0 usecs
>>
>> The function `univ8250_console_init()` is not available in
>> `/sys/kernel/debug/tracing/available_filter_functions`, so I’d like to
>> trace `univ8250_console_setup()`:
>>
>> initcall_debug log_buf_len=32M trace_buf_size=262144K trace_clock=global trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,funcgraph-duration,funcgraph-proc,funcgraph-tail,nofuncgraph-overhead,context-info,graph-time ftrace=function_graph ftrace_graph_max_depth=2 ftrace_graph_filter=univ8250_console_setup tp_printk
>>
>> Unfortunately, `/sys/kernel/debug/tracing/trace` is empty, so I guess
>> the console happens before ftrace is available?
>
> "function" tracing is enabled by then (I just tested it), but
> "function_graph" is not. Function graph requires trace events enabled,
> but I could see what happens if I do enabled it ;-)
>
>>
>> Is there another way to trace the serial console init, without having to
>> add print statements?
>
> Use "ftrace=function" but then you will get everything. You could add a
> "set_filter=<func>:traceoff" to set a trigger that would disable
> tracing, if you can find a function that would be good to stop tracing
> with.
Thank you. That worked. As I didn’t use a trigger to stop tracing, the
resulting trace was over 1 GB in size, but I found what I was looking for.
> Otherwise, I could take a look to see what it takes to get function
> graph tracing working that early.
Having earlier tracing is always an improvement, but right now it’s not
necessary at least for me anymore.
Thank you again.
Kind regards,
Paul
PS: With the trace, I started the thread *Do not delay boot when
printing log to serial console during startup?* [1].
[1]:
https://lore.kernel.org/linux-serial/c87cc376-3b0d-8fda-7fc1-555c930faaf1@molgen.mpg.de/
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2022-10-11 9:13 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-10-07 13:30 How to trace serial console init during boot-time? Paul Menzel
2022-10-08 20:43 ` Steven Rostedt
2022-10-11 9:13 ` Paul Menzel
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).