> -----Original Message----- > From: Francesco Valla <francesco@xxxxxxxx> ... > On Tuesday, 3 December 2024 at 21:33:06 Bird, Tim <Tim.Bird@xxxxxxxx> wrote: ... > > > -----Original Message----- > > > From: Francesco Valla <francesco@xxxxxxxx> ... > > > * deferred_probe_initcall -> 487483us > > > > I feel like this function is interfering with the ability to correctly assign > > boot time delays to the correct initcall. > > > > I would really like to see someone tackle this issue, by studying the deferred_probe_initcall > > function, to see if there's a way to instrument it so that the cost of each > > probe can be reported and then associated with corresponding initcall, when initcall_debug > > is used. > > > > Does anyone want to look into this issue? > > I can take a look, but probably toward the end of the year. Another similar area I'd like to investigate > is related to initcall time vs actual probe time: for drivers instantiated multiple time, I'd like to know > how much time each probe took rather than the overall time. OK - here's an experimental patch to instrument deferred probing more. It builds on the already existing instrumentation for initcall_debug, but prints a bit more detail about the probe function that is in effect during certain delays during boot. Here is some output, from a kernel with this patch, filtered by grepping for "probe": (this was on a beagleplay running a kernel with initcall_debug turned on) $ ttc bp1 run "dmesg | grep probe" [ 0.003825] calling init_kprobes+0x0/0x190 @ 1 [ 0.004085] initcall init_kprobes+0x0/0x190 returned 0 after 4000 usecs [ 0.044089] calling trace_events_eprobe_init_early+0x0/0x60 @ 1 [ 0.044101] initcall trace_events_eprobe_init_early+0x0/0x60 returned 0 after 0 usecs [ 0.044112] calling init_kprobe_trace_early+0x0/0x48 @ 1 [ 0.044125] initcall init_kprobe_trace_early+0x0/0x48 returned 0 after 0 usecs [ 0.046498] platform probe dummy_regulator_probe is being called [ 0.046674] probe platform_probe in driver reg-dummy for device reg-dummy returned 0 after 0 usecs [ 0.049728] calling release_early_probes+0x0/0x70 @ 1 [ 0.049739] initcall release_early_probes+0x0/0x70 returned 0 after 0 usecs [ 0.057708] probe platform_probe in driver davinci_gpio for device 4201000.gpio returned -517 after 0 usecs [ 0.058357] platform probe sram_probe is being called [ 0.058463] probe platform_probe in driver sram for device 70000000.sram returned 0 after 0 usecs [ 0.061883] probe platform_probe in driver davinci_gpio for device 600000.gpio returned -517 after 0 usecs [ 0.062054] probe platform_probe in driver davinci_gpio for device 601000.gpio returned -517 after 0 usecs [ 0.070308] platform probe k3_chipinfo_probe is being called [ 0.070580] probe platform_probe in driver k3-chipinfo for device 43000014.chipid returned 0 after 0 usecs [ 0.071233] platform probe reg_fixed_voltage_probe is being called [ 0.071401] probe platform_probe in driver reg-fixed-voltage for device regulator-2 returned -517 after 0 usecs [ 0.071437] probe platform_probe in driver reg-fixed-voltage for device regulator-3 returned -517 after 0 usecs [ 0.071461] probe platform_probe in driver reg-fixed-voltage for device regulator-4 returned -517 after 0 usecs [ 0.071487] probe platform_probe in driver gpio-regulator for device regulator-5 returned -517 after 0 usecs [ 0.071663] probe platform_probe in driver reg-fixed-voltage for device regulator-1 returned 0 after 0 usecs [ 0.073156] probe platform_probe in driver omap_i2c for device 4900000.i2c returned -517 after 0 usecs [ 0.073228] probe platform_probe in driver omap_i2c for device 20000000.i2c returned -517 after 0 usecs [ 0.073250] probe platform_probe in driver omap_i2c for device 20010000.i2c returned -517 after 0 usecs [ 0.073272] probe platform_probe in driver omap_i2c for device 20020000.i2c returned -517 after 0 usecs [ 0.073293] probe platform_probe in driver omap_i2c for device 20030000.i2c returned -517 after 0 usecs [ 0.074080] platform probe psci_cpuidle_domain_probe is being called [ 0.074129] probe platform_probe in driver psci-cpuidle-domain for device firmware:psci returned 0 after 0 usecs [ 0.077465] calling init_kprobe_trace+0x0/0x220 @ 1 [ 0.842940] initcall init_kprobe_trace+0x0/0x220 returned 0 after 765459 usecs [ 0.843041] calling init_uprobe_trace+0x0/0x98 @ 1 [ 0.843068] initcall init_uprobe_trace+0x0/0x98 returned 0 after 17 usecs [ 0.855784] calling arch_init_uprobes+0x0/0x48 @ 1 [ 0.855796] initcall arch_init_uprobes+0x0/0x48 returned 0 after 1 usecs [ 0.893082] platform probe ti_sci_intr_irq_domain_probe is being called [ 0.893128] probe platform_probe in driver ti-sci-intr for device 4210000.interrupt-controller returned 517 after 111 usecs [ 0.893318] platform probe ti_sci_intr_irq_domain_probe is being called [ 0.893339] probe platform_probe in driver ti-sci-intr for device bus@f0000:interrupt-controller@a00000 returned 517 after 54 usecs [ 0.893557] platform probe ti_sci_inta_irq_domain_probe is being called [ 0.893575] probe platform_probe in driver ti-sci-inta for device 48000000.interrupt-controller returned 517 after 44 usecs [ 0.893712] platform probe simple_pm_bus_probe is being called [ 0.894140] probe platform_probe in driver simple-pm-bus for device bus@f0000 returned 0 after 449 usecs [ 0.894178] platform probe simple_pm_bus_probe is being called [ 0.894234] probe platform_probe in driver simple-pm-bus for device bus@f0000:bus@4000000 returned 0 after 78 usecs [ 0.894279] platform probe simple_pm_bus_probe is being called [ 0.894317] probe platform_probe in driver simple-pm-bus for device bus@f0000:bus@b00000 returned 0 after 60 usecs [ 0.894351] platform probe simple_pm_bus_probe is being called [ 0.894363] probe platform_probe in driver simple-pm-bus for device 43000000.syscon returned 19 after 32 usecs [ 0.894403] platform probe simple_pm_bus_probe is being called [ 0.894414] probe platform_probe in driver simple-pm-bus for device 100000.syscon returned 19 after 30 usecs [ 0.894453] platform probe simple_pm_bus_probe is being called [ 0.894487] probe platform_probe in driver simple-pm-bus for device bus@f0000:bus@48000000 returned 0 after 54 usecs [ 0.894574] platform probe simple_pm_bus_probe is being called [ 0.894601] probe platform_probe in driver simple-pm-bus for device fc00000.bus returned 0 after 47 usecs [ 0.895465] platform probe phy_gmii_sel_probe is being called [ 0.895835] probe platform_probe in driver phy-gmii-sel for device 104044.phy returned 0 after 395 usecs [ 0.896246] platform probe pcs_probe is being called [ 0.896588] probe platform_probe in driver pinctrl-single for device 4084000.pinctrl returned 0 after 369 usecs [ 0.896686] platform probe pcs_probe is being called [ 0.898159] probe platform_probe in driver pinctrl-single for device f4000.pinctrl returned 0 after 1501 usecs [ 0.900582] platform probe ti_syscon_gate_clk_probe is being called [ 0.900789] probe platform_probe in driver ti-syscon-gate-clk for device 104130.clock-controller returned 0 after 251 usecs [ 0.900816] probe platform_probe in driver ti-syscon-gate-clk for device 1082e0.clock-controller returned -517 after 10 usecs [ 0.900837] probe platform_probe in driver ti-syscon-gate-clk for device 1082e4.clock-controller returned -517 after 7 usecs [ 0.901084] platform probe udma_probe is being called [ 0.901191] probe platform_probe in driver ti-udma for device 485c0100.dma-controller returned 517 after 140 usecs [ 0.901287] platform probe udma_probe is being called [ 0.901346] probe platform_probe in driver ti-udma for device 485c0000.dma-controller returned 517 after 89 usecs [ 0.906403] probe serial_ctrl_probe in driver ctrl for device serial8250:0 returned 0 after 37 usecs [ 0.906481] probe serial_port_probe in driver port for device serial8250:0.0 returned 0 after 18 usecs [ 0.906812] probe serial_port_probe in driver port for device serial8250:0.1 returned 0 after 21 usecs [ 0.907078] probe serial_port_probe in driver port for device serial8250:0.2 returned 0 after 17 usecs [ 0.907328] probe serial_port_probe in driver port for device serial8250:0.3 returned 0 after 17 usecs [ 0.907580] probe serial_port_probe in driver port for device serial8250:0.4 returned 0 after 17 usecs [ 0.907848] probe serial_port_probe in driver port for device serial8250:0.5 returned 0 after 17 usecs [ 0.908102] probe serial_port_probe in driver port for device serial8250:0.6 returned 0 after 18 usecs [ 0.908353] probe serial_port_probe in driver port for device serial8250:0.7 returned 0 after 17 usecs [ 0.908604] probe serial_port_probe in driver port for device serial8250:0.8 returned 0 after 16 usecs [ 0.908852] probe serial_port_probe in driver port for device serial8250:0.9 returned 0 after 16 usecs [ 0.909110] probe serial_port_probe in driver port for device serial8250:0.10 returned 0 after 17 usecs [ 0.909420] probe serial_port_probe in driver port for device serial8250:0.11 returned 0 after 19 usecs [ 0.909771] platform probe serial8250_probe is being called [ 0.909791] probe platform_probe in driver serial8250 for device serial8250 returned 0 after 41 usecs [ 0.910194] probe platform_probe in driver omap8250 for device 2800000.serial returned 517 after 121 usecs [ 0.910228] probe platform_probe in driver omap8250 for device 2850000.serial returned -517 after 16 usecs [ 0.910251] probe platform_probe in driver omap8250 for device 2860000.serial returned -517 after 7 usecs [ 0.920029] calling cfi_probe_init+0x0/0x40 @ 1 [ 0.920039] initcall cfi_probe_init+0x0/0x40 returned 0 after 0 usecs [ 0.923593] probe platform_probe in driver mdio-gpio for device mdio returned -517 after 9 usecs [ 0.924519] probe platform_probe in driver am65-cpsw-nuss for device 8000000.ethernet returned -517 after 21 usecs [ 0.925689] probe platform_probe in driver dwc3-am62 for device f900000.dwc3-usb returned -517 after 16 usecs [ 0.925713] probe platform_probe in driver dwc3-am62 for device f910000.dwc3-usb returned -517 after 7 usecs [ 0.928710] platform probe ti_cpufreq_probe is being called [ 0.929101] platform probe dt_cpufreq_probe is being called [ 0.929161] probe platform_probe in driver cpufreq-dt for device cpufreq-dt returned 517 after 78 usecs [ 0.929190] probe platform_probe in driver ti-cpufreq for device ti-cpufreq returned 0 after 518 usecs [ 0.929796] platform probe psci_cpuidle_probe is being called [ 0.929822] probe platform_probe in driver psci-cpuidle for device psci-cpuidle returned 19 after 46 usecs [ 0.930416] probe platform_probe in driver sdhci-am654 for device fa10000.mmc returned -517 after 21 usecs [ 0.930429] probe platform_probe in driver sdhci-am654 for device fa00000.mmc returned -517 after 15 usecs [ 0.930449] probe platform_probe in driver sdhci-am654 for device fa20000.mmc returned -517 after 19 usecs [ 0.930922] platform probe gpio_led_probe is being called [ 0.930973] probe platform_probe in driver leds-gpio for device leds returned 517 after 97 usecs [ 0.931496] probe platform_probe in driver ti-sci for device 44043000.system-controller returned -517 after 4 usecs [ 0.932190] probe platform_probe in driver omap_timer for device 2400000.timer returned -517 after 13 usecs [ 0.932217] probe platform_probe in driver omap_timer for device 2410000.timer returned -517 after 12 usecs [ 0.932238] probe platform_probe in driver omap_timer for device 2420000.timer returned -517 after 7 usecs [ 0.932258] probe platform_probe in driver omap_timer for device 2430000.timer returned -517 after 7 usecs [ 0.932277] probe platform_probe in driver omap_timer for device 2440000.timer returned -517 after 7 usecs [ 0.932297] probe platform_probe in driver omap_timer for device 2450000.timer returned -517 after 7 usecs [ 0.932317] probe platform_probe in driver omap_timer for device 2460000.timer returned -517 after 7 usecs [ 0.932337] probe platform_probe in driver omap_timer for device 2470000.timer returned -517 after 7 usecs [ 0.933540] platform probe omap_mbox_probe is being called [ 0.933594] probe platform_probe in driver omap-mailbox for device 29000000.mailbox returned 19 after 104 usecs [ 0.933746] platform probe ti_msgmgr_probe is being called [ 0.934097] probe platform_probe in driver ti-msgmgr for device 4d000000.mailbox returned 0 after 380 usecs [ 0.934692] platform probe armv8_pmu_device_probe is being called [ 0.935257] probe platform_probe in driver armv8-pmu for device pmu returned 0 after 593 usecs [ 0.935845] platform probe optee_probe is being called [ 0.952849] probe platform_probe in driver optee for device firmware:optee returned 0 after 17036 usecs [ 0.954457] platform probe snd_soc_dummy_probe is being called [ 0.954498] probe platform_probe in driver snd-soc-dummy for device snd-soc-dummy returned 0 after 73 usecs [ 0.963947] calling debugfs_kprobe_init+0x0/0xc0 @ 1 [ 0.963974] initcall debugfs_kprobe_init+0x0/0xc0 returned 0 after 17 usecs [ 0.973856] calling deferred_probe_initcall+0x0/0xc8 @ 1 [ 0.973989] probe platform_probe in driver davinci_gpio for device 4201000.gpio returned -517 after 24 usecs [ 0.974036] probe platform_probe in driver davinci_gpio for device 600000.gpio returned -517 after 8 usecs [ 0.974071] probe platform_probe in driver davinci_gpio for device 601000.gpio returned -517 after 7 usecs [ 0.974627] platform probe reg_fixed_voltage_probe is being called [ 0.974730] probe platform_probe in driver reg-fixed-voltage for device regulator-3 returned -517 after 6 usecs [ 0.974873] probe platform_probe in driver reg-fixed-voltage for device regulator-4 returned -517 after 4 usecs [ 0.975017] probe platform_probe in driver omap_i2c for device 4900000.i2c returned -517 after 23 usecs [ 0.975031] probe platform_probe in driver gpio-regulator for device regulator-5 returned -517 after 34 usecs [ 0.975059] probe platform_probe in driver omap_i2c for device 20000000.i2c returned -517 after 7 usecs [ 0.975075] probe platform_probe in driver reg-fixed-voltage for device regulator-2 returned 0 after 535 usecs [ 0.975093] probe platform_probe in driver omap_i2c for device 20010000.i2c returned -517 after 7 usecs [ 0.975124] probe platform_probe in driver omap_i2c for device 20020000.i2c returned -517 after 7 usecs [ 0.975156] probe platform_probe in driver omap_i2c for device 20030000.i2c returned -517 after 7 usecs [ 0.975238] platform probe ti_sci_intr_irq_domain_probe is being called [ 0.975272] probe platform_probe in driver ti-sci-intr for device 4210000.interrupt-controller returned 517 after 88 usecs [ 0.975471] platform probe ti_sci_intr_irq_domain_probe is being called [ 0.975488] probe platform_probe in driver ti-sci-intr for device bus@f0000:interrupt-controller@a00000 returned 517 after 44 usecs [ 0.975649] platform probe ti_sci_inta_irq_domain_probe is being called [ 0.975667] probe platform_probe in driver ti-sci-inta for device 48000000.interrupt-controller returned 517 after 46 usecs [ 0.975826] probe platform_probe in driver ti-syscon-gate-clk for device 1082e0.clock-controller returned -517 after 8 usecs [ 0.975885] probe platform_probe in driver ti-syscon-gate-clk for device 1082e4.clock-controller returned -517 after 8 usecs [ 0.975967] platform probe udma_probe is being called [ 0.976095] probe platform_probe in driver ti-udma for device 485c0100.dma-controller returned 517 after 157 usecs [ 0.976258] platform probe udma_probe is being called [ 0.976315] probe platform_probe in driver ti-udma for device 485c0000.dma-controller returned 517 after 85 usecs [ 0.976558] probe platform_probe in driver omap8250 for device 2800000.serial returned 517 after 93 usecs [ 0.976723] probe platform_probe in driver omap8250 for device 2850000.serial returned -517 after 11 usecs [ 0.976804] probe platform_probe in driver omap8250 for device 2860000.serial returned -517 after 7 usecs [ 0.976888] probe platform_probe in driver mdio-gpio for device mdio returned -517 after 3 usecs [ 0.976986] probe platform_probe in driver am65-cpsw-nuss for device 8000000.ethernet returned -517 after 8 usecs [ 0.977082] probe platform_probe in driver dwc3-am62 for device f900000.dwc3-usb returned -517 after 8 usecs [ 0.977178] probe platform_probe in driver dwc3-am62 for device f910000.dwc3-usb returned -517 after 7 usecs [ 0.977308] platform probe dt_cpufreq_probe is being called [ 0.977371] probe platform_probe in driver cpufreq-dt for device cpufreq-dt returned 517 after 93 usecs [ 0.977707] probe platform_probe in driver sdhci-am654 for device fa10000.mmc returned -517 after 13 usecs [ 0.977869] probe platform_probe in driver sdhci-am654 for device fa00000.mmc returned -517 after 16 usecs [ 0.978019] probe platform_probe in driver sdhci-am654 for device fa20000.mmc returned -517 after 9 usecs [ 0.978054] platform probe gpio_led_probe is being called [ 0.978102] probe platform_probe in driver leds-gpio for device leds returned 517 after 95 usecs [ 0.978264] platform probe ti_sci_probe is being called [ 0.981447] platform probe ti_sci_pm_domain_probe is being called [ 0.982522] probe platform_probe in driver ti_sci_pm_domains for device 44043000.system-controller:power-controller returned 0 after 1140 usecs [ 0.984639] platform probe ti_sci_clk_probe is being called [ 1.036888] probe platform_probe in driver ti-sci-clk for device 44043000.system-controller:clock-controller returned 0 after 52299 usecs [ 1.037414] platform probe ti_sci_reset_probe is being called [ 1.037459] probe platform_probe in driver ti-sci-reset for device 44043000.system-controller:reset-controller returned 0 after 101 usecs [ 1.037504] probe platform_probe in driver ti-sci for device 44043000.system-controller returned 0 after 59269 usecs [ 1.037910] platform probe omap_dm_timer_probe is being called [ 1.038244] probe platform_probe in driver omap_timer for device 2400000.timer returned 0 after 474 usecs [ 1.038564] platform probe omap_dm_timer_probe is being called [ 1.038788] probe platform_probe in driver omap_timer for device 2410000.timer returned 0 after 327 usecs [ 1.039185] platform probe omap_dm_timer_probe is being called [ 1.039449] probe platform_probe in driver omap_timer for device 2420000.timer returned 0 after 393 usecs [ 1.039752] platform probe omap_dm_timer_probe is being called [ 1.039948] probe platform_probe in driver omap_timer for device 2430000.timer returned 0 after 300 usecs [ 1.040211] platform probe omap_dm_timer_probe is being called [ 1.040394] probe platform_probe in driver omap_timer for device 2440000.timer returned 0 after 281 usecs [ 1.040647] platform probe omap_dm_timer_probe is being called [ 1.040840] probe platform_probe in driver omap_timer for device 2450000.timer returned 0 after 287 usecs [ 1.041096] platform probe omap_dm_timer_probe is being called [ 1.041348] probe platform_probe in driver omap_timer for device 2460000.timer returned 0 after 351 usecs [ 1.041623] platform probe omap_dm_timer_probe is being called [ 1.041812] probe platform_probe in driver omap_timer for device 2470000.timer returned 0 after 290 usecs [ 1.041845] probe platform_probe in driver davinci_gpio for device 4201000.gpio returned -517 after 7 usecs [ 1.041879] probe platform_probe in driver davinci_gpio for device 600000.gpio returned -517 after 3 usecs [ 1.041908] probe platform_probe in driver davinci_gpio for device 601000.gpio returned -517 after 3 usecs [ 1.042164] probe platform_probe in driver reg-fixed-voltage for device regulator-3 returned -517 after 5 usecs [ 1.042293] probe platform_probe in driver reg-fixed-voltage for device regulator-4 returned -517 after 3 usecs [ 1.042448] platform probe omap_i2c_probe is being called [ 1.043411] probe platform_probe in driver omap_i2c for device 4900000.i2c returned 0 after 1124 usecs [ 1.043762] probe platform_probe in driver gpio-regulator for device regulator-5 returned -517 after 16 usecs [ 1.043940] platform probe omap_i2c_probe is being called [ 1.070994] platform probe tps65219_regulator_probe is being called [ 1.070994] platform probe tps65219_gpio_probe is being called [ 1.071562] probe platform_probe in driver tps65219-gpio for device tps65219-gpio.1.auto returned 0 after 608 usecs [ 1.072220] probe i2c_device_probe in driver tps65219 for device 0-0030 returned 0 after 26681 usecs [ 1.072780] probe platform_probe in driver omap_i2c for device 20000000.i2c returned 0 after 29033 usecs [ 1.073092] platform probe omap_i2c_probe is being called [ 1.074288] probe platform_probe in driver omap_i2c for device 20010000.i2c returned 0 after 1442 usecs [ 1.074580] platform probe omap_i2c_probe is being called [ 1.076436] probe platform_probe in driver omap_i2c for device 20020000.i2c returned 0 after 2067 usecs [ 1.076737] platform probe omap_i2c_probe is being called [ 1.077779] probe platform_probe in driver omap_i2c for device 20030000.i2c returned 0 after 1273 usecs [ 1.077917] platform probe ti_sci_intr_irq_domain_probe is being called [ 1.078074] probe platform_probe in driver ti-sci-intr for device 4210000.interrupt-controller returned 0 after 214 usecs [ 1.078171] platform probe ti_sci_intr_irq_domain_probe is being called [ 1.078272] probe platform_probe in driver ti-sci-intr for device bus@f0000:interrupt-controller@a00000 returned 0 after 132 usecs [ 1.078332] platform probe ti_sci_inta_irq_domain_probe is being called [ 1.078346] probe platform_probe in driver tps65219-pmic for device tps65219-regulator.0.auto returned 0 after 7393 usecs [ 1.078574] probe platform_probe in driver ti-sci-inta for device 48000000.interrupt-controller returned 0 after 273 usecs [ 1.078749] platform probe ti_syscon_gate_clk_probe is being called [ 1.079164] probe platform_probe in driver ti-syscon-gate-clk for device 1082e0.clock-controller returned 0 after 473 usecs [ 1.079287] platform probe ti_syscon_gate_clk_probe is being called [ 1.079527] probe platform_probe in driver ti-syscon-gate-clk for device 1082e4.clock-controller returned 0 after 279 usecs [ 1.079628] platform probe udma_probe is being called [ 1.084883] probe platform_probe in driver ti-udma for device 485c0100.dma-controller returned 0 after 5285 usecs [ 1.085124] platform probe udma_probe is being called [ 1.092231] probe platform_probe in driver ti-udma for device 485c0000.dma-controller returned 0 after 7165 usecs [ 1.092699] platform probe omap8250_probe is being called [ 1.093664] probe serial_ctrl_probe in driver ctrl for device 2800000.serial:0 returned 0 after 38 usecs [ 1.093742] probe serial_port_probe in driver port for device 2800000.serial:0.0 returned 0 after 18 usecs [ 1.158223] probe platform_probe in driver omap8250 for device 2800000.serial returned 0 after 65754 usecs [ 1.158640] platform probe omap8250_probe is being called [ 1.159478] probe serial_ctrl_probe in driver ctrl for device 2850000.serial:0 returned 0 after 32 usecs [ 1.159564] probe serial_port_probe in driver port for device 2850000.serial:0.0 returned 0 after 18 usecs [ 1.159933] probe platform_probe in driver omap8250 for device 2850000.serial returned 0 after 1485 usecs [ 1.160268] platform probe omap8250_probe is being called [ 1.161013] probe serial_ctrl_probe in driver ctrl for device 2860000.serial:0 returned 0 after 30 usecs [ 1.161091] probe serial_port_probe in driver port for device 2860000.serial:0.0 returned 0 after 18 usecs [ 1.161705] probe platform_probe in driver omap8250 for device 2860000.serial returned 0 after 1598 usecs [ 1.162091] probe platform_probe in driver mdio-gpio for device mdio returned -517 after 8 usecs [ 1.162693] platform probe am65_cpsw_nuss_probe is being called [ 1.180111] probe platform_probe in driver am65-cpsw-nuss for device 8000000.ethernet returned 0 after 17869 usecs [ 1.180627] platform probe dwc3_ti_probe is being called [ 1.195673] platform probe dwc3_probe is being called [ 1.198203] probe platform_probe in driver dwc3 for device 31000000.usb returned 0 after 2569 usecs [ 1.198449] probe platform_probe in driver dwc3-am62 for device f900000.dwc3-usb returned 0 after 18007 usecs [ 1.198933] platform probe dwc3_ti_probe is being called [ 1.214312] platform probe dwc3_probe is being called [ 1.214861] platform probe xhci_generic_plat_probe is being called [ 1.216389] probe usb_probe_interface in driver hub for device 1-0:1.0 returned 0 after 237 usecs [ 1.216467] probe usb_probe_device in driver usb for device usb1 returned 0 after 436 usecs [ 1.216536] probe platform_probe in driver xhci-hcd for device xhci-hcd.3.auto returned 0 after 1703 usecs [ 1.216576] probe platform_probe in driver dwc3 for device 31100000.usb returned 0 after 2380 usecs [ 1.216939] probe platform_probe in driver dwc3-am62 for device f910000.dwc3-usb returned 0 after 18209 usecs [ 1.217124] platform probe dt_cpufreq_probe is being called [ 1.218721] probe platform_probe in driver cpufreq-dt for device cpufreq-dt returned 0 after 1641 usecs [ 1.219429] probe platform_probe in driver sdhci-am654 for device fa00000.mmc returned -517 after 8 usecs [ 1.219587] probe platform_probe in driver sdhci-am654 for device fa20000.mmc returned -517 after 4 usecs [ 1.219603] platform probe gpio_led_probe is being called [ 1.219603] platform probe sdhci_am654_probe is being called [ 1.219678] probe platform_probe in driver leds-gpio for device leds returned 517 after 110 usecs [ 1.219861] platform probe davinci_gpio_probe is being called [ 1.221502] probe platform_probe in driver davinci_gpio for device 4201000.gpio returned 0 after 1760 usecs [ 1.221830] platform probe davinci_gpio_probe is being called [ 1.225318] probe platform_probe in driver davinci_gpio for device 600000.gpio returned 0 after 3732 usecs [ 1.225607] platform probe davinci_gpio_probe is being called [ 1.227855] probe platform_probe in driver davinci_gpio for device 601000.gpio returned 0 after 2461 usecs [ 1.228478] platform probe reg_fixed_voltage_probe is being called [ 1.228613] platform probe reg_fixed_voltage_probe is being called [ 1.228800] platform probe mdio_gpio_probe is being called [ 1.229055] probe platform_probe in driver reg-fixed-voltage for device regulator-4 returned 0 after 531 usecs [ 1.229055] probe platform_probe in driver reg-fixed-voltage for device regulator-3 returned 0 after 722 usecs [ 1.229110] platform probe gpio_regulator_probe is being called [ 1.229760] probe platform_probe in driver gpio-regulator for device regulator-5 returned 0 after 741 usecs [ 1.231825] probe phy_probe in driver RTL8211F-VD Gigabit Ethernet for device gpio-0:00 returned 0 after 1503 usecs [ 1.257881] probe platform_probe in driver sdhci-am654 for device fa10000.mmc returned 0 after 38624 usecs [ 1.310422] probe mmc_bus_probe in driver mmcblk for device mmc0:0001 returned 0 after 4604 usecs [ 1.366103] probe phy_probe in driver TI DP83TD510E for device gpio-0:01 returned 0 after 68640 usecs [ 1.366296] probe platform_probe in driver mdio-gpio for device mdio returned 0 after 137582 usecs [ 1.367130] platform probe gpio_led_probe is being called [ 1.367262] platform probe sdhci_am654_probe is being called [ 1.367305] platform probe sdhci_am654_probe is being called [ 1.367917] probe platform_probe in driver leds-gpio for device leds returned 0 after 862 usecs [ 1.367997] initcall deferred_probe_initcall+0x0/0xc8 returned 0 after 394128 usecs [ 1.370955] platform probe gpio_keys_probe is being called [ 1.371580] probe platform_probe in driver gpio-keys for device gpio-keys returned 0 after 777 usecs [ 1.406004] probe platform_probe in driver sdhci-am654 for device fa20000.mmc returned 0 after 38948 usecs [ 1.408093] probe platform_probe in driver sdhci-am654 for device fa00000.mmc returned 0 after 41196 usecs [ 1.424172] probe mmc_bus_probe in driver mmcblk for device mmc2:0001 returned 19 after 71 usecs [ 1.624661] probe mmc_bus_probe in driver mmcblk for device mmc1:0001 returned 0 after 3742 usecs ---- Below is the patch that adds the extra instrumentation. My quick question is, does this look useful? Can it be used to find the more problematic (ie long-duration) probe functions or drivers initializations? Full boot data from a run with this instrumentation is available at: https://birdcloud.org/boot-time-files/boot-data-timslab-bp1-241208-191139.txt Please provide any feedback you have. -- Tim ---- diff --git a/drivers/base/dd.c b/drivers/base/dd.c index 0c3725c3eefa..5e19079b0a2b 100644 --- a/drivers/base/dd.c +++ b/drivers/base/dd.c @@ -28,6 +28,7 @@ #include <linux/pm_runtime.h> #include <linux/pinctrl/devinfo.h> #include <linux/slab.h> +#include <linux/kallsyms.h> #include "base.h" #include "power/power.h" @@ -732,8 +733,16 @@ static int really_probe(struct device *dev, struct device_driver *drv) static int really_probe_debug(struct device *dev, struct device_driver *drv) { ktime_t calltime, rettime; + char fn_name[KSYM_SYMBOL_LEN]; + unsigned long addr = 0; int ret; + if (dev->bus->probe) + addr = (unsigned long)dev->bus->probe; + else if (drv->probe) + addr = (unsigned long)drv->probe; + sprint_symbol_no_offset(fn_name, addr); + calltime = ktime_get(); ret = really_probe(dev, drv); rettime = ktime_get(); @@ -742,8 +751,8 @@ static int really_probe_debug(struct device *dev, struct device_driver *drv) * CONFIG_DYNAMIC_DEBUG and we want a simple 'initcall_debug' on the * kernel commandline to print this all the time at the debug level. */ - printk(KERN_DEBUG "probe of %s returned %d after %lld usecs\n", - dev_name(dev), ret, ktime_us_delta(rettime, calltime)); + printk(KERN_DEBUG "probe %s in driver %s for device %s returned %d after %lld usecs\n", + fn_name, drv->name, dev_name(dev), ret, ktime_us_delta(rettime, calltime)); return ret; } diff --git a/drivers/base/platform.c b/drivers/base/platform.c index 76bfcba25003..ae15969c483a 100644 --- a/drivers/base/platform.c +++ b/drivers/base/platform.c @@ -32,6 +32,7 @@ #include <linux/types.h> #include <linux/iommu.h> #include <linux/dma-map-ops.h> +#include <linux/kallsyms.h> #include "base.h" #include "power/power.h" @@ -1381,6 +1382,9 @@ static int platform_probe(struct device *_dev) struct platform_driver *drv = to_platform_driver(_dev->driver); struct platform_device *dev = to_platform_device(_dev); int ret; + char fn_name[KSYM_SYMBOL_LEN]; + unsigned long addr = 0; + /* * A driver registered using platform_driver_probe() cannot be bound @@ -1401,6 +1405,13 @@ static int platform_probe(struct device *_dev) goto out; if (drv->probe) { + if (initcall_debug) { + addr = (unsigned long)drv->probe; + sprint_symbol_no_offset(fn_name, addr); + + printk(KERN_DEBUG "platform probe %s is being called\n", fn_name); + } + ret = drv->probe(dev); if (ret) dev_pm_domain_detach(_dev, true);
