mmc: sdhci: pedantic clock rate debug logging

Add pr_info-level logging across the SDHCI subsystem and the Tegra
SDMMC clock providers so clock rate calculation, rounding, assigned
clocks and parents are visible in dmesg without needing dynamic_debug.

  - sdhci-tegra: log curr_clk_rate/max_clk/clock on set_clock entry and
    after clk_get_rate(), the requested host_clk, the rounded
    get_max_clock value, and dump regs before hw tuning.
  - sdhci: promote the DBG() macro from pr_debug to pr_info and log
    host->clock/max_clk/clock plus the computed divider/actual clock
    in sdhci_calc_clk() and sdhci_set_clock().
  - clk-sdmmc-mux / clk-divider / clk-utils: log div, mul, parent_rate,
    rounded rate and recalc_rate results in round_rate/recalc_rate/
    set_rate/div_frac_get so the full rate decision path is traceable.
  - mmc core: log the requested speed in mmc_set_clock() and the
    tuning entry/host-exec points in mmc_execute_tuning().

Change-Id: I4d569a01da8355db3319e82de942f1401dfac911

drivers/clk/tegra/clk-divider.c

@@ -11,6 +11,8 @@
 
 #include "clk.h"
 
+#define DRIVER_NAME "sdhci"
+
 #define pll_out_override(p) (BIT((p->shift - 6)))
 #define div_mask(d) ((1 << (d->width)) - 1)
 #define get_mul(d) (1 << d->frac_width)
@@ -48,6 +50,8 @@ static unsigned long clk_frac_div_recalc_rate(struct clk_hw *hw,
 
 	div = (reg >> divider->shift) & div_mask(divider);
 
+	pr_info("(" DRIVER_NAME ") clk read divider: %d\n", div);
+
 	mul = get_mul(divider);
 	div += mul;
 
@@ -55,6 +59,9 @@ static unsigned long clk_frac_div_recalc_rate(struct clk_hw *hw,
 	rate += div - 1;
 	do_div(rate, div);
 
+	pr_info("(" DRIVER_NAME ") (recalc_rate) got rate: %llu\n",
+		       (unsigned long long)rate);
+
 	return rate;
 }
 
@@ -78,10 +85,18 @@ static int clk_frac_div_determine_rate(struct clk_hw *hw,
 		return 0;
 	}
 
+	pr_info("(" DRIVER_NAME ") clk div %d rate: %lu parent_rate: %lu\n",
+		div, rate, output_rate);
+	pr_info("(" DRIVER_NAME ") (round_rate) got div: %d\n", div);
+
 	mul = get_mul(divider);
 
+	pr_info("(" DRIVER_NAME ") (round_rate) got mul: %d\n", mul);
+
 	req->rate = DIV_ROUND_UP(output_rate * mul, div + mul);
 
+	pr_info("(" DRIVER_NAME ") clk calculated rounded rate: %lu\n", req->rate);
+
 	return 0;
 }
 
@@ -93,10 +108,17 @@ static int clk_frac_div_set_rate(struct clk_hw *hw, unsigned long rate,
 	unsigned long flags = 0;
 	u32 val;
 
+	pr_info("(" DRIVER_NAME ") clk setting rate: %lu parent_rate: %lu\n",
+		rate, parent_rate);
+
 	div = get_div(divider, rate, parent_rate);
 	if (div < 0)
 		return div;
 
+	pr_info("(" DRIVER_NAME ") clk div %d rate: %lu parent_rate: %lu\n",
+		div, rate, parent_rate);
+	pr_info("(" DRIVER_NAME ") got div: %d\n", div);
+
 	if (divider->lock)
 		spin_lock_irqsave(divider->lock, flags);
 

drivers/clk/tegra/clk-sdmmc-mux.c

@@ -17,6 +17,8 @@
 
 #include "clk.h"
 
+#define DRIVER_NAME "sdhci"
+
 #define DIV_MASK GENMASK(7, 0)
 #define MUX_SHIFT 29
 #define MUX_MASK GENMASK(MUX_SHIFT + 2, MUX_SHIFT)
@@ -56,12 +58,16 @@ static u8 clk_sdmmc_mux_get_parent(struct clk_hw *hw)
 
 	for (i = 0; i < num_parents; i++) {
 		if (mux_idx[i] == src)
-			return i;
+			break;
 	}
 
-	WARN(1, "Unknown parent selector %d\n", src);
+	if (i < num_parents)
+		pr_info("(" DRIVER_NAME ") get_parent: src=%u parent=%s\n",
+			src, clk_hw_get_name(clk_hw_get_parent(hw)));
+	else
+		WARN(1, "Unknown parent selector %d\n", src);
 
-	return 0;
+	return i < num_parents ? i : 0;
 }
 
 static int clk_sdmmc_mux_set_parent(struct clk_hw *hw, u8 index)
@@ -95,12 +101,17 @@ static unsigned long clk_sdmmc_mux_recalc_rate(struct clk_hw *hw,
 	val = readl_relaxed(sdmmc_mux->reg);
 	div = get_div_field(val);
 
+	pr_info("(" DRIVER_NAME ") clk read divider: %d\n", div);
+
 	div += SDMMC_MUL;
 
 	rate *= SDMMC_MUL;
 	rate += div - 1;
 	do_div(rate, div);
 
+	pr_info("(" DRIVER_NAME ") (recalc_rate) got rate: %llu\n",
+		       (unsigned long long)rate);
+
 	return rate;
 }
 
@@ -121,12 +132,20 @@ static int clk_sdmmc_mux_determine_rate(struct clk_hw *hw,
 	if (div < 0)
 		div = 0;
 
+	pr_info("(" DRIVER_NAME ") clk div %d rate: %lu parent_rate: %lu\n",
+		div, req->rate, output_rate);
+	pr_info("(" DRIVER_NAME ") (round_rate) got div: %d\n", div);
+	pr_info("(" DRIVER_NAME ") (round_rate) got mul: %d\n", SDMMC_MUL);
+
 	if (sdmmc_mux->div_flags & TEGRA_DIVIDER_ROUND_UP)
 		req->rate =  DIV_ROUND_UP(output_rate * SDMMC_MUL,
 					  div + SDMMC_MUL);
 	else
 		req->rate =  output_rate * SDMMC_MUL / (div + SDMMC_MUL);
 
+	pr_info("(" DRIVER_NAME ") clk calculated rounded rate: %lu\n",
+		req->rate);
+
 	return 0;
 }
 
@@ -139,10 +158,17 @@ static int clk_sdmmc_mux_set_rate(struct clk_hw *hw, unsigned long rate,
 	u32 val;
 	u8 src;
 
+	pr_info("(" DRIVER_NAME ") clk setting rate: %lu parent_rate: %lu\n",
+		rate, parent_rate);
+
 	div = div_frac_get(rate, parent_rate, 8, 1, sdmmc_mux->div_flags);
 	if (div < 0)
 		return div;
 
+	pr_info("(" DRIVER_NAME ") clk div %d rate: %lu parent_rate: %lu\n",
+		div, rate, parent_rate);
+	pr_info("(" DRIVER_NAME ") got div: %d\n", div);
+
 	if (sdmmc_mux->lock)
 		spin_lock_irqsave(sdmmc_mux->lock, flags);
 

drivers/clk/tegra/clk-utils.c

@@ -7,6 +7,8 @@
 
 #include "clk.h"
 
+#define DRIVER_NAME "sdhci"
+
 #define div_mask(w) ((1 << (w)) - 1)
 
 int div_frac_get(unsigned long rate, unsigned parent_rate, u8 width,
@@ -39,5 +41,8 @@ int div_frac_get(unsigned long rate, unsigned parent_rate, u8 width,
 	if (div1_5_not_allowed && (divider_ux1 > 0) && (divider_ux1 < mul))
 		divider_ux1 = (flags & TEGRA_DIVIDER_ROUND_UP) ? mul : 0;
 
+	pr_info("(" DRIVER_NAME ") div_frac_get: rate=%lu parent_rate=%u div=%lld mul=%d\n",
+		rate, parent_rate, divider_ux1, mul);
+
 	return divider_ux1;
 }

drivers/mmc/core/core.c

@@ -924,6 +924,8 @@ void mmc_set_clock(struct mmc_host *host, unsigned int hz)
 	if (hz > host->f_max)
 		hz = host->f_max;
 
+	pr_info("mmc core: speed: %u\n", hz);
+
 	host->ios.clock = hz;
 	mmc_set_ios(host);
 }
@@ -934,6 +936,8 @@ int mmc_execute_tuning(struct mmc_card *card)
 	u32 opcode;
 	int err;
 
+	pr_info("mmc core tuning\n");
+
 	if (!host->ops->execute_tuning)
 		return 0;
 
@@ -945,6 +949,8 @@ int mmc_execute_tuning(struct mmc_card *card)
 	else
 		opcode = MMC_SEND_TUNING_BLOCK;
 
+	pr_info("mmc core host exec tuning\n");
+
 	err = host->ops->execute_tuning(host, opcode);
 	if (!err) {
 		mmc_retune_clear(host);

drivers/mmc/host/sdhci-tegra.c

@@ -796,6 +796,9 @@ static void tegra_sdhci_set_clock(struct sdhci_host *host, unsigned int clock)
 	unsigned long host_clk;
 	int err;
 
+	pr_info("sdhci-tegra: curr_clk_rate: %lu, max_clk: %u, clock: %u\n",
+		tegra_host->curr_clk_rate, host->max_clk, clock);
+
 	if (!clock)
 		return sdhci_set_clock(host, clock);
 
@@ -813,6 +816,8 @@ static void tegra_sdhci_set_clock(struct sdhci_host *host, unsigned int clock)
 	 */
 	host_clk = tegra_host->ddr_signaling ? clock * 2 : clock;
 
+	pr_info("sdhci-tegra: setting host clk to host_clk: %lu\n", host_clk);
+
 	err = dev_pm_opp_set_rate(dev, host_clk);
 	if (err)
 		dev_err(dev, "failed to set clk rate to %luHz: %d\n",
@@ -824,6 +829,9 @@ static void tegra_sdhci_set_clock(struct sdhci_host *host, unsigned int clock)
 	else
 		host->max_clk = clk_get_rate(pltfm_host->clk);
 
+	pr_info("sdhci-tegra: curr_clk_rate: %lu, max_clk: %u, clock: %u\n",
+		tegra_host->curr_clk_rate, host->max_clk, clock);
+
 	sdhci_set_clock(host, clock);
 
 	if (tegra_host->pad_calib_required) {
@@ -861,8 +869,12 @@ static void tegra_sdhci_hs400_enhanced_strobe(struct mmc_host *mmc,
 static unsigned int tegra_sdhci_get_max_clock(struct sdhci_host *host)
 {
 	struct sdhci_pltfm_host *pltfm_host = sdhci_priv(host);
+	unsigned long rounded;
 
-	return clk_round_rate(pltfm_host->clk, UINT_MAX);
+	rounded = clk_round_rate(pltfm_host->clk, 500000000);
+	pr_info("sdhci-tegra: get_max_clock rounded=%lu (requested 500000000)\n",
+		rounded);
+	return rounded;
 }
 
 static void tegra_sdhci_set_dqs_trim(struct sdhci_host *host, u8 trim)
@@ -1067,6 +1079,9 @@ static int tegra_sdhci_execute_hw_tuning(struct mmc_host *mmc, u32 opcode)
 	struct sdhci_host *host = mmc_priv(mmc);
 	int err;
 
+	pr_info("sdhci-tegra: hello fuckers, dumping regs\n");
+	sdhci_dumpregs(host);
+
 	err = sdhci_execute_tuning(mmc, opcode);
 	if (!err && !host->tuning_err)
 		tegra_sdhci_post_tuning(host);

drivers/mmc/host/sdhci.c

@@ -37,7 +37,7 @@
 #define DRIVER_NAME "sdhci"
 
 #define DBG(f, x...) \
-	pr_debug("%s: " DRIVER_NAME ": " f, mmc_hostname(host->mmc), ## x)
+	pr_info("%s: " DRIVER_NAME ": " f, mmc_hostname(host->mmc), ## x)
 
 #define SDHCI_DUMP(f, x...) \
 	pr_err("%s: " DRIVER_NAME ": " f, mmc_hostname(host->mmc), ## x)
@@ -1921,6 +1921,9 @@ u16 sdhci_calc_clk(struct sdhci_host *host, unsigned int clock,
 	u16 clk = 0;
 	bool switch_base_clk = false;
 
+	pr_info("%s: " DRIVER_NAME ": host->clock: %u, host->max_clk: %u, clock: %u\n",
+		mmc_hostname(host->mmc), host->clock, host->max_clk, clock);
+
 	if (host->version >= SDHCI_SPEC_300) {
 		if (host->preset_enabled) {
 			u16 pre_val;
@@ -1997,6 +2000,8 @@ u16 sdhci_calc_clk(struct sdhci_host *host, unsigned int clock,
 clock_set:
 	if (real_div)
 		*actual_clock = (host->max_clk * clk_mul) / real_div;
+	pr_info("%s: (" DRIVER_NAME ") clk div %d rate: %u parent_rate: %u\n",
+		mmc_hostname(host->mmc), real_div, *actual_clock, host->max_clk);
 	clk |= (div & SDHCI_DIV_MASK) << SDHCI_DIVIDER_SHIFT;
 	clk |= ((div & SDHCI_DIV_HI_MASK) >> SDHCI_DIV_MASK_LEN)
 		<< SDHCI_DIVIDER_HI_SHIFT;
@@ -2071,6 +2076,8 @@ void sdhci_set_clock(struct sdhci_host *host, unsigned int clock)
 		return;
 
 	clk = sdhci_calc_clk(host, clock, &host->mmc->actual_clock);
+	pr_info("%s: " DRIVER_NAME ": set_clock requested=%u actual=%u\n",
+		mmc_hostname(host->mmc), clock, host->mmc->actual_clock);
 	sdhci_enable_clk(host, clk);
 }
 EXPORT_SYMBOL_GPL(sdhci_set_clock);