| Message ID | 20231005095927.12398-2-b.spranger@linutronix.de (mailing list archive) |
|---|---|
| State | Not Applicable, archived |
| Headers | show |
| Series | Broken serial console on Altera Cyclon V board | expand |
Hi, On Thu, Oct 05, 2023 at 11:59:27AM +0200, Benedikt Spranger wrote: > Commit 9607beb917df ("clk: socfpga: gate: Add a determine_rate hook") > introduce a specific determine_rate hook. As a result the calculated > clock for the serial IP is off by factor 2 after that i.e. if the system > configures a baudrate of 115200 it is set physicaly to 57600. Where is that factor 2 coming from? > Change the determine_rate hook to the reparent variant > __clk_mux_determine_rate() to fix the issue. It's also not clear to me why that would fix anything. This patch should only make the old behaviour explicit, could you expand a bit on what happens? Thanks! Maxime
On Thu, 5 Oct 2023 13:34:01 +0200 Maxime Ripard <mripard@kernel.org> wrote: > Hi, > > On Thu, Oct 05, 2023 at 11:59:27AM +0200, Benedikt Spranger wrote: > > Commit 9607beb917df ("clk: socfpga: gate: Add a determine_rate > > hook") introduce a specific determine_rate hook. As a result the > > calculated clock for the serial IP is off by factor 2 after that > > i.e. if the system configures a baudrate of 115200 it is set > > physicaly to 57600. > > Where is that factor 2 coming from? In drivers/tty/serial/8250/8250_dw.c p->uartclk is set twice as high, as it should be: dw8250_set_termios() is called and rate is evaluated to 20000000 in the bad and 10000000 in the good case. As a result p->uartclk is set to 20000000 in the bad case. > > Change the determine_rate hook to the reparent variant > > __clk_mux_determine_rate() to fix the issue. > > It's also not clear to me why that would fix anything. This patch > should only make the old behaviour explicit, could you expand a bit > on what happens? Booting the kernel with console=ttyS0,115200 result in a corrupted character output. Setting the serial terminal application to 57600 make the serial console working. I dug deeper and added some debug output (see patch below): trace output (good - determine_rate = __clk_mux_determine_rate): # tracer: nop # # entries-in-buffer/entries-written: 237/237 #P:2 # # _-----=> irqs-off/BH-disabled # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / _-=> migrate-disable # |||| / delay # TASK-PID CPU# ||||| TIMESTAMP FUNCTION # | | | ||||| | | <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 462500000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 231250000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 115625000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 3125000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 97368421 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 97368421 <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = l4_mp_clk <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: l4_mp_clk = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = l4_sp_clk <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: l4_sp_clk = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 1953125 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 250000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 5 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 40000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 5 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 40000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 6250 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 32000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = sdmmc_clk <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: sdmmc_clk = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: fixed_div: div = 4 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = nand_x_clk <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: nand_clk / nand_x_clk = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: fixed_div: div = 4 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = qspi_clk <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: qspi_clk = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 3613281 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 400000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 800000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 400000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 133333333 <idle>-0 [000] d.... 0.000000: clk_prepare: osc1 <idle>-0 [000] d.... 0.000000: clk_prepare_complete: osc1 <idle>-0 [000] d.... 0.000000: clk_prepare: main_pll <idle>-0 [000] d.... 0.000000: clk_prepare_complete: main_pll <idle>-0 [000] d.... 0.000000: clk_prepare: mpuclk <idle>-0 [000] d.... 0.000000: clk_prepare_complete: mpuclk <idle>-0 [000] d.... 0.000000: clk_prepare: mpu_periph_clk <idle>-0 [000] d.... 0.000000: clk_prepare_complete: mpu_periph_clk <idle>-0 [000] d.... 0.000000: clk_enable: osc1 <idle>-0 [000] d.... 0.000000: clk_enable_complete: osc1 <idle>-0 [000] d.... 0.000000: clk_enable: main_pll <idle>-0 [000] d.... 0.000000: clk_enable_complete: main_pll <idle>-0 [000] d.... 0.000000: clk_enable: mpuclk <idle>-0 [000] d.... 0.000000: clk_enable_complete: mpuclk <idle>-0 [000] d.... 0.000000: clk_enable: mpu_periph_clk <idle>-0 [000] d.... 0.000000: clk_enable_complete: mpu_periph_clk <idle>-0 [000] d.... 0.000000: clk_prepare: periph_pll <idle>-0 [000] d.... 0.000000: clk_prepare_complete: periph_pll <idle>-0 [000] d.... 0.000000: clk_prepare: per_base_clk <idle>-0 [000] d.... 0.000000: clk_prepare_complete: per_base_clk <idle>-0 [000] d.... 0.000000: clk_prepare: l4_sp_clk <idle>-0 [000] d.... 0.000000: clk_prepare_complete: l4_sp_clk <idle>-0 [000] d.... 0.000000: clk_enable: periph_pll <idle>-0 [000] d.... 0.000000: clk_enable_complete: periph_pll <idle>-0 [000] d.... 0.000000: clk_enable: per_base_clk <idle>-0 [000] d.... 0.000000: clk_enable_complete: per_base_clk <idle>-0 [000] d.... 0.000000: clk_enable: l4_sp_clk <idle>-0 [000] d.... 0.000000: clk_enable_complete: l4_sp_clk init-1 [000] .n... 0.033332: clk_prepare: mainclk init-1 [000] .n... 0.033338: clk_prepare_complete: mainclk init-1 [000] .n... 0.033339: clk_prepare: l4_main_clk init-1 [000] .n... 0.033341: clk_prepare_complete: l4_main_clk init-1 [000] dn... 0.033344: clk_enable: mainclk init-1 [000] dn... 0.033345: clk_enable_complete: mainclk init-1 [000] dn... 0.033346: clk_enable: l4_main_clk init-1 [000] dn... 0.033349: clk_enable_complete: l4_main_clk init-1 [000] d.... 0.033420: clk_disable: l4_main_clk init-1 [000] d.... 0.033424: clk_disable_complete: l4_main_clk init-1 [000] d.... 0.033425: clk_disable: mainclk init-1 [000] d.... 0.033426: clk_disable_complete: mainclk init-1 [000] ..... 0.033430: clk_unprepare: l4_main_clk init-1 [000] ..... 0.033431: clk_unprepare_complete: l4_main_clk init-1 [000] ..... 0.033432: clk_unprepare: mainclk init-1 [000] ..... 0.033434: clk_unprepare_complete: mainclk init-1 [001] ..... 0.116063: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.116089: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.116096: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200 init-1 [001] ..... 0.116098: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000 init-1 [001] ..... 0.116100: dw8250_set_termios: dw8250_set_termios: after: uartclk = 100000000 init-1 [001] ..... 0.920389: clk_prepare: emac1_clk init-1 [001] ..... 0.920395: clk_prepare_complete: emac1_clk init-1 [001] ..... 0.920396: clk_prepare: emac_1_clk init-1 [001] ..... 0.920398: clk_prepare_complete: emac_1_clk init-1 [001] d.... 0.920401: clk_enable: emac1_clk init-1 [001] d.... 0.920403: clk_enable_complete: emac1_clk init-1 [001] d.... 0.920404: clk_enable: emac_1_clk init-1 [001] d.... 0.920407: clk_enable_complete: emac_1_clk kworker/1:1-36 [001] d.... 1.041458: clk_disable: emac_1_clk kworker/1:1-36 [001] d.... 1.041465: clk_disable_complete: emac_1_clk kworker/1:1-36 [001] d.... 1.041466: clk_disable: emac1_clk kworker/1:1-36 [001] d.... 1.041468: clk_disable_complete: emac1_clk kworker/1:1-36 [001] ..... 1.041471: clk_unprepare: emac_1_clk kworker/1:1-36 [001] ..... 1.041473: clk_unprepare_complete: emac_1_clk kworker/1:1-36 [001] ..... 1.041474: clk_unprepare: emac1_clk kworker/1:1-36 [001] ..... 1.041475: clk_unprepare_complete: emac1_clk init-1 [001] ..... 1.041519: clk_prepare: usb_mp_clk init-1 [001] ..... 1.041521: clk_prepare_complete: usb_mp_clk init-1 [001] d.... 1.041524: clk_enable: usb_mp_clk init-1 [001] d.... 1.041526: clk_enable_complete: usb_mp_clk kworker/u6:1-33 [001] ..... 1.093644: clk_prepare: l4_mp_clk kworker/u6:1-33 [001] ..... 1.093649: clk_prepare_complete: l4_mp_clk kworker/u6:1-33 [001] d.... 1.093652: clk_enable: l4_mp_clk kworker/u6:1-33 [001] d.... 1.093654: clk_enable_complete: l4_mp_clk kworker/u6:1-33 [001] ..... 1.093663: clk_prepare: per_nand_mmc_clk kworker/u6:1-33 [001] ..... 1.093665: clk_prepare_complete: per_nand_mmc_clk kworker/u6:1-33 [001] ..... 1.093666: clk_prepare: sdmmc_clk kworker/u6:1-33 [001] ..... 1.093667: clk_prepare_complete: sdmmc_clk kworker/u6:1-33 [001] ..... 1.093669: clk_prepare: sdmmc_clk_divided kworker/u6:1-33 [001] ..... 1.093670: clk_prepare_complete: sdmmc_clk_divided kworker/u6:1-33 [001] d.... 1.093672: clk_enable: per_nand_mmc_clk kworker/u6:1-33 [001] d.... 1.093673: clk_enable_complete: per_nand_mmc_clk kworker/u6:1-33 [001] d.... 1.093674: clk_enable: sdmmc_clk kworker/u6:1-33 [001] d.... 1.093676: clk_enable_complete: sdmmc_clk kworker/u6:1-33 [001] d.... 1.093678: clk_enable: sdmmc_clk_divided kworker/u6:1-33 [001] d.... 1.093679: clk_enable_complete: sdmmc_clk_divided kworker/u6:1-33 [001] ..... 1.235194: clk_prepare: mainclk kworker/u6:1-33 [001] ..... 1.235200: clk_prepare_complete: mainclk kworker/u6:1-33 [001] ..... 1.235202: clk_prepare: l4_main_clk kworker/u6:1-33 [001] ..... 1.235203: clk_prepare_complete: l4_main_clk kworker/u6:1-33 [001] d.... 1.235206: clk_enable: mainclk kworker/u6:1-33 [001] d.... 1.235207: clk_enable_complete: mainclk kworker/u6:1-33 [001] d.... 1.235209: clk_enable: l4_main_clk kworker/u6:1-33 [001] d.... 1.235212: clk_enable_complete: l4_main_clk init-1 [001] .n... 1.279697: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] .n... 1.279706: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] .n... 1.279712: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200 init-1 [001] .n... 1.279715: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000 init-1 [001] .n... 1.279717: dw8250_set_termios: dw8250_set_termios: after: uartclk = 100000000 kworker/1:1-36 [001] d.... 1.285954: clk_disable: l4_main_clk kworker/1:1-36 [001] d.... 1.285960: clk_disable_complete: l4_main_clk kworker/1:1-36 [001] d.... 1.285962: clk_disable: mainclk kworker/1:1-36 [001] d.... 1.285963: clk_disable_complete: mainclk (udev-worker)-83 [000] ..... 1.849061: clk_prepare: emac1_clk (udev-worker)-83 [000] ..... 1.849068: clk_prepare_complete: emac1_clk (udev-worker)-83 [000] ..... 1.849070: clk_prepare: emac_1_clk (udev-worker)-83 [000] ..... 1.849071: clk_prepare_complete: emac_1_clk (udev-worker)-83 [000] d.... 1.849075: clk_enable: emac1_clk (udev-worker)-83 [000] d.... 1.849077: clk_enable_complete: emac1_clk (udev-worker)-83 [000] d.... 1.849078: clk_enable: emac_1_clk (udev-worker)-83 [000] d.... 1.849082: clk_enable_complete: emac_1_clk kworker/0:1-10 [000] d.... 1.850179: clk_disable: emac_1_clk kworker/0:1-10 [000] d.... 1.850187: clk_disable_complete: emac_1_clk kworker/0:1-10 [000] d.... 1.850193: clk_disable: emac1_clk kworker/0:1-10 [000] d.... 1.850194: clk_disable_complete: emac1_clk kworker/0:1-10 [000] ..... 1.850198: clk_unprepare: emac_1_clk kworker/0:1-10 [000] ..... 1.850200: clk_unprepare_complete: emac_1_clk kworker/0:1-10 [000] ..... 1.850202: clk_unprepare: emac1_clk kworker/0:1-10 [000] ..... 1.850203: clk_unprepare_complete: emac1_clk init-1 [000] ..... 2.730939: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] ..... 2.730947: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] ..... 2.730953: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200 init-1 [000] ..... 2.730956: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000 init-1 [000] ..... 2.730958: dw8250_set_termios: dw8250_set_termios: after: uartclk = 100000000 (udev-worker)-229 [000] ..... 4.222397: clk_prepare: emac1_clk (udev-worker)-229 [000] ..... 4.222404: clk_prepare_complete: emac1_clk (udev-worker)-229 [000] ..... 4.222405: clk_prepare: emac_1_clk (udev-worker)-229 [000] ..... 4.222407: clk_prepare_complete: emac_1_clk (udev-worker)-229 [000] d.... 4.222410: clk_enable: emac1_clk (udev-worker)-229 [000] d.... 4.222412: clk_enable_complete: emac1_clk (udev-worker)-229 [000] d.... 4.222413: clk_enable: emac_1_clk (udev-worker)-229 [000] d.... 4.222416: clk_enable_complete: emac_1_clk kworker/0:1-10 [000] d.... 4.222472: clk_disable: emac_1_clk kworker/0:1-10 [000] d.... 4.222476: clk_disable_complete: emac_1_clk kworker/0:1-10 [000] d.... 4.222477: clk_disable: emac1_clk kworker/0:1-10 [000] d.... 4.222479: clk_disable_complete: emac1_clk kworker/0:1-10 [000] ..... 4.222482: clk_unprepare: emac_1_clk kworker/0:1-10 [000] ..... 4.222484: clk_unprepare_complete: emac_1_clk kworker/0:1-10 [000] ..... 4.222485: clk_unprepare: emac1_clk kworker/0:1-10 [000] ..... 4.222486: clk_unprepare_complete: emac1_clk (udev-worker)-229 [000] ..... 4.225917: clk_prepare: emac1_clk (udev-worker)-229 [000] ..... 4.225924: clk_prepare_complete: emac1_clk (udev-worker)-229 [000] ..... 4.225925: clk_prepare: emac_1_clk (udev-worker)-229 [000] ..... 4.225927: clk_prepare_complete: emac_1_clk (udev-worker)-229 [000] d.... 4.225931: clk_enable: emac1_clk (udev-worker)-229 [000] d.... 4.225932: clk_enable_complete: emac1_clk (udev-worker)-229 [000] d.... 4.225933: clk_enable: emac_1_clk (udev-worker)-229 [000] d.... 4.225937: clk_enable_complete: emac_1_clk kworker/0:1-10 [000] d.... 4.225993: clk_disable: emac_1_clk kworker/0:1-10 [000] d.... 4.225997: clk_disable_complete: emac_1_clk kworker/0:1-10 [000] d.... 4.225998: clk_disable: emac1_clk kworker/0:1-10 [000] d.... 4.226000: clk_disable_complete: emac1_clk kworker/0:1-10 [000] ..... 4.226003: clk_unprepare: emac_1_clk kworker/0:1-10 [000] ..... 4.226005: clk_unprepare_complete: emac_1_clk kworker/0:1-10 [000] ..... 4.226006: clk_unprepare: emac1_clk kworker/0:1-10 [000] ..... 4.226008: clk_unprepare_complete: emac1_clk (udev-worker)-229 [000] ..... 4.227357: clk_prepare: emac1_clk (udev-worker)-229 [000] ..... 4.227362: clk_prepare_complete: emac1_clk (udev-worker)-229 [000] ..... 4.227363: clk_prepare: emac_1_clk (udev-worker)-229 [000] ..... 4.227365: clk_prepare_complete: emac_1_clk (udev-worker)-229 [000] d.... 4.227368: clk_enable: emac1_clk (udev-worker)-229 [000] d.... 4.227370: clk_enable_complete: emac1_clk (udev-worker)-229 [000] d.... 4.227371: clk_enable: emac_1_clk (udev-worker)-229 [000] d.... 4.227374: clk_enable_complete: emac_1_clk kworker/0:1-10 [000] d.... 4.227507: clk_disable: emac_1_clk kworker/0:1-10 [000] d.... 4.227513: clk_disable_complete: emac_1_clk kworker/0:1-10 [000] d.... 4.227514: clk_disable: emac1_clk kworker/0:1-10 [000] d.... 4.227516: clk_disable_complete: emac1_clk kworker/0:1-10 [000] ..... 4.227519: clk_unprepare: emac_1_clk kworker/0:1-10 [000] ..... 4.227521: clk_unprepare_complete: emac_1_clk kworker/0:1-10 [000] ..... 4.227522: clk_unprepare: emac1_clk kworker/0:1-10 [000] ..... 4.227523: clk_unprepare_complete: emac1_clk ip-777 [001] ..... 8.834235: clk_prepare: emac1_clk ip-777 [001] ..... 8.834241: clk_prepare_complete: emac1_clk ip-777 [001] ..... 8.834242: clk_prepare: emac_1_clk ip-777 [001] ..... 8.834243: clk_prepare_complete: emac_1_clk ip-777 [001] d.... 8.834246: clk_enable: emac1_clk ip-777 [001] d.... 8.834248: clk_enable_complete: emac1_clk ip-777 [001] d.... 8.834249: clk_enable: emac_1_clk ip-777 [001] d.... 8.834252: clk_enable_complete: emac_1_clk getty-1284 [001] ..... 19.510813: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) getty-1284 [001] ..... 19.510822: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) getty-1284 [001] ..... 19.510828: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200 getty-1284 [001] ..... 19.510830: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000 getty-1284 [001] ..... 19.510832: dw8250_set_termios: dw8250_set_termios: after: uartclk = 100000000 trace output (bad - determine_rate = clk_hw_determine_rate_no_reparent): # tracer: nop # # entries-in-buffer/entries-written: 285/285 #P:2 # # _-----=> irqs-off/BH-disabled # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / _-=> migrate-disable # |||| / delay # TASK-PID CPU# ||||| TIMESTAMP FUNCTION # | | | ||||| | | <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 462500000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 231250000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 115625000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 3125000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 97368421 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 97368421 <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = l4_mp_clk <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: l4_mp_clk = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = l4_sp_clk <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: l4_sp_clk = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 1953125 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 250000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 5 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 40000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 5 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 40000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 6250 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 32000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = sdmmc_clk <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: sdmmc_clk = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: fixed_div: div = 4 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = nand_x_clk <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: nand_clk / nand_x_clk = 2 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: fixed_div: div = 4 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = qspi_clk <idle>-0 [000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: qspi_clk = 1 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 3613281 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 400000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 800000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 400000000 <idle>-0 [000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 133333333 <idle>-0 [000] d.... 0.000000: clk_prepare: osc1 <idle>-0 [000] d.... 0.000000: clk_prepare_complete: osc1 <idle>-0 [000] d.... 0.000000: clk_prepare: main_pll <idle>-0 [000] d.... 0.000000: clk_prepare_complete: main_pll <idle>-0 [000] d.... 0.000000: clk_prepare: mpuclk <idle>-0 [000] d.... 0.000000: clk_prepare_complete: mpuclk <idle>-0 [000] d.... 0.000000: clk_prepare: mpu_periph_clk <idle>-0 [000] d.... 0.000000: clk_prepare_complete: mpu_periph_clk <idle>-0 [000] d.... 0.000000: clk_enable: osc1 <idle>-0 [000] d.... 0.000000: clk_enable_complete: osc1 <idle>-0 [000] d.... 0.000000: clk_enable: main_pll <idle>-0 [000] d.... 0.000000: clk_enable_complete: main_pll <idle>-0 [000] d.... 0.000000: clk_enable: mpuclk <idle>-0 [000] d.... 0.000000: clk_enable_complete: mpuclk <idle>-0 [000] d.... 0.000000: clk_enable: mpu_periph_clk <idle>-0 [000] d.... 0.000000: clk_enable_complete: mpu_periph_clk <idle>-0 [000] d.... 0.000000: clk_prepare: periph_pll <idle>-0 [000] d.... 0.000000: clk_prepare_complete: periph_pll <idle>-0 [000] d.... 0.000000: clk_prepare: per_base_clk <idle>-0 [000] d.... 0.000000: clk_prepare_complete: per_base_clk <idle>-0 [000] d.... 0.000000: clk_prepare: l4_sp_clk <idle>-0 [000] d.... 0.000000: clk_prepare_complete: l4_sp_clk <idle>-0 [000] d.... 0.000000: clk_enable: periph_pll <idle>-0 [000] d.... 0.000000: clk_enable_complete: periph_pll <idle>-0 [000] d.... 0.000000: clk_enable: per_base_clk <idle>-0 [000] d.... 0.000000: clk_enable_complete: per_base_clk <idle>-0 [000] d.... 0.000000: clk_enable: l4_sp_clk <idle>-0 [000] d.... 0.000000: clk_enable_complete: l4_sp_clk init-1 [000] .n... 0.033336: clk_prepare: mainclk init-1 [000] .n... 0.033341: clk_prepare_complete: mainclk init-1 [000] .n... 0.033343: clk_prepare: l4_main_clk init-1 [000] .n... 0.033344: clk_prepare_complete: l4_main_clk init-1 [000] dn... 0.033347: clk_enable: mainclk init-1 [000] dn... 0.033349: clk_enable_complete: mainclk init-1 [000] dn... 0.033350: clk_enable: l4_main_clk init-1 [000] dn... 0.033352: clk_enable_complete: l4_main_clk init-1 [000] d.... 0.033421: clk_disable: l4_main_clk init-1 [000] d.... 0.033424: clk_disable_complete: l4_main_clk init-1 [000] d.... 0.033425: clk_disable: mainclk init-1 [000] d.... 0.033426: clk_disable_complete: mainclk init-1 [000] ..... 0.033430: clk_unprepare: l4_main_clk init-1 [000] ..... 0.033431: clk_unprepare_complete: l4_main_clk init-1 [000] ..... 0.033432: clk_unprepare: mainclk init-1 [000] ..... 0.033434: clk_unprepare_complete: mainclk init-1 [001] ..... 0.125643: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125651: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125657: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200 init-1 [001] ..... 0.125660: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000 init-1 [001] ..... 0.125662: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125664: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125666: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125668: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125673: clk_set_rate: l4_sp_clk 200000000 init-1 [001] ..... 0.125675: clk_set_rate_complete: l4_sp_clk 200000000 init-1 [001] ..... 0.125678: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 init-1 [001] ..... 0.125681: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000 init-1 [001] ..... 0.125683: dw8250_set_termios: dw8250_set_termios: after: uartclk = 200000000 init-1 [001] .n... 1.732756: clk_prepare: emac1_clk init-1 [001] .n... 1.732761: clk_prepare_complete: emac1_clk init-1 [001] .n... 1.732763: clk_prepare: emac_1_clk init-1 [001] .n... 1.732764: clk_prepare_complete: emac_1_clk init-1 [001] dn... 1.732767: clk_enable: emac1_clk init-1 [001] dn... 1.732769: clk_enable_complete: emac1_clk init-1 [001] dn... 1.732770: clk_enable: emac_1_clk init-1 [001] dn... 1.732773: clk_enable_complete: emac_1_clk kworker/1:1-36 [001] d.... 1.952366: clk_disable: emac_1_clk kworker/1:1-36 [001] d.... 1.952373: clk_disable_complete: emac_1_clk kworker/1:1-36 [001] d.... 1.952374: clk_disable: emac1_clk kworker/1:1-36 [001] d.... 1.952376: clk_disable_complete: emac1_clk kworker/1:1-36 [001] ..... 1.952379: clk_unprepare: emac_1_clk kworker/1:1-36 [001] ..... 1.952381: clk_unprepare_complete: emac_1_clk kworker/1:1-36 [001] ..... 1.952382: clk_unprepare: emac1_clk kworker/1:1-36 [001] ..... 1.952383: clk_unprepare_complete: emac1_clk init-1 [001] ..... 1.952436: clk_prepare: usb_mp_clk init-1 [001] ..... 1.952438: clk_prepare_complete: usb_mp_clk init-1 [001] d.... 1.952441: clk_enable: usb_mp_clk init-1 [001] d.... 1.952443: clk_enable_complete: usb_mp_clk kworker/u6:1-33 [001] ..... 2.053196: clk_prepare: l4_mp_clk kworker/u6:1-33 [001] ..... 2.053201: clk_prepare_complete: l4_mp_clk kworker/u6:1-33 [001] d.... 2.053203: clk_enable: l4_mp_clk kworker/u6:1-33 [001] d.... 2.053207: clk_enable_complete: l4_mp_clk kworker/u6:1-33 [001] ..... 2.053215: clk_prepare: per_nand_mmc_clk kworker/u6:1-33 [001] ..... 2.053217: clk_prepare_complete: per_nand_mmc_clk kworker/u6:1-33 [001] ..... 2.053218: clk_prepare: sdmmc_clk kworker/u6:1-33 [001] ..... 2.053220: clk_prepare_complete: sdmmc_clk kworker/u6:1-33 [001] ..... 2.053221: clk_prepare: sdmmc_clk_divided kworker/u6:1-33 [001] ..... 2.053222: clk_prepare_complete: sdmmc_clk_divided kworker/u6:1-33 [001] d.... 2.053224: clk_enable: per_nand_mmc_clk kworker/u6:1-33 [001] d.... 2.053225: clk_enable_complete: per_nand_mmc_clk kworker/u6:1-33 [001] d.... 2.053227: clk_enable: sdmmc_clk kworker/u6:1-33 [001] d.... 2.053228: clk_enable_complete: sdmmc_clk kworker/u6:1-33 [001] d.... 2.053230: clk_enable: sdmmc_clk_divided kworker/u6:1-33 [001] d.... 2.053232: clk_enable_complete: sdmmc_clk_divided kworker/u5:1-27 [000] ..... 2.319334: clk_prepare: mainclk kworker/u5:1-27 [000] ..... 2.319339: clk_prepare_complete: mainclk kworker/u5:1-27 [000] ..... 2.319341: clk_prepare: l4_main_clk kworker/u5:1-27 [000] ..... 2.319342: clk_prepare_complete: l4_main_clk kworker/u5:1-27 [000] d.... 2.319345: clk_enable: mainclk kworker/u5:1-27 [000] d.... 2.319346: clk_enable_complete: mainclk kworker/u5:1-27 [000] d.... 2.319348: clk_enable: l4_main_clk kworker/u5:1-27 [000] d.... 2.319350: clk_enable_complete: l4_main_clk kworker/0:2-50 [000] d.... 2.374974: clk_disable: l4_main_clk kworker/0:2-50 [000] d.... 2.374980: clk_disable_complete: l4_main_clk kworker/0:2-50 [000] d.... 2.374981: clk_disable: mainclk kworker/0:2-50 [000] d.... 2.374986: clk_disable_complete: mainclk init-1 [000] .n... 2.404394: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] .n... 2.404402: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] .n... 2.404408: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200 init-1 [000] .n... 2.404411: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000 init-1 [000] .n... 2.404413: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] .n... 2.404415: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] .n... 2.404418: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] .n... 2.404419: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] .n... 2.404429: clk_set_rate: l4_sp_clk 200000000 init-1 [000] .n... 2.404431: clk_set_rate_complete: l4_sp_clk 200000000 init-1 [000] .n... 2.404435: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 init-1 [000] .n... 2.404437: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000 init-1 [000] .n... 2.404440: dw8250_set_termios: dw8250_set_termios: after: uartclk = 200000000 (udev-worker)-86 [001] ..... 3.002615: clk_prepare: emac1_clk (udev-worker)-86 [001] ..... 3.002621: clk_prepare_complete: emac1_clk (udev-worker)-86 [001] ..... 3.002623: clk_prepare: emac_1_clk (udev-worker)-86 [001] ..... 3.002624: clk_prepare_complete: emac_1_clk (udev-worker)-86 [001] d.... 3.002628: clk_enable: emac1_clk (udev-worker)-86 [001] d.... 3.002629: clk_enable_complete: emac1_clk (udev-worker)-86 [001] d.... 3.002631: clk_enable: emac_1_clk (udev-worker)-86 [001] d.... 3.002635: clk_enable_complete: emac_1_clk kworker/1:2-45 [001] d.... 3.012426: clk_disable: emac_1_clk kworker/1:2-45 [001] d.... 3.012437: clk_disable_complete: emac_1_clk kworker/1:2-45 [001] d.... 3.012439: clk_disable: emac1_clk kworker/1:2-45 [001] d.... 3.012440: clk_disable_complete: emac1_clk kworker/1:2-45 [001] ..... 3.012445: clk_unprepare: emac_1_clk kworker/1:2-45 [001] ..... 3.012449: clk_unprepare_complete: emac_1_clk kworker/1:2-45 [001] ..... 3.012453: clk_unprepare: emac1_clk kworker/1:2-45 [001] ..... 3.012456: clk_unprepare_complete: emac1_clk (udev-worker)-86 [001] ..... 3.018662: clk_prepare: emac1_clk (udev-worker)-86 [001] ..... 3.018668: clk_prepare_complete: emac1_clk (udev-worker)-86 [001] ..... 3.018670: clk_prepare: emac_1_clk (udev-worker)-86 [001] ..... 3.018671: clk_prepare_complete: emac_1_clk (udev-worker)-86 [001] d.... 3.018675: clk_enable: emac1_clk (udev-worker)-86 [001] d.... 3.018677: clk_enable_complete: emac1_clk (udev-worker)-86 [001] d.... 3.018678: clk_enable: emac_1_clk (udev-worker)-86 [001] d.... 3.018681: clk_enable_complete: emac_1_clk kworker/1:2-45 [001] d.... 3.019794: clk_disable: emac_1_clk kworker/1:2-45 [001] d.... 3.019801: clk_disable_complete: emac_1_clk kworker/1:2-45 [001] d.... 3.019803: clk_disable: emac1_clk kworker/1:2-45 [001] d.... 3.019804: clk_disable_complete: emac1_clk kworker/1:2-45 [001] ..... 3.019808: clk_unprepare: emac_1_clk kworker/1:2-45 [001] ..... 3.019810: clk_unprepare_complete: emac_1_clk kworker/1:2-45 [001] ..... 3.019811: clk_unprepare: emac1_clk kworker/1:2-45 [001] ..... 3.019813: clk_unprepare_complete: emac1_clk init-1 [000] ..... 3.955433: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] ..... 3.955440: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] ..... 3.955446: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200 init-1 [000] ..... 3.955449: dw8250_set_termios: dw8250_set_termios: before: uartclk = 200000000 init-1 [000] ..... 3.955452: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] ..... 3.955453: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] ..... 3.955455: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] ..... 3.955457: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [000] ..... 3.955465: clk_set_rate: l4_sp_clk 200000000 init-1 [000] ..... 3.955467: clk_set_rate_complete: l4_sp_clk 200000000 init-1 [000] ..... 3.955471: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 init-1 [000] ..... 3.955473: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000 init-1 [000] ..... 3.955476: dw8250_set_termios: dw8250_set_termios: after: uartclk = 200000000 (udev-worker)-228 [000] ..... 5.422835: clk_prepare: emac1_clk (udev-worker)-228 [000] ..... 5.422842: clk_prepare_complete: emac1_clk (udev-worker)-228 [000] ..... 5.422843: clk_prepare: emac_1_clk (udev-worker)-228 [000] ..... 5.422845: clk_prepare_complete: emac_1_clk (udev-worker)-228 [000] d.... 5.422848: clk_enable: emac1_clk (udev-worker)-228 [000] d.... 5.422850: clk_enable_complete: emac1_clk (udev-worker)-228 [000] d.... 5.422851: clk_enable: emac_1_clk (udev-worker)-228 [000] d.... 5.422855: clk_enable_complete: emac_1_clk kworker/0:2-50 [000] d.... 5.432702: clk_disable: emac_1_clk kworker/0:2-50 [000] d.... 5.432710: clk_disable_complete: emac_1_clk kworker/0:2-50 [000] d.... 5.432712: clk_disable: emac1_clk kworker/0:2-50 [000] d.... 5.432714: clk_disable_complete: emac1_clk kworker/0:2-50 [000] ..... 5.432718: clk_unprepare: emac_1_clk kworker/0:2-50 [000] ..... 5.432719: clk_unprepare_complete: emac_1_clk kworker/0:2-50 [000] ..... 5.432721: clk_unprepare: emac1_clk kworker/0:2-50 [000] ..... 5.432722: clk_unprepare_complete: emac1_clk (udev-worker)-228 [000] ..... 5.444087: clk_prepare: emac1_clk (udev-worker)-228 [000] ..... 5.444092: clk_prepare_complete: emac1_clk (udev-worker)-228 [000] ..... 5.444094: clk_prepare: emac_1_clk (udev-worker)-228 [000] ..... 5.444095: clk_prepare_complete: emac_1_clk (udev-worker)-228 [000] d.... 5.444098: clk_enable: emac1_clk (udev-worker)-228 [000] d.... 5.444100: clk_enable_complete: emac1_clk (udev-worker)-228 [000] d.... 5.444101: clk_enable: emac_1_clk (udev-worker)-228 [000] d.... 5.444105: clk_enable_complete: emac_1_clk kworker/0:2-50 [000] d.... 5.444435: clk_disable: emac_1_clk kworker/0:2-50 [000] d.... 5.444441: clk_disable_complete: emac_1_clk kworker/0:2-50 [000] d.... 5.444443: clk_disable: emac1_clk kworker/0:2-50 [000] d.... 5.444444: clk_disable_complete: emac1_clk kworker/0:2-50 [000] ..... 5.444448: clk_unprepare: emac_1_clk kworker/0:2-50 [000] ..... 5.444450: clk_unprepare_complete: emac_1_clk kworker/0:2-50 [000] ..... 5.444451: clk_unprepare: emac1_clk kworker/0:2-50 [000] ..... 5.444452: clk_unprepare_complete: emac1_clk (udev-worker)-228 [000] ..... 5.463489: clk_prepare: emac1_clk (udev-worker)-228 [000] ..... 5.463494: clk_prepare_complete: emac1_clk (udev-worker)-228 [000] ..... 5.463496: clk_prepare: emac_1_clk (udev-worker)-228 [000] ..... 5.463497: clk_prepare_complete: emac_1_clk (udev-worker)-228 [000] d.... 5.463501: clk_enable: emac1_clk (udev-worker)-228 [000] d.... 5.463503: clk_enable_complete: emac1_clk (udev-worker)-228 [000] d.... 5.463504: clk_enable: emac_1_clk (udev-worker)-228 [000] d.... 5.463507: clk_enable_complete: emac_1_clk kworker/0:2-50 [000] d.... 5.465073: clk_disable: emac_1_clk kworker/0:2-50 [000] d.... 5.465084: clk_disable_complete: emac_1_clk kworker/0:2-50 [000] d.... 5.465085: clk_disable: emac1_clk kworker/0:2-50 [000] d.... 5.465087: clk_disable_complete: emac1_clk kworker/0:2-50 [000] ..... 5.465091: clk_unprepare: emac_1_clk kworker/0:2-50 [000] ..... 5.465093: clk_unprepare_complete: emac_1_clk kworker/0:2-50 [000] ..... 5.465094: clk_unprepare: emac1_clk kworker/0:2-50 [000] ..... 5.465096: clk_unprepare_complete: emac1_clk ip-777 [001] ..... 11.417588: clk_prepare: emac1_clk ip-777 [001] ..... 11.417594: clk_prepare_complete: emac1_clk ip-777 [001] ..... 11.417596: clk_prepare: emac_1_clk ip-777 [001] ..... 11.417597: clk_prepare_complete: emac_1_clk ip-777 [001] d.... 11.417600: clk_enable: emac1_clk ip-777 [001] d.... 11.417602: clk_enable_complete: emac1_clk ip-777 [001] d.... 11.417603: clk_enable: emac_1_clk ip-777 [001] d.... 11.417606: clk_enable_complete: emac_1_clk getty-1283 [001] ..... 19.978213: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) getty-1283 [001] ..... 19.978220: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) getty-1283 [001] ..... 19.978226: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200 getty-1283 [001] ..... 19.978229: dw8250_set_termios: dw8250_set_termios: before: uartclk = 200000000 getty-1283 [001] ..... 19.978231: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) getty-1283 [001] ..... 19.978233: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) getty-1283 [001] ..... 19.978235: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) getty-1283 [001] ..... 19.978237: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) getty-1283 [001] ..... 19.978245: clk_set_rate: l4_sp_clk 200000000 getty-1283 [001] ..... 19.978247: clk_set_rate_complete: l4_sp_clk 200000000 getty-1283 [001] ..... 19.978251: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 getty-1283 [001] ..... 19.978254: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000 getty-1283 [001] ..... 19.978256: dw8250_set_termios: dw8250_set_termios: after: uartclk = 200000000 --- drivers/clk/socfpga/clk-gate.c | 43 ++++++++++++++++++++++------- drivers/tty/serial/8250/8250_dw.c | 3 ++ drivers/tty/serial/8250/8250_port.c | 2 ++ 3 files changed, 38 insertions(+), 10 deletions(-) diff --git a/drivers/clk/socfpga/clk-gate.c b/drivers/clk/socfpga/clk-gate.c index 47500976f987..48e5c241f528 100644 --- a/drivers/clk/socfpga/clk-gate.c +++ b/drivers/clk/socfpga/clk-gate.c @@ -31,26 +31,39 @@ static u8 socfpga_clk_get_parent(struct clk_hw *hwclk) u32 l4_src; u32 perpll_src; const char *name = clk_hw_get_name(hwclk); + u8 ret; + + trace_printk("%s: name = %s\n", __func__, name); if (streq(name, SOCFPGA_L4_MP_CLK)) { l4_src = readl(clk_mgr_base_addr + CLKMGR_L4SRC); - return l4_src & 0x1; + ret = l4_src & 0x1; + trace_printk("%s: l4_mp_clk = %d\n", __func__, ret); + return ret; } if (streq(name, SOCFPGA_L4_SP_CLK)) { l4_src = readl(clk_mgr_base_addr + CLKMGR_L4SRC); - return !!(l4_src & 2); + ret = !!(l4_src & 2); + trace_printk("%s: l4_sp_clk = %d\n", __func__, ret); + return ret; } perpll_src = readl(clk_mgr_base_addr + CLKMGR_PERPLL_SRC); - if (streq(name, SOCFPGA_MMC_CLK)) - return perpll_src & 0x3; + if (streq(name, SOCFPGA_MMC_CLK)) { + ret = perpll_src & 0x3; + trace_printk("%s: sdmmc_clk = %d\n", __func__, ret); + return ret; + } if (streq(name, SOCFPGA_NAND_CLK) || - streq(name, SOCFPGA_NAND_X_CLK)) - return (perpll_src >> 2) & 3; - + streq(name, SOCFPGA_NAND_X_CLK)) { + ret = (perpll_src >> 2) & 3; + trace_printk("%s: nand_clk / nand_x_clk = %d\n", __func__, ret); + return ret; + } /* QSPI clock */ - return (perpll_src >> 4) & 3; - + ret = (perpll_src >> 4) & 3; + trace_printk("%s: qspi_clk = %d\n", __func__, ret); + return ret; } static int socfpga_clk_set_parent(struct clk_hw *hwclk, u8 parent) @@ -63,23 +76,28 @@ static int socfpga_clk_set_parent(struct clk_hw *hwclk, u8 parent) src_reg &= ~0x1; src_reg |= parent; writel(src_reg, clk_mgr_base_addr + CLKMGR_L4SRC); + trace_printk("%s: l4_mp_clk: src_reg = %d\n", __func__, src_reg); } else if (streq(name, SOCFPGA_L4_SP_CLK)) { src_reg = readl(clk_mgr_base_addr + CLKMGR_L4SRC); src_reg &= ~0x2; src_reg |= (parent << 1); writel(src_reg, clk_mgr_base_addr + CLKMGR_L4SRC); + trace_printk("%s: l4_sp_clk: src_reg = %d\n", __func__, src_reg); } else { src_reg = readl(clk_mgr_base_addr + CLKMGR_PERPLL_SRC); if (streq(name, SOCFPGA_MMC_CLK)) { src_reg &= ~0x3; src_reg |= parent; + trace_printk("%s: sdmmc_clk: src_reg = %d\n", __func__, src_reg); } else if (streq(name, SOCFPGA_NAND_CLK) || streq(name, SOCFPGA_NAND_X_CLK)) { src_reg &= ~0xC; src_reg |= (parent << 2); + trace_printk("%s: nand_clk: src_reg = %d\n", __func__, src_reg); } else {/* QSPI clock */ src_reg &= ~0x30; src_reg |= (parent << 4); + trace_printk("%s: qspi_clk: src_reg = %d\n", __func__, src_reg); } writel(src_reg, clk_mgr_base_addr + CLKMGR_PERPLL_SRC); } @@ -93,8 +111,10 @@ static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk, struct socfpga_gate_clk *socfpgaclk = to_socfpga_gate_clk(hwclk); u32 div = 1, val; - if (socfpgaclk->fixed_div) + if (socfpgaclk->fixed_div) { div = socfpgaclk->fixed_div; + trace_printk("%s: fixed_div: div = %d\n", __func__, div); + } else if (socfpgaclk->div_reg) { val = readl(socfpgaclk->div_reg) >> socfpgaclk->shift; val &= GENMASK(socfpgaclk->width - 1, 0); @@ -103,8 +123,11 @@ static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk, div = val + 1; else div = (1 << val); + trace_printk("%s: div_reg: div = %d\n", __func__, div); } + trace_printk("%s: rate = %ld\n", __func__, parent_rate / div); + return parent_rate / div; } diff --git a/drivers/tty/serial/8250/8250_dw.c b/drivers/tty/serial/8250/8250_dw.c index f4cafca1a7da..1e21ef8b046c 100644 --- a/drivers/tty/serial/8250/8250_dw.c +++ b/drivers/tty/serial/8250/8250_dw.c @@ -359,6 +359,8 @@ static void dw8250_set_termios(struct uart_port *p, struct ktermios *termios, clk_disable_unprepare(d->clk); rate = clk_round_rate(d->clk, newrate); + trace_printk("%s: rate = %ld newrate = %ld\n", __func__, rate, newrate); + trace_printk("%s: before: uartclk = %d\n", __func__, p->uartclk); if (rate > 0) { /* * Note that any clock-notifer worker will block in @@ -368,6 +370,7 @@ static void dw8250_set_termios(struct uart_port *p, struct ktermios *termios, if (!ret) p->uartclk = rate; } + trace_printk("%s: after: uartclk = %d\n", __func__, p->uartclk); clk_prepare_enable(d->clk); dw8250_do_set_termios(p, termios, old); diff --git a/drivers/tty/serial/8250/8250_port.c b/drivers/tty/serial/8250/8250_port.c index 141627370aab..61f278e8d41b 100644 --- a/drivers/tty/serial/8250/8250_port.c +++ b/drivers/tty/serial/8250/8250_port.c @@ -2758,6 +2758,8 @@ void serial8250_update_uartclk(struct uart_port *port, unsigned int uartclk) uart_update_timeout(port, termios->c_cflag, baud); + trace_printk("%s: %s: uartclk: %d baud: %d quot: %d frac: %d\n", + __func__, port->name, uartclk, baud, quot, frac); serial8250_set_divisor(port, baud, quot, frac); serial_port_out(port, UART_LCR, up->lcr);
Quoting Benedikt Spranger (2023-10-05 11:32:23) > On Thu, 5 Oct 2023 13:34:01 +0200 > Maxime Ripard <mripard@kernel.org> wrote: > > > Hi, > > > > On Thu, Oct 05, 2023 at 11:59:27AM +0200, Benedikt Spranger wrote: > > > Commit 9607beb917df ("clk: socfpga: gate: Add a determine_rate > > > hook") introduce a specific determine_rate hook. As a result the > > > calculated clock for the serial IP is off by factor 2 after that > > > i.e. if the system configures a baudrate of 115200 it is set > > > physicaly to 57600. > > > > Where is that factor 2 coming from? > In drivers/tty/serial/8250/8250_dw.c p->uartclk is set twice as high, > as it should be: > > dw8250_set_termios() is called and rate is evaluated to 20000000 in the > bad and 10000000 in the good case. As a result p->uartclk is set to > 20000000 in the bad case. > > > > Change the determine_rate hook to the reparent variant > > > __clk_mux_determine_rate() to fix the issue. > > > > It's also not clear to me why that would fix anything. This patch > > should only make the old behaviour explicit, could you expand a bit > > on what happens? > Booting the kernel with console=ttyS0,115200 result in a corrupted > character output. Setting the serial terminal application to 57600 > make the serial console working. > > I dug deeper and added some debug output (see patch below): What's your analysis? Does this patch also fix it? ---8<--- diff --git a/drivers/clk/socfpga/clk-gate.c b/drivers/clk/socfpga/clk-gate.c index 8dd601bd8538..b3400d2d8128 100644 --- a/drivers/clk/socfpga/clk-gate.c +++ b/drivers/clk/socfpga/clk-gate.c @@ -173,6 +173,7 @@ void __init socfpga_gate_init(struct device_node *node) if (init.num_parents < 2) { ops->get_parent = NULL; ops->set_parent = NULL; + ops->determine_rate = NULL; } init.parent_names = parent_name;
On Thu, 05 Oct 2023 14:03:19 -0700 Stephen Boyd <sboyd@kernel.org> wrote: > What's your analysis? Commit 9607beb917df ("clk: socfpga: gate: Add a determine_rate hook") breaks serial console output and changing the determine_rate hook to __clk_mux_determine_rate() fix the issue. > Does this patch also fix it? > > ---8<--- > diff --git a/drivers/clk/socfpga/clk-gate.c > b/drivers/clk/socfpga/clk-gate.c index 8dd601bd8538..b3400d2d8128 > 100644 --- a/drivers/clk/socfpga/clk-gate.c > +++ b/drivers/clk/socfpga/clk-gate.c > @@ -173,6 +173,7 @@ void __init socfpga_gate_init(struct device_node > *node) if (init.num_parents < 2) { > ops->get_parent = NULL; > ops->set_parent = NULL; > + ops->determine_rate = NULL; > } > > init.parent_names = parent_name; No. serial console is broken too. Regards Benedikt Spranger
On Fri, Oct 06, 2023 at 05:39:06AM +0200, Benedikt Spranger wrote: > > What's your analysis? > Commit 9607beb917df ("clk: socfpga: gate: Add a determine_rate hook") > breaks serial console output and changing the determine_rate hook to > __clk_mux_determine_rate() fix the issue. That's not a sickness, that's a symptom. There's something wrong somewhere, and you're just papering over it. Maxime
On Thu, Oct 05, 2023 at 08:32:23PM +0200, Benedikt Spranger wrote: > On Thu, 5 Oct 2023 13:34:01 +0200 > Maxime Ripard <mripard@kernel.org> wrote: > > > Hi, > > > > On Thu, Oct 05, 2023 at 11:59:27AM +0200, Benedikt Spranger wrote: > > > Commit 9607beb917df ("clk: socfpga: gate: Add a determine_rate > > > hook") introduce a specific determine_rate hook. As a result the > > > calculated clock for the serial IP is off by factor 2 after that > > > i.e. if the system configures a baudrate of 115200 it is set > > > physicaly to 57600. > > > > Where is that factor 2 coming from? > In drivers/tty/serial/8250/8250_dw.c p->uartclk is set twice as high, > as it should be: > > dw8250_set_termios() is called and rate is evaluated to 20000000 in the > bad and 10000000 in the good case. As a result p->uartclk is set to > 20000000 in the bad case. Sure, sorry I worded that poorly. What I meant was what clock tree decision is taken now that wasn't taken before that leads to that factor 2 difference. > > > Change the determine_rate hook to the reparent variant > > > __clk_mux_determine_rate() to fix the issue. > > > > It's also not clear to me why that would fix anything. This patch > > should only make the old behaviour explicit, could you expand a bit > > on what happens? > Booting the kernel with console=ttyS0,115200 result in a corrupted > character output. Setting the serial terminal application to 57600 > make the serial console working. > > I dug deeper and added some debug output (see patch below): Thanks for the traces, that's helpful. It looks like the culprit is: Good: init-1 [001] ..... 0.125643: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125651: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125657: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200 vs Bad: init-1 [001] ..... 0.116063: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.116089: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.116096: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200 The rate returned is super suspicious, as it's an -EINVAL casted into an unsigned long. So I think something on that clock chain is returning an error for some reason, which is then treated as a rate by the rest and everybody's just confused. What is the board that you're using? Maxime
On Fri, 6 Oct 2023 17:01:34 +0200 Maxime Ripard <mripard@kernel.org> wrote: > On Thu, Oct 05, 2023 at 08:32:23PM +0200, Benedikt Spranger wrote: > > On Thu, 5 Oct 2023 13:34:01 +0200 > > Maxime Ripard <mripard@kernel.org> wrote: > > > > > Where is that factor 2 coming from? > > In drivers/tty/serial/8250/8250_dw.c p->uartclk is set twice as high, > > as it should be: > > > > dw8250_set_termios() is called and rate is evaluated to 20000000 in the > > bad and 10000000 in the good case. As a result p->uartclk is set to > > 20000000 in the bad case. > > Sure, sorry I worded that poorly. What I meant was what clock tree > decision is taken now that wasn't taken before that leads to that factor > 2 difference. OK. > Thanks for the traces, that's helpful. It looks like the culprit is: > > Good: > > init-1 [001] ..... 0.125643: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) > init-1 [001] ..... 0.125651: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) > init-1 [001] ..... 0.125657: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200 > > vs Bad: > > init-1 [001] ..... 0.116063: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) > init-1 [001] ..... 0.116089: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) > init-1 [001] ..... 0.116096: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200 > > The rate returned is super suspicious, as it's an -EINVAL casted into an > unsigned long. So I think something on that clock chain is returning an > error for some reason, which is then treated as a rate by the rest and > everybody's just confused. OK. > What is the board that you're using? I am using a Cyclone5 DE0-Nano-Soc/Atlas board (socfpga_cyclone5_de0_nano_soc.dts). Regards Benedikt Spranger
On Fri, Oct 06, 2023 at 05:01:34PM +0200, Maxime Ripard wrote: > On Thu, Oct 05, 2023 at 08:32:23PM +0200, Benedikt Spranger wrote: > > On Thu, 5 Oct 2023 13:34:01 +0200 > > Maxime Ripard <mripard@kernel.org> wrote: > > > > > Hi, > > > > > > On Thu, Oct 05, 2023 at 11:59:27AM +0200, Benedikt Spranger wrote: > > > > Commit 9607beb917df ("clk: socfpga: gate: Add a determine_rate > > > > hook") introduce a specific determine_rate hook. As a result the > > > > calculated clock for the serial IP is off by factor 2 after that > > > > i.e. if the system configures a baudrate of 115200 it is set > > > > physicaly to 57600. > > > > > > Where is that factor 2 coming from? > > In drivers/tty/serial/8250/8250_dw.c p->uartclk is set twice as high, > > as it should be: > > > > dw8250_set_termios() is called and rate is evaluated to 20000000 in the > > bad and 10000000 in the good case. As a result p->uartclk is set to > > 20000000 in the bad case. > > Sure, sorry I worded that poorly. What I meant was what clock tree > decision is taken now that wasn't taken before that leads to that factor > 2 difference. > > > > > Change the determine_rate hook to the reparent variant > > > > __clk_mux_determine_rate() to fix the issue. > > > > > > It's also not clear to me why that would fix anything. This patch > > > should only make the old behaviour explicit, could you expand a bit > > > on what happens? > > Booting the kernel with console=ttyS0,115200 result in a corrupted > > character output. Setting the serial terminal application to 57600 > > make the serial console working. > > > > I dug deeper and added some debug output (see patch below): > > Thanks for the traces, that's helpful. It looks like the culprit is: > > Good: > > init-1 [001] ..... 0.125643: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) > init-1 [001] ..... 0.125651: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) > init-1 [001] ..... 0.125657: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200 > > vs Bad: > > init-1 [001] ..... 0.116063: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) > init-1 [001] ..... 0.116089: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) > init-1 [001] ..... 0.116096: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200 > > The rate returned is super suspicious, as it's an -EINVAL casted into an > unsigned long. So I think something on that clock chain is returning an > error for some reason, which is then treated as a rate by the rest and > everybody's just confused. Wait, no, I got confused. The good traces have: init-1 [001] ..... 0.116063: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.116089: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.116096: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200 init-1 [001] ..... 0.116098: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000 init-1 [001] ..... 0.116100: dw8250_set_termios: dw8250_set_termios: after: uartclk = 100000000 So the weird cast is actually in the "working" case. The bad traces have: init-1 [001] ..... 0.125643: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125651: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125657: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200 init-1 [001] ..... 0.125660: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000 init-1 [001] ..... 0.125662: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125664: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125666: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125668: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000) init-1 [001] ..... 0.125673: clk_set_rate: l4_sp_clk 200000000 init-1 [001] ..... 0.125675: clk_set_rate_complete: l4_sp_clk 200000000 init-1 [001] ..... 0.125678: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2 init-1 [001] ..... 0.125681: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000 init-1 [001] ..... 0.125683: dw8250_set_termios: dw8250_set_termios: after: uartclk = 200000000 First, it looks like dw8250_set_termios uses a signed long and you're using %ld in your trace_printk calls so it's not entirely clear to me why 4294967274 doesn't show up as -22. That being said, it looks like the code handles it properly and just skips the clk_set_rate call because (rate > 0) isn't true. The rate isn't changed, and the dividers don't need to be adjusted either: the clock rate change fails, but it keeps on working (probably because it was already setup as a console and the baudrate didn't change). In the bad case, the rate returned is actually the one we would expect when if we don't reparent and we don't have CLK_SET_RATE_PARENT: the one of its currently muxed parent, per_base_clk in this case, so 200MHz. Since the rate returned by clk_round_rate is now greater than 0, clk_set_rate is called, we go into clk_change_rate() with a rate of 200MHz as expected, and since the gateclk_ops don't have a set_rate hook, we end up with "clk_set_rate_complete: l4_sp_clk 200000000". We're here so far: https://elixir.bootlin.com/linux/latest/source/drivers/clk/clk.c#L2350 The next line is a call to clk_recalc, which is going to call socfpga_clk_recalc_rate, and since that clocks appears to have some dividers, it returns the parent rate divided by the divider, 100MHz in this case. There's a couple of (broken) things here: - The clock rate change was completely ignored before because the driver was returning an error. I'm pretty sure it was broken too if you were trying to change the baudrate, but since that's not really common nobody noticed. It's also pretty trivial, so I'm not sure why there was an error in the first place. I think it's because we hit https://elixir.bootlin.com/linux/v6.5.7/source/drivers/clk/clk.c#L684 But again, not entirely sure why using either parents doesn't really work. - It looks like the patch you mentioned is now exerting the rate change logic that wasn't really tested before due to the above, and it doesn't go well. The main culprit is that the socfpga gate driver kind of hides its divider, but not entirely. The rate returned by clk_round_rate doesn't take it into account, but the one stored in the internal structure does, which probably leads to other interesting issues. Could you test that patch? ----8<---- diff --git a/drivers/clk/socfpga/clk-gate.c b/drivers/clk/socfpga/clk-gate.c index 8dd601bd8538..486a4d84e418 100644 --- a/drivers/clk/socfpga/clk-gate.c +++ b/drivers/clk/socfpga/clk-gate.c @@ -87,10 +87,8 @@ static int socfpga_clk_set_parent(struct clk_hw *hwclk, u8 parent) return 0; } -static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk, - unsigned long parent_rate) +static u32 socfpga_clk_get_div(struct socfpga_gate_clk *socfpgaclk) { - struct socfpga_gate_clk *socfpgaclk = to_socfpga_gate_clk(hwclk); u32 div = 1, val; if (socfpgaclk->fixed_div) @@ -105,12 +103,33 @@ static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk, div = (1 << val); } + return div; +} + +static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk, + unsigned long parent_rate) +{ + struct socfpga_gate_clk *socfpgaclk = to_socfpga_gate_clk(hwclk); + u32 div = socfpga_clk_get_div(socfpgaclk); + return parent_rate / div; } + +static int socfpga_clk_determine_rate(struct clk_hw *hw, + struct clk_rate_request *req) +{ + struct socfpga_gate_clk *socfpgaclk = to_socfpga_gate_clk(hwclk); + u32 div = socfpga_clk_get_div(socfpgaclk); + + req->rate = req->best_parent_rate / div; + + return 0; +} + static struct clk_ops gateclk_ops = { .recalc_rate = socfpga_clk_recalc_rate, - .determine_rate = clk_hw_determine_rate_no_reparent, + .determine_rate = socfpga_clk_determine_rate, .get_parent = socfpga_clk_get_parent, .set_parent = socfpga_clk_set_parent, }; ----8<---- Maxime
On Wed, 11 Oct 2023 11:17:22 +0200 Maxime Ripard <mripard@kernel.org> wrote: Hi, > Could you test that patch? The system booted fine. Serial console is working as expected > ----8<---- > > diff --git a/drivers/clk/socfpga/clk-gate.c b/drivers/clk/socfpga/clk-gate.c > index 8dd601bd8538..486a4d84e418 100644 > --- a/drivers/clk/socfpga/clk-gate.c > +++ b/drivers/clk/socfpga/clk-gate.c > @@ -87,10 +87,8 @@ static int socfpga_clk_set_parent(struct clk_hw *hwclk, u8 parent) > return 0; > } > > -static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk, > - unsigned long parent_rate) > +static u32 socfpga_clk_get_div(struct socfpga_gate_clk *socfpgaclk) > { > - struct socfpga_gate_clk *socfpgaclk = to_socfpga_gate_clk(hwclk); > u32 div = 1, val; > > if (socfpgaclk->fixed_div) > @@ -105,12 +103,33 @@ static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk, > div = (1 << val); > } > > + return div; > +} > + > +static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk, > + unsigned long parent_rate) > +{ > + struct socfpga_gate_clk *socfpgaclk = to_socfpga_gate_clk(hwclk); > + u32 div = socfpga_clk_get_div(socfpgaclk); > + > return parent_rate / div; > } > > + > +static int socfpga_clk_determine_rate(struct clk_hw *hw, *hwclk, > + struct clk_rate_request *req) > +{ > + struct socfpga_gate_clk *socfpgaclk = to_socfpga_gate_clk(hwclk); > + u32 div = socfpga_clk_get_div(socfpgaclk); > + > + req->rate = req->best_parent_rate / div; > + > + return 0; > +} > + > static struct clk_ops gateclk_ops = { > .recalc_rate = socfpga_clk_recalc_rate, > - .determine_rate = clk_hw_determine_rate_no_reparent, > + .determine_rate = socfpga_clk_determine_rate, > .get_parent = socfpga_clk_get_parent, > .set_parent = socfpga_clk_set_parent, > }; Regards Benedikt Spranger
diff --git a/drivers/clk/socfpga/clk-gate.c b/drivers/clk/socfpga/clk-gate.c index 8dd601bd8538..47500976f987 100644 --- a/drivers/clk/socfpga/clk-gate.c +++ b/drivers/clk/socfpga/clk-gate.c @@ -110,7 +110,7 @@ static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk, static struct clk_ops gateclk_ops = { .recalc_rate = socfpga_clk_recalc_rate, - .determine_rate = clk_hw_determine_rate_no_reparent, + .determine_rate = __clk_mux_determine_rate, .get_parent = socfpga_clk_get_parent, .set_parent = socfpga_clk_set_parent, };
Commit 9607beb917df ("clk: socfpga: gate: Add a determine_rate hook") introduce a specific determine_rate hook. As a result the calculated clock for the serial IP is off by factor 2 after that i.e. if the system configures a baudrate of 115200 it is set physicaly to 57600. Change the determine_rate hook to the reparent variant __clk_mux_determine_rate() to fix the issue. Cc: stable@vger.kernel.org Fixes: 9607beb917df ("clk: socfpga: gate: Add a determine_rate hook") Signed-off-by: Benedikt Spranger <b.spranger@linutronix.de> --- drivers/clk/socfpga/clk-gate.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)