pm_trace displays the wrong time from the RTC

pm_trace displays the wrong time from the RTC

[Chuck Ebbert]

When resuming, systems print this when booted on 07/31/07:

Date: 06/31/107

/drivers/base/power/trace.c::read_magic_time():
114	get_rtc_time(&time);
115	printk("Time: %2d:%02d:%02d Date: %02d/%02d/%02d\n",
116		time.tm_hour, time.tm_min, time.tm_sec,
117		time.tm_mon, time.tm_mday, time.tm_year);

include/asm-generic/rtc.h:
102         /*
103          * Account for differences between how the RTC uses the values
104          * and how they are defined in a struct rtc_time;
105          */
106         if (time->tm_year <= 69)
107                 time->tm_year += 100;
108 
109         time->tm_mon--;

Re: pm_trace displays the wrong time from the RTC

[Randy Dunlap]

On Tue, 31 Jul 2007 17:20:10 -0400 Chuck Ebbert wrote:

> When resuming, systems print this when booted on 07/31/07:
> 
> Date: 06/31/107
> 
> /drivers/base/power/trace.c::read_magic_time():
> 114	get_rtc_time(&time);
> 115	printk("Time: %2d:%02d:%02d Date: %02d/%02d/%02d\n",
> 116		time.tm_hour, time.tm_min, time.tm_sec,
> 117		time.tm_mon, time.tm_mday, time.tm_year);
> 
> include/asm-generic/rtc.h:
> 102         /*
> 103          * Account for differences between how the RTC uses the values
> 104          * and how they are defined in a struct rtc_time;
> 105          */
> 106         if (time->tm_year <= 69)
> 107                 time->tm_year += 100;
> 108 
> 109         time->tm_mon--;


That's this config option (read all of it):

config PM_TRACE
	bool "Suspend/resume event tracing"
	depends on PM_DEBUG && X86 && EXPERIMENTAL
	default n
	---help---
	This enables some cheesy code to save the last PM event point in the
	RTC across reboots, so that you can debug a machine that just hangs
	during suspend (or more commonly, during resume).

	To use this debugging feature you should attempt to suspend the machine,
	then reboot it, then run

		dmesg -s 1000000 | grep 'hash matches'

	CAUTION: this option will cause your machine's real-time clock to be
	set to an invalid time after a resume.


---
~Randy
*** Remember to use Documentation/SubmitChecklist when testing your code ***

Re: pm_trace displays the wrong time from the RTC

[Dave Jones]

On Tue, Jul 31, 2007 at 02:39:39PM -0700, Randy Dunlap wrote:
 > On Tue, 31 Jul 2007 17:20:10 -0400 Chuck Ebbert wrote:

 > > include/asm-generic/rtc.h:
 > > 102         /*
 > > 103          * Account for differences between how the RTC uses the values
 > > 104          * and how they are defined in a struct rtc_time;
 > > 105          */
 > > 106         if (time->tm_year <= 69)
 > > 107                 time->tm_year += 100;
 > > 108 
 > > 109         time->tm_mon--;
 > 
 > 
 > That's this config option (read all of it):
 > 
 > config PM_TRACE
 > 	bool "Suspend/resume event tracing"
 > 	depends on PM_DEBUG && X86 && EXPERIMENTAL
 > 	default n
 > 	---help---
 > 	This enables some cheesy code to save the last PM event point in the
 > 	RTC across reboots, so that you can debug a machine that just hangs
 > 	during suspend (or more commonly, during resume).
 > 
 > 	To use this debugging feature you should attempt to suspend the machine,
 > 	then reboot it, then run
 > 
 > 		dmesg -s 1000000 | grep 'hash matches'
 > 
 > 	CAUTION: this option will cause your machine's real-time clock to be
 > 	set to an invalid time after a resume.

Doesn't this only take effect if you've been poking /sys/power/pm_trace though ?
Also, look at the date in the output from Chuck. It looks like only the
year is wrong.  I'd have expected more than just the century byte to have been
corrupted.

That +100 heuristic seems really odd to me.  Possibly it needs to be
checking if the century byte is set/unset, or it needs additional
clamping to make sure it doesn't overflow.

	Dave

-- 
http://www.codemonkey.org.uk

Re: pm_trace displays the wrong time from the RTC

[Randy Dunlap]

On Tue, 31 Jul 2007 17:56:09 -0400 Dave Jones wrote:

> On Tue, Jul 31, 2007 at 02:39:39PM -0700, Randy Dunlap wrote:
>  > On Tue, 31 Jul 2007 17:20:10 -0400 Chuck Ebbert wrote:
> 
>  > > include/asm-generic/rtc.h:
>  > > 102         /*
>  > > 103          * Account for differences between how the RTC uses the values
>  > > 104          * and how they are defined in a struct rtc_time;
>  > > 105          */
>  > > 106         if (time->tm_year <= 69)
>  > > 107                 time->tm_year += 100;
>  > > 108 
>  > > 109         time->tm_mon--;
>  > 
>  > 
>  > That's this config option (read all of it):
>  > 
>  > config PM_TRACE
>  > 	bool "Suspend/resume event tracing"
>  > 	depends on PM_DEBUG && X86 && EXPERIMENTAL
>  > 	default n
>  > 	---help---
>  > 	This enables some cheesy code to save the last PM event point in the
>  > 	RTC across reboots, so that you can debug a machine that just hangs
>  > 	during suspend (or more commonly, during resume).
>  > 
>  > 	To use this debugging feature you should attempt to suspend the machine,
>  > 	then reboot it, then run
>  > 
>  > 		dmesg -s 1000000 | grep 'hash matches'
>  > 
>  > 	CAUTION: this option will cause your machine's real-time clock to be
>  > 	set to an invalid time after a resume.
> 
> Doesn't this only take effect if you've been poking /sys/power/pm_trace though ?

Looks like only if /sys/power/pm_trace is enabled, yes.

> Also, look at the date in the output from Chuck. It looks like only the
> year is wrong.  I'd have expected more than just the century byte to have been
> corrupted.

and month, but the code snippet that he posted accounts for that also.

> That +100 heuristic seems really odd to me.  Possibly it needs to be
> checking if the century byte is set/unset, or it needs additional
> clamping to make sure it doesn't overflow.

OK, worth looking into...

---
~Randy
*** Remember to use Documentation/SubmitChecklist when testing your code ***

Re: pm_trace displays the wrong time from the RTC

[Rafael J. Wysocki]

Sorry for slow response, I've just noticed this thread.

On Tuesday, 31 July 2007 23:20, Chuck Ebbert wrote:
> When resuming, systems print this when booted on 07/31/07:
> 
> Date: 06/31/107
> 
> /drivers/base/power/trace.c::read_magic_time():
> 114	get_rtc_time(&time);
> 115	printk("Time: %2d:%02d:%02d Date: %02d/%02d/%02d\n",
> 116		time.tm_hour, time.tm_min, time.tm_sec,
> 117		time.tm_mon, time.tm_mday, time.tm_year);
> 
> include/asm-generic/rtc.h:
> 102         /*
> 103          * Account for differences between how the RTC uses the values
> 104          * and how they are defined in a struct rtc_time;
> 105          */
> 106         if (time->tm_year <= 69)
> 107                 time->tm_year += 100;
> 108 
> 109         time->tm_mon--;

Do you mean that systems display bad date after resuming if PM_TRACE is set,
even if /sys/power/pm_trace contains 1 ?

If that's the case, are they i386 or x86_64?

Greetings,
Rafael


-- 
"Premature optimization is the root of all evil." - Donald Knuth

Re: pm_trace displays the wrong time from the RTC

[Rafael J. Wysocki]

On Wednesday, 1 August 2007 17:47, Rafael J. Wysocki wrote:
> Sorry for slow response, I've just noticed this thread.
> 
> On Tuesday, 31 July 2007 23:20, Chuck Ebbert wrote:
> > When resuming, systems print this when booted on 07/31/07:
> > 
> > Date: 06/31/107
> > 
> > /drivers/base/power/trace.c::read_magic_time():
> > 114	get_rtc_time(&time);
> > 115	printk("Time: %2d:%02d:%02d Date: %02d/%02d/%02d\n",
> > 116		time.tm_hour, time.tm_min, time.tm_sec,
> > 117		time.tm_mon, time.tm_mday, time.tm_year);
> > 
> > include/asm-generic/rtc.h:
> > 102         /*
> > 103          * Account for differences between how the RTC uses the values
> > 104          * and how they are defined in a struct rtc_time;
> > 105          */
> > 106         if (time->tm_year <= 69)
> > 107                 time->tm_year += 100;
> > 108 
> > 109         time->tm_mon--;
> 
> Do you mean that systems display bad date after resuming if PM_TRACE is set,
> even if /sys/power/pm_trace contains 1 ?

s/1/0/ (sorry)

Re: pm_trace displays the wrong time from the RTC

[Chuck Ebbert]

On 08/01/2007 11:47 AM, Rafael J. Wysocki wrote:
> Sorry for slow response, I've just noticed this thread.
> 
> On Tuesday, 31 July 2007 23:20, Chuck Ebbert wrote:
>> When resuming, systems print this when booted on 07/31/07:
>>
>> Date: 06/31/107
>>
>> /drivers/base/power/trace.c::read_magic_time():
>> 114	get_rtc_time(&time);
>> 115	printk("Time: %2d:%02d:%02d Date: %02d/%02d/%02d\n",
>> 116		time.tm_hour, time.tm_min, time.tm_sec,
>> 117		time.tm_mon, time.tm_mday, time.tm_year);
>>
>> include/asm-generic/rtc.h:
>> 102         /*
>> 103          * Account for differences between how the RTC uses the values
>> 104          * and how they are defined in a struct rtc_time;
>> 105          */
>> 106         if (time->tm_year <= 69)
>> 107                 time->tm_year += 100;
>> 108 
>> 109         time->tm_mon--;
> 
> Do you mean that systems display bad date after resuming if PM_TRACE is set,
> even if /sys/power/pm_trace contains 1 ?
> 
> If that's the case, are they i386 or x86_64?
> 

i386:

https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=250238

Re: pm_trace displays the wrong time from the RTC

[Rafael J. Wysocki]

On Wednesday, 1 August 2007 20:15, Chuck Ebbert wrote:
> On 08/01/2007 11:47 AM, Rafael J. Wysocki wrote:
> > Sorry for slow response, I've just noticed this thread.
> > 
> > On Tuesday, 31 July 2007 23:20, Chuck Ebbert wrote:
> >> When resuming, systems print this when booted on 07/31/07:
> >>
> >> Date: 06/31/107
> >>
> >> /drivers/base/power/trace.c::read_magic_time():
> >> 114	get_rtc_time(&time);
> >> 115	printk("Time: %2d:%02d:%02d Date: %02d/%02d/%02d\n",
> >> 116		time.tm_hour, time.tm_min, time.tm_sec,
> >> 117		time.tm_mon, time.tm_mday, time.tm_year);
> >>
> >> include/asm-generic/rtc.h:
> >> 102         /*
> >> 103          * Account for differences between how the RTC uses the values
> >> 104          * and how they are defined in a struct rtc_time;
> >> 105          */
> >> 106         if (time->tm_year <= 69)
> >> 107                 time->tm_year += 100;
> >> 108 
> >> 109         time->tm_mon--;
> > 
> > Do you mean that systems display bad date after resuming if PM_TRACE is set,
> > even if /sys/power/pm_trace contains 1 ?
> > 
> > If that's the case, are they i386 or x86_64?
> > 
> 
> i386:
> 
> https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=250238

OK, I now see what you mean.

On my x86_64 test box this also happens after a fresh boot without
suspending/resuming, so I think the problem is that we just shouldn't add 100
to the year and decrease the month in get_rtc_time().

Greetings,
Rafael


-- 
"Premature optimization is the root of all evil." - Donald Knuth

Re: pm_trace displays the wrong time from the RTC

[Rafael J. Wysocki]

On Wednesday, 1 August 2007 20:15, Chuck Ebbert wrote:
> On 08/01/2007 11:47 AM, Rafael J. Wysocki wrote:
> > Sorry for slow response, I've just noticed this thread.
> > 
> > On Tuesday, 31 July 2007 23:20, Chuck Ebbert wrote:
> >> When resuming, systems print this when booted on 07/31/07:
> >>
> >> Date: 06/31/107
> >>
> >> /drivers/base/power/trace.c::read_magic_time():
> >> 114	get_rtc_time(&time);
> >> 115	printk("Time: %2d:%02d:%02d Date: %02d/%02d/%02d\n",
> >> 116		time.tm_hour, time.tm_min, time.tm_sec,
> >> 117		time.tm_mon, time.tm_mday, time.tm_year);
> >>
> >> include/asm-generic/rtc.h:
> >> 102         /*
> >> 103          * Account for differences between how the RTC uses the values
> >> 104          * and how they are defined in a struct rtc_time;
> >> 105          */
> >> 106         if (time->tm_year <= 69)
> >> 107                 time->tm_year += 100;
> >> 108 
> >> 109         time->tm_mon--;
> > 
> > Do you mean that systems display bad date after resuming if PM_TRACE is set,
> > even if /sys/power/pm_trace contains 1 ?

s/1/0/

> > If that's the case, are they i386 or x86_64?
> > 
> 
> i386:
> 
> https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=250238

OK, I think the appended patch is needed.

Greetings,
Rafael


---
The way in which read_magic_time() displays the date read from the RTC is
apparently confusing to the users
(cf. https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=250238).  Make it
print dates in the standard way.

Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
---
 drivers/base/power/trace.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Index: linux-2.6.23-rc1/drivers/base/power/trace.c
===================================================================
--- linux-2.6.23-rc1.orig/drivers/base/power/trace.c	2007-07-23 22:06:42.000000000 +0200
+++ linux-2.6.23-rc1/drivers/base/power/trace.c	2007-08-01 22:51:16.000000000 +0200
@@ -114,7 +114,7 @@ static unsigned int read_magic_time(void
 	get_rtc_time(&time);
 	printk("Time: %2d:%02d:%02d  Date: %02d/%02d/%02d\n",
 		time.tm_hour, time.tm_min, time.tm_sec,
-		time.tm_mon, time.tm_mday, time.tm_year);
+		time.tm_mon + 1, time.tm_mday, time.tm_year % 100);
 	val = time.tm_year;				/* 100 years */
 	if (val > 100)
 		val -= 100;

Re: pm_trace displays the wrong time from the RTC

[Dave Jones]

The patch below seems to have got dropped on the floor.
We've had it in Fedora since it was posted, and it does the
right thing, so I'm happy to give this an

ACKed-by: Dave Jones <davej@redhat.com>

if it helps it into upstream.

	Dave

On Wed, Aug 01, 2007 at 11:04:34PM +0200, Rafael J. Wysocki wrote:

 > > On 08/01/2007 11:47 AM, Rafael J. Wysocki wrote:
 > > > Sorry for slow response, I've just noticed this thread.
 > > > 
 > > > On Tuesday, 31 July 2007 23:20, Chuck Ebbert wrote:
 > > >> When resuming, systems print this when booted on 07/31/07:
 > > >>
 > > >> Date: 06/31/107
 > > >>
 > > >> /drivers/base/power/trace.c::read_magic_time():
 > > >> 114	get_rtc_time(&time);
 > > >> 115	printk("Time: %2d:%02d:%02d Date: %02d/%02d/%02d\n",
 > > >> 116		time.tm_hour, time.tm_min, time.tm_sec,
 > > >> 117		time.tm_mon, time.tm_mday, time.tm_year);
 > > >>
 > > >> include/asm-generic/rtc.h:
 > > >> 102         /*
 > > >> 103          * Account for differences between how the RTC uses the values
 > > >> 104          * and how they are defined in a struct rtc_time;
 > > >> 105          */
 > > >> 106         if (time->tm_year <= 69)
 > > >> 107                 time->tm_year += 100;
 > > >> 108 
 > > >> 109         time->tm_mon--;
 > > > 
 > > > Do you mean that systems display bad date after resuming if PM_TRACE is set,
 > > > even if /sys/power/pm_trace contains 1 ?
 > 
 > s/1/0/
 > 
 > > > If that's the case, are they i386 or x86_64?
 > > > 
 > > 
 > > i386:
 > > 
 > > https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=250238
 > 
 > OK, I think the appended patch is needed.
 > 
 > Greetings,
 > Rafael
 > 
 > 
 > ---
 > The way in which read_magic_time() displays the date read from the RTC is
 > apparently confusing to the users
 > (cf. https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=250238).  Make it
 > print dates in the standard way.
 > 
 > Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
 > ---
 >  drivers/base/power/trace.c |    2 +-
 >  1 file changed, 1 insertion(+), 1 deletion(-)
 > 
 > Index: linux-2.6.23-rc1/drivers/base/power/trace.c
 > ===================================================================
 > --- linux-2.6.23-rc1.orig/drivers/base/power/trace.c	2007-07-23 22:06:42.000000000 +0200
 > +++ linux-2.6.23-rc1/drivers/base/power/trace.c	2007-08-01 22:51:16.000000000 +0200
 > @@ -114,7 +114,7 @@ static unsigned int read_magic_time(void
 >  	get_rtc_time(&time);
 >  	printk("Time: %2d:%02d:%02d  Date: %02d/%02d/%02d\n",
 >  		time.tm_hour, time.tm_min, time.tm_sec,
 > -		time.tm_mon, time.tm_mday, time.tm_year);
 > +		time.tm_mon + 1, time.tm_mday, time.tm_year % 100);
 >  	val = time.tm_year;				/* 100 years */
 >  	if (val > 100)
 >  		val -= 100;
 > -
 > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
 > the body of a message to majordomo@vger.kernel.org
 > More majordomo info at  http://vger.kernel.org/majordomo-info.html
 > Please read the FAQ at  http://www.tux.org/lkml/
---end quoted text---

-- 
http://www.codemonkey.org.uk

Re: pm_trace displays the wrong time from the RTC

[Andrew Morton]

On Wed, 17 Oct 2007 15:48:40 -0400
Dave Jones <davej@redhat.com> wrote:

> The patch below seems to have got dropped on the floor.
> We've had it in Fedora since it was posted, and it does the
> right thing, so I'm happy to give this an
> 
> ACKed-by: Dave Jones <davej@redhat.com>
> 
> if it helps it into upstream.

I have it queued for 2.6.24, but the entire PM patch series is presently
twiddling thumbs awaiting an acpi merge.