Message-ID: <c6cf7030-69c7-6a63-f646-b40f87ce7b54@gmail.com>
Date:   Fri, 27 Dec 2019 16:47:03 +0300
From:   Dmitry Osipenko <digetx@...il.com>
To:     Thierry Reding <thierry.reding@...il.com>,
        "Rafael J. Wysocki" <rjw@...ysocki.net>,
        Mikko Perttunen <cyndis@...si.fi>
Cc:     Jonathan Hunter <jonathanh@...dia.com>,
        Laxman Dewangan <ldewangan@...dia.com>,
        Wolfram Sang <wsa@...-dreams.de>, linux-i2c@...r.kernel.org,
        linux-tegra@...r.kernel.org, linux-kernel@...r.kernel.org
Subject: Re: [PATCH v1 3/3] i2c: tegra: Fix suspending in active runtime PM
 state

20.12.2019 01:58, Dmitry Osipenko пишет:
> 13.12.2019 21:01, Dmitry Osipenko пишет:
>> 13.12.2019 17:04, Dmitry Osipenko пишет:
>>> 13.12.2019 16:47, Thierry Reding пишет:
>>>> On Fri, Dec 13, 2019 at 02:34:28AM +0300, Dmitry Osipenko wrote:
>>>>> I noticed that sometime I2C clock is kept enabled during suspend-resume.
>>>>> This happens because runtime PM defers dynamic suspension and thus it may
>>>>> happen that runtime PM is in active state when system enters into suspend.
>>>>> In particular I2C controller that is used for CPU's DVFS is often kept ON
>>>>> during suspend because CPU's voltage scaling happens quite often.
>>>>>
>>>>> Note: we marked runtime PM as IRQ-safe during the driver's probe in the
>>>>> "Support atomic transfers" patch, thus it's okay to enforce runtime PM
>>>>> suspend/resume in the NOIRQ phase which is used for the system-level
>>>>> suspend/resume of the driver.
>>>>>
>>>>> Signed-off-by: Dmitry Osipenko <digetx@...il.com>
>>>>> ---
>>>>>  drivers/i2c/busses/i2c-tegra.c | 9 +++++++++
>>>>>  1 file changed, 9 insertions(+)
>>>>
>>>> I've recently discussed this with Rafael in the context of runtime PM
>>>> support in the Tegra DRM driver and my understanding is that you're not
>>>> supposed to force runtime PM suspension like this.
>>>>
>>>> I had meant to send out an alternative patch to fix this, which I've
>>>> done now:
>>>>
>>>> 	http://patchwork.ozlabs.org/patch/1209148/
>>>>
>>>> That's more in line with what Rafael and I had discussed in the other
>>>> thread and should address the issue that you're seeing as well.
>>>
>>> Well, either me or you are still having some misunderstanding of the
>>> runtime PM :) To my knowledge there are a lot of drivers that enforce
>>> suspension of the runtime PM during system's suspend, it should be a
>>> right thing to do especially in a context of the Tegra I2C driver
>>> because we're using asynchronous pm_runtime_put() and thus at the time
>>> of system's suspending, the runtime PM could be ON (as I wrote in the
>>> commit message) and then Terga's I2C driver manually disables the clock
>>> on resume (woopsie).
>>
>> Actually, looks like it's not the asynchronous pm_runtime_put() is the
>> cause of suspending in active state. I see that only one of three I2C
>> controllers is suspended in the enabled state, maybe some child (I2C
>> client) device keeps it awake, will try to find out.
>>
>>> By invoking pm_runtime_force_suspend() on systems's suspend, the runtime
>>> PM executes tegra_i2c_runtime_suspend() if device is in active state. On
>>> system resume, pm_runtime_force_resume() either keeps device in a
>>> suspended state or resumes it, say if for userspace disabled the runtime
>>> PM for the I2C controller.
>>>
>>> Rafael, could you please clarify whether my patch is doing a wrong thing?
> 
> [snip]
> 
> I'm now thinking that it will be not very worthwhile to spend time on
> trying to understand why runtime PM isn't working as expected here. It
> will be better to simply remove runtime PM from the I2C driver because
> it is used only for clock-gating/pinmuxing and it is a very light
> operation in comparison to I2C transfer performance. Thus it should be
> better to avoid the runtime PM overhead by enabling/disabling the I2C
> clocks before/after the transfer, I think that's what driver did before
> the runtime PM addition.
> 
> Thierry / Jon / Mikko, any objections?
> 

I took another look at the trouble and now feeling quite confident that
the forced suspend/resume should be the correct solution.

To clarify what I'm seeing:

Here is the change I made (on top of this series) which shows that some
I2C controllers stay resumed during suspend:

diff --git a/drivers/i2c/busses/i2c-tegra.c b/drivers/i2c/busses/i2c-tegra.c
index 263e0c540dbf..8526822003c8 100644
--- a/drivers/i2c/busses/i2c-tegra.c
+++ b/drivers/i2c/busses/i2c-tegra.c
@@ -279,6 +279,7 @@ struct tegra_i2c_dev {
        bool is_curr_dma_xfer;
        struct completion dma_complete;
        bool is_curr_atomic_xfer;
+       bool resumed;
 };

 static void dvc_writel(struct tegra_i2c_dev *i2c_dev, u32 val,
@@ -662,6 +663,10 @@ static int __maybe_unused
tegra_i2c_runtime_resume(struct device *dev)
                return ret;
        }

+       pr_err("%s: %pOF\n", __func__, i2c_dev->dev->of_node);
+
+       i2c_dev->resumed = 1;
+
        return 0;
 }

@@ -669,6 +674,10 @@ static int __maybe_unused
tegra_i2c_runtime_suspend(struct device *dev)
 {
        struct tegra_i2c_dev *i2c_dev = dev_get_drvdata(dev);

+       pr_err("%s: %pOF\n", __func__, i2c_dev->dev->of_node);
+
+       i2c_dev->resumed = 0;
+
        clk_disable(i2c_dev->div_clk);
        if (!i2c_dev->hw->has_single_clk_source)
                clk_disable(i2c_dev->fast_clk);
@@ -1764,9 +1773,12 @@ static int __maybe_unused
tegra_i2c_suspend(struct device *dev)

        i2c_mark_adapter_suspended(&i2c_dev->adapter);

-       err = pm_runtime_force_suspend(dev);
-       if (err < 0)
-               return err;
+//     err = pm_runtime_force_suspend(dev);
+//     if (err < 0)
+//             return err;
+
+       pr_err("%s: %pOF resumed %d\n", __func__,
+               i2c_dev->dev->of_node, i2c_dev->resumed);

        return 0;
 }
@@ -1776,6 +1788,9 @@ static int __maybe_unused tegra_i2c_resume(struct
device *dev)
        struct tegra_i2c_dev *i2c_dev = dev_get_drvdata(dev);
        int err;

+       pr_err("%s: %pOF resumed %d\n", __func__,
+               i2c_dev->dev->of_node, i2c_dev->resumed);
+
        err = tegra_i2c_runtime_resume(dev);
        if (err)
                return err;
@@ -1788,9 +1803,9 @@ static int __maybe_unused tegra_i2c_resume(struct
device *dev)
        if (err)
                return err;

-       err = pm_runtime_force_resume(dev);
-       if (err < 0)
-               return err;
+//     err = pm_runtime_force_resume(dev);
+//     if (err < 0)
+//             return err;

        i2c_mark_adapter_resumed(&i2c_dev->adapter);

---

Running these commands:

# trace-cmd record -e power:* -e rpm:*
# rtcwake -s10 -mmem

gives the following KMSG output:

...
[   27.651391] tegra_i2c_runtime_resume: /i2c@...0d000
[   27.652663] tegra_i2c_runtime_suspend: /i2c@...0d000
[   27.652912] tegra_i2c_runtime_resume: /i2c@...0d000
[   27.653726] tegra_i2c_runtime_suspend: /i2c@...0d000
[   27.653970] tegra_i2c_runtime_resume: /i2c@...0d000
[   27.654569] tegra_i2c_runtime_suspend: /i2c@...0d000
[   27.707558] PM: suspend entry (deep)
[   27.707886] Filesystems sync: 0.000 seconds
[   27.743987] Freezing user space processes ... (elapsed 0.001 seconds)
done.
[   27.745773] OOM killer disabled.
[   27.745953] Freezing remaining freezable tasks ... (elapsed 0.001
seconds) done.
[   27.841496] tegra_i2c_runtime_resume: /i2c@...0d000
[   27.872012] tegra_i2c_runtime_resume: /i2c@...0c500
[   27.880717] tegra_i2c_suspend: /i2c@...0d000 resumed 1
[   27.880851] tegra_i2c_suspend: /i2c@...0c500 resumed 1
[   27.881048] tegra_i2c_suspend: /i2c@...0c400 resumed 0
[   27.881298] Disabling non-boot CPUs ...
[   27.882099] IRQ 18: no longer affine to CPU1
[   27.884006] IRQ 19: no longer affine to CPU2
[   27.885452] IRQ 20: no longer affine to CPU3
[   27.899472] Entering suspend state LP1
[   27.899539] Enabling non-boot CPUs ...
[   27.901351] CPU1 is up
[   27.902650] CPU2 is up
[   27.903932] CPU3 is up
[   27.904582] tegra_i2c_resume: /i2c@...0c400 resumed 0
[   27.904706] tegra_i2c_runtime_resume: /i2c@...0c400
[   27.904916] tegra_i2c_runtime_suspend: /i2c@...0c400
[   27.905039] tegra_i2c_resume: /i2c@...0c500 resumed 1
[   27.905226] tegra_i2c_runtime_resume: /i2c@...0c500
[   27.905343] tegra_i2c_runtime_suspend: /i2c@...0c500
[   27.905538] tegra_i2c_resume: /i2c@...0d000 resumed 1
[   27.905644] tegra_i2c_runtime_resume: /i2c@...0d000
[   27.905839] tegra_i2c_runtime_suspend: /i2c@...0d000
[   27.948618] tegra_i2c_runtime_resume: /i2c@...0c400
[   28.075318] elants_i2c 0-0010: unknown packet ff ff ff ff
[   28.522799] OOM killer enabled.
[   28.523007] Restarting tasks ...
[   28.523275] tegra_i2c_runtime_suspend: /i2c@...0d000
[   28.523783] tegra_i2c_runtime_suspend: /i2c@...0c500
[   28.524015] tegra_i2c_runtime_suspend: /i2c@...0c400
[   28.525942] done.
[   28.526323] tegra_i2c_runtime_resume: /i2c@...0d000
[   28.537613] tegra_i2c_runtime_suspend: /i2c@...0d000
[   28.563458] PM: suspend exit
[   32.488633] vcore_emmc: disabling
[   32.488866] vdd_camera: disabling
[   32.489226] tegra_i2c_runtime_resume: /i2c@...0d000
...

here is what PM tracing shows:

# trace-cmd report

see the attached trace.txt

---

Once the forced RPM suspend/resume are uncommented, the suspend-resume
sequence works like expected.

So either using forced RPM suspend/resume or removing RPM entirely will
solve the problem properly. I'm going to update this series to v2 soon,
keeping the forced RPM for suspend-resume since it works properly.

View attachment "trace.txt" of type "text/plain" (357780 bytes)

Powered by blists - more mailing lists