diff mbox series

[v5,3/3] PM/runtime:Replace jiffies based accounting with ktime based accounting

Message ID 1545388436-7489-4-git-send-email-vincent.guittot@linaro.org (mailing list archive)
State New, archived
Headers show
Series Move pm_runtime accounted time to raw nsec | expand

Commit Message

Vincent Guittot Dec. 21, 2018, 10:33 a.m. UTC
From: Thara Gopinath <thara.gopinath@linaro.org>

This patch replaces jiffies based accounting for runtime_active_time
and runtime_suspended_time with ktime base accounting. This makes the
runtime debug counters inline with genpd and other pm subsytems which
uses ktime based accounting.

timekeeping is initialized before pm_runtime_init() so ktime_get() will
be ready before first call. In fact, timekeeping_init() is called early
in start_kernel() which is way before driver_init() (and that's when
devices can start to be initialized) called from rest_init() via
kernel_init_freeable() and do_basic_setup().

Signed-off-by: Thara Gopinath <thara.gopinath@linaro.org>
[move from ktime to raw nsec]
Signed-off-by: Vincent Guittot <vincent.guittot@linaro.org>
---
 drivers/base/power/runtime.c | 17 +++++++++--------
 drivers/base/power/sysfs.c   | 11 ++++++++---
 include/linux/pm.h           |  6 +++---
 3 files changed, 20 insertions(+), 14 deletions(-)

Comments

Ulf Hansson Dec. 21, 2018, 10:43 a.m. UTC | #1
On Fri, 21 Dec 2018 at 11:34, Vincent Guittot
<vincent.guittot@linaro.org> wrote:
>
> From: Thara Gopinath <thara.gopinath@linaro.org>
>
> This patch replaces jiffies based accounting for runtime_active_time
> and runtime_suspended_time with ktime base accounting. This makes the
> runtime debug counters inline with genpd and other pm subsytems which
> uses ktime based accounting.
>
> timekeeping is initialized before pm_runtime_init() so ktime_get() will
> be ready before first call. In fact, timekeeping_init() is called early
> in start_kernel() which is way before driver_init() (and that's when
> devices can start to be initialized) called from rest_init() via
> kernel_init_freeable() and do_basic_setup().
>
> Signed-off-by: Thara Gopinath <thara.gopinath@linaro.org>
> [move from ktime to raw nsec]
> Signed-off-by: Vincent Guittot <vincent.guittot@linaro.org>

Reviewed-by: Ulf Hansson <ulf.hansson@linaro.org>

Kind regards
Uffe

> ---
>  drivers/base/power/runtime.c | 17 +++++++++--------
>  drivers/base/power/sysfs.c   | 11 ++++++++---
>  include/linux/pm.h           |  6 +++---
>  3 files changed, 20 insertions(+), 14 deletions(-)
>
> diff --git a/drivers/base/power/runtime.c b/drivers/base/power/runtime.c
> index e695544..f700524 100644
> --- a/drivers/base/power/runtime.c
> +++ b/drivers/base/power/runtime.c
> @@ -64,8 +64,8 @@ static int rpm_suspend(struct device *dev, int rpmflags);
>   */
>  void update_pm_runtime_accounting(struct device *dev)
>  {
> -       unsigned long now = jiffies;
> -       unsigned long delta;
> +       u64 now = ktime_to_ns(ktime_get());
> +       u64 delta;
>
>         delta = now - dev->power.accounting_timestamp;
>
> @@ -75,9 +75,9 @@ void update_pm_runtime_accounting(struct device *dev)
>                 return;
>
>         if (dev->power.runtime_status == RPM_SUSPENDED)
> -               dev->power.suspended_jiffies += delta;
> +               dev->power.suspended_time += delta;
>         else
> -               dev->power.active_jiffies += delta;
> +               dev->power.active_time += delta;
>  }
>
>  static void __update_runtime_status(struct device *dev, enum rpm_status status)
> @@ -88,17 +88,18 @@ static void __update_runtime_status(struct device *dev, enum rpm_status status)
>
>  u64 pm_runtime_suspended_time(struct device *dev)
>  {
> -       unsigned long flags, time;
> +       u64 time;
> +       unsigned long flags;
>
>         spin_lock_irqsave(&dev->power.lock, flags);
>
>         update_pm_runtime_accounting(dev);
>
> -       time = dev->power.suspended_jiffies;
> +       time = dev->power.suspended_time;
>
>         spin_unlock_irqrestore(&dev->power.lock, flags);
>
> -       return jiffies_to_nsecs(time);
> +       return time;
>  }
>  EXPORT_SYMBOL_GPL(pm_runtime_suspended_time);
>
> @@ -1503,7 +1504,7 @@ void pm_runtime_init(struct device *dev)
>         dev->power.request_pending = false;
>         dev->power.request = RPM_REQ_NONE;
>         dev->power.deferred_resume = false;
> -       dev->power.accounting_timestamp = jiffies;
> +       dev->power.accounting_timestamp = ktime_to_ns(ktime_get());
>         INIT_WORK(&dev->power.work, pm_runtime_work);
>
>         dev->power.timer_expires = 0;
> diff --git a/drivers/base/power/sysfs.c b/drivers/base/power/sysfs.c
> index d713738..96c8a22 100644
> --- a/drivers/base/power/sysfs.c
> +++ b/drivers/base/power/sysfs.c
> @@ -125,9 +125,12 @@ static ssize_t runtime_active_time_show(struct device *dev,
>                                 struct device_attribute *attr, char *buf)
>  {
>         int ret;
> +       u64 tmp;
>         spin_lock_irq(&dev->power.lock);
>         update_pm_runtime_accounting(dev);
> -       ret = sprintf(buf, "%i\n", jiffies_to_msecs(dev->power.active_jiffies));
> +       tmp = dev->power.active_time;
> +       do_div(tmp, NSEC_PER_MSEC);
> +       ret = sprintf(buf, "%llu\n", tmp);
>         spin_unlock_irq(&dev->power.lock);
>         return ret;
>  }
> @@ -138,10 +141,12 @@ static ssize_t runtime_suspended_time_show(struct device *dev,
>                                 struct device_attribute *attr, char *buf)
>  {
>         int ret;
> +       u64 tmp;
>         spin_lock_irq(&dev->power.lock);
>         update_pm_runtime_accounting(dev);
> -       ret = sprintf(buf, "%i\n",
> -               jiffies_to_msecs(dev->power.suspended_jiffies));
> +       tmp = dev->power.suspended_time;
> +       do_div(tmp, NSEC_PER_MSEC);
> +       ret = sprintf(buf, "%llu\n", tmp);
>         spin_unlock_irq(&dev->power.lock);
>         return ret;
>  }
> diff --git a/include/linux/pm.h b/include/linux/pm.h
> index e723b78..e5a34e2 100644
> --- a/include/linux/pm.h
> +++ b/include/linux/pm.h
> @@ -632,9 +632,9 @@ struct dev_pm_info {
>         int                     runtime_error;
>         int                     autosuspend_delay;
>         unsigned long           last_busy;
> -       unsigned long           active_jiffies;
> -       unsigned long           suspended_jiffies;
> -       unsigned long           accounting_timestamp;
> +       u64                     active_time;
> +       u64                     suspended_time;
> +       u64                     accounting_timestamp;
>  #endif
>         struct pm_subsys_data   *subsys_data;  /* Owned by the subsystem. */
>         void (*set_latency_tolerance)(struct device *, s32);
> --
> 2.7.4
>
Guenter Roeck Jan. 17, 2019, 10:16 p.m. UTC | #2
On Fri, Dec 21, 2018 at 11:33:56AM +0100, Vincent Guittot wrote:
> From: Thara Gopinath <thara.gopinath@linaro.org>
> 
> This patch replaces jiffies based accounting for runtime_active_time
> and runtime_suspended_time with ktime base accounting. This makes the
> runtime debug counters inline with genpd and other pm subsytems which
> uses ktime based accounting.
> 
> timekeeping is initialized before pm_runtime_init() so ktime_get() will
> be ready before first call. In fact, timekeeping_init() is called early
> in start_kernel() which is way before driver_init() (and that's when
> devices can start to be initialized) called from rest_init() via
> kernel_init_freeable() and do_basic_setup().
> 
This is not (always) correct. My qemu "collie" boot test fails with this
patch applied. Reverting the patch fixes the problem. Bisect log attached.

With some added debugging:

...
IRQS: 16, nr_irqs: 65, preallocated irqs: 65
irq: Cannot allocate irq_descs @ IRQ1, assuming pre-allocated
gpio gpiochip0: ############### pm_runtime_init() ############
irq: Cannot allocate irq_descs @ IRQ33, assuming pre-allocated
############## timekeeping_init() ####################
sched_clock: 32 bits at 3686kHz, resolution 271ns, wraps every 582542222200ns^M
...

This is with:

void pm_runtime_init(struct device *dev)
{
+       dev_info(dev, "############### pm_runtime_init() ############\n");
+
...
@@ -1526,6 +1526,8 @@ void __init timekeeping_init(void)
	struct clocksource *clock;
	unsigned long flags;
		 
+       pr_info("############## timekeeping_init() ####################\n");
+

Guenter

---
# bad: [a37d50ca3b837c19a297f349365d11a20c1087d0] Add linux-next specific files for 20190117
# good: [1c7fc5cbc33980acd13d668f1c8f0313d6ae9fd8] Linux 5.0-rc2
git bisect start 'HEAD' 'v5.0-rc2'
# bad: [4edb817d29fdf19fb5d52784bb3c29c40e00f586] Merge remote-tracking branch 'pm/linux-next'
git bisect bad 4edb817d29fdf19fb5d52784bb3c29c40e00f586
# good: [6d95886720d306a1914a7c9a8aeb0bcbc7aef018] Merge remote-tracking branch 'omap/for-next'
git bisect good 6d95886720d306a1914a7c9a8aeb0bcbc7aef018
# good: [975b5cdd74430bc8a04f832d65a47cdb95b73fec] Merge remote-tracking branch 'fuse/for-next'
git bisect good 975b5cdd74430bc8a04f832d65a47cdb95b73fec
# good: [112386d2189fc54b979c3a8bf64b2908df91e123] Merge remote-tracking branch 'i2c/i2c/for-next'
git bisect good 112386d2189fc54b979c3a8bf64b2908df91e123
# good: [3943f059823b6e15884387f31618b84826e924b3] media: coda: Add control for h.264 chroma qp index offset
git bisect good 3943f059823b6e15884387f31618b84826e924b3
# good: [44970bbbbb5079ee100875b06e45db5d6e91a16e] Merge remote-tracking branch 'v4l-dvb/master'
git bisect good 44970bbbbb5079ee100875b06e45db5d6e91a16e
# bad: [599170c2b860aca3364574f833bb9cc801c9668d] Merge branch 'pm-core' into linux-next
git bisect bad 599170c2b860aca3364574f833bb9cc801c9668d
# good: [347d570919ca9a3a3653ce9cbb7399c7c0ba8248] Merge branch 'acpi-pci' into linux-next
git bisect good 347d570919ca9a3a3653ce9cbb7399c7c0ba8248
# good: [e0a9fde86ba1bc26dd754c733b32e70cd8f1c187] Merge branches 'acpi-tables' and 'acpi-apei' into linux-next
git bisect good e0a9fde86ba1bc26dd754c733b32e70cd8f1c187
# good: [3b4ed2e2eb5583774a1ed4aa4596a5a3c55f2567] drm/i915: Move on the new pm runtime interface
git bisect good 3b4ed2e2eb5583774a1ed4aa4596a5a3c55f2567
# bad: [c75c303933a68c547f3352d1d708843f9449d3f4] PM: clock_ops: fix missing clk_prepare() return value check
git bisect bad c75c303933a68c547f3352d1d708843f9449d3f4
# bad: [3982ab9ce433efc72ca31eb9ddc85d9355966444] PM-runtime: Replace jiffies based accounting with ktime-based accounting
git bisect bad 3982ab9ce433efc72ca31eb9ddc85d9355966444
# first bad commit: [3982ab9ce433efc72ca31eb9ddc85d9355966444] PM-runtime: Replace jiffies based accounting with ktime-based accounting
Vincent Guittot Jan. 18, 2019, 10:42 a.m. UTC | #3
Hi Guenter,

Le Thursday 17 Jan 2019 à 14:16:28 (-0800), Guenter Roeck a écrit :
> On Fri, Dec 21, 2018 at 11:33:56AM +0100, Vincent Guittot wrote:
> > From: Thara Gopinath <thara.gopinath@linaro.org>
> > 
> > This patch replaces jiffies based accounting for runtime_active_time
> > and runtime_suspended_time with ktime base accounting. This makes the
> > runtime debug counters inline with genpd and other pm subsytems which
> > uses ktime based accounting.
> > 
> > timekeeping is initialized before pm_runtime_init() so ktime_get() will
> > be ready before first call. In fact, timekeeping_init() is called early
> > in start_kernel() which is way before driver_init() (and that's when
> > devices can start to be initialized) called from rest_init() via
> > kernel_init_freeable() and do_basic_setup().
> > 
> This is not (always) correct. My qemu "collie" boot test fails with this
> patch applied. Reverting the patch fixes the problem. Bisect log attached.
> 

Can you try the patch below ?
ktime_get_mono_fast_ns() has the advantage of being init with dummy clock so
it can be used at early_init.

---
 drivers/base/power/runtime.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/drivers/base/power/runtime.c b/drivers/base/power/runtime.c
index ae1c728..118c7f6 100644
--- a/drivers/base/power/runtime.c
+++ b/drivers/base/power/runtime.c
@@ -66,7 +66,7 @@ static int rpm_suspend(struct device *dev, int rpmflags);
  */
 void update_pm_runtime_accounting(struct device *dev)
 {
-	u64 now = ktime_to_ns(ktime_get());
+	u64 now = ktime_get_mono_fast_ns();
 	u64 delta;
 
 	delta = now - dev->power.accounting_timestamp;
@@ -1507,7 +1507,7 @@ void pm_runtime_init(struct device *dev)
 	dev->power.request_pending = false;
 	dev->power.request = RPM_REQ_NONE;
 	dev->power.deferred_resume = false;
-	dev->power.accounting_timestamp = ktime_to_ns(ktime_get());
+	dev->power.accounting_timestamp = ktime_get_mono_fast_ns();
 	INIT_WORK(&dev->power.work, pm_runtime_work);
 
 	dev->power.timer_expires = 0;
Vincent Guittot Jan. 18, 2019, 10:53 a.m. UTC | #4
On Fri, 18 Jan 2019 at 11:42, Vincent Guittot
<vincent.guittot@linaro.org> wrote:
>
> Hi Guenter,
>
> Le Thursday 17 Jan 2019 à 14:16:28 (-0800), Guenter Roeck a écrit :
> > On Fri, Dec 21, 2018 at 11:33:56AM +0100, Vincent Guittot wrote:
> > > From: Thara Gopinath <thara.gopinath@linaro.org>
> > >
> > > This patch replaces jiffies based accounting for runtime_active_time
> > > and runtime_suspended_time with ktime base accounting. This makes the
> > > runtime debug counters inline with genpd and other pm subsytems which
> > > uses ktime based accounting.
> > >
> > > timekeeping is initialized before pm_runtime_init() so ktime_get() will
> > > be ready before first call. In fact, timekeeping_init() is called early
> > > in start_kernel() which is way before driver_init() (and that's when
> > > devices can start to be initialized) called from rest_init() via
> > > kernel_init_freeable() and do_basic_setup().
> > >
> > This is not (always) correct. My qemu "collie" boot test fails with this
> > patch applied. Reverting the patch fixes the problem. Bisect log attached.
> >
>
> Can you try the patch below ?
> ktime_get_mono_fast_ns() has the advantage of being init with dummy clock so
> it can be used at early_init.

Another possibility would be delay the init of the gpiochip

>
> ---
>  drivers/base/power/runtime.c | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/drivers/base/power/runtime.c b/drivers/base/power/runtime.c
> index ae1c728..118c7f6 100644
> --- a/drivers/base/power/runtime.c
> +++ b/drivers/base/power/runtime.c
> @@ -66,7 +66,7 @@ static int rpm_suspend(struct device *dev, int rpmflags);
>   */
>  void update_pm_runtime_accounting(struct device *dev)
>  {
> -       u64 now = ktime_to_ns(ktime_get());
> +       u64 now = ktime_get_mono_fast_ns();
>         u64 delta;
>
>         delta = now - dev->power.accounting_timestamp;
> @@ -1507,7 +1507,7 @@ void pm_runtime_init(struct device *dev)
>         dev->power.request_pending = false;
>         dev->power.request = RPM_REQ_NONE;
>         dev->power.deferred_resume = false;
> -       dev->power.accounting_timestamp = ktime_to_ns(ktime_get());
> +       dev->power.accounting_timestamp = ktime_get_mono_fast_ns();
>         INIT_WORK(&dev->power.work, pm_runtime_work);
>
>         dev->power.timer_expires = 0;
> --
> 2.7.4
>
>
> > With some added debugging:
> >
> > ...
> > IRQS: 16, nr_irqs: 65, preallocated irqs: 65
> > irq: Cannot allocate irq_descs @ IRQ1, assuming pre-allocated
> > gpio gpiochip0: ############### pm_runtime_init() ############
> > irq: Cannot allocate irq_descs @ IRQ33, assuming pre-allocated
> > ############## timekeeping_init() ####################
> > sched_clock: 32 bits at 3686kHz, resolution 271ns, wraps every 582542222200ns^M
> > ...
> >
> > This is with:
> >
> > void pm_runtime_init(struct device *dev)
> > {
> > +       dev_info(dev, "############### pm_runtime_init() ############\n");
> > +
> > ...
> > @@ -1526,6 +1526,8 @@ void __init timekeeping_init(void)
> >       struct clocksource *clock;
> >       unsigned long flags;
> >
> > +       pr_info("############## timekeeping_init() ####################\n");
> > +
> >
> > Guenter
> >
> > ---
> > # bad: [a37d50ca3b837c19a297f349365d11a20c1087d0] Add linux-next specific files for 20190117
> > # good: [1c7fc5cbc33980acd13d668f1c8f0313d6ae9fd8] Linux 5.0-rc2
> > git bisect start 'HEAD' 'v5.0-rc2'
> > # bad: [4edb817d29fdf19fb5d52784bb3c29c40e00f586] Merge remote-tracking branch 'pm/linux-next'
> > git bisect bad 4edb817d29fdf19fb5d52784bb3c29c40e00f586
> > # good: [6d95886720d306a1914a7c9a8aeb0bcbc7aef018] Merge remote-tracking branch 'omap/for-next'
> > git bisect good 6d95886720d306a1914a7c9a8aeb0bcbc7aef018
> > # good: [975b5cdd74430bc8a04f832d65a47cdb95b73fec] Merge remote-tracking branch 'fuse/for-next'
> > git bisect good 975b5cdd74430bc8a04f832d65a47cdb95b73fec
> > # good: [112386d2189fc54b979c3a8bf64b2908df91e123] Merge remote-tracking branch 'i2c/i2c/for-next'
> > git bisect good 112386d2189fc54b979c3a8bf64b2908df91e123
> > # good: [3943f059823b6e15884387f31618b84826e924b3] media: coda: Add control for h.264 chroma qp index offset
> > git bisect good 3943f059823b6e15884387f31618b84826e924b3
> > # good: [44970bbbbb5079ee100875b06e45db5d6e91a16e] Merge remote-tracking branch 'v4l-dvb/master'
> > git bisect good 44970bbbbb5079ee100875b06e45db5d6e91a16e
> > # bad: [599170c2b860aca3364574f833bb9cc801c9668d] Merge branch 'pm-core' into linux-next
> > git bisect bad 599170c2b860aca3364574f833bb9cc801c9668d
> > # good: [347d570919ca9a3a3653ce9cbb7399c7c0ba8248] Merge branch 'acpi-pci' into linux-next
> > git bisect good 347d570919ca9a3a3653ce9cbb7399c7c0ba8248
> > # good: [e0a9fde86ba1bc26dd754c733b32e70cd8f1c187] Merge branches 'acpi-tables' and 'acpi-apei' into linux-next
> > git bisect good e0a9fde86ba1bc26dd754c733b32e70cd8f1c187
> > # good: [3b4ed2e2eb5583774a1ed4aa4596a5a3c55f2567] drm/i915: Move on the new pm runtime interface
> > git bisect good 3b4ed2e2eb5583774a1ed4aa4596a5a3c55f2567
> > # bad: [c75c303933a68c547f3352d1d708843f9449d3f4] PM: clock_ops: fix missing clk_prepare() return value check
> > git bisect bad c75c303933a68c547f3352d1d708843f9449d3f4
> > # bad: [3982ab9ce433efc72ca31eb9ddc85d9355966444] PM-runtime: Replace jiffies based accounting with ktime-based accounting
> > git bisect bad 3982ab9ce433efc72ca31eb9ddc85d9355966444
> > # first bad commit: [3982ab9ce433efc72ca31eb9ddc85d9355966444] PM-runtime: Replace jiffies based accounting with ktime-based accounting
Rafael J. Wysocki Jan. 18, 2019, 10:54 a.m. UTC | #5
On Thu, Jan 17, 2019 at 11:16 PM Guenter Roeck <linux@roeck-us.net> wrote:
>
> On Fri, Dec 21, 2018 at 11:33:56AM +0100, Vincent Guittot wrote:
> > From: Thara Gopinath <thara.gopinath@linaro.org>
> >
> > This patch replaces jiffies based accounting for runtime_active_time
> > and runtime_suspended_time with ktime base accounting. This makes the
> > runtime debug counters inline with genpd and other pm subsytems which
> > uses ktime based accounting.
> >
> > timekeeping is initialized before pm_runtime_init() so ktime_get() will
> > be ready before first call. In fact, timekeeping_init() is called early
> > in start_kernel() which is way before driver_init() (and that's when
> > devices can start to be initialized) called from rest_init() via
> > kernel_init_freeable() and do_basic_setup().
> >
> This is not (always) correct. My qemu "collie" boot test fails with this
> patch applied. Reverting the patch fixes the problem. Bisect log attached.
>
> With some added debugging:
>
> ...
> IRQS: 16, nr_irqs: 65, preallocated irqs: 65
> irq: Cannot allocate irq_descs @ IRQ1, assuming pre-allocated
> gpio gpiochip0: ############### pm_runtime_init() ############
> irq: Cannot allocate irq_descs @ IRQ33, assuming pre-allocated
> ############## timekeeping_init() ####################
> sched_clock: 32 bits at 3686kHz, resolution 271ns, wraps every 582542222200ns^M
> ...
>
> This is with:
>
> void pm_runtime_init(struct device *dev)
> {
> +       dev_info(dev, "############### pm_runtime_init() ############\n");
> +
> ...
> @@ -1526,6 +1526,8 @@ void __init timekeeping_init(void)
>         struct clocksource *clock;
>         unsigned long flags;
>
> +       pr_info("############## timekeeping_init() ####################\n");
> +
>
> Guenter
>
> ---
> # bad: [a37d50ca3b837c19a297f349365d11a20c1087d0] Add linux-next specific files for 20190117
> # good: [1c7fc5cbc33980acd13d668f1c8f0313d6ae9fd8] Linux 5.0-rc2
> git bisect start 'HEAD' 'v5.0-rc2'
> # bad: [4edb817d29fdf19fb5d52784bb3c29c40e00f586] Merge remote-tracking branch 'pm/linux-next'
> git bisect bad 4edb817d29fdf19fb5d52784bb3c29c40e00f586
> # good: [6d95886720d306a1914a7c9a8aeb0bcbc7aef018] Merge remote-tracking branch 'omap/for-next'
> git bisect good 6d95886720d306a1914a7c9a8aeb0bcbc7aef018
> # good: [975b5cdd74430bc8a04f832d65a47cdb95b73fec] Merge remote-tracking branch 'fuse/for-next'
> git bisect good 975b5cdd74430bc8a04f832d65a47cdb95b73fec
> # good: [112386d2189fc54b979c3a8bf64b2908df91e123] Merge remote-tracking branch 'i2c/i2c/for-next'
> git bisect good 112386d2189fc54b979c3a8bf64b2908df91e123
> # good: [3943f059823b6e15884387f31618b84826e924b3] media: coda: Add control for h.264 chroma qp index offset
> git bisect good 3943f059823b6e15884387f31618b84826e924b3
> # good: [44970bbbbb5079ee100875b06e45db5d6e91a16e] Merge remote-tracking branch 'v4l-dvb/master'
> git bisect good 44970bbbbb5079ee100875b06e45db5d6e91a16e
> # bad: [599170c2b860aca3364574f833bb9cc801c9668d] Merge branch 'pm-core' into linux-next
> git bisect bad 599170c2b860aca3364574f833bb9cc801c9668d
> # good: [347d570919ca9a3a3653ce9cbb7399c7c0ba8248] Merge branch 'acpi-pci' into linux-next
> git bisect good 347d570919ca9a3a3653ce9cbb7399c7c0ba8248
> # good: [e0a9fde86ba1bc26dd754c733b32e70cd8f1c187] Merge branches 'acpi-tables' and 'acpi-apei' into linux-next
> git bisect good e0a9fde86ba1bc26dd754c733b32e70cd8f1c187
> # good: [3b4ed2e2eb5583774a1ed4aa4596a5a3c55f2567] drm/i915: Move on the new pm runtime interface
> git bisect good 3b4ed2e2eb5583774a1ed4aa4596a5a3c55f2567
> # bad: [c75c303933a68c547f3352d1d708843f9449d3f4] PM: clock_ops: fix missing clk_prepare() return value check
> git bisect bad c75c303933a68c547f3352d1d708843f9449d3f4
> # bad: [3982ab9ce433efc72ca31eb9ddc85d9355966444] PM-runtime: Replace jiffies based accounting with ktime-based accounting
> git bisect bad 3982ab9ce433efc72ca31eb9ddc85d9355966444
> # first bad commit: [3982ab9ce433efc72ca31eb9ddc85d9355966444] PM-runtime: Replace jiffies based accounting with ktime-based accounting

OK, dropping this one for now, we need a working replacement.

Thanks!
Rafael J. Wysocki Jan. 18, 2019, 11:05 a.m. UTC | #6
On Fri, Jan 18, 2019 at 11:53 AM Vincent Guittot
<vincent.guittot@linaro.org> wrote:
>
> On Fri, 18 Jan 2019 at 11:42, Vincent Guittot
> <vincent.guittot@linaro.org> wrote:
> >
> > Hi Guenter,
> >
> > Le Thursday 17 Jan 2019 à 14:16:28 (-0800), Guenter Roeck a écrit :
> > > On Fri, Dec 21, 2018 at 11:33:56AM +0100, Vincent Guittot wrote:
> > > > From: Thara Gopinath <thara.gopinath@linaro.org>
> > > >
> > > > This patch replaces jiffies based accounting for runtime_active_time
> > > > and runtime_suspended_time with ktime base accounting. This makes the
> > > > runtime debug counters inline with genpd and other pm subsytems which
> > > > uses ktime based accounting.
> > > >
> > > > timekeeping is initialized before pm_runtime_init() so ktime_get() will
> > > > be ready before first call. In fact, timekeeping_init() is called early
> > > > in start_kernel() which is way before driver_init() (and that's when
> > > > devices can start to be initialized) called from rest_init() via
> > > > kernel_init_freeable() and do_basic_setup().
> > > >
> > > This is not (always) correct. My qemu "collie" boot test fails with this
> > > patch applied. Reverting the patch fixes the problem. Bisect log attached.
> > >
> >
> > Can you try the patch below ?
> > ktime_get_mono_fast_ns() has the advantage of being init with dummy clock so
> > it can be used at early_init.
>
> Another possibility would be delay the init of the gpiochip

Well, right.

Initializing devices before timekeeping doesn't feel particularly
robust from the design perspective.

How exactly does that happen?
Vincent Guittot Jan. 21, 2019, 3:17 p.m. UTC | #7
On Fri, 18 Jan 2019 at 13:08, Guenter Roeck <linux@roeck-us.net> wrote:
>
> On 1/18/19 3:05 AM, Rafael J. Wysocki wrote:
> > On Fri, Jan 18, 2019 at 11:53 AM Vincent Guittot
> > <vincent.guittot@linaro.org> wrote:
> >>
> >> On Fri, 18 Jan 2019 at 11:42, Vincent Guittot
> >> <vincent.guittot@linaro.org> wrote:
> >>>
> >>> Hi Guenter,
> >>>
> >>> Le Thursday 17 Jan 2019 à 14:16:28 (-0800), Guenter Roeck a écrit :
> >>>> On Fri, Dec 21, 2018 at 11:33:56AM +0100, Vincent Guittot wrote:
> >>>>> From: Thara Gopinath <thara.gopinath@linaro.org>
> >>>>>
> >>>>> This patch replaces jiffies based accounting for runtime_active_time
> >>>>> and runtime_suspended_time with ktime base accounting. This makes the
> >>>>> runtime debug counters inline with genpd and other pm subsytems which
> >>>>> uses ktime based accounting.
> >>>>>
> >>>>> timekeeping is initialized before pm_runtime_init() so ktime_get() will
> >>>>> be ready before first call. In fact, timekeeping_init() is called early
> >>>>> in start_kernel() which is way before driver_init() (and that's when
> >>>>> devices can start to be initialized) called from rest_init() via
> >>>>> kernel_init_freeable() and do_basic_setup().
> >>>>>
> >>>> This is not (always) correct. My qemu "collie" boot test fails with this
> >>>> patch applied. Reverting the patch fixes the problem. Bisect log attached.
> >>>>
> >>>
> >>> Can you try the patch below ?
> >>> ktime_get_mono_fast_ns() has the advantage of being init with dummy clock so
> >>> it can be used at early_init.
> >>
> >> Another possibility would be delay the init of the gpiochip
> >
> > Well, right.
> >
> > Initializing devices before timekeeping doesn't feel particularly
> > robust from the design perspective.
> >
> > How exactly does that happen?
> >
>
> With an added 'initialized' flag and backtrace into the timekeeping code,
> with the change suggested earlier applied:
>
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 0 at kernel/time/timekeeping.c:453 ktime_get_mono_fast_ns+0x114/0x12c
> Timekeeping not initialized
> CPU: 0 PID: 0 Comm: swapper Not tainted 5.0.0-rc2-next-20190117-dirty #2
> Hardware name: Sharp-Collie
> Backtrace:
> [<c000dce8>] (dump_backtrace) from [<c000df78>] (show_stack+0x18/0x1c)
>   r7:00000009 r6:00000000 r5:c065ba90 r4:c06d3e54
> [<c000df60>] (show_stack) from [<c0588930>] (dump_stack+0x20/0x28)
> [<c0588910>] (dump_stack) from [<c0018ae8>] (__warn+0xcc/0xf4)
> [<c0018a1c>] (__warn) from [<c0018b5c>] (warn_slowpath_fmt+0x4c/0x6c)
>   r8:df407b08 r7:00000000 r6:c0c01550 r5:c065bad8 r4:c06dd028
> [<c0018b14>] (warn_slowpath_fmt) from [<c0069e2c>] (ktime_get_mono_fast_ns+0x114/0x12c)
>   r3:00000000 r2:c065bad8
>   r5:00000000 r4:df407b08
> [<c0069d18>] (ktime_get_mono_fast_ns) from [<c03c7810>] (pm_runtime_init+0x38/0xb8)
>   r9:c06c9a5c r8:df407b08 r7:00000000 r6:c0c01550 r5:00000000 r4:df407b08
> [<c03c77d8>] (pm_runtime_init) from [<c03b6a34>] (device_initialize+0xb0/0xec)
>   r7:00000000 r6:c0c01550 r5:00000000 r4:df407b08
> [<c03b6984>] (device_initialize) from [<c0366d30>] (gpiochip_add_data_with_key+0x9c/0x884)
>   r7:00000000 r6:c06fca34 r5:00000000 r4:00000000
> [<c0366c94>] (gpiochip_add_data_with_key) from [<c06b9708>] (sa1100_init_gpio+0x40/0x98)
>   r10:dfffcd60 r9:c06c9a5c r8:c06dd020 r7:c06dd028 r6:ffffffff r5:00000000
>   r4:c06fca34
> [<c06b96c8>] (sa1100_init_gpio) from [<c06ae58c>] (sa1100_init_irq+0x2c/0x3c)
>   r7:c06dd028 r6:ffffffff r5:c0713300 r4:c06e1070
> [<c06ae560>] (sa1100_init_irq) from [<c06aab1c>] (init_IRQ+0x20/0x28)
>   r5:c0713300 r4:00000000
> [<c06aaafc>] (init_IRQ) from [<c06a7cd0>] (start_kernel+0x254/0x4cc)
> [<c06a7a7c>] (start_kernel) from [<00000000>] (  (null))
>   r10:0000717f r9:6901b119 r8:c0000100 r7:00000092 r6:0000313d r5:00000053
>   r4:c06a7330
> ---[ end trace 91e1bd00dd7cce32 ]---

Does it means that only the pm_runtime_init is done before
timekeeping_init() but no update_pm_runtime_accounting() ?
In this case, we can keep using ktimeçget in
update_pm_runtime_accounting() and find a solution to deal with
early_call of pm_runtime_init()

Vincent
>
> Guenter
Guenter Roeck Jan. 21, 2019, 3:24 p.m. UTC | #8
On 1/21/19 7:17 AM, Vincent Guittot wrote:
> On Fri, 18 Jan 2019 at 13:08, Guenter Roeck <linux@roeck-us.net> wrote:
>>
>> On 1/18/19 3:05 AM, Rafael J. Wysocki wrote:
>>> On Fri, Jan 18, 2019 at 11:53 AM Vincent Guittot
>>> <vincent.guittot@linaro.org> wrote:
>>>>
>>>> On Fri, 18 Jan 2019 at 11:42, Vincent Guittot
>>>> <vincent.guittot@linaro.org> wrote:
>>>>>
>>>>> Hi Guenter,
>>>>>
>>>>> Le Thursday 17 Jan 2019 à 14:16:28 (-0800), Guenter Roeck a écrit :
>>>>>> On Fri, Dec 21, 2018 at 11:33:56AM +0100, Vincent Guittot wrote:
>>>>>>> From: Thara Gopinath <thara.gopinath@linaro.org>
>>>>>>>
>>>>>>> This patch replaces jiffies based accounting for runtime_active_time
>>>>>>> and runtime_suspended_time with ktime base accounting. This makes the
>>>>>>> runtime debug counters inline with genpd and other pm subsytems which
>>>>>>> uses ktime based accounting.
>>>>>>>
>>>>>>> timekeeping is initialized before pm_runtime_init() so ktime_get() will
>>>>>>> be ready before first call. In fact, timekeeping_init() is called early
>>>>>>> in start_kernel() which is way before driver_init() (and that's when
>>>>>>> devices can start to be initialized) called from rest_init() via
>>>>>>> kernel_init_freeable() and do_basic_setup().
>>>>>>>
>>>>>> This is not (always) correct. My qemu "collie" boot test fails with this
>>>>>> patch applied. Reverting the patch fixes the problem. Bisect log attached.
>>>>>>
>>>>>
>>>>> Can you try the patch below ?
>>>>> ktime_get_mono_fast_ns() has the advantage of being init with dummy clock so
>>>>> it can be used at early_init.
>>>>
>>>> Another possibility would be delay the init of the gpiochip
>>>
>>> Well, right.
>>>
>>> Initializing devices before timekeeping doesn't feel particularly
>>> robust from the design perspective.
>>>
>>> How exactly does that happen?
>>>
>>
>> With an added 'initialized' flag and backtrace into the timekeeping code,
>> with the change suggested earlier applied:
>>
>> ------------[ cut here ]------------
>> WARNING: CPU: 0 PID: 0 at kernel/time/timekeeping.c:453 ktime_get_mono_fast_ns+0x114/0x12c
>> Timekeeping not initialized
>> CPU: 0 PID: 0 Comm: swapper Not tainted 5.0.0-rc2-next-20190117-dirty #2
>> Hardware name: Sharp-Collie
>> Backtrace:
>> [<c000dce8>] (dump_backtrace) from [<c000df78>] (show_stack+0x18/0x1c)
>>    r7:00000009 r6:00000000 r5:c065ba90 r4:c06d3e54
>> [<c000df60>] (show_stack) from [<c0588930>] (dump_stack+0x20/0x28)
>> [<c0588910>] (dump_stack) from [<c0018ae8>] (__warn+0xcc/0xf4)
>> [<c0018a1c>] (__warn) from [<c0018b5c>] (warn_slowpath_fmt+0x4c/0x6c)
>>    r8:df407b08 r7:00000000 r6:c0c01550 r5:c065bad8 r4:c06dd028
>> [<c0018b14>] (warn_slowpath_fmt) from [<c0069e2c>] (ktime_get_mono_fast_ns+0x114/0x12c)
>>    r3:00000000 r2:c065bad8
>>    r5:00000000 r4:df407b08
>> [<c0069d18>] (ktime_get_mono_fast_ns) from [<c03c7810>] (pm_runtime_init+0x38/0xb8)
>>    r9:c06c9a5c r8:df407b08 r7:00000000 r6:c0c01550 r5:00000000 r4:df407b08
>> [<c03c77d8>] (pm_runtime_init) from [<c03b6a34>] (device_initialize+0xb0/0xec)
>>    r7:00000000 r6:c0c01550 r5:00000000 r4:df407b08
>> [<c03b6984>] (device_initialize) from [<c0366d30>] (gpiochip_add_data_with_key+0x9c/0x884)
>>    r7:00000000 r6:c06fca34 r5:00000000 r4:00000000
>> [<c0366c94>] (gpiochip_add_data_with_key) from [<c06b9708>] (sa1100_init_gpio+0x40/0x98)
>>    r10:dfffcd60 r9:c06c9a5c r8:c06dd020 r7:c06dd028 r6:ffffffff r5:00000000
>>    r4:c06fca34
>> [<c06b96c8>] (sa1100_init_gpio) from [<c06ae58c>] (sa1100_init_irq+0x2c/0x3c)
>>    r7:c06dd028 r6:ffffffff r5:c0713300 r4:c06e1070
>> [<c06ae560>] (sa1100_init_irq) from [<c06aab1c>] (init_IRQ+0x20/0x28)
>>    r5:c0713300 r4:00000000
>> [<c06aaafc>] (init_IRQ) from [<c06a7cd0>] (start_kernel+0x254/0x4cc)
>> [<c06a7a7c>] (start_kernel) from [<00000000>] (  (null))
>>    r10:0000717f r9:6901b119 r8:c0000100 r7:00000092 r6:0000313d r5:00000053
>>    r4:c06a7330
>> ---[ end trace 91e1bd00dd7cce32 ]---
> 
> Does it means that only the pm_runtime_init is done before
> timekeeping_init() but no update_pm_runtime_accounting() ?
> In this case, we can keep using ktimeçget in
> update_pm_runtime_accounting() and find a solution to deal with
> early_call of pm_runtime_init()
> 

For this platform that is correct. I can't answer for the generic case.

Guenter
Rafael J. Wysocki Jan. 21, 2019, 10:52 p.m. UTC | #9
On Mon, Jan 21, 2019 at 4:17 PM Vincent Guittot
<vincent.guittot@linaro.org> wrote:
>
> On Fri, 18 Jan 2019 at 13:08, Guenter Roeck <linux@roeck-us.net> wrote:
> >
> > On 1/18/19 3:05 AM, Rafael J. Wysocki wrote:
> > > On Fri, Jan 18, 2019 at 11:53 AM Vincent Guittot
> > > <vincent.guittot@linaro.org> wrote:
> > >>
> > >> On Fri, 18 Jan 2019 at 11:42, Vincent Guittot
> > >> <vincent.guittot@linaro.org> wrote:
> > >>>
> > >>> Hi Guenter,
> > >>>
> > >>> Le Thursday 17 Jan 2019 à 14:16:28 (-0800), Guenter Roeck a écrit :
> > >>>> On Fri, Dec 21, 2018 at 11:33:56AM +0100, Vincent Guittot wrote:
> > >>>>> From: Thara Gopinath <thara.gopinath@linaro.org>
> > >>>>>
> > >>>>> This patch replaces jiffies based accounting for runtime_active_time
> > >>>>> and runtime_suspended_time with ktime base accounting. This makes the
> > >>>>> runtime debug counters inline with genpd and other pm subsytems which
> > >>>>> uses ktime based accounting.
> > >>>>>
> > >>>>> timekeeping is initialized before pm_runtime_init() so ktime_get() will
> > >>>>> be ready before first call. In fact, timekeeping_init() is called early
> > >>>>> in start_kernel() which is way before driver_init() (and that's when
> > >>>>> devices can start to be initialized) called from rest_init() via
> > >>>>> kernel_init_freeable() and do_basic_setup().
> > >>>>>
> > >>>> This is not (always) correct. My qemu "collie" boot test fails with this
> > >>>> patch applied. Reverting the patch fixes the problem. Bisect log attached.
> > >>>>
> > >>>
> > >>> Can you try the patch below ?
> > >>> ktime_get_mono_fast_ns() has the advantage of being init with dummy clock so
> > >>> it can be used at early_init.
> > >>
> > >> Another possibility would be delay the init of the gpiochip
> > >
> > > Well, right.
> > >
> > > Initializing devices before timekeeping doesn't feel particularly
> > > robust from the design perspective.
> > >
> > > How exactly does that happen?
> > >
> >
> > With an added 'initialized' flag and backtrace into the timekeeping code,
> > with the change suggested earlier applied:
> >
> > ------------[ cut here ]------------
> > WARNING: CPU: 0 PID: 0 at kernel/time/timekeeping.c:453 ktime_get_mono_fast_ns+0x114/0x12c
> > Timekeeping not initialized
> > CPU: 0 PID: 0 Comm: swapper Not tainted 5.0.0-rc2-next-20190117-dirty #2
> > Hardware name: Sharp-Collie
> > Backtrace:
> > [<c000dce8>] (dump_backtrace) from [<c000df78>] (show_stack+0x18/0x1c)
> >   r7:00000009 r6:00000000 r5:c065ba90 r4:c06d3e54
> > [<c000df60>] (show_stack) from [<c0588930>] (dump_stack+0x20/0x28)
> > [<c0588910>] (dump_stack) from [<c0018ae8>] (__warn+0xcc/0xf4)
> > [<c0018a1c>] (__warn) from [<c0018b5c>] (warn_slowpath_fmt+0x4c/0x6c)
> >   r8:df407b08 r7:00000000 r6:c0c01550 r5:c065bad8 r4:c06dd028
> > [<c0018b14>] (warn_slowpath_fmt) from [<c0069e2c>] (ktime_get_mono_fast_ns+0x114/0x12c)
> >   r3:00000000 r2:c065bad8
> >   r5:00000000 r4:df407b08
> > [<c0069d18>] (ktime_get_mono_fast_ns) from [<c03c7810>] (pm_runtime_init+0x38/0xb8)
> >   r9:c06c9a5c r8:df407b08 r7:00000000 r6:c0c01550 r5:00000000 r4:df407b08
> > [<c03c77d8>] (pm_runtime_init) from [<c03b6a34>] (device_initialize+0xb0/0xec)
> >   r7:00000000 r6:c0c01550 r5:00000000 r4:df407b08
> > [<c03b6984>] (device_initialize) from [<c0366d30>] (gpiochip_add_data_with_key+0x9c/0x884)
> >   r7:00000000 r6:c06fca34 r5:00000000 r4:00000000
> > [<c0366c94>] (gpiochip_add_data_with_key) from [<c06b9708>] (sa1100_init_gpio+0x40/0x98)
> >   r10:dfffcd60 r9:c06c9a5c r8:c06dd020 r7:c06dd028 r6:ffffffff r5:00000000
> >   r4:c06fca34
> > [<c06b96c8>] (sa1100_init_gpio) from [<c06ae58c>] (sa1100_init_irq+0x2c/0x3c)
> >   r7:c06dd028 r6:ffffffff r5:c0713300 r4:c06e1070
> > [<c06ae560>] (sa1100_init_irq) from [<c06aab1c>] (init_IRQ+0x20/0x28)
> >   r5:c0713300 r4:00000000
> > [<c06aaafc>] (init_IRQ) from [<c06a7cd0>] (start_kernel+0x254/0x4cc)
> > [<c06a7a7c>] (start_kernel) from [<00000000>] (  (null))
> >   r10:0000717f r9:6901b119 r8:c0000100 r7:00000092 r6:0000313d r5:00000053
> >   r4:c06a7330
> > ---[ end trace 91e1bd00dd7cce32 ]---
>
> Does it means that only the pm_runtime_init is done before
> timekeeping_init() but no update_pm_runtime_accounting() ?

This platform calls device_initialize(), via sa1100_init_irq(), from
init_IRQ() which is in the start_kernel() code path before
timekeeping_init().  That's the initialization of structure fields
alone.

Runtime PM really cannot be used legitimately before driver_init(),
because it needs bus types to be there at least.

> In this case, we can keep using ktimeçget in
> update_pm_runtime_accounting() and find a solution to deal with
> early_call of pm_runtime_init()

Given the above, I think that initializing accounting_timestamp in
pm_runtime_init() to anything different from 0 is a mistake.

Note that update_pm_runtime_accounting() ignores the delta value if
power.disable_depth is not zero anyway, so it really should be
sufficient to update accounting_timestamp when enabling runtime PM -
and I'm not sure why it is not updated in pm_runtime_enable() for that
matter (that looks like a bug to me).
Vincent Guittot Jan. 22, 2019, 7:57 a.m. UTC | #10
On Mon, 21 Jan 2019 at 23:53, Rafael J. Wysocki <rafael@kernel.org> wrote:
>
> On Mon, Jan 21, 2019 at 4:17 PM Vincent Guittot
> <vincent.guittot@linaro.org> wrote:
> >
> > On Fri, 18 Jan 2019 at 13:08, Guenter Roeck <linux@roeck-us.net> wrote:
> > >
> > > On 1/18/19 3:05 AM, Rafael J. Wysocki wrote:
> > > > On Fri, Jan 18, 2019 at 11:53 AM Vincent Guittot
> > > > <vincent.guittot@linaro.org> wrote:
> > > >>
> > > >> On Fri, 18 Jan 2019 at 11:42, Vincent Guittot
> > > >> <vincent.guittot@linaro.org> wrote:
> > > >>>
> > > >>> Hi Guenter,
> > > >>>
> > > >>> Le Thursday 17 Jan 2019 à 14:16:28 (-0800), Guenter Roeck a écrit :
> > > >>>> On Fri, Dec 21, 2018 at 11:33:56AM +0100, Vincent Guittot wrote:
> > > >>>>> From: Thara Gopinath <thara.gopinath@linaro.org>
> > > >>>>>
> > > >>>>> This patch replaces jiffies based accounting for runtime_active_time
> > > >>>>> and runtime_suspended_time with ktime base accounting. This makes the
> > > >>>>> runtime debug counters inline with genpd and other pm subsytems which
> > > >>>>> uses ktime based accounting.
> > > >>>>>
> > > >>>>> timekeeping is initialized before pm_runtime_init() so ktime_get() will
> > > >>>>> be ready before first call. In fact, timekeeping_init() is called early
> > > >>>>> in start_kernel() which is way before driver_init() (and that's when
> > > >>>>> devices can start to be initialized) called from rest_init() via
> > > >>>>> kernel_init_freeable() and do_basic_setup().
> > > >>>>>
> > > >>>> This is not (always) correct. My qemu "collie" boot test fails with this
> > > >>>> patch applied. Reverting the patch fixes the problem. Bisect log attached.
> > > >>>>
> > > >>>
> > > >>> Can you try the patch below ?
> > > >>> ktime_get_mono_fast_ns() has the advantage of being init with dummy clock so
> > > >>> it can be used at early_init.
> > > >>
> > > >> Another possibility would be delay the init of the gpiochip
> > > >
> > > > Well, right.
> > > >
> > > > Initializing devices before timekeeping doesn't feel particularly
> > > > robust from the design perspective.
> > > >
> > > > How exactly does that happen?
> > > >
> > >
> > > With an added 'initialized' flag and backtrace into the timekeeping code,
> > > with the change suggested earlier applied:
> > >
> > > ------------[ cut here ]------------
> > > WARNING: CPU: 0 PID: 0 at kernel/time/timekeeping.c:453 ktime_get_mono_fast_ns+0x114/0x12c
> > > Timekeeping not initialized
> > > CPU: 0 PID: 0 Comm: swapper Not tainted 5.0.0-rc2-next-20190117-dirty #2
> > > Hardware name: Sharp-Collie
> > > Backtrace:
> > > [<c000dce8>] (dump_backtrace) from [<c000df78>] (show_stack+0x18/0x1c)
> > >   r7:00000009 r6:00000000 r5:c065ba90 r4:c06d3e54
> > > [<c000df60>] (show_stack) from [<c0588930>] (dump_stack+0x20/0x28)
> > > [<c0588910>] (dump_stack) from [<c0018ae8>] (__warn+0xcc/0xf4)
> > > [<c0018a1c>] (__warn) from [<c0018b5c>] (warn_slowpath_fmt+0x4c/0x6c)
> > >   r8:df407b08 r7:00000000 r6:c0c01550 r5:c065bad8 r4:c06dd028
> > > [<c0018b14>] (warn_slowpath_fmt) from [<c0069e2c>] (ktime_get_mono_fast_ns+0x114/0x12c)
> > >   r3:00000000 r2:c065bad8
> > >   r5:00000000 r4:df407b08
> > > [<c0069d18>] (ktime_get_mono_fast_ns) from [<c03c7810>] (pm_runtime_init+0x38/0xb8)
> > >   r9:c06c9a5c r8:df407b08 r7:00000000 r6:c0c01550 r5:00000000 r4:df407b08
> > > [<c03c77d8>] (pm_runtime_init) from [<c03b6a34>] (device_initialize+0xb0/0xec)
> > >   r7:00000000 r6:c0c01550 r5:00000000 r4:df407b08
> > > [<c03b6984>] (device_initialize) from [<c0366d30>] (gpiochip_add_data_with_key+0x9c/0x884)
> > >   r7:00000000 r6:c06fca34 r5:00000000 r4:00000000
> > > [<c0366c94>] (gpiochip_add_data_with_key) from [<c06b9708>] (sa1100_init_gpio+0x40/0x98)
> > >   r10:dfffcd60 r9:c06c9a5c r8:c06dd020 r7:c06dd028 r6:ffffffff r5:00000000
> > >   r4:c06fca34
> > > [<c06b96c8>] (sa1100_init_gpio) from [<c06ae58c>] (sa1100_init_irq+0x2c/0x3c)
> > >   r7:c06dd028 r6:ffffffff r5:c0713300 r4:c06e1070
> > > [<c06ae560>] (sa1100_init_irq) from [<c06aab1c>] (init_IRQ+0x20/0x28)
> > >   r5:c0713300 r4:00000000
> > > [<c06aaafc>] (init_IRQ) from [<c06a7cd0>] (start_kernel+0x254/0x4cc)
> > > [<c06a7a7c>] (start_kernel) from [<00000000>] (  (null))
> > >   r10:0000717f r9:6901b119 r8:c0000100 r7:00000092 r6:0000313d r5:00000053
> > >   r4:c06a7330
> > > ---[ end trace 91e1bd00dd7cce32 ]---
> >
> > Does it means that only the pm_runtime_init is done before
> > timekeeping_init() but no update_pm_runtime_accounting() ?
>
> This platform calls device_initialize(), via sa1100_init_irq(), from
> init_IRQ() which is in the start_kernel() code path before
> timekeeping_init().  That's the initialization of structure fields
> alone.
>
> Runtime PM really cannot be used legitimately before driver_init(),
> because it needs bus types to be there at least.
>
> > In this case, we can keep using ktimeçget in
> > update_pm_runtime_accounting() and find a solution to deal with
> > early_call of pm_runtime_init()
>
> Given the above, I think that initializing accounting_timestamp in
> pm_runtime_init() to anything different from 0 is a mistake.

I agree

>
> Note that update_pm_runtime_accounting() ignores the delta value if
> power.disable_depth is not zero anyway, so it really should be
> sufficient to update accounting_timestamp when enabling runtime PM -
> and I'm not sure why it is not updated in pm_runtime_enable() for that
> matter (that looks like a bug to me).

That's sounds reasonable to me. I'm going to add a patch to add this
changes before moving to ktime_get
diff mbox series

Patch

diff --git a/drivers/base/power/runtime.c b/drivers/base/power/runtime.c
index e695544..f700524 100644
--- a/drivers/base/power/runtime.c
+++ b/drivers/base/power/runtime.c
@@ -64,8 +64,8 @@  static int rpm_suspend(struct device *dev, int rpmflags);
  */
 void update_pm_runtime_accounting(struct device *dev)
 {
-	unsigned long now = jiffies;
-	unsigned long delta;
+	u64 now = ktime_to_ns(ktime_get());
+	u64 delta;
 
 	delta = now - dev->power.accounting_timestamp;
 
@@ -75,9 +75,9 @@  void update_pm_runtime_accounting(struct device *dev)
 		return;
 
 	if (dev->power.runtime_status == RPM_SUSPENDED)
-		dev->power.suspended_jiffies += delta;
+		dev->power.suspended_time += delta;
 	else
-		dev->power.active_jiffies += delta;
+		dev->power.active_time += delta;
 }
 
 static void __update_runtime_status(struct device *dev, enum rpm_status status)
@@ -88,17 +88,18 @@  static void __update_runtime_status(struct device *dev, enum rpm_status status)
 
 u64 pm_runtime_suspended_time(struct device *dev)
 {
-	unsigned long flags, time;
+	u64 time;
+	unsigned long flags;
 
 	spin_lock_irqsave(&dev->power.lock, flags);
 
 	update_pm_runtime_accounting(dev);
 
-	time = dev->power.suspended_jiffies;
+	time = dev->power.suspended_time;
 
 	spin_unlock_irqrestore(&dev->power.lock, flags);
 
-	return jiffies_to_nsecs(time);
+	return time;
 }
 EXPORT_SYMBOL_GPL(pm_runtime_suspended_time);
 
@@ -1503,7 +1504,7 @@  void pm_runtime_init(struct device *dev)
 	dev->power.request_pending = false;
 	dev->power.request = RPM_REQ_NONE;
 	dev->power.deferred_resume = false;
-	dev->power.accounting_timestamp = jiffies;
+	dev->power.accounting_timestamp = ktime_to_ns(ktime_get());
 	INIT_WORK(&dev->power.work, pm_runtime_work);
 
 	dev->power.timer_expires = 0;
diff --git a/drivers/base/power/sysfs.c b/drivers/base/power/sysfs.c
index d713738..96c8a22 100644
--- a/drivers/base/power/sysfs.c
+++ b/drivers/base/power/sysfs.c
@@ -125,9 +125,12 @@  static ssize_t runtime_active_time_show(struct device *dev,
 				struct device_attribute *attr, char *buf)
 {
 	int ret;
+	u64 tmp;
 	spin_lock_irq(&dev->power.lock);
 	update_pm_runtime_accounting(dev);
-	ret = sprintf(buf, "%i\n", jiffies_to_msecs(dev->power.active_jiffies));
+	tmp = dev->power.active_time;
+	do_div(tmp, NSEC_PER_MSEC);
+	ret = sprintf(buf, "%llu\n", tmp);
 	spin_unlock_irq(&dev->power.lock);
 	return ret;
 }
@@ -138,10 +141,12 @@  static ssize_t runtime_suspended_time_show(struct device *dev,
 				struct device_attribute *attr, char *buf)
 {
 	int ret;
+	u64 tmp;
 	spin_lock_irq(&dev->power.lock);
 	update_pm_runtime_accounting(dev);
-	ret = sprintf(buf, "%i\n",
-		jiffies_to_msecs(dev->power.suspended_jiffies));
+	tmp = dev->power.suspended_time;
+	do_div(tmp, NSEC_PER_MSEC);
+	ret = sprintf(buf, "%llu\n", tmp);
 	spin_unlock_irq(&dev->power.lock);
 	return ret;
 }
diff --git a/include/linux/pm.h b/include/linux/pm.h
index e723b78..e5a34e2 100644
--- a/include/linux/pm.h
+++ b/include/linux/pm.h
@@ -632,9 +632,9 @@  struct dev_pm_info {
 	int			runtime_error;
 	int			autosuspend_delay;
 	unsigned long		last_busy;
-	unsigned long		active_jiffies;
-	unsigned long		suspended_jiffies;
-	unsigned long		accounting_timestamp;
+	u64			active_time;
+	u64			suspended_time;
+	u64			accounting_timestamp;
 #endif
 	struct pm_subsys_data	*subsys_data;  /* Owned by the subsystem. */
 	void (*set_latency_tolerance)(struct device *, s32);