diff mbox

s3 + klog: make log scanning more robust for S3 (LP: #1522292)

Message ID 1449171808-19354-1-git-send-email-colin.king@canonical.com
State Accepted
Headers show

Commit Message

Colin Ian King Dec. 3, 2015, 7:43 p.m. UTC 
From: Colin Ian King <colin.king@canonical.com>

We sometimes get klog messages not appearing in the kernel log
when written by userspace via /dev/kmsg on recent kernels. I've
not yet figured out why that is, but a simple workaround for
the moment is to make the kernel log scanning for the FWTS S3
going to suspend marker is to check for other messages fwts
inserts into the log since at least one of these messages always
ends up in the log.

Also, add a kernel log priority level and fwts: prefix to all
messages from fwts that get written to /dev/ksmg for easier
identification.

Signed-off-by: Colin Ian King <colin.king@canonical.com>
---
 src/acpi/s3/s3.c        | 12 ++++++++----
 src/lib/src/fwts_klog.c |  3 ++-
 2 files changed, 10 insertions(+), 5 deletions(-)

Comments

Ivan Hu Dec. 8, 2015, 6:26 a.m. UTC | #1 
On 2015年12月04日 03:43, Colin King wrote:
> From: Colin Ian King <colin.king@canonical.com>
>
> We sometimes get klog messages not appearing in the kernel log
> when written by userspace via /dev/kmsg on recent kernels. I've
> not yet figured out why that is, but a simple workaround for
> the moment is to make the kernel log scanning for the FWTS S3
> going to suspend marker is to check for other messages fwts
> inserts into the log since at least one of these messages always
> ends up in the log.
>
> Also, add a kernel log priority level and fwts: prefix to all
> messages from fwts that get written to /dev/ksmg for easier
> identification.
>
> Signed-off-by: Colin Ian King <colin.king@canonical.com>
> ---
>   src/acpi/s3/s3.c        | 12 ++++++++----
>   src/lib/src/fwts_klog.c |  3 ++-
>   2 files changed, 10 insertions(+), 5 deletions(-)
>
> diff --git a/src/acpi/s3/s3.c b/src/acpi/s3/s3.c
> index 2af93dc..8e224cf 100644
> --- a/src/acpi/s3/s3.c
> +++ b/src/acpi/s3/s3.c
> @@ -103,10 +103,11 @@ static int wrap_sysfs_do_suspend(fwts_pm_method_vars *fwts_settings,
>   	int status;
>   
>   	FWTS_UNUSED(str);
> +	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
>   	fwts_progress_message(fwts_settings->fw, percent, "(Suspending)");
> -	time(&(fwts_settings->t_start));
> -	(void)fwts_klog_write(fwts_settings->fw, "Starting fwts suspend\n");
>   	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
> +	(void)fwts_klog_write(fwts_settings->fw, "Starting fwts suspend\n");
> +	time(&(fwts_settings->t_start));
>   	status = fwts_sysfs_do_suspend(fwts_settings, s3_hybrid);
>   	(void)fwts_klog_write(fwts_settings->fw, FWTS_RESUME "\n");
>   	(void)fwts_klog_write(fwts_settings->fw, "Finished fwts resume\n");
> @@ -125,10 +126,12 @@ static int wrap_pmutils_do_suspend(fwts_pm_method_vars *fwts_settings,
>   {
>   	int status;
>   
> +	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
>   	fwts_progress_message(fwts_settings->fw, percent, "(Suspending)");
> -	time(&(fwts_settings->t_start));
> +	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
>   	(void)fwts_klog_write(fwts_settings->fw, "Starting fwts suspend\n");
>   	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
> +	time(&(fwts_settings->t_start));
>   	(void)fwts_exec(command, &status);
>   	(void)fwts_klog_write(fwts_settings->fw, FWTS_RESUME "\n");
>   	(void)fwts_klog_write(fwts_settings->fw, "Finished fwts resume\n");
> @@ -318,7 +321,8 @@ static int s3_scan_times(
>   
>   		/* Get log time stamp */
>   		sscanf(bracket + 1, "%lf", &ts);
> -		if (strstr(txt, FWTS_SUSPEND)) {
> +		if (strstr(txt, FWTS_SUSPEND) ||
> +		    strstr(txt, "Starting fwts suspend")) {
>   			s3_suspend_start = ts;
>   			continue;
>   		}
> diff --git a/src/lib/src/fwts_klog.c b/src/lib/src/fwts_klog.c
> index c164396..214117f 100644
> --- a/src/lib/src/fwts_klog.c
> +++ b/src/lib/src/fwts_klog.c
> @@ -547,7 +547,8 @@ int fwts_klog_write(fwts_framework *fw, const char *msg)
>   		return FWTS_ERROR;
>   	}
>   
> -	fprintf(fp, "%s", msg);
> +	fprintf(fp, "<7>fwts: %s", msg);
> +	fflush(fp);
>   	fclose(fp);
>   
>   	return FWTS_OK;
Acked-by: Ivan Hu <ivan.hu@canonical.com>
Alex Hung Dec. 9, 2015, 3:03 a.m. UTC | #2 
On 12/04/2015 03:43 AM, Colin King wrote:
> From: Colin Ian King <colin.king@canonical.com>
>
> We sometimes get klog messages not appearing in the kernel log
> when written by userspace via /dev/kmsg on recent kernels. I've
> not yet figured out why that is, but a simple workaround for
> the moment is to make the kernel log scanning for the FWTS S3
> going to suspend marker is to check for other messages fwts
> inserts into the log since at least one of these messages always
> ends up in the log.
>
> Also, add a kernel log priority level and fwts: prefix to all
> messages from fwts that get written to /dev/ksmg for easier
> identification.
>
> Signed-off-by: Colin Ian King <colin.king@canonical.com>
> ---
>   src/acpi/s3/s3.c        | 12 ++++++++----
>   src/lib/src/fwts_klog.c |  3 ++-
>   2 files changed, 10 insertions(+), 5 deletions(-)
>
> diff --git a/src/acpi/s3/s3.c b/src/acpi/s3/s3.c
> index 2af93dc..8e224cf 100644
> --- a/src/acpi/s3/s3.c
> +++ b/src/acpi/s3/s3.c
> @@ -103,10 +103,11 @@ static int wrap_sysfs_do_suspend(fwts_pm_method_vars *fwts_settings,
>   	int status;
>
>   	FWTS_UNUSED(str);
> +	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
>   	fwts_progress_message(fwts_settings->fw, percent, "(Suspending)");
> -	time(&(fwts_settings->t_start));
> -	(void)fwts_klog_write(fwts_settings->fw, "Starting fwts suspend\n");
>   	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
> +	(void)fwts_klog_write(fwts_settings->fw, "Starting fwts suspend\n");
> +	time(&(fwts_settings->t_start));
>   	status = fwts_sysfs_do_suspend(fwts_settings, s3_hybrid);
>   	(void)fwts_klog_write(fwts_settings->fw, FWTS_RESUME "\n");
>   	(void)fwts_klog_write(fwts_settings->fw, "Finished fwts resume\n");
> @@ -125,10 +126,12 @@ static int wrap_pmutils_do_suspend(fwts_pm_method_vars *fwts_settings,
>   {
>   	int status;
>
> +	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
>   	fwts_progress_message(fwts_settings->fw, percent, "(Suspending)");
> -	time(&(fwts_settings->t_start));
> +	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
>   	(void)fwts_klog_write(fwts_settings->fw, "Starting fwts suspend\n");
>   	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
> +	time(&(fwts_settings->t_start));
>   	(void)fwts_exec(command, &status);
>   	(void)fwts_klog_write(fwts_settings->fw, FWTS_RESUME "\n");
>   	(void)fwts_klog_write(fwts_settings->fw, "Finished fwts resume\n");
> @@ -318,7 +321,8 @@ static int s3_scan_times(
>
>   		/* Get log time stamp */
>   		sscanf(bracket + 1, "%lf", &ts);
> -		if (strstr(txt, FWTS_SUSPEND)) {
> +		if (strstr(txt, FWTS_SUSPEND) ||
> +		    strstr(txt, "Starting fwts suspend")) {
>   			s3_suspend_start = ts;
>   			continue;
>   		}
> diff --git a/src/lib/src/fwts_klog.c b/src/lib/src/fwts_klog.c
> index c164396..214117f 100644
> --- a/src/lib/src/fwts_klog.c
> +++ b/src/lib/src/fwts_klog.c
> @@ -547,7 +547,8 @@ int fwts_klog_write(fwts_framework *fw, const char *msg)
>   		return FWTS_ERROR;
>   	}
>
> -	fprintf(fp, "%s", msg);
> +	fprintf(fp, "<7>fwts: %s", msg);
> +	fflush(fp);
>   	fclose(fp);
>
>   	return FWTS_OK;
>

Acked-by: Alex Hung <alex.hung@canonical.com>
diff mbox

Patch

diff --git a/src/acpi/s3/s3.c b/src/acpi/s3/s3.c
index 2af93dc..8e224cf 100644
--- a/src/acpi/s3/s3.c
+++ b/src/acpi/s3/s3.c
@@ -103,10 +103,11 @@  static int wrap_sysfs_do_suspend(fwts_pm_method_vars *fwts_settings,
 	int status;
 
 	FWTS_UNUSED(str);
+	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
 	fwts_progress_message(fwts_settings->fw, percent, "(Suspending)");
-	time(&(fwts_settings->t_start));
-	(void)fwts_klog_write(fwts_settings->fw, "Starting fwts suspend\n");
 	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
+	(void)fwts_klog_write(fwts_settings->fw, "Starting fwts suspend\n");
+	time(&(fwts_settings->t_start));
 	status = fwts_sysfs_do_suspend(fwts_settings, s3_hybrid);
 	(void)fwts_klog_write(fwts_settings->fw, FWTS_RESUME "\n");
 	(void)fwts_klog_write(fwts_settings->fw, "Finished fwts resume\n");
@@ -125,10 +126,12 @@  static int wrap_pmutils_do_suspend(fwts_pm_method_vars *fwts_settings,
 {
 	int status;
 
+	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
 	fwts_progress_message(fwts_settings->fw, percent, "(Suspending)");
-	time(&(fwts_settings->t_start));
+	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
 	(void)fwts_klog_write(fwts_settings->fw, "Starting fwts suspend\n");
 	(void)fwts_klog_write(fwts_settings->fw, FWTS_SUSPEND "\n");
+	time(&(fwts_settings->t_start));
 	(void)fwts_exec(command, &status);
 	(void)fwts_klog_write(fwts_settings->fw, FWTS_RESUME "\n");
 	(void)fwts_klog_write(fwts_settings->fw, "Finished fwts resume\n");
@@ -318,7 +321,8 @@  static int s3_scan_times(
 
 		/* Get log time stamp */
 		sscanf(bracket + 1, "%lf", &ts);
-		if (strstr(txt, FWTS_SUSPEND)) {
+		if (strstr(txt, FWTS_SUSPEND) ||
+		    strstr(txt, "Starting fwts suspend")) {
 			s3_suspend_start = ts;
 			continue;
 		}
diff --git a/src/lib/src/fwts_klog.c b/src/lib/src/fwts_klog.c
index c164396..214117f 100644
--- a/src/lib/src/fwts_klog.c
+++ b/src/lib/src/fwts_klog.c
@@ -547,7 +547,8 @@  int fwts_klog_write(fwts_framework *fw, const char *msg)
 		return FWTS_ERROR;
 	}
 
-	fprintf(fp, "%s", msg);
+	fprintf(fp, "<7>fwts: %s", msg);
+	fflush(fp);
 	fclose(fp);
 
 	return FWTS_OK;