Message ID | 170108152012.780347.6355289232990337333.stgit@mhiramat.roam.corp.google.com |
---|---|
State | New |
Headers |
Return-Path: <linux-kernel-owner@vger.kernel.org> Delivered-To: ouuuleilei@gmail.com Received: by 2002:a59:ce62:0:b0:403:3b70:6f57 with SMTP id o2csp2995721vqx; Mon, 27 Nov 2023 02:39:08 -0800 (PST) X-Google-Smtp-Source: AGHT+IEOhppS3Ppf7vekFFJCTSOpJwAKntCoiLjul/WNJAHucL2t9d7ymcMm0PeslYzw7DMiufUa X-Received: by 2002:a05:6a20:8f15:b0:18c:159b:777 with SMTP id b21-20020a056a208f1500b0018c159b0777mr9605972pzk.26.1701081547748; Mon, 27 Nov 2023 02:39:07 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1701081547; cv=none; d=google.com; s=arc-20160816; b=ALObvBVdBYPUonOfVeCM0gVThgplqGO+ryO4tilOYsYear1ce2gkCrbmFmS+QjLbXg 7ySSrC4nv6dP0q0PSiTLToAExIFK2iCmO2Ie4BYGIw/2s6VXTMiQlNQUss1yLVsOlI8l D4JSNy1YnCuUwYJhM24ro5g2s+s+HpvRoPgyAUZBwD9ES1OtPNaH5Y2BdFZWyGWy9J7P nUFr3WzZo0miH9Q426yWkvZCj9l9zSaJLDw+4zS2W9JsPczLNDPDzFNw/rtlaatEuMyi vSkP1m3iMq0SA5DlmDsGZcChvWlFnU0zqEuKmqpgYZzgmEAzAG76pPyTFljWl6nYQeDy 1Mrg== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:content-transfer-encoding:mime-version :user-agent:references:in-reply-to:message-id:date:subject:cc:to :from:dkim-signature; bh=LqfdF+x6aTw81Y0jmFXVaWsqAyIgpswlUUVPfDNxIqY=; fh=oiYXZnyCWaHSSrYq9dyNG2pzytK5T+ASx4J+x2KhCYU=; b=shtSIVRA7h+th8e2niow7pmd0yE5Kei+7pKi+vfTgBDjfuh3cULivPdMZbqoo0dUau dejFLKr1RwVJep9sCU8NPfcZzMJsl2blVonItwmcfdj0777R0gfDGDThax4Bbw8pHdqr 6geGXCTnYfI8KMT6uYupFqqM/Vk4NKLrDlGKueAMSoOAJ9q3WXBxG3XXawmBCjVOJtC4 XbSqR9dnHiJFdoK6GgnlrBjhVuL8jHR28vymYftebp5aVBv+30XhspMbx1sXS+/vphIm 0mhsWb59KAw2sHmsXw81KdjMGM1tz9+APcIaRCq1/9jqe5BVM3bAplIoKdrGqnLLFLe1 fX1w== ARC-Authentication-Results: i=1; mx.google.com; dkim=pass header.i=@kernel.org header.s=k20201202 header.b=LdiSzZ8T; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.38 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=kernel.org Received: from fry.vger.email (fry.vger.email. [23.128.96.38]) by mx.google.com with ESMTPS id c11-20020a170902aa4b00b001cf5cb58df6si3945946plr.73.2023.11.27.02.39.07 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 27 Nov 2023 02:39:07 -0800 (PST) Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.38 as permitted sender) client-ip=23.128.96.38; Authentication-Results: mx.google.com; dkim=pass header.i=@kernel.org header.s=k20201202 header.b=LdiSzZ8T; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.38 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=kernel.org Received: from out1.vger.email (depot.vger.email [IPv6:2620:137:e000::3:0]) by fry.vger.email (Postfix) with ESMTP id BB29C808F00E; Mon, 27 Nov 2023 02:39:04 -0800 (PST) X-Virus-Status: Clean X-Virus-Scanned: clamav-milter 0.103.11 at fry.vger.email Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S233030AbjK0Kil (ORCPT <rfc822;toshivichauhan@gmail.com> + 99 others); Mon, 27 Nov 2023 05:38:41 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:60254 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S233035AbjK0Kih (ORCPT <rfc822;linux-kernel@vger.kernel.org>); Mon, 27 Nov 2023 05:38:37 -0500 Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 1C1D7136 for <linux-kernel@vger.kernel.org>; Mon, 27 Nov 2023 02:38:44 -0800 (PST) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 09490C433C8; Mon, 27 Nov 2023 10:38:41 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=k20201202; t=1701081523; bh=Rj4mqiBm74uqQ7jupy3m57Hn64R7pf9jHFEyrduOPvg=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=LdiSzZ8T/tVzv0VHjvaO62Q1AdOv5V1EOpN+dXj2AXc28nsLfiCE6X/X8hpWFs2U4 yWSwch+0C5Ks81p1c+vknBDoLAgwOf4bJeEXtTXJH44BxiWIJuriub3jZPUSvlPyuz LrqKszDDIKoZkOaXHK/k546cN9po2Iu8zGr9bwX46PfHrweCS4uoRp3asDznUOgRQa UEnoqaP/eq2YnZ/lZX65OYCI2lr6KVfUd/tNou/FzAm2/h2oD8jJe6lkBnlPV6FGu7 ya/bAQ9kA8LjiLy/FE8I+m1PUVRxDoOBQS81qPsAgu89yNm6eIL0yR4pjjJtZ//0Jw nKabny2rQMBDg== From: "Masami Hiramatsu (Google)" <mhiramat@kernel.org> To: "Rafael J . Wysocki" <rafael@kernel.org>, Pavel Machek <pavel@ucw.cz>, Len Brown <len.brown@intel.com>, Randy Dunlap <rdunlap@infradead.org> Cc: suleiman@google.com, briannorris@google.com, Masami Hiramatsu <mhiramat@kernel.org>, linux-kernel@vger.kernel.org, linux-pm@vger.kernel.org Subject: [PATCH v5] PM: sleep: Expose last succeeded resumed timestamp in sysfs Date: Mon, 27 Nov 2023 19:38:40 +0900 Message-ID: <170108152012.780347.6355289232990337333.stgit@mhiramat.roam.corp.google.com> X-Mailer: git-send-email 2.43.0.rc1.413.gea7ed67945-goog In-Reply-To: <170108151076.780347.2482745314490930894.stgit@mhiramat.roam.corp.google.com> References: <170108151076.780347.2482745314490930894.stgit@mhiramat.roam.corp.google.com> User-Agent: StGit/0.19 MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: 8bit X-Spam-Status: No, score=-1.2 required=5.0 tests=DKIMWL_WL_HIGH,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,MAILING_LIST_MULTI, SPF_HELO_NONE,SPF_PASS,T_SCC_BODY_TEXT_LINE autolearn=unavailable autolearn_force=no version=3.4.6 X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on fry.vger.email Precedence: bulk List-ID: <linux-kernel.vger.kernel.org> X-Mailing-List: linux-kernel@vger.kernel.org X-Greylist: Sender passed SPF test, not delayed by milter-greylist-4.6.4 (fry.vger.email [0.0.0.0]); Mon, 27 Nov 2023 02:39:04 -0800 (PST) X-getmail-retrieved-from-mailbox: INBOX X-GMAIL-THRID: 1783713277301612073 X-GMAIL-MSGID: 1783713285024682989 |
Series |
[v5] PM: sleep: Expose last succeeded resumed timestamp in sysfs
|
|
Commit Message
Masami Hiramatsu (Google)
Nov. 27, 2023, 10:38 a.m. UTC
From: Masami Hiramatsu <mhiramat@kernel.org> Expose last succeeded resumed timestamp as last_success_resume_time attribute of suspend_stats in sysfs. There are some printk()s for printing the similar resume timing to dmesg, but those are recorded with local_clock(), and user can not compare it with current time. We also have tracing events but it requires CAP_SYS_ADMIN to use it. This suspend_stats attribute is easy to access and only expose the timestamp in CLOCK_MONOTONIC. So user can find the actual resumed time and measure the elapsed time from the time when the kernel finished the resume to the user-space action (e.g. display the UI). Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org> --- Changes in v5: - Just updated for v6.7-rc3. Changes in v4.1: - Fix document typo (again). Changes in v4: - Update description to add why. - Fix document typo. Changes in v3: - Add (unsigned long long) casting for %llu. - Add a line after last_success_resume_time_show(). Changes in v2: - Use %llu instead of %lu for printing u64 value. - Remove unneeded indent spaces from the last_success_resume_time line in the debugfs suspend_stat file. --- Documentation/ABI/testing/sysfs-power | 10 ++++++++++ include/linux/suspend.h | 2 ++ kernel/power/main.c | 15 +++++++++++++++ kernel/power/suspend.c | 1 + 4 files changed, 28 insertions(+)
Comments
Hi-- On 11/27/23 02:38, Masami Hiramatsu (Google) wrote: > From: Masami Hiramatsu <mhiramat@kernel.org> > > diff --git a/kernel/power/main.c b/kernel/power/main.c > index f6425ae3e8b0..2ab23fd3daac 100644 > --- a/kernel/power/main.c > +++ b/kernel/power/main.c > @@ -514,6 +526,9 @@ static int suspend_stats_show(struct seq_file *s, void *unused) > suspend_step_name( > suspend_stats.failed_steps[index])); > } > + seq_printf(s, "last_success_resume_time:\t%-llu.%llu\n", The <TAB> after "s," is a bit odd IMO, but I don't see a need to resend it just for that. > + (unsigned long long)suspend_stats.last_success_resume_time.tv_sec, > + (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec); > > return 0; > }
Hi Randy, On Mon, 27 Nov 2023 15:47:01 -0800 Randy Dunlap <rdunlap@infradead.org> wrote: > Hi-- > > > On 11/27/23 02:38, Masami Hiramatsu (Google) wrote: > > From: Masami Hiramatsu <mhiramat@kernel.org> > > > > > diff --git a/kernel/power/main.c b/kernel/power/main.c > > index f6425ae3e8b0..2ab23fd3daac 100644 > > --- a/kernel/power/main.c > > +++ b/kernel/power/main.c > > > @@ -514,6 +526,9 @@ static int suspend_stats_show(struct seq_file *s, void *unused) > > suspend_step_name( > > suspend_stats.failed_steps[index])); > > } > > + seq_printf(s, "last_success_resume_time:\t%-llu.%llu\n", > > The <TAB> after "s," is a bit odd IMO, but I don't see a need to resend it > just for that. Yeah, this might be a cosmetic tab. You can see the other seq_prints() in the same function also have the same <TAB>. I don't want to break it. Thank you, > > > + (unsigned long long)suspend_stats.last_success_resume_time.tv_sec, > > + (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec); > > > > return 0; > > } > > -- > ~Randy
On Mon, Nov 27, 2023 at 11:38 AM Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote: > > From: Masami Hiramatsu <mhiramat@kernel.org> > > Expose last succeeded resumed timestamp as last_success_resume_time > attribute of suspend_stats in sysfs. > > There are some printk()s for printing the similar resume timing to > dmesg, but those are recorded with local_clock(), and user can not > compare it with current time. We also have tracing events but it > requires CAP_SYS_ADMIN to use it. > > This suspend_stats attribute is easy to access and only expose the > timestamp in CLOCK_MONOTONIC. Why CLOCK_MONOTONIC? > So user can find the actual resumed > time and measure the elapsed time from the time when the kernel > finished the resume to the user-space action (e.g. display the UI). Can you please say a bit more about why this is useful? The time stamp is taken at the point when user space has been already running for some time, so what's the exact benefit of it? > Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org> > --- > Changes in v5: > - Just updated for v6.7-rc3. > Changes in v4.1: > - Fix document typo (again). > Changes in v4: > - Update description to add why. > - Fix document typo. > Changes in v3: > - Add (unsigned long long) casting for %llu. > - Add a line after last_success_resume_time_show(). > Changes in v2: > - Use %llu instead of %lu for printing u64 value. > - Remove unneeded indent spaces from the last_success_resume_time > line in the debugfs suspend_stat file. > --- > Documentation/ABI/testing/sysfs-power | 10 ++++++++++ > include/linux/suspend.h | 2 ++ > kernel/power/main.c | 15 +++++++++++++++ > kernel/power/suspend.c | 1 + > 4 files changed, 28 insertions(+) > > diff --git a/Documentation/ABI/testing/sysfs-power b/Documentation/ABI/testing/sysfs-power > index a3942b1036e2..e14975859766 100644 > --- a/Documentation/ABI/testing/sysfs-power > +++ b/Documentation/ABI/testing/sysfs-power > @@ -442,6 +442,16 @@ Description: > 'total_hw_sleep' and 'last_hw_sleep' may not be accurate. > This number is measured in microseconds. > > +What: /sys/power/suspend_stats/last_success_resume_time > +Date: Oct 2023 > +Contact: Masami Hiramatsu <mhiramat@kernel.org> > +Description: > + The /sys/power/suspend_stats/last_success_resume_time file > + contains the timestamp of when the kernel successfully > + resumed from suspend/hibernate. > + This floating point number is measured in seconds by monotonic > + clock. > + > What: /sys/power/sync_on_suspend > Date: October 2019 > Contact: Jonas Meurer <jonas@freesources.org> > diff --git a/include/linux/suspend.h b/include/linux/suspend.h > index ef503088942d..ddd789044960 100644 > --- a/include/linux/suspend.h > +++ b/include/linux/suspend.h > @@ -8,6 +8,7 @@ > #include <linux/pm.h> > #include <linux/mm.h> > #include <linux/freezer.h> > +#include <linux/timekeeping.h> > #include <asm/errno.h> > > #ifdef CONFIG_VT > @@ -71,6 +72,7 @@ struct suspend_stats { > u64 last_hw_sleep; > u64 total_hw_sleep; > u64 max_hw_sleep; > + struct timespec64 last_success_resume_time; > enum suspend_stat_step failed_steps[REC_FAILED_NUM]; > }; > > diff --git a/kernel/power/main.c b/kernel/power/main.c > index f6425ae3e8b0..2ab23fd3daac 100644 > --- a/kernel/power/main.c > +++ b/kernel/power/main.c > @@ -421,6 +421,17 @@ static ssize_t last_failed_step_show(struct kobject *kobj, > } > static struct kobj_attribute last_failed_step = __ATTR_RO(last_failed_step); > > +static ssize_t last_success_resume_time_show(struct kobject *kobj, > + struct kobj_attribute *attr, char *buf) > +{ > + return sprintf(buf, "%llu.%llu\n", > + (unsigned long long)suspend_stats.last_success_resume_time.tv_sec, > + (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec); > +} > + > +static struct kobj_attribute last_success_resume_time = > + __ATTR_RO(last_success_resume_time); > + > static struct attribute *suspend_attrs[] = { > &success.attr, > &fail.attr, > @@ -438,6 +449,7 @@ static struct attribute *suspend_attrs[] = { > &last_hw_sleep.attr, > &total_hw_sleep.attr, > &max_hw_sleep.attr, > + &last_success_resume_time.attr, > NULL, > }; > > @@ -514,6 +526,9 @@ static int suspend_stats_show(struct seq_file *s, void *unused) > suspend_step_name( > suspend_stats.failed_steps[index])); > } > + seq_printf(s, "last_success_resume_time:\t%-llu.%llu\n", > + (unsigned long long)suspend_stats.last_success_resume_time.tv_sec, > + (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec); > > return 0; > } > diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c > index fa3bf161d13f..33334565d5a6 100644 > --- a/kernel/power/suspend.c > +++ b/kernel/power/suspend.c > @@ -622,6 +622,7 @@ int pm_suspend(suspend_state_t state) > dpm_save_failed_errno(error); > } else { > suspend_stats.success++; > + ktime_get_ts64(&suspend_stats.last_success_resume_time); And so hibernation is not really covered. > } > pr_info("suspend exit\n"); > return error; >
Hi Rafael, On Tue, 12 Dec 2023 14:39:17 +0100 "Rafael J. Wysocki" <rafael@kernel.org> wrote: > On Mon, Nov 27, 2023 at 11:38 AM Masami Hiramatsu (Google) > <mhiramat@kernel.org> wrote: > > > > From: Masami Hiramatsu <mhiramat@kernel.org> > > > > Expose last succeeded resumed timestamp as last_success_resume_time > > attribute of suspend_stats in sysfs. > > > > There are some printk()s for printing the similar resume timing to > > dmesg, but those are recorded with local_clock(), and user can not > > compare it with current time. We also have tracing events but it > > requires CAP_SYS_ADMIN to use it. > > > > This suspend_stats attribute is easy to access and only expose the > > timestamp in CLOCK_MONOTONIC. > > Why CLOCK_MONOTONIC? CLOCK_MONOTONIC is the simplest clock which can be used in both user space and kernel space. If we use the CLOCK_LOCAL here, user can not know the actual time delta from the succeeded resume. > > > So user can find the actual resumed > > time and measure the elapsed time from the time when the kernel > > finished the resume to the user-space action (e.g. display the UI). > > Can you please say a bit more about why this is useful? This is a reference timestamp from the user space to measure their processing time for resuming. The kernel side is OK to just trace or printk the each component or subsystem internally. But the user space needs to know when the kernel resume has been done for measuring its component or processes done. Actually this is obscure because the end of resuming in userspace is defined by the user-space application or desktop systems. But anyway if there is a reference point, user process can calculate the delta at any point from that. > > The time stamp is taken at the point when user space has been already > running for some time, so what's the exact benefit of it? Yes, but that timestamp can be scheduled afterwards so it may not be so accurate. This can provide the accurate time of the kernel resume. Thank you, > > > Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org> > > --- > > Changes in v5: > > - Just updated for v6.7-rc3. > > Changes in v4.1: > > - Fix document typo (again). > > Changes in v4: > > - Update description to add why. > > - Fix document typo. > > Changes in v3: > > - Add (unsigned long long) casting for %llu. > > - Add a line after last_success_resume_time_show(). > > Changes in v2: > > - Use %llu instead of %lu for printing u64 value. > > - Remove unneeded indent spaces from the last_success_resume_time > > line in the debugfs suspend_stat file. > > --- > > Documentation/ABI/testing/sysfs-power | 10 ++++++++++ > > include/linux/suspend.h | 2 ++ > > kernel/power/main.c | 15 +++++++++++++++ > > kernel/power/suspend.c | 1 + > > 4 files changed, 28 insertions(+) > > > > diff --git a/Documentation/ABI/testing/sysfs-power b/Documentation/ABI/testing/sysfs-power > > index a3942b1036e2..e14975859766 100644 > > --- a/Documentation/ABI/testing/sysfs-power > > +++ b/Documentation/ABI/testing/sysfs-power > > @@ -442,6 +442,16 @@ Description: > > 'total_hw_sleep' and 'last_hw_sleep' may not be accurate. > > This number is measured in microseconds. > > > > +What: /sys/power/suspend_stats/last_success_resume_time > > +Date: Oct 2023 > > +Contact: Masami Hiramatsu <mhiramat@kernel.org> > > +Description: > > + The /sys/power/suspend_stats/last_success_resume_time file > > + contains the timestamp of when the kernel successfully > > + resumed from suspend/hibernate. > > + This floating point number is measured in seconds by monotonic > > + clock. > > + > > What: /sys/power/sync_on_suspend > > Date: October 2019 > > Contact: Jonas Meurer <jonas@freesources.org> > > diff --git a/include/linux/suspend.h b/include/linux/suspend.h > > index ef503088942d..ddd789044960 100644 > > --- a/include/linux/suspend.h > > +++ b/include/linux/suspend.h > > @@ -8,6 +8,7 @@ > > #include <linux/pm.h> > > #include <linux/mm.h> > > #include <linux/freezer.h> > > +#include <linux/timekeeping.h> > > #include <asm/errno.h> > > > > #ifdef CONFIG_VT > > @@ -71,6 +72,7 @@ struct suspend_stats { > > u64 last_hw_sleep; > > u64 total_hw_sleep; > > u64 max_hw_sleep; > > + struct timespec64 last_success_resume_time; > > enum suspend_stat_step failed_steps[REC_FAILED_NUM]; > > }; > > > > diff --git a/kernel/power/main.c b/kernel/power/main.c > > index f6425ae3e8b0..2ab23fd3daac 100644 > > --- a/kernel/power/main.c > > +++ b/kernel/power/main.c > > @@ -421,6 +421,17 @@ static ssize_t last_failed_step_show(struct kobject *kobj, > > } > > static struct kobj_attribute last_failed_step = __ATTR_RO(last_failed_step); > > > > +static ssize_t last_success_resume_time_show(struct kobject *kobj, > > + struct kobj_attribute *attr, char *buf) > > +{ > > + return sprintf(buf, "%llu.%llu\n", > > + (unsigned long long)suspend_stats.last_success_resume_time.tv_sec, > > + (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec); > > +} > > + > > +static struct kobj_attribute last_success_resume_time = > > + __ATTR_RO(last_success_resume_time); > > + > > static struct attribute *suspend_attrs[] = { > > &success.attr, > > &fail.attr, > > @@ -438,6 +449,7 @@ static struct attribute *suspend_attrs[] = { > > &last_hw_sleep.attr, > > &total_hw_sleep.attr, > > &max_hw_sleep.attr, > > + &last_success_resume_time.attr, > > NULL, > > }; > > > > @@ -514,6 +526,9 @@ static int suspend_stats_show(struct seq_file *s, void *unused) > > suspend_step_name( > > suspend_stats.failed_steps[index])); > > } > > + seq_printf(s, "last_success_resume_time:\t%-llu.%llu\n", > > + (unsigned long long)suspend_stats.last_success_resume_time.tv_sec, > > + (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec); > > > > return 0; > > } > > diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c > > index fa3bf161d13f..33334565d5a6 100644 > > --- a/kernel/power/suspend.c > > +++ b/kernel/power/suspend.c > > @@ -622,6 +622,7 @@ int pm_suspend(suspend_state_t state) > > dpm_save_failed_errno(error); > > } else { > > suspend_stats.success++; > > + ktime_get_ts64(&suspend_stats.last_success_resume_time); > > And so hibernation is not really covered. > > > } > > pr_info("suspend exit\n"); > > return error; > >
On Tue, Dec 12, 2023 at 3:32 PM Masami Hiramatsu <mhiramat@kernel.org> wrote: > > Hi Rafael, > > On Tue, 12 Dec 2023 14:39:17 +0100 > "Rafael J. Wysocki" <rafael@kernel.org> wrote: > > > On Mon, Nov 27, 2023 at 11:38 AM Masami Hiramatsu (Google) > > <mhiramat@kernel.org> wrote: > > > > > > From: Masami Hiramatsu <mhiramat@kernel.org> > > > > > > Expose last succeeded resumed timestamp as last_success_resume_time > > > attribute of suspend_stats in sysfs. > > > > > > There are some printk()s for printing the similar resume timing to > > > dmesg, but those are recorded with local_clock(), and user can not > > > compare it with current time. We also have tracing events but it > > > requires CAP_SYS_ADMIN to use it. > > > > > > This suspend_stats attribute is easy to access and only expose the > > > timestamp in CLOCK_MONOTONIC. > > > > Why CLOCK_MONOTONIC? > > CLOCK_MONOTONIC is the simplest clock which can be used in both user > space and kernel space. If we use the CLOCK_LOCAL here, user can not > know the actual time delta from the succeeded resume. So what does user space need to do to use this value? > > > > > So user can find the actual resumed > > > time and measure the elapsed time from the time when the kernel > > > finished the resume to the user-space action (e.g. display the UI). > > > > Can you please say a bit more about why this is useful? > > This is a reference timestamp from the user space to measure their > processing time for resuming. The kernel side is OK to just trace > or printk the each component or subsystem internally. But the user > space needs to know when the kernel resume has been done for measuring > its component or processes done. Why does it need to know that? > Actually this is obscure because the > end of resuming in userspace is defined by the user-space application > or desktop systems. But anyway if there is a reference point, user > process can calculate the delta at any point from that. > > > > > The time stamp is taken at the point when user space has been already > > running for some time, so what's the exact benefit of it? > > Yes, but that timestamp can be scheduled afterwards so it may not > be so accurate. This can provide the accurate time of the kernel > resume. I'm talking about the timestamp added by this patch, that is /sys/power/suspend_stats/last_success_resume_time. By the time ktime_get_ts64() in pm_suspend() is called, user space has already been thawed and is running, so why is this useful?
On Tue, 12 Dec 2023 15:57:52 +0100 "Rafael J. Wysocki" <rafael@kernel.org> wrote: > On Tue, Dec 12, 2023 at 3:32 PM Masami Hiramatsu <mhiramat@kernel.org> wrote: > > > > Hi Rafael, > > > > On Tue, 12 Dec 2023 14:39:17 +0100 > > "Rafael J. Wysocki" <rafael@kernel.org> wrote: > > > > > On Mon, Nov 27, 2023 at 11:38 AM Masami Hiramatsu (Google) > > > <mhiramat@kernel.org> wrote: > > > > > > > > From: Masami Hiramatsu <mhiramat@kernel.org> > > > > > > > > Expose last succeeded resumed timestamp as last_success_resume_time > > > > attribute of suspend_stats in sysfs. > > > > > > > > There are some printk()s for printing the similar resume timing to > > > > dmesg, but those are recorded with local_clock(), and user can not > > > > compare it with current time. We also have tracing events but it > > > > requires CAP_SYS_ADMIN to use it. > > > > > > > > This suspend_stats attribute is easy to access and only expose the > > > > timestamp in CLOCK_MONOTONIC. > > > > > > Why CLOCK_MONOTONIC? > > > > CLOCK_MONOTONIC is the simplest clock which can be used in both user > > space and kernel space. If we use the CLOCK_LOCAL here, user can not > > know the actual time delta from the succeeded resume. > > So what does user space need to do to use this value? This will be used to measure the delay of the user-space resuming as a metric of system health. > > > > > > > So user can find the actual resumed > > > > time and measure the elapsed time from the time when the kernel > > > > finished the resume to the user-space action (e.g. display the UI). > > > > > > Can you please say a bit more about why this is useful? > > > > This is a reference timestamp from the user space to measure their > > processing time for resuming. The kernel side is OK to just trace > > or printk the each component or subsystem internally. But the user > > space needs to know when the kernel resume has been done for measuring > > its component or processes done. > > Why does it need to know that? For the metrics, the kernel side resume time and user-side resume time are important to know if any update caused regressions and separate the issue. > > > Actually this is obscure because the > > end of resuming in userspace is defined by the user-space application > > or desktop systems. But anyway if there is a reference point, user > > process can calculate the delta at any point from that. > > > > > > > > The time stamp is taken at the point when user space has been already > > > running for some time, so what's the exact benefit of it? > > > > Yes, but that timestamp can be scheduled afterwards so it may not > > be so accurate. This can provide the accurate time of the kernel > > resume. > > I'm talking about the timestamp added by this patch, that is > /sys/power/suspend_stats/last_success_resume_time. > > By the time ktime_get_ts64() in pm_suspend() is called, user space has > already been thawed and is running, so why is this useful? Aaah, good catch! It should be right before thawing process, right? Thank you,
diff --git a/Documentation/ABI/testing/sysfs-power b/Documentation/ABI/testing/sysfs-power index a3942b1036e2..e14975859766 100644 --- a/Documentation/ABI/testing/sysfs-power +++ b/Documentation/ABI/testing/sysfs-power @@ -442,6 +442,16 @@ Description: 'total_hw_sleep' and 'last_hw_sleep' may not be accurate. This number is measured in microseconds. +What: /sys/power/suspend_stats/last_success_resume_time +Date: Oct 2023 +Contact: Masami Hiramatsu <mhiramat@kernel.org> +Description: + The /sys/power/suspend_stats/last_success_resume_time file + contains the timestamp of when the kernel successfully + resumed from suspend/hibernate. + This floating point number is measured in seconds by monotonic + clock. + What: /sys/power/sync_on_suspend Date: October 2019 Contact: Jonas Meurer <jonas@freesources.org> diff --git a/include/linux/suspend.h b/include/linux/suspend.h index ef503088942d..ddd789044960 100644 --- a/include/linux/suspend.h +++ b/include/linux/suspend.h @@ -8,6 +8,7 @@ #include <linux/pm.h> #include <linux/mm.h> #include <linux/freezer.h> +#include <linux/timekeeping.h> #include <asm/errno.h> #ifdef CONFIG_VT @@ -71,6 +72,7 @@ struct suspend_stats { u64 last_hw_sleep; u64 total_hw_sleep; u64 max_hw_sleep; + struct timespec64 last_success_resume_time; enum suspend_stat_step failed_steps[REC_FAILED_NUM]; }; diff --git a/kernel/power/main.c b/kernel/power/main.c index f6425ae3e8b0..2ab23fd3daac 100644 --- a/kernel/power/main.c +++ b/kernel/power/main.c @@ -421,6 +421,17 @@ static ssize_t last_failed_step_show(struct kobject *kobj, } static struct kobj_attribute last_failed_step = __ATTR_RO(last_failed_step); +static ssize_t last_success_resume_time_show(struct kobject *kobj, + struct kobj_attribute *attr, char *buf) +{ + return sprintf(buf, "%llu.%llu\n", + (unsigned long long)suspend_stats.last_success_resume_time.tv_sec, + (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec); +} + +static struct kobj_attribute last_success_resume_time = + __ATTR_RO(last_success_resume_time); + static struct attribute *suspend_attrs[] = { &success.attr, &fail.attr, @@ -438,6 +449,7 @@ static struct attribute *suspend_attrs[] = { &last_hw_sleep.attr, &total_hw_sleep.attr, &max_hw_sleep.attr, + &last_success_resume_time.attr, NULL, }; @@ -514,6 +526,9 @@ static int suspend_stats_show(struct seq_file *s, void *unused) suspend_step_name( suspend_stats.failed_steps[index])); } + seq_printf(s, "last_success_resume_time:\t%-llu.%llu\n", + (unsigned long long)suspend_stats.last_success_resume_time.tv_sec, + (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec); return 0; } diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c index fa3bf161d13f..33334565d5a6 100644 --- a/kernel/power/suspend.c +++ b/kernel/power/suspend.c @@ -622,6 +622,7 @@ int pm_suspend(suspend_state_t state) dpm_save_failed_errno(error); } else { suspend_stats.success++; + ktime_get_ts64(&suspend_stats.last_success_resume_time); } pr_info("suspend exit\n"); return error;