| Message ID | 1545388436-7489-4-git-send-email-vincent.guittot@linaro.org (mailing list archive) |
|---|---|
| State | Mainlined |
| Delegated to: | Rafael Wysocki |
| Headers | show |
| Series | Move pm_runtime accounted time to raw nsec | expand |
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 >
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
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;
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
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!
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?
On 1/18/19 2:42 AM, Vincent Guittot 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. > Yes, that works. Guenter > --- > 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; >
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 ]--- Guenter
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
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
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).
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 --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);