[PATCH] PM / suspend: measure the time of filesystem syncing

[PATCH] PM / suspend: measure the time of filesystem syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing a filesystem sync during suspend; although developer
can guess by the timestamp of next log or enable the ftrace power event
for manual calculation, this manner is easier to read and benefits the
automatic script.

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 kernel/power/suspend.c | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..f3b7c64f2242 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -550,6 +550,8 @@ static void suspend_finish(void)
 static int enter_state(suspend_state_t state)
 {
 	int error;
+	ktime_t start, end, elapsed;
+	unsigned int elapsed_msecs;
 
 	trace_suspend_resume(TPS("suspend_enter"), state, true);
 	if (state == PM_SUSPEND_TO_IDLE) {
@@ -570,9 +572,14 @@ static int enter_state(suspend_state_t state)
 
 #ifndef CONFIG_SUSPEND_SKIP_SYNC
 	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+	start = ktime_get_boottime();
 	pr_info("Syncing filesystems ... ");
 	ksys_sync();
-	pr_cont("done.\n");
+	end = ktime_get_boottime();
+	elapsed = ktime_sub(end, start);
+	elapsed_msecs = ktime_to_ms(elapsed);
+	pr_cont("(elapsed %d.%03d seconds) done.\n", elapsed_msecs / 1000,
+		elapsed_msecs % 1000);
 	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
 #endif
 
-- 
2.18.1

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Rafael J. Wysocki]

On Sunday, February 3, 2019 6:20:07 AM CET Harry Pan wrote:
> This patch gives the reader an intuitive metric of the time cost by
> the kernel issuing a filesystem sync during suspend; although developer
> can guess by the timestamp of next log or enable the ftrace power event
> for manual calculation, this manner is easier to read and benefits the
> automatic script.
> 
> Signed-off-by: Harry Pan <harry.pan@intel.com>
> ---
>  kernel/power/suspend.c | 9 ++++++++-
>  1 file changed, 8 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
> index 0bd595a0b610..f3b7c64f2242 100644
> --- a/kernel/power/suspend.c
> +++ b/kernel/power/suspend.c
> @@ -550,6 +550,8 @@ static void suspend_finish(void)
>  static int enter_state(suspend_state_t state)
>  {
>  	int error;
> +	ktime_t start, end, elapsed;

Why do you need three vars here?  One should be sufficient.

> +	unsigned int elapsed_msecs;
>  
>  	trace_suspend_resume(TPS("suspend_enter"), state, true);
>  	if (state == PM_SUSPEND_TO_IDLE) {
> @@ -570,9 +572,14 @@ static int enter_state(suspend_state_t state)
>  
>  #ifndef CONFIG_SUSPEND_SKIP_SYNC
>  	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
> +	start = ktime_get_boottime();

Why _boottime()?

>  	pr_info("Syncing filesystems ... ");
>  	ksys_sync();
> -	pr_cont("done.\n");
> +	end = ktime_get_boottime();
> +	elapsed = ktime_sub(end, start);
> +	elapsed_msecs = ktime_to_ms(elapsed);
> +	pr_cont("(elapsed %d.%03d seconds) done.\n", elapsed_msecs / 1000,
> +		elapsed_msecs % 1000);
>  	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
>  #endif
>  
> 

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Pan, Harry]

On Tue, 2019-02-05 at 12:55 +0100, Rafael J. Wysocki wrote:
> 
> > +	ktime_t start, end, elapsed;
> 
> Why do you need three vars here?  One should be sufficient.
...
> > +	start = ktime_get_boottime();
> 
> Why _boottime()?
> 
Yes, I agree both comments.

BTW, The initial idea came from processes freezing, apology my sketchy
imitation not considering the context well to choose a proper API.

-Harry

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Pavel Machek]

[-- Attachment #1: Type: text/plain, Size: 1900 bytes --]

On Sun 2019-02-03 13:20:07, Harry Pan wrote:
> This patch gives the reader an intuitive metric of the time cost by
> the kernel issuing a filesystem sync during suspend; although developer
> can guess by the timestamp of next log or enable the ftrace power event
> for manual calculation, this manner is easier to read and benefits the
> automatic script.

Do we really need this functionality?

As you explained, developers can already use next timestamp or
ftrace... and this is really not that interesting number.

								Pavel

> Signed-off-by: Harry Pan <harry.pan@intel.com>
> ---
>  kernel/power/suspend.c | 9 ++++++++-
>  1 file changed, 8 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
> index 0bd595a0b610..f3b7c64f2242 100644
> --- a/kernel/power/suspend.c
> +++ b/kernel/power/suspend.c
> @@ -550,6 +550,8 @@ static void suspend_finish(void)
>  static int enter_state(suspend_state_t state)
>  {
>  	int error;
> +	ktime_t start, end, elapsed;
> +	unsigned int elapsed_msecs;
>  
>  	trace_suspend_resume(TPS("suspend_enter"), state, true);
>  	if (state == PM_SUSPEND_TO_IDLE) {
> @@ -570,9 +572,14 @@ static int enter_state(suspend_state_t state)
>  
>  #ifndef CONFIG_SUSPEND_SKIP_SYNC
>  	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
> +	start = ktime_get_boottime();
>  	pr_info("Syncing filesystems ... ");
>  	ksys_sync();
> -	pr_cont("done.\n");
> +	end = ktime_get_boottime();
> +	elapsed = ktime_sub(end, start);
> +	elapsed_msecs = ktime_to_ms(elapsed);
> +	pr_cont("(elapsed %d.%03d seconds) done.\n", elapsed_msecs / 1000,
> +		elapsed_msecs % 1000);
>  	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
>  #endif
>  

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Pan, Harry]

On Tue, 2019-02-05 at 22:23 +0100, Pavel Machek wrote:
> On Sun 2019-02-03 13:20:07, Harry Pan wrote:
> > This patch gives the reader an intuitive metric of the time cost by
> > the kernel issuing a filesystem sync during suspend; although
> > developer
> > can guess by the timestamp of next log or enable the ftrace power
> > event
> > for manual calculation, this manner is easier to read and benefits
> > the
> > automatic script.
> 
> Do we really need this functionality?
> 
> As you explained, developers can already use next timestamp or
> ftrace... and this is really not that interesting number.

The backdrop is some stress test script of suspend/resume, like Chrome
OS, is designed to program an expected RTC wake-alarm then issue
suspend command, while in rare case (or buggy software), the filesystem
sync could cost longer time in seconds, this consumes the alarm budget
causes suspend aborting, it could be abstruse to production line
developers to realize it is not a platform issue in terms of drivers
suspending; given a such metric might make the communication easier,
this is my intuition.

-Harry

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Pan, Harry]

> The backdrop is some stress test script of suspend/resume, like
> Chrome
> OS, is designed to program an expected RTC wake-alarm then issue
> suspend command, while in rare case (or buggy software), the
> filesystem
> sync could cost longer time in seconds, this consumes the alarm
> budget
> causes suspend aborting, it could be abstruse to production line
> developers to realize it is not a platform issue in terms of drivers
> suspending; given a such metric might make the communication easier,
> this is my intuition.
> 
apologize rephrase: my intuition -> my motivation

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Pavel Machek]

[-- Attachment #1: Type: text/plain, Size: 1637 bytes --]

On Wed 2019-02-06 15:08:18, Pan, Harry wrote:
> On Tue, 2019-02-05 at 22:23 +0100, Pavel Machek wrote:
> > On Sun 2019-02-03 13:20:07, Harry Pan wrote:
> > > This patch gives the reader an intuitive metric of the time cost by
> > > the kernel issuing a filesystem sync during suspend; although
> > > developer
> > > can guess by the timestamp of next log or enable the ftrace power
> > > event
> > > for manual calculation, this manner is easier to read and benefits
> > > the
> > > automatic script.
> > 
> > Do we really need this functionality?
> > 
> > As you explained, developers can already use next timestamp or
> > ftrace... and this is really not that interesting number.
> 
> The backdrop is some stress test script of suspend/resume, like Chrome
> OS, is designed to program an expected RTC wake-alarm then issue
> suspend command, while in rare case (or buggy software), the filesystem
> sync could cost longer time in seconds, this consumes the alarm budget
> causes suspend aborting, it could be abstruse to production line
> developers to realize it is not a platform issue in terms of drivers
> suspending; given a such metric might make the communication easier,
> this is my intuition.

I'd rather educate other developers that this may happen. dmesg
timestamps should already make it easy to see.

And actually... if you do "time sync" in userspace just before
programing the RTC and suspending, this whole issue should go away.

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Pan, Harry]

> 
> I'd rather educate other developers that this may happen. dmesg
> timestamps should already make it easy to see.
> 
> And actually... if you do "time sync" in userspace just before
> programing the RTC and suspending, this whole issue should go away.
> 
> 
I agree w/ you on both comments basically.

Thad said, when it comes to dmesg, readers would guess by current
implementation of the program, the two lines of pr_info and pm_pr_dbg
are controlled by compilation flags as well as printk run-level, I
think the information is enough while it is not guaranteed for this
subject.

Another reason is, months ago I worked on my community to illustrate
this odd, adding 'sync' policy in the userspace script [1] mitigated
the longer sync (issued by kernel) in suspending, however I realized
there is still rare case because the userspace sync is before the
processes freeze, the script is potentially competing w/ other high
loading tasks which means there is still a small window (sync ->
program alarm -> suspend until freeze) that could generate such odd.

Short recap this topic is trying to give a clear indication as simple
mechanism for the platform and OS developers who may concern the
suspending time w/ some sort of time constrain; given a clear metric it
allows developers to have an easier triage such hard-to-reproduce issue
shall go to virtual memory/filesystem rather than examine whether there
is longer cost on each PM sub-state along w/ the device callbacks
through a long suspending log.

Lastly, I understand this data might not so interesting to kernel
developers; somehow my role is sitting in between trying to bridge
kernel and OS developers, I fully respect reviewers' comments and
justification.


Sincerely,
Harry 

[1] 
https://chromium-review.googlesource.com/c/chromiumos/platform2/+/458560/14/power_manager/tools/suspend_stress_test#202
(Apologize long URL and context as reference)

[PATCH] PM / suspend: measure the time of filesystem syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing a filesystem sync during suspend; although developer
can guess by the timestamp of next log or enable the ftrace power event
for manual calculation, this manner is easier to read and benefits the
automatic script.

v2: simplify the variables, apply the simplest form of ktime API.

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 kernel/power/suspend.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..87c0073f0c9d 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -550,6 +550,8 @@ static void suspend_finish(void)
 static int enter_state(suspend_state_t state)
 {
 	int error;
+	ktime_t start;
+	unsigned int elapsed_msecs;
 
 	trace_suspend_resume(TPS("suspend_enter"), state, true);
 	if (state == PM_SUSPEND_TO_IDLE) {
@@ -570,9 +572,12 @@ static int enter_state(suspend_state_t state)
 
 #ifndef CONFIG_SUSPEND_SKIP_SYNC
 	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+	start = ktime_get();
 	pr_info("Syncing filesystems ... ");
 	ksys_sync();
-	pr_cont("done.\n");
+	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+	pr_cont("(elapsed %d.%03d seconds) done.\n", elapsed_msecs / 1000,
+		elapsed_msecs % 1000);
 	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
 #endif
 
-- 
2.18.1

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Pavel Machek]

[-- Attachment #1: Type: text/plain, Size: 1751 bytes --]

On Wed 2019-02-06 22:42:57, Harry Pan wrote:
> This patch gives the reader an intuitive metric of the time cost by
> the kernel issuing a filesystem sync during suspend; although developer
> can guess by the timestamp of next log or enable the ftrace power event
> for manual calculation, this manner is easier to read and benefits the
> automatic script.
> 
> v2: simplify the variables, apply the simplest form of ktime API.
> 
> Signed-off-by: Harry Pan <harry.pan@intel.com>

NAK.
								Pavel
								
> ---
>  kernel/power/suspend.c | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
> index 0bd595a0b610..87c0073f0c9d 100644
> --- a/kernel/power/suspend.c
> +++ b/kernel/power/suspend.c
> @@ -550,6 +550,8 @@ static void suspend_finish(void)
>  static int enter_state(suspend_state_t state)
>  {
>  	int error;
> +	ktime_t start;
> +	unsigned int elapsed_msecs;
>  
>  	trace_suspend_resume(TPS("suspend_enter"), state, true);
>  	if (state == PM_SUSPEND_TO_IDLE) {
> @@ -570,9 +572,12 @@ static int enter_state(suspend_state_t state)
>  
>  #ifndef CONFIG_SUSPEND_SKIP_SYNC
>  	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
> +	start = ktime_get();
>  	pr_info("Syncing filesystems ... ");
>  	ksys_sync();
> -	pr_cont("done.\n");
> +	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
> +	pr_cont("(elapsed %d.%03d seconds) done.\n", elapsed_msecs / 1000,
> +		elapsed_msecs % 1000);
>  	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
>  #endif
>  

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Rafael J. Wysocki]

On Wed, Feb 6, 2019 at 4:57 PM Harry Pan <harry.pan@intel.com> wrote:
>
> This patch gives the reader an intuitive metric of the time cost by
> the kernel issuing a filesystem sync during suspend; although developer
> can guess by the timestamp of next log or enable the ftrace power event
> for manual calculation, this manner is easier to read and benefits the
> automatic script.
>
> v2: simplify the variables, apply the simplest form of ktime API.
>
> Signed-off-by: Harry Pan <harry.pan@intel.com>
> ---
>  kernel/power/suspend.c | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
> index 0bd595a0b610..87c0073f0c9d 100644
> --- a/kernel/power/suspend.c
> +++ b/kernel/power/suspend.c
> @@ -550,6 +550,8 @@ static void suspend_finish(void)
>  static int enter_state(suspend_state_t state)
>  {
>         int error;
> +       ktime_t start;
> +       unsigned int elapsed_msecs;

You only need these two if CONFIG_SUSPEND_SKIP_SYNC is set, ->

>
>         trace_suspend_resume(TPS("suspend_enter"), state, true);
>         if (state == PM_SUSPEND_TO_IDLE) {
> @@ -570,9 +572,12 @@ static int enter_state(suspend_state_t state)
>
>  #ifndef CONFIG_SUSPEND_SKIP_SYNC

-> so I would change this to

if (IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
     ktime_t start;
     unsigned int elapsed_msecs;

>         trace_suspend_resume(TPS("sync_filesystems"), 0, true);
> +       start = ktime_get();

Why don't you do this after printing the message below?

>         pr_info("Syncing filesystems ... ");
>         ksys_sync();
> -       pr_cont("done.\n");
> +       elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
> +       pr_cont("(elapsed %d.%03d seconds) done.\n", elapsed_msecs / 1000,
> +               elapsed_msecs % 1000);

Use MSEC_PER_SEC here.

>         trace_suspend_resume(TPS("sync_filesystems"), 0, false);
>  #endif
>

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Rafael J. Wysocki]

On Wed, Feb 13, 2019 at 12:21 AM Rafael J. Wysocki <rafael@kernel.org> wrote:
>
> On Wed, Feb 6, 2019 at 4:57 PM Harry Pan <harry.pan@intel.com> wrote:
> >
> > This patch gives the reader an intuitive metric of the time cost by
> > the kernel issuing a filesystem sync during suspend; although developer
> > can guess by the timestamp of next log or enable the ftrace power event
> > for manual calculation, this manner is easier to read and benefits the
> > automatic script.
> >
> > v2: simplify the variables, apply the simplest form of ktime API.
> >
> > Signed-off-by: Harry Pan <harry.pan@intel.com>
> > ---
> >  kernel/power/suspend.c | 7 ++++++-
> >  1 file changed, 6 insertions(+), 1 deletion(-)
> >
> > diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
> > index 0bd595a0b610..87c0073f0c9d 100644
> > --- a/kernel/power/suspend.c
> > +++ b/kernel/power/suspend.c
> > @@ -550,6 +550,8 @@ static void suspend_finish(void)
> >  static int enter_state(suspend_state_t state)
> >  {
> >         int error;
> > +       ktime_t start;
> > +       unsigned int elapsed_msecs;
>
> You only need these two if CONFIG_SUSPEND_SKIP_SYNC is set, ->
>
> >
> >         trace_suspend_resume(TPS("suspend_enter"), state, true);
> >         if (state == PM_SUSPEND_TO_IDLE) {
> > @@ -570,9 +572,12 @@ static int enter_state(suspend_state_t state)
> >
> >  #ifndef CONFIG_SUSPEND_SKIP_SYNC
>
> -> so I would change this to
>
> if (IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {

if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {

that is (missing "!").

>      ktime_t start;
>      unsigned int elapsed_msecs;
>
> >         trace_suspend_resume(TPS("sync_filesystems"), 0, true);
> > +       start = ktime_get();
>
> Why don't you do this after printing the message below?
>
> >         pr_info("Syncing filesystems ... ");
> >         ksys_sync();
> > -       pr_cont("done.\n");
> > +       elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
> > +       pr_cont("(elapsed %d.%03d seconds) done.\n", elapsed_msecs / 1000,
> > +               elapsed_msecs % 1000);
>
> Use MSEC_PER_SEC here.
>
> >         trace_suspend_resume(TPS("sync_filesystems"), 0, false);
> >  #endif
> >

Re: [PATCH] PM / suspend: measure the time of filesystem syncing

[Rafael J. Wysocki]

On Wed, Feb 13, 2019 at 12:21 AM Rafael J. Wysocki <rafael@kernel.org> wrote:
>
> On Wed, Feb 6, 2019 at 4:57 PM Harry Pan <harry.pan@intel.com> wrote:
> >
> > This patch gives the reader an intuitive metric of the time cost by
> > the kernel issuing a filesystem sync during suspend; although developer
> > can guess by the timestamp of next log or enable the ftrace power event
> > for manual calculation, this manner is easier to read and benefits the
> > automatic script.
> >
> > v2: simplify the variables, apply the simplest form of ktime API.
> >
> > Signed-off-by: Harry Pan <harry.pan@intel.com>
> > ---
> >  kernel/power/suspend.c | 7 ++++++-
> >  1 file changed, 6 insertions(+), 1 deletion(-)
> >
> > diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
> > index 0bd595a0b610..87c0073f0c9d 100644
> > --- a/kernel/power/suspend.c
> > +++ b/kernel/power/suspend.c
> > @@ -550,6 +550,8 @@ static void suspend_finish(void)
> >  static int enter_state(suspend_state_t state)
> >  {
> >         int error;
> > +       ktime_t start;
> > +       unsigned int elapsed_msecs;
>
> You only need these two if CONFIG_SUSPEND_SKIP_SYNC is set, ->

s/set/unset/

Sorry for the confusion.

[PATCH v2] PM / suspend: measure the time of filesystem syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing a filesystem sync during suspend; although developer
can guess by the timestamp of next log or enable the ftrace power event
for manual calculation, this manner is easier to read and benefits the
automatic script.

v2: simplify the variables, apply the simplest form of ktime API.

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 kernel/power/suspend.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..87c0073f0c9d 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -550,6 +550,8 @@ static void suspend_finish(void)
 static int enter_state(suspend_state_t state)
 {
 	int error;
+	ktime_t start;
+	unsigned int elapsed_msecs;
 
 	trace_suspend_resume(TPS("suspend_enter"), state, true);
 	if (state == PM_SUSPEND_TO_IDLE) {
@@ -570,9 +572,12 @@ static int enter_state(suspend_state_t state)
 
 #ifndef CONFIG_SUSPEND_SKIP_SYNC
 	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+	start = ktime_get();
 	pr_info("Syncing filesystems ... ");
 	ksys_sync();
-	pr_cont("done.\n");
+	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+	pr_cont("(elapsed %d.%03d seconds) done.\n", elapsed_msecs / 1000,
+		elapsed_msecs % 1000);
 	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
 #endif
 
-- 
2.18.1

[PATCH v3] PM / suspend: measure the time of filesystem syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing a filesystem sync during suspend; although developer
can guess by the timestamp of next log or enable the ftrace power event
for manual calculation, this manner is easier to read and benefits the
automatic script.

v2: simplify the variables, apply the simplest form of ktime API.
v3: reduce conditional compilation, rectify profiling in better syntax

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 kernel/power/suspend.c | 21 ++++++++++++++-------
 1 file changed, 14 insertions(+), 7 deletions(-)

diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..4844fc6a796d 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -568,13 +568,20 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_TO_IDLE)
 		s2idle_begin();
 
-#ifndef CONFIG_SUSPEND_SKIP_SYNC
-	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	pr_info("Syncing filesystems ... ");
-	ksys_sync();
-	pr_cont("done.\n");
-	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
-#endif
+	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
+		ktime_t start;
+		unsigned int elapsed_msecs;
+
+		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+		pr_info("Syncing filesystems ... ");
+		start = ktime_get();
+		ksys_sync();
+		elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+		pr_cont("(elapsed %d.%03d seconds) done.\n",
+			elapsed_msecs / MSEC_PER_SEC,
+			elapsed_msecs % MSEC_PER_SEC);
+		trace_suspend_resume(TPS("sync_filesystems"), 0, false);
+	}
 
 	pm_pr_dbg("Preparing system for sleep (%s)\n", mem_sleep_labels[state]);
 	pm_suspend_clear_flags();
-- 
2.18.1

[PATCH v3] PM / suspend: measure the time of filesystem syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing a filesystem sync during suspend; although developer
can guess by the timestamp of next log or enable the ftrace power event
for manual calculation, this manner is easier to read and benefits the
automatic script.

v2: simplify the variables, apply the simplest form of ktime API.
v3: reduce conditional compilation, rectify profiling in better syntax

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 kernel/power/suspend.c | 21 ++++++++++++++-------
 1 file changed, 14 insertions(+), 7 deletions(-)

diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..4844fc6a796d 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -568,13 +568,20 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_TO_IDLE)
 		s2idle_begin();
 
-#ifndef CONFIG_SUSPEND_SKIP_SYNC
-	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	pr_info("Syncing filesystems ... ");
-	ksys_sync();
-	pr_cont("done.\n");
-	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
-#endif
+	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
+		ktime_t start;
+		unsigned int elapsed_msecs;
+
+		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+		pr_info("Syncing filesystems ... ");
+		start = ktime_get();
+		ksys_sync();
+		elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+		pr_cont("(elapsed %d.%03d seconds) done.\n",
+			elapsed_msecs / MSEC_PER_SEC,
+			elapsed_msecs % MSEC_PER_SEC);
+		trace_suspend_resume(TPS("sync_filesystems"), 0, false);
+	}
 
 	pm_pr_dbg("Preparing system for sleep (%s)\n", mem_sleep_labels[state]);
 	pm_suspend_clear_flags();
-- 
2.18.1

Re: [PATCH v3] PM / suspend: measure the time of filesystem syncing

[Rafael J. Wysocki]

On Thursday, February 14, 2019 12:15:43 PM CET Harry Pan wrote:
> This patch gives the reader an intuitive metric of the time cost by
> the kernel issuing a filesystem sync during suspend; although developer
> can guess by the timestamp of next log or enable the ftrace power event
> for manual calculation, this manner is easier to read and benefits the
> automatic script.
> 
> v2: simplify the variables, apply the simplest form of ktime API.
> v3: reduce conditional compilation, rectify profiling in better syntax
> 
> Signed-off-by: Harry Pan <harry.pan@intel.com>
> ---
>  kernel/power/suspend.c | 21 ++++++++++++++-------
>  1 file changed, 14 insertions(+), 7 deletions(-)
> 
> diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
> index 0bd595a0b610..4844fc6a796d 100644
> --- a/kernel/power/suspend.c
> +++ b/kernel/power/suspend.c
> @@ -568,13 +568,20 @@ static int enter_state(suspend_state_t state)
>  	if (state == PM_SUSPEND_TO_IDLE)
>  		s2idle_begin();
>  
> -#ifndef CONFIG_SUSPEND_SKIP_SYNC
> -	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
> -	pr_info("Syncing filesystems ... ");
> -	ksys_sync();
> -	pr_cont("done.\n");
> -	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
> -#endif
> +	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
> +		ktime_t start;
> +		unsigned int elapsed_msecs;
> +
> +		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
> +		pr_info("Syncing filesystems ... ");
> +		start = ktime_get();
> +		ksys_sync();
> +		elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
> +		pr_cont("(elapsed %d.%03d seconds) done.\n",
> +			elapsed_msecs / MSEC_PER_SEC,
> +			elapsed_msecs % MSEC_PER_SEC);

One more nit.

Since you are printing the sync time anyway, there is a little sense to
split the message using pr_cont() that may be messed up with by any
intervening messages, so why don't you just print a one-line
pr_info("Filesystems sync: %d.%03d seconds\n", ...) message?

Also, if you change it here, I guess it would be consistent to make an
analogous change for hibernation.

> +		trace_suspend_resume(TPS("sync_filesystems"), 0, false);
> +	}
>  
>  	pm_pr_dbg("Preparing system for sleep (%s)\n", mem_sleep_labels[state]);
>  	pm_suspend_clear_flags();
> 

Re: [PATCH v3] PM / suspend: measure the time of filesystem syncing

[Pan, Harry]

Thanks for comments.

> > +	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
> > +		ktime_t start;
> > +		unsigned int elapsed_msecs;
> > +
> > +		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
> > +		pr_info("Syncing filesystems ... ");
> > +		start = ktime_get();
> > +		ksys_sync();
> > +		elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(),
> > start));
> > +		pr_cont("(elapsed %d.%03d seconds) done.\n",
> > +			elapsed_msecs / MSEC_PER_SEC,
> > +			elapsed_msecs % MSEC_PER_SEC);
> 
> One more nit.
> 
> Since you are printing the sync time anyway, there is a little sense
> to
> split the message using pr_cont() that may be messed up with by any
> intervening messages, so why don't you just print a one-line
> pr_info("Filesystems sync: %d.%03d seconds\n", ...) message?
> 
Yes, I agree.
In practical, I did see intervening messages (between pr_info and
pr_cont) when it came to long sync in kernel.
I was hesitated in this considering not fully understanding the
backdrop of split messages using pr_info() then pr_cont().

> Also, if you change it here, I guess it would be consistent to make
> an analogous change for hibernation.

One potential last-mile need your wisdom, which is about the switch
case of SNAPSHOT_FREEZE of the userspace interface you wrote.
I am yet to touch it, nor understand how to validate it.

That said, I am digesting your documents and source; I used the pm_test
from the doc to validate the patch on hibernation partially even non of
my handy laptons fully work well on it.


Sincerely,
Harry

Re: [PATCH v3] PM / suspend: measure the time of filesystem syncing

[Rafael J. Wysocki]

On Wed, Feb 20, 2019 at 5:44 PM Pan, Harry <harry.pan@intel.com> wrote:
>
> Thanks for comments.
>
> > > +   if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
> > > +           ktime_t start;
> > > +           unsigned int elapsed_msecs;
> > > +
> > > +           trace_suspend_resume(TPS("sync_filesystems"), 0, true);
> > > +           pr_info("Syncing filesystems ... ");
> > > +           start = ktime_get();
> > > +           ksys_sync();
> > > +           elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(),
> > > start));
> > > +           pr_cont("(elapsed %d.%03d seconds) done.\n",
> > > +                   elapsed_msecs / MSEC_PER_SEC,
> > > +                   elapsed_msecs % MSEC_PER_SEC);
> >
> > One more nit.
> >
> > Since you are printing the sync time anyway, there is a little sense
> > to
> > split the message using pr_cont() that may be messed up with by any
> > intervening messages, so why don't you just print a one-line
> > pr_info("Filesystems sync: %d.%03d seconds\n", ...) message?
> >
> Yes, I agree.
> In practical, I did see intervening messages (between pr_info and
> pr_cont) when it came to long sync in kernel.
> I was hesitated in this considering not fully understanding the
> backdrop of split messages using pr_info() then pr_cont().
>
> > Also, if you change it here, I guess it would be consistent to make
> > an analogous change for hibernation.
>
> One potential last-mile need your wisdom, which is about the switch
> case of SNAPSHOT_FREEZE of the userspace interface you wrote.
> I am yet to touch it, nor understand how to validate it.

Why don't you add a "sync" helper function in main.c with the timing
and message that will be called from hibernate.c, user.c and suspend.c
(in the last one conditional on
!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC))?

That would reduce some code duplication nicely.

Re: [PATCH v3] PM / suspend: measure the time of filesystem syncing

[Pan, Harry]

> Why don't you add a "sync" helper function in main.c with the timing
> and message that will be called from hibernate.c, user.c and
> suspend.c
> (in the last one conditional on
> !IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC))?
> 
> That would reduce some code duplication nicely.

I uploaded v5 in reciprocate to your comment, I apologize I sent it
second time in order to clean up the header files.

-Harry

[PATCH v4] PM / suspend: measure the time of filesystem syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing a filesystem sync during suspend; although developer
can guess by the timestamp of next log or enable the ftrace power event
for manual calculation, this manner is easier to read and benefits the
automatic script.

v2: simplify the variables, apply the simplest form of ktime API.
v3: reduce conditional compilation, rectify profiling in better syntax
v4: avoid interposition, profile on hibernation, rectify printk format

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 kernel/power/hibernate.c |  9 +++++++--
 kernel/power/suspend.c   | 20 +++++++++++++-------
 2 files changed, 20 insertions(+), 9 deletions(-)

diff --git a/kernel/power/hibernate.c b/kernel/power/hibernate.c
index abef759de7c8..387703907827 100644
--- a/kernel/power/hibernate.c
+++ b/kernel/power/hibernate.c
@@ -688,6 +688,8 @@ int hibernate(void)
 {
 	int error, nr_calls = 0;
 	bool snapshot_test = false;
+	ktime_t start;
+	s64 elapsed_msecs;
 
 	if (!hibernation_available()) {
 		pm_pr_dbg("Hibernation not available.\n");
@@ -709,9 +711,12 @@ int hibernate(void)
 		goto Exit;
 	}
 
-	pr_info("Syncing filesystems ... \n");
+	start = ktime_get();
 	ksys_sync();
-	pr_info("done.\n");
+	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+	pr_info("Filesystems sync: %lld.%03lld seconds\n",
+		elapsed_msecs / MSEC_PER_SEC,
+		elapsed_msecs % MSEC_PER_SEC);
 
 	error = freeze_processes();
 	if (error)
diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..7fb5ba1314d3 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -568,13 +568,19 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_TO_IDLE)
 		s2idle_begin();
 
-#ifndef CONFIG_SUSPEND_SKIP_SYNC
-	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	pr_info("Syncing filesystems ... ");
-	ksys_sync();
-	pr_cont("done.\n");
-	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
-#endif
+	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
+		ktime_t start;
+		s64 elapsed_msecs;
+
+		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+		start = ktime_get();
+		ksys_sync();
+		elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+		pr_info("Filesystems sync: %lld.%03lld seconds\n",
+			elapsed_msecs / MSEC_PER_SEC,
+			elapsed_msecs % MSEC_PER_SEC);
+		trace_suspend_resume(TPS("sync_filesystems"), 0, false);
+	}
 
 	pm_pr_dbg("Preparing system for sleep (%s)\n", mem_sleep_labels[state]);
 	pm_suspend_clear_flags();
-- 
2.18.1

[PATCH v4] PM / suspend: measure the time of filesystem syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing a filesystem sync during suspend; although developer
can guess by the timestamp of next log or enable the ftrace power event
for manual calculation, this manner is easier to read and benefits the
automatic script.

v2: simplify the variables, apply the simplest form of ktime API.
v3: reduce conditional compilation, rectify profiling in better syntax
v4: avoid interposition, profile on hibernation, rectify printk format

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 kernel/power/hibernate.c |  9 +++++++--
 kernel/power/suspend.c   | 20 +++++++++++++-------
 2 files changed, 20 insertions(+), 9 deletions(-)

diff --git a/kernel/power/hibernate.c b/kernel/power/hibernate.c
index abef759de7c8..387703907827 100644
--- a/kernel/power/hibernate.c
+++ b/kernel/power/hibernate.c
@@ -688,6 +688,8 @@ int hibernate(void)
 {
 	int error, nr_calls = 0;
 	bool snapshot_test = false;
+	ktime_t start;
+	s64 elapsed_msecs;
 
 	if (!hibernation_available()) {
 		pm_pr_dbg("Hibernation not available.\n");
@@ -709,9 +711,12 @@ int hibernate(void)
 		goto Exit;
 	}
 
-	pr_info("Syncing filesystems ... \n");
+	start = ktime_get();
 	ksys_sync();
-	pr_info("done.\n");
+	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+	pr_info("Filesystems sync: %lld.%03lld seconds\n",
+		elapsed_msecs / MSEC_PER_SEC,
+		elapsed_msecs % MSEC_PER_SEC);
 
 	error = freeze_processes();
 	if (error)
diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..7fb5ba1314d3 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -568,13 +568,19 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_TO_IDLE)
 		s2idle_begin();
 
-#ifndef CONFIG_SUSPEND_SKIP_SYNC
-	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	pr_info("Syncing filesystems ... ");
-	ksys_sync();
-	pr_cont("done.\n");
-	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
-#endif
+	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
+		ktime_t start;
+		s64 elapsed_msecs;
+
+		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+		start = ktime_get();
+		ksys_sync();
+		elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+		pr_info("Filesystems sync: %lld.%03lld seconds\n",
+			elapsed_msecs / MSEC_PER_SEC,
+			elapsed_msecs % MSEC_PER_SEC);
+		trace_suspend_resume(TPS("sync_filesystems"), 0, false);
+	}
 
 	pm_pr_dbg("Preparing system for sleep (%s)\n", mem_sleep_labels[state]);
 	pm_suspend_clear_flags();
-- 
2.18.1

[PATCH v5] PM / sleep: measure the time of filesystem syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing a filesystem sync during system sleep; although
developer can guess by the timestamp of next log or enable the ftrace
power event for manual calculation, this manner is easier to read and
benefits the automatic script.

v2: simplify the variables, apply the simplest form of ktime API.
v3: reduce conditional compilation, rectify profiling in better syntax
v4: avoid interposition, profile on hibernation, rectify printk format
v5: introduce sync helper shared by suspend, hibernate, and snapshot

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 include/linux/suspend.h  |  3 +++
 kernel/power/hibernate.c |  4 +---
 kernel/power/main.c      | 15 +++++++++++++++
 kernel/power/suspend.c   | 13 +++++--------
 kernel/power/user.c      |  4 +---
 5 files changed, 25 insertions(+), 14 deletions(-)

diff --git a/include/linux/suspend.h b/include/linux/suspend.h
index 3f529ad9a9d2..6b3ea9ea6a9e 100644
--- a/include/linux/suspend.h
+++ b/include/linux/suspend.h
@@ -425,6 +425,7 @@ void restore_processor_state(void);
 /* kernel/power/main.c */
 extern int register_pm_notifier(struct notifier_block *nb);
 extern int unregister_pm_notifier(struct notifier_block *nb);
+extern void ksys_sync_helper(void);
 
 #define pm_notifier(fn, pri) {				\
 	static struct notifier_block fn##_nb =			\
@@ -462,6 +463,8 @@ static inline int unregister_pm_notifier(struct notifier_block *nb)
 	return 0;
 }
 
+static inline void ksys_sync_helper(void) {}
+
 #define pm_notifier(fn, pri)	do { (void)(fn); } while (0)
 
 static inline bool pm_wakeup_pending(void) { return false; }
diff --git a/kernel/power/hibernate.c b/kernel/power/hibernate.c
index abef759de7c8..895f43a5f10c 100644
--- a/kernel/power/hibernate.c
+++ b/kernel/power/hibernate.c
@@ -709,9 +709,7 @@ int hibernate(void)
 		goto Exit;
 	}
 
-	pr_info("Syncing filesystems ... \n");
-	ksys_sync();
-	pr_info("done.\n");
+	ksys_sync_helper();
 
 	error = freeze_processes();
 	if (error)
diff --git a/kernel/power/main.c b/kernel/power/main.c
index 35b50823d83b..a08dcc743f31 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -16,6 +16,7 @@
 #include <linux/debugfs.h>
 #include <linux/seq_file.h>
 #include <linux/suspend.h>
+#include <linux/syscalls.h>
 
 #include "power.h"
 
@@ -51,6 +52,20 @@ void unlock_system_sleep(void)
 }
 EXPORT_SYMBOL_GPL(unlock_system_sleep);
 
+void ksys_sync_helper(void)
+{
+	ktime_t start;
+	s64 elapsed_msecs;
+
+	start = ktime_get();
+	ksys_sync();
+	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+	pr_info("Filesystems sync: %lld.%03lld seconds\n",
+		elapsed_msecs / MSEC_PER_SEC,
+		elapsed_msecs % MSEC_PER_SEC);
+}
+EXPORT_SYMBOL_GPL(ksys_sync_helper);
+
 /* Routines for PM-transition notifications */
 
 static BLOCKING_NOTIFIER_HEAD(pm_chain_head);
diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..e39059dea38b 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -17,7 +17,6 @@
 #include <linux/console.h>
 #include <linux/cpu.h>
 #include <linux/cpuidle.h>
-#include <linux/syscalls.h>
 #include <linux/gfp.h>
 #include <linux/io.h>
 #include <linux/kernel.h>
@@ -568,13 +567,11 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_TO_IDLE)
 		s2idle_begin();
 
-#ifndef CONFIG_SUSPEND_SKIP_SYNC
-	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	pr_info("Syncing filesystems ... ");
-	ksys_sync();
-	pr_cont("done.\n");
-	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
-#endif
+	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
+		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+		ksys_sync_helper();
+		trace_suspend_resume(TPS("sync_filesystems"), 0, false);
+	}
 
 	pm_pr_dbg("Preparing system for sleep (%s)\n", mem_sleep_labels[state]);
 	pm_suspend_clear_flags();
diff --git a/kernel/power/user.c b/kernel/power/user.c
index 2d8b60a3c86b..68dbd9eac8e1 100644
--- a/kernel/power/user.c
+++ b/kernel/power/user.c
@@ -228,9 +228,7 @@ static long snapshot_ioctl(struct file *filp, unsigned int cmd,
 		if (data->frozen)
 			break;
 
-		printk("Syncing filesystems ... ");
-		ksys_sync();
-		printk("done.\n");
+		ksys_sync_helper();
 
 		error = freeze_processes();
 		if (error)
-- 
2.18.1

Re: [PATCH v5] PM / sleep: measure the time of filesystem syncing

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 1211 bytes --]

Hi Harry,

Thank you for the patch! Yet something to improve:

[auto build test ERROR on linus/master]
[also build test ERROR on v5.0-rc4 next-20190222]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]

url:    https://github.com/0day-ci/linux/commits/Harry-Pan/PM-sleep-measure-the-time-of-filesystem-syncing/20190225-023616
config: nds32-defconfig (attached as .config)
compiler: nds32le-linux-gcc (GCC) 6.4.0
reproduce:
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # save the attached .config to linux build tree
        GCC_VERSION=6.4.0 make.cross ARCH=nds32 

All errors (new ones prefixed by >>):

   kernel/power/main.o: In function `ksys_sync_helper':
>> main.c:(.text+0x150): undefined reference to `__moddi3'
   main.c:(.text+0x154): undefined reference to `__moddi3'
>> main.c:(.text+0x168): undefined reference to `__divdi3'
   main.c:(.text+0x16c): undefined reference to `__divdi3'

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 9712 bytes --]

Re: [PATCH v5] PM / sleep: measure the time of filesystem syncing

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 1179 bytes --]

Hi Harry,

Thank you for the patch! Yet something to improve:

[auto build test ERROR on linus/master]
[also build test ERROR on v5.0-rc4 next-20190222]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]

url:    https://github.com/0day-ci/linux/commits/Harry-Pan/PM-sleep-measure-the-time-of-filesystem-syncing/20190225-023616
config: mips-allmodconfig (attached as .config)
compiler: mips-linux-gnu-gcc (Debian 8.2.0-11) 8.2.0
reproduce:
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # save the attached .config to linux build tree
        GCC_VERSION=8.2.0 make.cross ARCH=mips 

All errors (new ones prefixed by >>):

   mips-linux-gnu-ld: kernel/power/main.o: in function `ksys_sync_helper':
>> main.c:(.text.ksys_sync_helper+0x130): undefined reference to `__divdi3'
>> mips-linux-gnu-ld: main.c:(.text.ksys_sync_helper+0x14c): undefined reference to `__moddi3'

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 58579 bytes --]

[PATCH v5] PM / sleep: measure the time of filesystem syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing a filesystem sync during system sleep; although
developer can guess by the timestamp of next log or enable the ftrace
power event for manual calculation, this manner is easier to read and
benefits the automatic script.

v2: simplify the variables, apply the simplest form of ktime API.
v3: reduce conditional compilation, rectify profiling in better syntax
v4: avoid interposition, profile on hibernation, rectify printk format
v5: introduce sync helper shared by suspend, hibernate, and snapshot

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 include/linux/suspend.h  |  3 +++
 kernel/power/hibernate.c |  5 +----
 kernel/power/main.c      | 15 +++++++++++++++
 kernel/power/suspend.c   | 13 +++++--------
 kernel/power/user.c      |  5 +----
 5 files changed, 25 insertions(+), 16 deletions(-)

diff --git a/include/linux/suspend.h b/include/linux/suspend.h
index 3f529ad9a9d2..6b3ea9ea6a9e 100644
--- a/include/linux/suspend.h
+++ b/include/linux/suspend.h
@@ -425,6 +425,7 @@ void restore_processor_state(void);
 /* kernel/power/main.c */
 extern int register_pm_notifier(struct notifier_block *nb);
 extern int unregister_pm_notifier(struct notifier_block *nb);
+extern void ksys_sync_helper(void);
 
 #define pm_notifier(fn, pri) {				\
 	static struct notifier_block fn##_nb =			\
@@ -462,6 +463,8 @@ static inline int unregister_pm_notifier(struct notifier_block *nb)
 	return 0;
 }
 
+static inline void ksys_sync_helper(void) {}
+
 #define pm_notifier(fn, pri)	do { (void)(fn); } while (0)
 
 static inline bool pm_wakeup_pending(void) { return false; }
diff --git a/kernel/power/hibernate.c b/kernel/power/hibernate.c
index abef759de7c8..cc105ecd9c07 100644
--- a/kernel/power/hibernate.c
+++ b/kernel/power/hibernate.c
@@ -14,7 +14,6 @@
 
 #include <linux/export.h>
 #include <linux/suspend.h>
-#include <linux/syscalls.h>
 #include <linux/reboot.h>
 #include <linux/string.h>
 #include <linux/device.h>
@@ -709,9 +708,7 @@ int hibernate(void)
 		goto Exit;
 	}
 
-	pr_info("Syncing filesystems ... \n");
-	ksys_sync();
-	pr_info("done.\n");
+	ksys_sync_helper();
 
 	error = freeze_processes();
 	if (error)
diff --git a/kernel/power/main.c b/kernel/power/main.c
index 35b50823d83b..a08dcc743f31 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -16,6 +16,7 @@
 #include <linux/debugfs.h>
 #include <linux/seq_file.h>
 #include <linux/suspend.h>
+#include <linux/syscalls.h>
 
 #include "power.h"
 
@@ -51,6 +52,20 @@ void unlock_system_sleep(void)
 }
 EXPORT_SYMBOL_GPL(unlock_system_sleep);
 
+void ksys_sync_helper(void)
+{
+	ktime_t start;
+	s64 elapsed_msecs;
+
+	start = ktime_get();
+	ksys_sync();
+	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+	pr_info("Filesystems sync: %lld.%03lld seconds\n",
+		elapsed_msecs / MSEC_PER_SEC,
+		elapsed_msecs % MSEC_PER_SEC);
+}
+EXPORT_SYMBOL_GPL(ksys_sync_helper);
+
 /* Routines for PM-transition notifications */
 
 static BLOCKING_NOTIFIER_HEAD(pm_chain_head);
diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..e39059dea38b 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -17,7 +17,6 @@
 #include <linux/console.h>
 #include <linux/cpu.h>
 #include <linux/cpuidle.h>
-#include <linux/syscalls.h>
 #include <linux/gfp.h>
 #include <linux/io.h>
 #include <linux/kernel.h>
@@ -568,13 +567,11 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_TO_IDLE)
 		s2idle_begin();
 
-#ifndef CONFIG_SUSPEND_SKIP_SYNC
-	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	pr_info("Syncing filesystems ... ");
-	ksys_sync();
-	pr_cont("done.\n");
-	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
-#endif
+	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
+		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+		ksys_sync_helper();
+		trace_suspend_resume(TPS("sync_filesystems"), 0, false);
+	}
 
 	pm_pr_dbg("Preparing system for sleep (%s)\n", mem_sleep_labels[state]);
 	pm_suspend_clear_flags();
diff --git a/kernel/power/user.c b/kernel/power/user.c
index 2d8b60a3c86b..cb24e840a3e6 100644
--- a/kernel/power/user.c
+++ b/kernel/power/user.c
@@ -10,7 +10,6 @@
  */
 
 #include <linux/suspend.h>
-#include <linux/syscalls.h>
 #include <linux/reboot.h>
 #include <linux/string.h>
 #include <linux/device.h>
@@ -228,9 +227,7 @@ static long snapshot_ioctl(struct file *filp, unsigned int cmd,
 		if (data->frozen)
 			break;
 
-		printk("Syncing filesystems ... ");
-		ksys_sync();
-		printk("done.\n");
+		ksys_sync_helper();
 
 		error = freeze_processes();
 		if (error)
-- 
2.18.1

Re: [PATCH v5] PM / sleep: measure the time of filesystem syncing

[Pavel Machek]

[-- Attachment #1: Type: text/plain, Size: 3570 bytes --]

On Fri 2019-02-22 23:49:04, Harry Pan wrote:
> This patch gives the reader an intuitive metric of the time cost by
> the kernel issuing a filesystem sync during system sleep; although
> developer can guess by the timestamp of next log or enable the ftrace
> power event for manual calculation, this manner is easier to read and
> benefits the automatic script.
> 
> v2: simplify the variables, apply the simplest form of ktime API.
> v3: reduce conditional compilation, rectify profiling in better syntax
> v4: avoid interposition, profile on hibernation, rectify printk format
> v5: introduce sync helper shared by suspend, hibernate, and snapshot
> 
> Signed-off-by: Harry Pan <harry.pan@intel.com>
> ---
>  include/linux/suspend.h  |  3 +++
>  kernel/power/hibernate.c |  5 +----
>  kernel/power/main.c      | 15 +++++++++++++++
>  kernel/power/suspend.c   | 13 +++++--------
>  kernel/power/user.c      |  5 +----
>  5 files changed, 25 insertions(+), 16 deletions(-)
> 
> diff --git a/include/linux/suspend.h b/include/linux/suspend.h
> index 3f529ad9a9d2..6b3ea9ea6a9e 100644
> --- a/include/linux/suspend.h
> +++ b/include/linux/suspend.h
> @@ -425,6 +425,7 @@ void restore_processor_state(void);
>  /* kernel/power/main.c */
>  extern int register_pm_notifier(struct notifier_block *nb);
>  extern int unregister_pm_notifier(struct notifier_block *nb);
> +extern void ksys_sync_helper(void);
>  
>  #define pm_notifier(fn, pri) {				\
>  	static struct notifier_block fn##_nb =			\
> @@ -462,6 +463,8 @@ static inline int unregister_pm_notifier(struct notifier_block *nb)
>  	return 0;
>  }
>  
> +static inline void ksys_sync_helper(void) {}
> +
>  #define pm_notifier(fn, pri)	do { (void)(fn); } while (0)
>  
>  static inline bool pm_wakeup_pending(void) { return false; }
> diff --git a/kernel/power/hibernate.c b/kernel/power/hibernate.c
> index abef759de7c8..cc105ecd9c07 100644
> --- a/kernel/power/hibernate.c
> +++ b/kernel/power/hibernate.c
> @@ -14,7 +14,6 @@
>  
>  #include <linux/export.h>
>  #include <linux/suspend.h>
> -#include <linux/syscalls.h>
>  #include <linux/reboot.h>
>  #include <linux/string.h>
>  #include <linux/device.h>
> @@ -709,9 +708,7 @@ int hibernate(void)
>  		goto Exit;
>  	}
>  
> -	pr_info("Syncing filesystems ... \n");
> -	ksys_sync();
> -	pr_info("done.\n");
> +	ksys_sync_helper();
>  
>  	error = freeze_processes();
>  	if (error)
> diff --git a/kernel/power/main.c b/kernel/power/main.c
> index 35b50823d83b..a08dcc743f31 100644
> --- a/kernel/power/main.c
> +++ b/kernel/power/main.c
> @@ -16,6 +16,7 @@
>  #include <linux/debugfs.h>
>  #include <linux/seq_file.h>
>  #include <linux/suspend.h>
> +#include <linux/syscalls.h>
>  
>  #include "power.h"
>  
> @@ -51,6 +52,20 @@ void unlock_system_sleep(void)
>  }
>  EXPORT_SYMBOL_GPL(unlock_system_sleep);
>  
> +void ksys_sync_helper(void)
> +{
> +	ktime_t start;
> +	s64 elapsed_msecs;
> +
> +	start = ktime_get();
> +	ksys_sync();
> +	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
> +	pr_info("Filesystems sync: %lld.%03lld seconds\n",
> +		elapsed_msecs / MSEC_PER_SEC,
> +		elapsed_msecs % MSEC_PER_SEC);
> +}

Sharing code is fine. Changing message, remove partial print before
long operation is not.

Adding timing is not, either. There are other ways to get that info.

NAK.
									Pavel
								
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

[PATCH v6 1/2] PM / sleep: refactor the filesystems sync to reduce duplication

[Harry Pan]

This patch creates a common helper to sync filesystems and shares
to the suspend, hibernate, and snapshot.

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 include/linux/suspend.h  |  3 +++
 kernel/power/hibernate.c |  5 +----
 kernel/power/main.c      |  9 +++++++++
 kernel/power/suspend.c   | 13 +++++--------
 kernel/power/user.c      |  5 +----
 5 files changed, 19 insertions(+), 16 deletions(-)

diff --git a/include/linux/suspend.h b/include/linux/suspend.h
index 3f529ad9a9d2..6b3ea9ea6a9e 100644
--- a/include/linux/suspend.h
+++ b/include/linux/suspend.h
@@ -425,6 +425,7 @@ void restore_processor_state(void);
 /* kernel/power/main.c */
 extern int register_pm_notifier(struct notifier_block *nb);
 extern int unregister_pm_notifier(struct notifier_block *nb);
+extern void ksys_sync_helper(void);
 
 #define pm_notifier(fn, pri) {				\
 	static struct notifier_block fn##_nb =			\
@@ -462,6 +463,8 @@ static inline int unregister_pm_notifier(struct notifier_block *nb)
 	return 0;
 }
 
+static inline void ksys_sync_helper(void) {}
+
 #define pm_notifier(fn, pri)	do { (void)(fn); } while (0)
 
 static inline bool pm_wakeup_pending(void) { return false; }
diff --git a/kernel/power/hibernate.c b/kernel/power/hibernate.c
index abef759de7c8..cc105ecd9c07 100644
--- a/kernel/power/hibernate.c
+++ b/kernel/power/hibernate.c
@@ -14,7 +14,6 @@
 
 #include <linux/export.h>
 #include <linux/suspend.h>
-#include <linux/syscalls.h>
 #include <linux/reboot.h>
 #include <linux/string.h>
 #include <linux/device.h>
@@ -709,9 +708,7 @@ int hibernate(void)
 		goto Exit;
 	}
 
-	pr_info("Syncing filesystems ... \n");
-	ksys_sync();
-	pr_info("done.\n");
+	ksys_sync_helper();
 
 	error = freeze_processes();
 	if (error)
diff --git a/kernel/power/main.c b/kernel/power/main.c
index 35b50823d83b..a8a8e6ec57e6 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -16,6 +16,7 @@
 #include <linux/debugfs.h>
 #include <linux/seq_file.h>
 #include <linux/suspend.h>
+#include <linux/syscalls.h>
 
 #include "power.h"
 
@@ -51,6 +52,14 @@ void unlock_system_sleep(void)
 }
 EXPORT_SYMBOL_GPL(unlock_system_sleep);
 
+void ksys_sync_helper(void)
+{
+	pr_info("Syncing filesystems ... ");
+	ksys_sync();
+	pr_cont("done.\n");
+}
+EXPORT_SYMBOL_GPL(ksys_sync_helper);
+
 /* Routines for PM-transition notifications */
 
 static BLOCKING_NOTIFIER_HEAD(pm_chain_head);
diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..e39059dea38b 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -17,7 +17,6 @@
 #include <linux/console.h>
 #include <linux/cpu.h>
 #include <linux/cpuidle.h>
-#include <linux/syscalls.h>
 #include <linux/gfp.h>
 #include <linux/io.h>
 #include <linux/kernel.h>
@@ -568,13 +567,11 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_TO_IDLE)
 		s2idle_begin();
 
-#ifndef CONFIG_SUSPEND_SKIP_SYNC
-	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	pr_info("Syncing filesystems ... ");
-	ksys_sync();
-	pr_cont("done.\n");
-	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
-#endif
+	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
+		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+		ksys_sync_helper();
+		trace_suspend_resume(TPS("sync_filesystems"), 0, false);
+	}
 
 	pm_pr_dbg("Preparing system for sleep (%s)\n", mem_sleep_labels[state]);
 	pm_suspend_clear_flags();
diff --git a/kernel/power/user.c b/kernel/power/user.c
index 2d8b60a3c86b..cb24e840a3e6 100644
--- a/kernel/power/user.c
+++ b/kernel/power/user.c
@@ -10,7 +10,6 @@
  */
 
 #include <linux/suspend.h>
-#include <linux/syscalls.h>
 #include <linux/reboot.h>
 #include <linux/string.h>
 #include <linux/device.h>
@@ -228,9 +227,7 @@ static long snapshot_ioctl(struct file *filp, unsigned int cmd,
 		if (data->frozen)
 			break;
 
-		printk("Syncing filesystems ... ");
-		ksys_sync();
-		printk("done.\n");
+		ksys_sync_helper();
 
 		error = freeze_processes();
 		if (error)
-- 
2.18.1

[PATCH v6 2/2] PM / sleep: measure the time of filesystems syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing filesystems sync during system sleep; although
developer can guess by the timestamp of next log or enable the ftrace
power event for manual calculation, this manner is easier to read and
benefits the automation script.

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 kernel/power/main.c | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/kernel/power/main.c b/kernel/power/main.c
index a8a8e6ec57e6..a08dcc743f31 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -54,9 +54,15 @@ EXPORT_SYMBOL_GPL(unlock_system_sleep);
 
 void ksys_sync_helper(void)
 {
-	pr_info("Syncing filesystems ... ");
+	ktime_t start;
+	s64 elapsed_msecs;
+
+	start = ktime_get();
 	ksys_sync();
-	pr_cont("done.\n");
+	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+	pr_info("Filesystems sync: %lld.%03lld seconds\n",
+		elapsed_msecs / MSEC_PER_SEC,
+		elapsed_msecs % MSEC_PER_SEC);
 }
 EXPORT_SYMBOL_GPL(ksys_sync_helper);
 
-- 
2.18.1

Re: [PATCH v6 2/2] PM / sleep: measure the time of filesystems syncing

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 971 bytes --]

Hi Harry,

Thank you for the patch! Yet something to improve:

[auto build test ERROR on linus/master]
[also build test ERROR on v5.0-rc4 next-20190222]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]

url:    https://github.com/0day-ci/linux/commits/Harry-Pan/PM-sleep-refactor-the-filesystems-sync-to-reduce-duplication/20190225-025843
config: i386-defconfig (attached as .config)
compiler: gcc-8 (Debian 8.2.0-20) 8.2.0
reproduce:
        # save the attached .config to linux build tree
        make ARCH=i386 

All errors (new ones prefixed by >>):

   ld: kernel/power/main.o: in function `ksys_sync_helper.cold.2':
>> main.c:(.text.unlikely+0x23): undefined reference to `__moddi3'
>> ld: main.c:(.text.unlikely+0x37): undefined reference to `__divdi3'

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 26942 bytes --]

Re: [PATCH v6 2/2] PM / sleep: measure the time of filesystems syncing

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 1179 bytes --]

Hi Harry,

Thank you for the patch! Yet something to improve:

[auto build test ERROR on linus/master]
[also build test ERROR on v5.0-rc4 next-20190222]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]

url:    https://github.com/0day-ci/linux/commits/Harry-Pan/PM-sleep-refactor-the-filesystems-sync-to-reduce-duplication/20190225-025843
config: arm-allmodconfig (attached as .config)
compiler: arm-linux-gnueabi-gcc (Debian 8.2.0-11) 8.2.0
reproduce:
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # save the attached .config to linux build tree
        GCC_VERSION=8.2.0 make.cross ARCH=arm 

All errors (new ones prefixed by >>):

   arm-linux-gnueabi-ld: kernel/power/main.o: in function `ksys_sync_helper':
>> main.c:(.text+0x150): undefined reference to `__aeabi_ldivmod'
>> arm-linux-gnueabi-ld: main.c:(.text+0x16c): undefined reference to `__aeabi_ldivmod'

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 68401 bytes --]

[PATCH v7 1/2] PM / sleep: refactor the filesystems sync to reduce duplication

[Harry Pan]

This patch creates a common helper to sync filesystems and shares
to the suspend, hibernate, and snapshot.

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 include/linux/suspend.h  |  3 +++
 kernel/power/hibernate.c |  5 +----
 kernel/power/main.c      |  9 +++++++++
 kernel/power/suspend.c   | 13 +++++--------
 kernel/power/user.c      |  5 +----
 5 files changed, 19 insertions(+), 16 deletions(-)

diff --git a/include/linux/suspend.h b/include/linux/suspend.h
index 3f529ad9a9d2..6b3ea9ea6a9e 100644
--- a/include/linux/suspend.h
+++ b/include/linux/suspend.h
@@ -425,6 +425,7 @@ void restore_processor_state(void);
 /* kernel/power/main.c */
 extern int register_pm_notifier(struct notifier_block *nb);
 extern int unregister_pm_notifier(struct notifier_block *nb);
+extern void ksys_sync_helper(void);
 
 #define pm_notifier(fn, pri) {				\
 	static struct notifier_block fn##_nb =			\
@@ -462,6 +463,8 @@ static inline int unregister_pm_notifier(struct notifier_block *nb)
 	return 0;
 }
 
+static inline void ksys_sync_helper(void) {}
+
 #define pm_notifier(fn, pri)	do { (void)(fn); } while (0)
 
 static inline bool pm_wakeup_pending(void) { return false; }
diff --git a/kernel/power/hibernate.c b/kernel/power/hibernate.c
index abef759de7c8..cc105ecd9c07 100644
--- a/kernel/power/hibernate.c
+++ b/kernel/power/hibernate.c
@@ -14,7 +14,6 @@
 
 #include <linux/export.h>
 #include <linux/suspend.h>
-#include <linux/syscalls.h>
 #include <linux/reboot.h>
 #include <linux/string.h>
 #include <linux/device.h>
@@ -709,9 +708,7 @@ int hibernate(void)
 		goto Exit;
 	}
 
-	pr_info("Syncing filesystems ... \n");
-	ksys_sync();
-	pr_info("done.\n");
+	ksys_sync_helper();
 
 	error = freeze_processes();
 	if (error)
diff --git a/kernel/power/main.c b/kernel/power/main.c
index 35b50823d83b..a8a8e6ec57e6 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -16,6 +16,7 @@
 #include <linux/debugfs.h>
 #include <linux/seq_file.h>
 #include <linux/suspend.h>
+#include <linux/syscalls.h>
 
 #include "power.h"
 
@@ -51,6 +52,14 @@ void unlock_system_sleep(void)
 }
 EXPORT_SYMBOL_GPL(unlock_system_sleep);
 
+void ksys_sync_helper(void)
+{
+	pr_info("Syncing filesystems ... ");
+	ksys_sync();
+	pr_cont("done.\n");
+}
+EXPORT_SYMBOL_GPL(ksys_sync_helper);
+
 /* Routines for PM-transition notifications */
 
 static BLOCKING_NOTIFIER_HEAD(pm_chain_head);
diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..e39059dea38b 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -17,7 +17,6 @@
 #include <linux/console.h>
 #include <linux/cpu.h>
 #include <linux/cpuidle.h>
-#include <linux/syscalls.h>
 #include <linux/gfp.h>
 #include <linux/io.h>
 #include <linux/kernel.h>
@@ -568,13 +567,11 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_TO_IDLE)
 		s2idle_begin();
 
-#ifndef CONFIG_SUSPEND_SKIP_SYNC
-	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	pr_info("Syncing filesystems ... ");
-	ksys_sync();
-	pr_cont("done.\n");
-	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
-#endif
+	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
+		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+		ksys_sync_helper();
+		trace_suspend_resume(TPS("sync_filesystems"), 0, false);
+	}
 
 	pm_pr_dbg("Preparing system for sleep (%s)\n", mem_sleep_labels[state]);
 	pm_suspend_clear_flags();
diff --git a/kernel/power/user.c b/kernel/power/user.c
index 2d8b60a3c86b..cb24e840a3e6 100644
--- a/kernel/power/user.c
+++ b/kernel/power/user.c
@@ -10,7 +10,6 @@
  */
 
 #include <linux/suspend.h>
-#include <linux/syscalls.h>
 #include <linux/reboot.h>
 #include <linux/string.h>
 #include <linux/device.h>
@@ -228,9 +227,7 @@ static long snapshot_ioctl(struct file *filp, unsigned int cmd,
 		if (data->frozen)
 			break;
 
-		printk("Syncing filesystems ... ");
-		ksys_sync();
-		printk("done.\n");
+		ksys_sync_helper();
 
 		error = freeze_processes();
 		if (error)
-- 
2.18.1

[PATCH v7 2/2] PM / sleep: measure the time of filesystems syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing filesystems sync during system sleep; although
developer can guess by the timestamp of next log or enable the ftrace
power event for manual calculation, this manner is easier to read and
benefits the automation script.

v1 to v5: context discussion
v6: split patches logically in code refactor and sync profile
v7: improve 32/64 bit machine compatibility

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 kernel/power/main.c | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/kernel/power/main.c b/kernel/power/main.c
index a8a8e6ec57e6..eea3d65eb960 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -54,9 +54,15 @@ EXPORT_SYMBOL_GPL(unlock_system_sleep);
 
 void ksys_sync_helper(void)
 {
-	pr_info("Syncing filesystems ... ");
+	ktime_t start;
+	long elapsed_msecs;
+
+	start = ktime_get();
 	ksys_sync();
-	pr_cont("done.\n");
+	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+	pr_info("Filesystems sync: %ld.%03ld seconds\n",
+		elapsed_msecs / MSEC_PER_SEC,
+		elapsed_msecs % MSEC_PER_SEC);
 }
 EXPORT_SYMBOL_GPL(ksys_sync_helper);
 
-- 
2.18.1

[PATCH v7 1/2] PM / sleep: refactor the filesystems sync to reduce duplication

[Harry Pan]

This patch creates a common helper to sync filesystems and shares
to the suspend, hibernate, and snapshot.

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 include/linux/suspend.h  |  3 +++
 kernel/power/hibernate.c |  5 +----
 kernel/power/main.c      |  9 +++++++++
 kernel/power/suspend.c   | 13 +++++--------
 kernel/power/user.c      |  5 +----
 5 files changed, 19 insertions(+), 16 deletions(-)

diff --git a/include/linux/suspend.h b/include/linux/suspend.h
index 3f529ad9a9d2..6b3ea9ea6a9e 100644
--- a/include/linux/suspend.h
+++ b/include/linux/suspend.h
@@ -425,6 +425,7 @@ void restore_processor_state(void);
 /* kernel/power/main.c */
 extern int register_pm_notifier(struct notifier_block *nb);
 extern int unregister_pm_notifier(struct notifier_block *nb);
+extern void ksys_sync_helper(void);
 
 #define pm_notifier(fn, pri) {				\
 	static struct notifier_block fn##_nb =			\
@@ -462,6 +463,8 @@ static inline int unregister_pm_notifier(struct notifier_block *nb)
 	return 0;
 }
 
+static inline void ksys_sync_helper(void) {}
+
 #define pm_notifier(fn, pri)	do { (void)(fn); } while (0)
 
 static inline bool pm_wakeup_pending(void) { return false; }
diff --git a/kernel/power/hibernate.c b/kernel/power/hibernate.c
index abef759de7c8..cc105ecd9c07 100644
--- a/kernel/power/hibernate.c
+++ b/kernel/power/hibernate.c
@@ -14,7 +14,6 @@
 
 #include <linux/export.h>
 #include <linux/suspend.h>
-#include <linux/syscalls.h>
 #include <linux/reboot.h>
 #include <linux/string.h>
 #include <linux/device.h>
@@ -709,9 +708,7 @@ int hibernate(void)
 		goto Exit;
 	}
 
-	pr_info("Syncing filesystems ... \n");
-	ksys_sync();
-	pr_info("done.\n");
+	ksys_sync_helper();
 
 	error = freeze_processes();
 	if (error)
diff --git a/kernel/power/main.c b/kernel/power/main.c
index 35b50823d83b..a8a8e6ec57e6 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -16,6 +16,7 @@
 #include <linux/debugfs.h>
 #include <linux/seq_file.h>
 #include <linux/suspend.h>
+#include <linux/syscalls.h>
 
 #include "power.h"
 
@@ -51,6 +52,14 @@ void unlock_system_sleep(void)
 }
 EXPORT_SYMBOL_GPL(unlock_system_sleep);
 
+void ksys_sync_helper(void)
+{
+	pr_info("Syncing filesystems ... ");
+	ksys_sync();
+	pr_cont("done.\n");
+}
+EXPORT_SYMBOL_GPL(ksys_sync_helper);
+
 /* Routines for PM-transition notifications */
 
 static BLOCKING_NOTIFIER_HEAD(pm_chain_head);
diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 0bd595a0b610..e39059dea38b 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -17,7 +17,6 @@
 #include <linux/console.h>
 #include <linux/cpu.h>
 #include <linux/cpuidle.h>
-#include <linux/syscalls.h>
 #include <linux/gfp.h>
 #include <linux/io.h>
 #include <linux/kernel.h>
@@ -568,13 +567,11 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_TO_IDLE)
 		s2idle_begin();
 
-#ifndef CONFIG_SUSPEND_SKIP_SYNC
-	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	pr_info("Syncing filesystems ... ");
-	ksys_sync();
-	pr_cont("done.\n");
-	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
-#endif
+	if (!IS_ENABLED(CONFIG_SUSPEND_SKIP_SYNC)) {
+		trace_suspend_resume(TPS("sync_filesystems"), 0, true);
+		ksys_sync_helper();
+		trace_suspend_resume(TPS("sync_filesystems"), 0, false);
+	}
 
 	pm_pr_dbg("Preparing system for sleep (%s)\n", mem_sleep_labels[state]);
 	pm_suspend_clear_flags();
diff --git a/kernel/power/user.c b/kernel/power/user.c
index 2d8b60a3c86b..cb24e840a3e6 100644
--- a/kernel/power/user.c
+++ b/kernel/power/user.c
@@ -10,7 +10,6 @@
  */
 
 #include <linux/suspend.h>
-#include <linux/syscalls.h>
 #include <linux/reboot.h>
 #include <linux/string.h>
 #include <linux/device.h>
@@ -228,9 +227,7 @@ static long snapshot_ioctl(struct file *filp, unsigned int cmd,
 		if (data->frozen)
 			break;
 
-		printk("Syncing filesystems ... ");
-		ksys_sync();
-		printk("done.\n");
+		ksys_sync_helper();
 
 		error = freeze_processes();
 		if (error)
-- 
2.18.1

[PATCH v7 2/2] PM / sleep: measure the time of filesystems syncing

[Harry Pan]

This patch gives the reader an intuitive metric of the time cost by
the kernel issuing filesystems sync during system sleep; although
developer can guess by the timestamp of next log or enable the ftrace
power event for manual calculation, this manner is easier to read and
benefits the automation script.

v1 to v5: context discussion
v6: split patches logically in code refactor and sync profile
v7: improve 32/64 bit machine compatibility

Signed-off-by: Harry Pan <harry.pan@intel.com>
---
 kernel/power/main.c | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/kernel/power/main.c b/kernel/power/main.c
index a8a8e6ec57e6..eea3d65eb960 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -54,9 +54,15 @@ EXPORT_SYMBOL_GPL(unlock_system_sleep);
 
 void ksys_sync_helper(void)
 {
-	pr_info("Syncing filesystems ... ");
+	ktime_t start;
+	long elapsed_msecs;
+
+	start = ktime_get();
 	ksys_sync();
-	pr_cont("done.\n");
+	elapsed_msecs = ktime_to_ms(ktime_sub(ktime_get(), start));
+	pr_info("Filesystems sync: %ld.%03ld seconds\n",
+		elapsed_msecs / MSEC_PER_SEC,
+		elapsed_msecs % MSEC_PER_SEC);
 }
 EXPORT_SYMBOL_GPL(ksys_sync_helper);
 
-- 
2.18.1

Re: [PATCH v7 1/2] PM / sleep: refactor the filesystems sync to reduce duplication

[Pavel Machek]

[-- Attachment #1: Type: text/plain, Size: 362 bytes --]

On Mon 2019-02-25 20:36:41, Harry Pan wrote:
> This patch creates a common helper to sync filesystems and shares
> to the suspend, hibernate, and snapshot.
> 
> Signed-off-by: Harry Pan <harry.pan@intel.com>

ACK.

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

Re: [PATCH v5] PM / sleep: measure the time of filesystem syncing

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 1308 bytes --]

Hi Harry,

Thank you for the patch! Yet something to improve:

[auto build test ERROR on linus/master]
[also build test ERROR on v5.0-rc4 next-20190222]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]

url:    https://github.com/0day-ci/linux/commits/Harry-Pan/PM-sleep-measure-the-time-of-filesystem-syncing/20190225-032342
config: powerpc-sbc8548_defconfig (attached as .config)
compiler: powerpc-linux-gnu-gcc (Debian 8.2.0-11) 8.2.0
reproduce:
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # save the attached .config to linux build tree
        GCC_VERSION=8.2.0 make.cross ARCH=powerpc 

All errors (new ones prefixed by >>):

   powerpc-linux-gnu-ld: warning: orphan section `.branch_lt' from `arch/powerpc/kernel/head_fsl_booke.o' being placed in section `.branch_lt'
   powerpc-linux-gnu-ld: kernel/power/main.o: in function `ksys_sync_helper':
   main.c:(.text+0x6e0): undefined reference to `__moddi3'
>> powerpc-linux-gnu-ld: main.c:(.text+0x6fc): undefined reference to `__divdi3'

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 12649 bytes --]