How to trace serial console init during boot-time?

[Paul Menzel]

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