[PATCH 0/1] Broken serial console on Altera Cyclon V board

[PATCH 0/1] Broken serial console on Altera Cyclon V board

[Benedikt Spranger]

Hi,

trying to boot e recent Kernel on a Altera Cyclone V based board I
faced a broken serial console. The "real" baudrate is half of the set
baudrate i.e. 57600 instead of configured 115200. Traking down the issue
let to commit 9607beb917df ("clk: socfpga: gate: Add a determine_rate hook").

Change the determine_rate hook to fix the issue.

Regards
    Benedikt Spranger

Benedikt Spranger (1):
  clk: socfpga: gate: Fix of by factor 2 for serial console

 drivers/clk/socfpga/clk-gate.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

-- 
2.42.0

[PATCH 1/1] clk: socfpga: gate: Fix of by factor 2 for serial console

[Benedikt Spranger]

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(-)

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,
 };
-- 
2.42.0

Re: [PATCH 1/1] clk: socfpga: gate: Fix of by factor 2 for serial console

[Maxime Ripard]

[-- Attachment #1: Type: text/plain, Size: 664 bytes --]

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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: [PATCH 1/1] clk: socfpga: gate: Fix of by factor 2 for serial console

[Benedikt Spranger]

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);
 
-- 
2.30.2

Re: [PATCH 1/1] clk: socfpga: gate: Fix of by factor 2 for serial console

[Stephen Boyd]

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;

Re: [PATCH 1/1] clk: socfpga: gate: Fix of by factor 2 for serial console

[Benedikt Spranger]

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

Re: [PATCH 1/1] clk: socfpga: gate: Fix of by factor 2 for serial console

[Maxime Ripard]

[-- Attachment #1: Type: text/plain, Size: 410 bytes --]

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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: [PATCH 1/1] clk: socfpga: gate: Fix of by factor 2 for serial console

[Maxime Ripard]

[-- Attachment #1: Type: text/plain, Size: 2772 bytes --]

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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: [PATCH 1/1] clk: socfpga: gate: Fix of by factor 2 for serial console

[Benedikt Spranger]

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

Re: [PATCH 1/1] clk: socfpga: gate: Fix of by factor 2 for serial console

[Maxime Ripard]

[-- Attachment #1: Type: text/plain, Size: 9303 bytes --]

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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]

Re: [PATCH 1/1] clk: socfpga: gate: Fix of by factor 2 for serial console

[Benedikt Spranger]

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