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@xxxxxxxxxxxxx/
