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

2023-10-05 13:59:30

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

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: [email protected]
Fixes: 9607beb917df ("clk: socfpga: gate: Add a determine_rate hook")
Signed-off-by: Benedikt Spranger <[email protected]>
---
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

2023-10-05 14:57:35

by Maxime Ripard

[permalink] [raw]

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

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

Attachments:

(No filename) (683.00 B)
signature.asc (235.00 B)
Download all attachments

2023-10-05 18:33:20

by Benedikt Spranger

[permalink] [raw]

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

On Thu, 5 Oct 2023 13:34:01 +0200
Maxime Ripard
> Hi,
>
> On Thu, > > > > > > > > > > physicaly to 57600.
>
> Where In drivers/tty/seri as it should be:

dw8250_set_termios() bad and 10000000 20000000 in the bad case.

> > > > >
> It's > should > on what happens?
Booting the character make the serial console working.

I dug deeper
trace output # tracer: nop
#
# entries-in-buffer #
# # # # # # # TASK-PID # | | <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 init-1 init-1 init-1 init-1 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 init-1 init-1 init-1 init-1 init-1 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 (udev-worker)-83 (udev-worker)-83 (udev-worker)-83 (udev-worker)-83 (udev-worker)-83 (udev-worker)-83 (udev-worker)-83 (udev-worker)-83 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 init-1 init-1 init-1 init-1 init-1 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 (udev-worker)-229 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 kworker/0:1-10 getty-1284 getty-1284 getty-1284 getty-1284 getty-1284
trace output # tracer: nop
#
# entries-in-buffer #
# # # # # # # TASK-PID # | | <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 <idle>-0 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 kworker/1:1-36 init-1 init-1 init-1 init-1 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u6:1-33 kworker/u5:1-27 kworker/u5:1-27 kworker/u5:1-27 kworker/u5:1-27 kworker/u5:1-27 kworker/u5:1-27 kworker/u5:1-27 kworker/u5:1-27 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 (udev-worker)-86 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 kworker/1:2-45 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 init-1 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 (udev-worker)-228 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 kworker/0:2-50 getty-1283 getty-1283 getty-1283 getty-1283 getty-1283 getty-1283 getty-1283 getty-1283 getty-1283 getty-1283 getty-1283 getty-1283 getty-1283
---
drivers/clk/socfpga/clk-gate.c drivers/tty/serial drivers/tty/serial 3 files changed,
diff --git index 47500976f987..48e5c241f528 --- a/drivers/clk/s +++ b/drivers/clk/s @@ -31,26 u32 l4_src;
u32 perpll_src;
const char + u8 ret;
+
+ trace_printk("%s:
if (streq(name, l4_src - return l4_src & 0x1;
+ ret = l4_src & 0x1;
+ trace_printk("%s: + return ret;
}
if (streq(name, l4_src - return !!(l4_src & 2);
+ ret = !!(l4_src & 2);
+ trace_printk("%s: + return ret;
}

perpll_src - if (streq(name, - return perpll_src & 0x3;
+ if (streq(name, + ret = perpll_src & 0x3;
+ trace_printk("%s: + return ret;
+ }
if (streq(name, - streq(name, - return -
+ streq(name, + ret = (perpll_src + trace_printk("%s: + return ret;
+ }
/* QSPI clock */
- return (perpll_src -
+ ret = (perpll_src + trace_printk("%s: + return ret;
}

static int @@ -63,23 src_reg &= ~0x1;
src_reg |= parent;
writel(src_reg, + trace_printk("%s: } else if src_reg src_reg &= ~0x2;
src_reg writel(src_reg, + trace_printk("%s: } else {
src_reg if (streq(name, src_reg &= ~0x3;
src_reg |= parent;
+ trace_printk("%s: } else streq(name, src_reg &= ~0xC;
src_reg + trace_printk("%s: } else {/* QSPI clock */
src_reg &= ~0x30;
src_reg + trace_printk("%s: }
writel(src_reg, }
@@ -93,8 +111,10 struct socfpga_gate_clk u32 div = 1, val;

- if (socfpgaclk->fixed_div)
+ if (socfpgaclk->fixed_div) {
div = socfpgaclk + trace_printk("%s: + }
else if val = readl(socf val &= @@ -103,8 div = val + 1;
else
div = (1 << val);
+ trace_printk("%s: }

+ trace_printk("%s: +
return parent_rate / div;
}

diff --git index f4cafca1a7da..1e21ef8b046c --- a/drivers/tty/s +++ b/drivers/tty/s @@ -359,6
clk_disable_unpre rate = clk_round_ + trace_printk("%s: + trace_printk("%s: if (rate > 0) {
/*
* Note @@ -368,6 if (!ret)
p->uartclk = rate;
}
+ trace_printk("%s: clk_prepare_enable(d->clk);

dw8250_do_set_termios(p, diff --git index 141627370aab..61f278e8d41b --- a/drivers/tty/s +++ b/drivers/tty/s @@ -2758,6
uart_update_timeout(port,
+ trace_printk("%s: + __func__, serial8250_set_divisor(port, serial_port_out(port,
--
2.30.2

<[email protected]> wrote:
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
is that factor 2 coming from?
al/8250/8250_dw.c p->uartclk is set twice as high,
is called and rate is evaluated to 20000000 in the
in the good case. As a result p->uartclk is set to
Change the determine_rate hook to the reparent variant
__clk_mux_determine_rate() to fix the issue.
also not clear to me why that would fix anything. This patch
only make the old behaviour explicit, could you expand a bit
kernel with console=ttyS0,115200 result in a corrupted
output. Setting the serial terminal application to 57600
and added some debug output (see patch below):
(good - determine_rate = __clk_mux_determine_rate):
/entries-written: 237/237 #P:2
_-----=> irqs-off/BH-disabled
/ _----=> need-resched
| / _---=> hardirq/softirq
|| / _--=> preempt-depth
||| / _-=> migrate-disable
|||| / delay
CPU# ||||| TIMESTAMP FUNCTION
| ||||| | |
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 462500000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 231250000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 115625000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 3125000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 97368421
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 97368421
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = l4_mp_clk
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: l4_mp_clk = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = l4_sp_clk
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: l4_sp_clk = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 1953125
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 250000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 5
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 40000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 5
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 40000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 6250
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 32000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = sdmmc_clk
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: sdmmc_clk = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: fixed_div: div = 4
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = nand_x_clk
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: nand_clk / nand_x_clk = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: fixed_div: div = 4
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = qspi_clk
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: qspi_clk = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 3613281
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 400000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 800000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 400000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 133333333
[000] d.... 0.000000: clk_prepare: osc1
[000] d.... 0.000000: clk_prepare_complete: osc1
[000] d.... 0.000000: clk_prepare: main_pll
[000] d.... 0.000000: clk_prepare_complete: main_pll
[000] d.... 0.000000: clk_prepare: mpuclk
[000] d.... 0.000000: clk_prepare_complete: mpuclk
[000] d.... 0.000000: clk_prepare: mpu_periph_clk
[000] d.... 0.000000: clk_prepare_complete: mpu_periph_clk
[000] d.... 0.000000: clk_enable: osc1
[000] d.... 0.000000: clk_enable_complete: osc1
[000] d.... 0.000000: clk_enable: main_pll
[000] d.... 0.000000: clk_enable_complete: main_pll
[000] d.... 0.000000: clk_enable: mpuclk
[000] d.... 0.000000: clk_enable_complete: mpuclk
[000] d.... 0.000000: clk_enable: mpu_periph_clk
[000] d.... 0.000000: clk_enable_complete: mpu_periph_clk
[000] d.... 0.000000: clk_prepare: periph_pll
[000] d.... 0.000000: clk_prepare_complete: periph_pll
[000] d.... 0.000000: clk_prepare: per_base_clk
[000] d.... 0.000000: clk_prepare_complete: per_base_clk
[000] d.... 0.000000: clk_prepare: l4_sp_clk
[000] d.... 0.000000: clk_prepare_complete: l4_sp_clk
[000] d.... 0.000000: clk_enable: periph_pll
[000] d.... 0.000000: clk_enable_complete: periph_pll
[000] d.... 0.000000: clk_enable: per_base_clk
[000] d.... 0.000000: clk_enable_complete: per_base_clk
[000] d.... 0.000000: clk_enable: l4_sp_clk
[000] d.... 0.000000: clk_enable_complete: l4_sp_clk
[000] .n... 0.033332: clk_prepare: mainclk
[000] .n... 0.033338: clk_prepare_complete: mainclk
[000] .n... 0.033339: clk_prepare: l4_main_clk
[000] .n... 0.033341: clk_prepare_complete: l4_main_clk
[000] dn... 0.033344: clk_enable: mainclk
[000] dn... 0.033345: clk_enable_complete: mainclk
[000] dn... 0.033346: clk_enable: l4_main_clk
[000] dn... 0.033349: clk_enable_complete: l4_main_clk
[000] d.... 0.033420: clk_disable: l4_main_clk
[000] d.... 0.033424: clk_disable_complete: l4_main_clk
[000] d.... 0.033425: clk_disable: mainclk
[000] d.... 0.033426: clk_disable_complete: mainclk
[000] ..... 0.033430: clk_unprepare: l4_main_clk
[000] ..... 0.033431: clk_unprepare_complete: l4_main_clk
[000] ..... 0.033432: clk_unprepare: mainclk
[000] ..... 0.033434: clk_unprepare_complete: mainclk
[001] ..... 0.116063: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 0.116089: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 0.116096: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200
[001] ..... 0.116098: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000
[001] ..... 0.116100: dw8250_set_termios: dw8250_set_termios: after: uartclk = 100000000
[001] ..... 0.920389: clk_prepare: emac1_clk
[001] ..... 0.920395: clk_prepare_complete: emac1_clk
[001] ..... 0.920396: clk_prepare: emac_1_clk
[001] ..... 0.920398: clk_prepare_complete: emac_1_clk
[001] d.... 0.920401: clk_enable: emac1_clk
[001] d.... 0.920403: clk_enable_complete: emac1_clk
[001] d.... 0.920404: clk_enable: emac_1_clk
[001] d.... 0.920407: clk_enable_complete: emac_1_clk
[001] d.... 1.041458: clk_disable: emac_1_clk
[001] d.... 1.041465: clk_disable_complete: emac_1_clk
[001] d.... 1.041466: clk_disable: emac1_clk
[001] d.... 1.041468: clk_disable_complete: emac1_clk
[001] ..... 1.041471: clk_unprepare: emac_1_clk
[001] ..... 1.041473: clk_unprepare_complete: emac_1_clk
[001] ..... 1.041474: clk_unprepare: emac1_clk
[001] ..... 1.041475: clk_unprepare_complete: emac1_clk
[001] ..... 1.041519: clk_prepare: usb_mp_clk
[001] ..... 1.041521: clk_prepare_complete: usb_mp_clk
[001] d.... 1.041524: clk_enable: usb_mp_clk
[001] d.... 1.041526: clk_enable_complete: usb_mp_clk
[001] ..... 1.093644: clk_prepare: l4_mp_clk
[001] ..... 1.093649: clk_prepare_complete: l4_mp_clk
[001] d.... 1.093652: clk_enable: l4_mp_clk
[001] d.... 1.093654: clk_enable_complete: l4_mp_clk
[001] ..... 1.093663: clk_prepare: per_nand_mmc_clk
[001] ..... 1.093665: clk_prepare_complete: per_nand_mmc_clk
[001] ..... 1.093666: clk_prepare: sdmmc_clk
[001] ..... 1.093667: clk_prepare_complete: sdmmc_clk
[001] ..... 1.093669: clk_prepare: sdmmc_clk_divided
[001] ..... 1.093670: clk_prepare_complete: sdmmc_clk_divided
[001] d.... 1.093672: clk_enable: per_nand_mmc_clk
[001] d.... 1.093673: clk_enable_complete: per_nand_mmc_clk
[001] d.... 1.093674: clk_enable: sdmmc_clk
[001] d.... 1.093676: clk_enable_complete: sdmmc_clk
[001] d.... 1.093678: clk_enable: sdmmc_clk_divided
[001] d.... 1.093679: clk_enable_complete: sdmmc_clk_divided
[001] ..... 1.235194: clk_prepare: mainclk
[001] ..... 1.235200: clk_prepare_complete: mainclk
[001] ..... 1.235202: clk_prepare: l4_main_clk
[001] ..... 1.235203: clk_prepare_complete: l4_main_clk
[001] d.... 1.235206: clk_enable: mainclk
[001] d.... 1.235207: clk_enable_complete: mainclk
[001] d.... 1.235209: clk_enable: l4_main_clk
[001] d.... 1.235212: clk_enable_complete: l4_main_clk
[001] .n... 1.279697: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] .n... 1.279706: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] .n... 1.279712: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200
[001] .n... 1.279715: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000
[001] .n... 1.279717: dw8250_set_termios: dw8250_set_termios: after: uartclk = 100000000
[001] d.... 1.285954: clk_disable: l4_main_clk
[001] d.... 1.285960: clk_disable_complete: l4_main_clk
[001] d.... 1.285962: clk_disable: mainclk
[001] d.... 1.285963: clk_disable_complete: mainclk
[000] ..... 1.849061: clk_prepare: emac1_clk
[000] ..... 1.849068: clk_prepare_complete: emac1_clk
[000] ..... 1.849070: clk_prepare: emac_1_clk
[000] ..... 1.849071: clk_prepare_complete: emac_1_clk
[000] d.... 1.849075: clk_enable: emac1_clk
[000] d.... 1.849077: clk_enable_complete: emac1_clk
[000] d.... 1.849078: clk_enable: emac_1_clk
[000] d.... 1.849082: clk_enable_complete: emac_1_clk
[000] d.... 1.850179: clk_disable: emac_1_clk
[000] d.... 1.850187: clk_disable_complete: emac_1_clk
[000] d.... 1.850193: clk_disable: emac1_clk
[000] d.... 1.850194: clk_disable_complete: emac1_clk
[000] ..... 1.850198: clk_unprepare: emac_1_clk
[000] ..... 1.850200: clk_unprepare_complete: emac_1_clk
[000] ..... 1.850202: clk_unprepare: emac1_clk
[000] ..... 1.850203: clk_unprepare_complete: emac1_clk
[000] ..... 2.730939: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] ..... 2.730947: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] ..... 2.730953: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200
[000] ..... 2.730956: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000
[000] ..... 2.730958: dw8250_set_termios: dw8250_set_termios: after: uartclk = 100000000
[000] ..... 4.222397: clk_prepare: emac1_clk
[000] ..... 4.222404: clk_prepare_complete: emac1_clk
[000] ..... 4.222405: clk_prepare: emac_1_clk
[000] ..... 4.222407: clk_prepare_complete: emac_1_clk
[000] d.... 4.222410: clk_enable: emac1_clk
[000] d.... 4.222412: clk_enable_complete: emac1_clk
[000] d.... 4.222413: clk_enable: emac_1_clk
[000] d.... 4.222416: clk_enable_complete: emac_1_clk
[000] d.... 4.222472: clk_disable: emac_1_clk
[000] d.... 4.222476: clk_disable_complete: emac_1_clk
[000] d.... 4.222477: clk_disable: emac1_clk
[000] d.... 4.222479: clk_disable_complete: emac1_clk
[000] ..... 4.222482: clk_unprepare: emac_1_clk
[000] ..... 4.222484: clk_unprepare_complete: emac_1_clk
[000] ..... 4.222485: clk_unprepare: emac1_clk
[000] ..... 4.222486: clk_unprepare_complete: emac1_clk
[000] ..... 4.225917: clk_prepare: emac1_clk
[000] ..... 4.225924: clk_prepare_complete: emac1_clk
[000] ..... 4.225925: clk_prepare: emac_1_clk
[000] ..... 4.225927: clk_prepare_complete: emac_1_clk
[000] d.... 4.225931: clk_enable: emac1_clk
[000] d.... 4.225932: clk_enable_complete: emac1_clk
[000] d.... 4.225933: clk_enable: emac_1_clk
[000] d.... 4.225937: clk_enable_complete: emac_1_clk
[000] d.... 4.225993: clk_disable: emac_1_clk
[000] d.... 4.225997: clk_disable_complete: emac_1_clk
[000] d.... 4.225998: clk_disable: emac1_clk
[000] d.... 4.226000: clk_disable_complete: emac1_clk
[000] ..... 4.226003: clk_unprepare: emac_1_clk
[000] ..... 4.226005: clk_unprepare_complete: emac_1_clk
[000] ..... 4.226006: clk_unprepare: emac1_clk
[000] ..... 4.226008: clk_unprepare_complete: emac1_clk
[000] ..... 4.227357: clk_prepare: emac1_clk
[000] ..... 4.227362: clk_prepare_complete: emac1_clk
[000] ..... 4.227363: clk_prepare: emac_1_clk
[000] ..... 4.227365: clk_prepare_complete: emac_1_clk
[000] d.... 4.227368: clk_enable: emac1_clk
[000] d.... 4.227370: clk_enable_complete: emac1_clk
[000] d.... 4.227371: clk_enable: emac_1_clk
[000] d.... 4.227374: clk_enable_complete: emac_1_clk
[000] d.... 4.227507: clk_disable: emac_1_clk
[000] d.... 4.227513: clk_disable_complete: emac_1_clk
[000] d.... 4.227514: clk_disable: emac1_clk
[000] d.... 4.227516: clk_disable_complete: emac1_clk
[000] ..... 4.227519: clk_unprepare: emac_1_clk
[000] ..... 4.227521: clk_unprepare_complete: emac_1_clk
[000] ..... 4.227522: clk_unprepare: emac1_clk
[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
[001] ..... 19.510813: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 19.510822: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 19.510828: dw8250_set_termios: dw8250_set_termios: rate = 4294967274 newrate = 1843200
[001] ..... 19.510830: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000
[001] ..... 19.510832: dw8250_set_termios: dw8250_set_termios: after: uartclk = 100000000
(bad - determine_rate = clk_hw_determine_rate_no_reparent):
/entries-written: 285/285 #P:2
_-----=> irqs-off/BH-disabled
/ _----=> need-resched
| / _---=> hardirq/softirq
|| / _--=> preempt-depth
||| / _-=> migrate-disable
|||| / delay
CPU# ||||| TIMESTAMP FUNCTION
| ||||| | |
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 462500000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 231250000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 115625000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 3125000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 6250000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 97368421
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 97368421
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = l4_mp_clk
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: l4_mp_clk = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = l4_sp_clk
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: l4_sp_clk = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 1953125
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 250000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 5
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 40000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 5
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 40000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 6250
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 32000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = sdmmc_clk
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: sdmmc_clk = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: fixed_div: div = 4
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = nand_x_clk
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: nand_clk / nand_x_clk = 2
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 200000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: fixed_div: div = 4
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 50000000
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: name = qspi_clk
[000] d.... 0.000000: socfpga_clk_get_parent: socfpga_clk_get_parent: qspi_clk = 1
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 3613281
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 400000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 800000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 400000000
[000] d.... 0.000000: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 133333333
[000] d.... 0.000000: clk_prepare: osc1
[000] d.... 0.000000: clk_prepare_complete: osc1
[000] d.... 0.000000: clk_prepare: main_pll
[000] d.... 0.000000: clk_prepare_complete: main_pll
[000] d.... 0.000000: clk_prepare: mpuclk
[000] d.... 0.000000: clk_prepare_complete: mpuclk
[000] d.... 0.000000: clk_prepare: mpu_periph_clk
[000] d.... 0.000000: clk_prepare_complete: mpu_periph_clk
[000] d.... 0.000000: clk_enable: osc1
[000] d.... 0.000000: clk_enable_complete: osc1
[000] d.... 0.000000: clk_enable: main_pll
[000] d.... 0.000000: clk_enable_complete: main_pll
[000] d.... 0.000000: clk_enable: mpuclk
[000] d.... 0.000000: clk_enable_complete: mpuclk
[000] d.... 0.000000: clk_enable: mpu_periph_clk
[000] d.... 0.000000: clk_enable_complete: mpu_periph_clk
[000] d.... 0.000000: clk_prepare: periph_pll
[000] d.... 0.000000: clk_prepare_complete: periph_pll
[000] d.... 0.000000: clk_prepare: per_base_clk
[000] d.... 0.000000: clk_prepare_complete: per_base_clk
[000] d.... 0.000000: clk_prepare: l4_sp_clk
[000] d.... 0.000000: clk_prepare_complete: l4_sp_clk
[000] d.... 0.000000: clk_enable: periph_pll
[000] d.... 0.000000: clk_enable_complete: periph_pll
[000] d.... 0.000000: clk_enable: per_base_clk
[000] d.... 0.000000: clk_enable_complete: per_base_clk
[000] d.... 0.000000: clk_enable: l4_sp_clk
[000] d.... 0.000000: clk_enable_complete: l4_sp_clk
[000] .n... 0.033336: clk_prepare: mainclk
[000] .n... 0.033341: clk_prepare_complete: mainclk
[000] .n... 0.033343: clk_prepare: l4_main_clk
[000] .n... 0.033344: clk_prepare_complete: l4_main_clk
[000] dn... 0.033347: clk_enable: mainclk
[000] dn... 0.033349: clk_enable_complete: mainclk
[000] dn... 0.033350: clk_enable: l4_main_clk
[000] dn... 0.033352: clk_enable_complete: l4_main_clk
[000] d.... 0.033421: clk_disable: l4_main_clk
[000] d.... 0.033424: clk_disable_complete: l4_main_clk
[000] d.... 0.033425: clk_disable: mainclk
[000] d.... 0.033426: clk_disable_complete: mainclk
[000] ..... 0.033430: clk_unprepare: l4_main_clk
[000] ..... 0.033431: clk_unprepare_complete: l4_main_clk
[000] ..... 0.033432: clk_unprepare: mainclk
[000] ..... 0.033434: clk_unprepare_complete: mainclk
[001] ..... 0.125643: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 0.125651: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 0.125657: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200
[001] ..... 0.125660: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000
[001] ..... 0.125662: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 0.125664: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 0.125666: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 0.125668: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 0.125673: clk_set_rate: l4_sp_clk 200000000
[001] ..... 0.125675: clk_set_rate_complete: l4_sp_clk 200000000
[001] ..... 0.125678: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[001] ..... 0.125681: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000
[001] ..... 0.125683: dw8250_set_termios: dw8250_set_termios: after: uartclk = 200000000
[001] .n... 1.732756: clk_prepare: emac1_clk
[001] .n... 1.732761: clk_prepare_complete: emac1_clk
[001] .n... 1.732763: clk_prepare: emac_1_clk
[001] .n... 1.732764: clk_prepare_complete: emac_1_clk
[001] dn... 1.732767: clk_enable: emac1_clk
[001] dn... 1.732769: clk_enable_complete: emac1_clk
[001] dn... 1.732770: clk_enable: emac_1_clk
[001] dn... 1.732773: clk_enable_complete: emac_1_clk
[001] d.... 1.952366: clk_disable: emac_1_clk
[001] d.... 1.952373: clk_disable_complete: emac_1_clk
[001] d.... 1.952374: clk_disable: emac1_clk
[001] d.... 1.952376: clk_disable_complete: emac1_clk
[001] ..... 1.952379: clk_unprepare: emac_1_clk
[001] ..... 1.952381: clk_unprepare_complete: emac_1_clk
[001] ..... 1.952382: clk_unprepare: emac1_clk
[001] ..... 1.952383: clk_unprepare_complete: emac1_clk
[001] ..... 1.952436: clk_prepare: usb_mp_clk
[001] ..... 1.952438: clk_prepare_complete: usb_mp_clk
[001] d.... 1.952441: clk_enable: usb_mp_clk
[001] d.... 1.952443: clk_enable_complete: usb_mp_clk
[001] ..... 2.053196: clk_prepare: l4_mp_clk
[001] ..... 2.053201: clk_prepare_complete: l4_mp_clk
[001] d.... 2.053203: clk_enable: l4_mp_clk
[001] d.... 2.053207: clk_enable_complete: l4_mp_clk
[001] ..... 2.053215: clk_prepare: per_nand_mmc_clk
[001] ..... 2.053217: clk_prepare_complete: per_nand_mmc_clk
[001] ..... 2.053218: clk_prepare: sdmmc_clk
[001] ..... 2.053220: clk_prepare_complete: sdmmc_clk
[001] ..... 2.053221: clk_prepare: sdmmc_clk_divided
[001] ..... 2.053222: clk_prepare_complete: sdmmc_clk_divided
[001] d.... 2.053224: clk_enable: per_nand_mmc_clk
[001] d.... 2.053225: clk_enable_complete: per_nand_mmc_clk
[001] d.... 2.053227: clk_enable: sdmmc_clk
[001] d.... 2.053228: clk_enable_complete: sdmmc_clk
[001] d.... 2.053230: clk_enable: sdmmc_clk_divided
[001] d.... 2.053232: clk_enable_complete: sdmmc_clk_divided
[000] ..... 2.319334: clk_prepare: mainclk
[000] ..... 2.319339: clk_prepare_complete: mainclk
[000] ..... 2.319341: clk_prepare: l4_main_clk
[000] ..... 2.319342: clk_prepare_complete: l4_main_clk
[000] d.... 2.319345: clk_enable: mainclk
[000] d.... 2.319346: clk_enable_complete: mainclk
[000] d.... 2.319348: clk_enable: l4_main_clk
[000] d.... 2.319350: clk_enable_complete: l4_main_clk
[000] d.... 2.374974: clk_disable: l4_main_clk
[000] d.... 2.374980: clk_disable_complete: l4_main_clk
[000] d.... 2.374981: clk_disable: mainclk
[000] d.... 2.374986: clk_disable_complete: mainclk
[000] .n... 2.404394: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] .n... 2.404402: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] .n... 2.404408: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200
[000] .n... 2.404411: dw8250_set_termios: dw8250_set_termios: before: uartclk = 100000000
[000] .n... 2.404413: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] .n... 2.404415: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] .n... 2.404418: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] .n... 2.404419: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] .n... 2.404429: clk_set_rate: l4_sp_clk 200000000
[000] .n... 2.404431: clk_set_rate_complete: l4_sp_clk 200000000
[000] .n... 2.404435: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] .n... 2.404437: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000
[000] .n... 2.404440: dw8250_set_termios: dw8250_set_termios: after: uartclk = 200000000
[001] ..... 3.002615: clk_prepare: emac1_clk
[001] ..... 3.002621: clk_prepare_complete: emac1_clk
[001] ..... 3.002623: clk_prepare: emac_1_clk
[001] ..... 3.002624: clk_prepare_complete: emac_1_clk
[001] d.... 3.002628: clk_enable: emac1_clk
[001] d.... 3.002629: clk_enable_complete: emac1_clk
[001] d.... 3.002631: clk_enable: emac_1_clk
[001] d.... 3.002635: clk_enable_complete: emac_1_clk
[001] d.... 3.012426: clk_disable: emac_1_clk
[001] d.... 3.012437: clk_disable_complete: emac_1_clk
[001] d.... 3.012439: clk_disable: emac1_clk
[001] d.... 3.012440: clk_disable_complete: emac1_clk
[001] ..... 3.012445: clk_unprepare: emac_1_clk
[001] ..... 3.012449: clk_unprepare_complete: emac_1_clk
[001] ..... 3.012453: clk_unprepare: emac1_clk
[001] ..... 3.012456: clk_unprepare_complete: emac1_clk
[001] ..... 3.018662: clk_prepare: emac1_clk
[001] ..... 3.018668: clk_prepare_complete: emac1_clk
[001] ..... 3.018670: clk_prepare: emac_1_clk
[001] ..... 3.018671: clk_prepare_complete: emac_1_clk
[001] d.... 3.018675: clk_enable: emac1_clk
[001] d.... 3.018677: clk_enable_complete: emac1_clk
[001] d.... 3.018678: clk_enable: emac_1_clk
[001] d.... 3.018681: clk_enable_complete: emac_1_clk
[001] d.... 3.019794: clk_disable: emac_1_clk
[001] d.... 3.019801: clk_disable_complete: emac_1_clk
[001] d.... 3.019803: clk_disable: emac1_clk
[001] d.... 3.019804: clk_disable_complete: emac1_clk
[001] ..... 3.019808: clk_unprepare: emac_1_clk
[001] ..... 3.019810: clk_unprepare_complete: emac_1_clk
[001] ..... 3.019811: clk_unprepare: emac1_clk
[001] ..... 3.019813: clk_unprepare_complete: emac1_clk
[000] ..... 3.955433: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] ..... 3.955440: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] ..... 3.955446: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200
[000] ..... 3.955449: dw8250_set_termios: dw8250_set_termios: before: uartclk = 200000000
[000] ..... 3.955452: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] ..... 3.955453: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] ..... 3.955455: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] ..... 3.955457: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[000] ..... 3.955465: clk_set_rate: l4_sp_clk 200000000
[000] ..... 3.955467: clk_set_rate_complete: l4_sp_clk 200000000
[000] ..... 3.955471: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[000] ..... 3.955473: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000
[000] ..... 3.955476: dw8250_set_termios: dw8250_set_termios: after: uartclk = 200000000
[000] ..... 5.422835: clk_prepare: emac1_clk
[000] ..... 5.422842: clk_prepare_complete: emac1_clk
[000] ..... 5.422843: clk_prepare: emac_1_clk
[000] ..... 5.422845: clk_prepare_complete: emac_1_clk
[000] d.... 5.422848: clk_enable: emac1_clk
[000] d.... 5.422850: clk_enable_complete: emac1_clk
[000] d.... 5.422851: clk_enable: emac_1_clk
[000] d.... 5.422855: clk_enable_complete: emac_1_clk
[000] d.... 5.432702: clk_disable: emac_1_clk
[000] d.... 5.432710: clk_disable_complete: emac_1_clk
[000] d.... 5.432712: clk_disable: emac1_clk
[000] d.... 5.432714: clk_disable_complete: emac1_clk
[000] ..... 5.432718: clk_unprepare: emac_1_clk
[000] ..... 5.432719: clk_unprepare_complete: emac_1_clk
[000] ..... 5.432721: clk_unprepare: emac1_clk
[000] ..... 5.432722: clk_unprepare_complete: emac1_clk
[000] ..... 5.444087: clk_prepare: emac1_clk
[000] ..... 5.444092: clk_prepare_complete: emac1_clk
[000] ..... 5.444094: clk_prepare: emac_1_clk
[000] ..... 5.444095: clk_prepare_complete: emac_1_clk
[000] d.... 5.444098: clk_enable: emac1_clk
[000] d.... 5.444100: clk_enable_complete: emac1_clk
[000] d.... 5.444101: clk_enable: emac_1_clk
[000] d.... 5.444105: clk_enable_complete: emac_1_clk
[000] d.... 5.444435: clk_disable: emac_1_clk
[000] d.... 5.444441: clk_disable_complete: emac_1_clk
[000] d.... 5.444443: clk_disable: emac1_clk
[000] d.... 5.444444: clk_disable_complete: emac1_clk
[000] ..... 5.444448: clk_unprepare: emac_1_clk
[000] ..... 5.444450: clk_unprepare_complete: emac_1_clk
[000] ..... 5.444451: clk_unprepare: emac1_clk
[000] ..... 5.444452: clk_unprepare_complete: emac1_clk
[000] ..... 5.463489: clk_prepare: emac1_clk
[000] ..... 5.463494: clk_prepare_complete: emac1_clk
[000] ..... 5.463496: clk_prepare: emac_1_clk
[000] ..... 5.463497: clk_prepare_complete: emac_1_clk
[000] d.... 5.463501: clk_enable: emac1_clk
[000] d.... 5.463503: clk_enable_complete: emac1_clk
[000] d.... 5.463504: clk_enable: emac_1_clk
[000] d.... 5.463507: clk_enable_complete: emac_1_clk
[000] d.... 5.465073: clk_disable: emac_1_clk
[000] d.... 5.465084: clk_disable_complete: emac_1_clk
[000] d.... 5.465085: clk_disable: emac1_clk
[000] d.... 5.465087: clk_disable_complete: emac1_clk
[000] ..... 5.465091: clk_unprepare: emac_1_clk
[000] ..... 5.465093: clk_unprepare_complete: emac_1_clk
[000] ..... 5.465094: clk_unprepare: emac1_clk
[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
[001] ..... 19.978213: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 19.978220: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 19.978226: dw8250_set_termios: dw8250_set_termios: rate = 200000000 newrate = 1843200
[001] ..... 19.978229: dw8250_set_termios: dw8250_set_termios: before: uartclk = 200000000
[001] ..... 19.978231: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 19.978233: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 19.978235: clk_rate_request_start: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 19.978237: clk_rate_request_done: l4_sp_clk min 0 max 4294967295, parent per_base_clk (200000000)
[001] ..... 19.978245: clk_set_rate: l4_sp_clk 200000000
[001] ..... 19.978247: clk_set_rate_complete: l4_sp_clk 200000000
[001] ..... 19.978251: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: div_reg: div = 2
[001] ..... 19.978254: socfpga_clk_recalc_rate: socfpga_clk_recalc_rate: rate = 100000000
[001] ..... 19.978256: dw8250_set_termios: dw8250_set_termios: after: uartclk = 200000000
| 43 ++++++++++++++++++++++-------
/8250/8250_dw.c | 3 ++
/8250/8250_port.c | 2 ++
38 insertions(+), 10 deletions(-)
a/drivers/clk/socfpga/clk-gate.c b/drivers/clk/socfpga/clk-gate.c
100644
ocfpga/clk-gate.c
ocfpga/clk-gate.c
+31,39 @@ static u8 socfpga_clk_get_parent(struct clk_hw *hwclk)
*name = clk_hw_get_name(hwclk);
name = %s\n", __func__, name);
SOCFPGA_L4_MP_CLK)) {
= readl(clk_mgr_base_addr + CLKMGR_L4SRC);
l4_mp_clk = %d\n", __func__, ret);
SOCFPGA_L4_SP_CLK)) {
= readl(clk_mgr_base_addr + CLKMGR_L4SRC);
l4_sp_clk = %d\n", __func__, ret);
= readl(clk_mgr_base_addr + CLKMGR_PERPLL_SRC);
SOCFPGA_MMC_CLK))
SOCFPGA_MMC_CLK)) {
sdmmc_clk = %d\n", __func__, ret);
SOCFPGA_NAND_CLK) ||
SOCFPGA_NAND_X_CLK))
(perpll_src >> 2) & 3;
SOCFPGA_NAND_X_CLK)) {
>> 2) & 3;
nand_clk / nand_x_clk = %d\n", __func__, ret);
>> 4) & 3;
>> 4) & 3;
qspi_clk = %d\n", __func__, ret);
socfpga_clk_set_parent(struct clk_hw *hwclk, u8 parent)
+76,28 @@ static int socfpga_clk_set_parent(struct clk_hw *hwclk, u8 parent)
clk_mgr_base_addr + CLKMGR_L4SRC);
l4_mp_clk: src_reg = %d\n", __func__, src_reg);
(streq(name, SOCFPGA_L4_SP_CLK)) {
= readl(clk_mgr_base_addr + CLKMGR_L4SRC);
|= (parent << 1);
clk_mgr_base_addr + CLKMGR_L4SRC);
l4_sp_clk: src_reg = %d\n", __func__, src_reg);
= readl(clk_mgr_base_addr + CLKMGR_PERPLL_SRC);
SOCFPGA_MMC_CLK)) {
sdmmc_clk: src_reg = %d\n", __func__, src_reg);
if (streq(name, SOCFPGA_NAND_CLK) ||
SOCFPGA_NAND_X_CLK)) {
|= (parent << 2);
nand_clk: src_reg = %d\n", __func__, src_reg);
|= (parent << 4);
qspi_clk: src_reg = %d\n", __func__, src_reg);
clk_mgr_base_addr + CLKMGR_PERPLL_SRC);
@@ static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk,
*socfpgaclk = to_socfpga_gate_clk(hwclk);
->fixed_div;
fixed_div: div = %d\n", __func__, div);
(socfpgaclk->div_reg) {
pgaclk->div_reg) >> socfpgaclk->shift;
GENMASK(socfpgaclk->width - 1, 0);
+123,11 @@ static unsigned long socfpga_clk_recalc_rate(struct clk_hw *hwclk,
div_reg: div = %d\n", __func__, div);
rate = %ld\n", __func__, parent_rate / div);
a/drivers/tty/serial/8250/8250_dw.c b/drivers/tty/serial/8250/8250_dw.c
100644
erial/8250/8250_dw.c
erial/8250/8250_dw.c
+359,8 @@ static void dw8250_set_termios(struct uart_port *p, struct ktermios *termios,
pare(d->clk);
rate(d->clk, newrate);
rate = %ld newrate = %ld\n", __func__, rate, newrate);
before: uartclk = %d\n", __func__, p->uartclk);
that any clock-notifer worker will block in
+370,7 @@ static void dw8250_set_termios(struct uart_port *p, struct ktermios *termios,
after: uartclk = %d\n", __func__, p->uartclk);
termios, old);
a/drivers/tty/serial/8250/8250_port.c b/drivers/tty/serial/8250/8250_port.c
100644
erial/8250/8250_port.c
erial/8250/8250_port.c
+2758,8 @@ void serial8250_update_uartclk(struct uart_port *port, unsigned int uartclk)
termios->c_cflag, baud);
%s: uartclk: %d baud: %d quot: %d frac: %d\n",
port->name, uartclk, baud, quot, frac);
baud, quot, frac);
UART_LCR, up->lcr);

2023-10-05 21:03:48

by Stephen Boyd

[permalink] [raw]

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

Quoting Benedikt Spranger (2023-10-05 11:32:23)
> On Thu, 5 Oct 2023 13:34:01 +0200
> Maxime Ripard <[email protected]> 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;

2023-10-06 03:39:49

by Benedikt Spranger

[permalink] [raw]

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

On Thu, 05 Oct 2023 14:03:19 -0700
Stephen Boyd <[email protected]> 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

2023-10-06 14:53:39

by Maxime Ripard

[permalink] [raw]

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

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

Attachments:

(No filename) (410.00 B)
signature.asc (235.00 B)
Download all attachments

2023-10-06 15:01:58

by Maxime Ripard

[permalink] [raw]

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

On Thu, Oct 05, 2023 at 08:32:23PM +0200, Benedikt Spranger wrote:
> On Thu, 5 Oct 2023 13:34:01 +0200
> Maxime Ripard <[email protected]> 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

Attachments:

(No filename) (2.71 kB)
signature.asc (235.00 B)
Download all attachments

2023-10-06 16:41:32

by Benedikt Spranger

[permalink] [raw]

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

On Fri, 6 Oct 2023 17:01:34 +0200
Maxime Ripard <[email protected]> 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 <[email protected]> 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

2023-10-11 09:17:40

by Maxime Ripard

[permalink] [raw]

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

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 <[email protected]> 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

Attachments:

(No filename) (9.08 kB)
signature.asc (235.00 B)
Download all attachments

2023-10-11 14:04:39

by Benedikt Spranger

[permalink] [raw]

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

On Wed, 11 Oct 2023 11:17:22 +0200
Maxime Ripard <[email protected]> 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