[PATCH] printk: add sleep time into timestamp

[PATCH] printk: add sleep time into timestamp

[Neil Zhang]

Add sleep time into timestamp to reflect the actual time since
sched_clock will be stopped during suspend.

This patch depends on the following patch.
timekeeping: check params before use them

Signed-off-by: Neil Zhang <zhangwm@marvell.com>
---
 kernel/printk/printk.c |   15 +++++++++++++--
 1 file changed, 13 insertions(+), 2 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 4dae9cb..2dc6145 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -250,6 +250,17 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
 
+static u64 print_clock(void)
+{
+	struct timespec	ts;
+	u64 ts_nsec = local_clock();
+
+	get_xtime_and_monotonic_and_sleep_offset(NULL, NULL, &ts);
+	ts_nsec += (u64)ts.tv_sec * NSEC_PER_SEC + (u64)ts.tv_nsec;
+
+	return ts_nsec;
+}
+
 /* cpu currently holding logbuf_lock */
 static volatile unsigned int logbuf_cpu = UINT_MAX;
 
@@ -349,7 +360,7 @@ static void log_store(int facility, int level,
 	if (ts_nsec > 0)
 		msg->ts_nsec = ts_nsec;
 	else
-		msg->ts_nsec = local_clock();
+		msg->ts_nsec = print_clock();
 	memset(log_dict(msg) + dict_len, 0, pad_len);
 	msg->len = sizeof(struct printk_log) + text_len + dict_len + pad_len;
 
@@ -1440,7 +1451,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.facility = facility;
 		cont.level = level;
 		cont.owner = current;
-		cont.ts_nsec = local_clock();
+		cont.ts_nsec = print_clock();
 		cont.flags = 0;
 		cont.cons = 0;
 		cont.flushed = false;
-- 
1.7.9.5

Re: [PATCH] printk: add sleep time into timestamp

[John Stultz]

On Thu, Mar 27, 2014 at 1:17 AM, Neil Zhang <zhangwm@marvell.com> wrote:
> Add sleep time into timestamp to reflect the actual time since
> sched_clock will be stopped during suspend.

So why is this change necessary?

Further, since the sleep time may be updated a bit late in the resume
cycle (in many cases we cannot access the RTC until irqs are enabled
back on), you may see messages that show pre-suspend times when really
they occur after we resume (but before the sleep time is incremented).

More comments below....

> This patch depends on the following patch.
> timekeeping: check params before use them
>
> Signed-off-by: Neil Zhang <zhangwm@marvell.com>
> ---
>  kernel/printk/printk.c |   15 +++++++++++++--
>  1 file changed, 13 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 4dae9cb..2dc6145 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -250,6 +250,17 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
>  static char *log_buf = __log_buf;
>  static u32 log_buf_len = __LOG_BUF_LEN;
>
> +static u64 print_clock(void)
> +{
> +       struct timespec ts;
> +       u64 ts_nsec = local_clock();
> +
> +       get_xtime_and_monotonic_and_sleep_offset(NULL, NULL, &ts);

So this will cause deadlocks anytime we print from the timekeeping
core, since we may hold a write on the timekeeper lock, and this patch
makes every printk try to take a read-lock on the timekeeper lock.

I'd suggest you use monotonic_to_bootbased() here instead of hacking
up this hrtimer specific interface, but even so, right now that call
doesn't take the timekeeper lock, but probably should, so its not a
good long term plan.

I'm still not convinced this change needs to be done, but a  better
solution here would be to add infrastructure that when the sleep time
is updated we update an offset that the is adding to the local_clock()
however, you probably want to be careful since you don't want sleep
time in normal local_clock/sched_clock calls since it would mess up
scheduling.

thanks
-john

RE: [PATCH] printk: add sleep time into timestamp

[Neil Zhang]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="gb2312", Size: 3225 bytes --]

John,
 
> -----Original Message-----
> From: johnstul.lkml@gmail.com [mailto:johnstul.lkml@gmail.com] On Behalf
> Of John Stultz
> Sent: 2014Äê3ÔÂ28ÈÕ 11:18
> To: Neil Zhang
> Cc: Andrew Morton; Linux Kernel Mailing List
> Subject: Re: [PATCH] printk: add sleep time into timestamp
> 
> On Thu, Mar 27, 2014 at 1:17 AM, Neil Zhang <zhangwm@marvell.com>
> wrote:
> > Add sleep time into timestamp to reflect the actual time since
> > sched_clock will be stopped during suspend.
> 
> So why is this change necessary?
> 
> Further, since the sleep time may be updated a bit late in the resume cycle (in
> many cases we cannot access the RTC until irqs are enabled back on), you may
> see messages that show pre-suspend times when really they occur after we
> resume (but before the sleep time is incremented).
> 
Thanks for the comments.
Yes, the sleep time will be update in RTC and the print in the resume procedure still w/o the sleep time.
But I think the messages are not too much at this stage. 

> More comments below....
> 
> > This patch depends on the following patch.
> > timekeeping: check params before use them
> >
> > Signed-off-by: Neil Zhang <zhangwm@marvell.com>
> > ---
> >  kernel/printk/printk.c |   15 +++++++++++++--
> >  1 file changed, 13 insertions(+), 2 deletions(-)
> >
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index
> > 4dae9cb..2dc6145 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -250,6 +250,17 @@ static char __log_buf[__LOG_BUF_LEN]
> > __aligned(LOG_ALIGN);  static char *log_buf = __log_buf;  static u32
> > log_buf_len = __LOG_BUF_LEN;
> >
> > +static u64 print_clock(void)
> > +{
> > +       struct timespec ts;
> > +       u64 ts_nsec = local_clock();
> > +
> > +       get_xtime_and_monotonic_and_sleep_offset(NULL, NULL, &ts);
> 
> So this will cause deadlocks anytime we print from the timekeeping core, since
> we may hold a write on the timekeeper lock, and this patch makes every printk
> try to take a read-lock on the timekeeper lock.
> 
Sorry, I don't quite understand why it will cause deadlock.
Yes, it will take a read-lock, but it should not be expensive.

> I'd suggest you use monotonic_to_bootbased() here instead of hacking up this
> hrtimer specific interface, but even so, right now that call doesn't take the
> timekeeper lock, but probably should, so its not a good long term plan.

It maybe doable, or whether we can add another function to only return sleep time.
Then no read-lock is needed.

> 
> I'm still not convinced this change needs to be done, but a  better solution
> here would be to add infrastructure that when the sleep time is updated we
> update an offset that the is adding to the local_clock() however, you probably
> want to be careful since you don't want sleep time in normal
> local_clock/sched_clock calls since it would mess up scheduling.
> 
Sometimes we need to compare the kernel log with user space log, 
so it would be convenient to add the sleep time into kernel timestamp.

> thanks
> -john

Best Regards,
Neil Zhang
ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

Re: [PATCH] printk: add sleep time into timestamp

[John Stultz]

On 03/27/2014 11:45 PM, Neil Zhang wrote:
> John,
>  
>> -----Original Message-----
>> From: johnstul.lkml@gmail.com [mailto:johnstul.lkml@gmail.com] On Behalf
>> Of John Stultz
>> Sent: 2014年3月28日 11:18
>> To: Neil Zhang
>> Cc: Andrew Morton; Linux Kernel Mailing List
>> Subject: Re: [PATCH] printk: add sleep time into timestamp
>>
>> On Thu, Mar 27, 2014 at 1:17 AM, Neil Zhang <zhangwm@marvell.com>
>> wrote:
>>> Add sleep time into timestamp to reflect the actual time since
>>> sched_clock will be stopped during suspend.
>> So why is this change necessary?
>>
>> Further, since the sleep time may be updated a bit late in the resume cycle (in
>> many cases we cannot access the RTC until irqs are enabled back on), you may
>> see messages that show pre-suspend times when really they occur after we
>> resume (but before the sleep time is incremented).
>>
> Thanks for the comments.
> Yes, the sleep time will be update in RTC and the print in the resume procedure still w/o the sleep time.
> But I think the messages are not too much at this stage. 

Not sure I understand what you mean by "the messages are not too much",
could you expand that a bit?

>> More comments below....
>>
>>> This patch depends on the following patch.
>>> timekeeping: check params before use them
>>>
>>> Signed-off-by: Neil Zhang <zhangwm@marvell.com>
>>> ---
>>>  kernel/printk/printk.c |   15 +++++++++++++--
>>>  1 file changed, 13 insertions(+), 2 deletions(-)
>>>
>>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index
>>> 4dae9cb..2dc6145 100644
>>> --- a/kernel/printk/printk.c
>>> +++ b/kernel/printk/printk.c
>>> @@ -250,6 +250,17 @@ static char __log_buf[__LOG_BUF_LEN]
>>> __aligned(LOG_ALIGN);  static char *log_buf = __log_buf;  static u32
>>> log_buf_len = __LOG_BUF_LEN;
>>>
>>> +static u64 print_clock(void)
>>> +{
>>> +       struct timespec ts;
>>> +       u64 ts_nsec = local_clock();
>>> +
>>> +       get_xtime_and_monotonic_and_sleep_offset(NULL, NULL, &ts);
>> So this will cause deadlocks anytime we print from the timekeeping core, since
>> we may hold a write on the timekeeper lock, and this patch makes every printk
>> try to take a read-lock on the timekeeper lock.
>>
> Sorry, I don't quite understand why it will cause deadlock.
> Yes, it will take a read-lock, but it should not be expensive.

If we call or trigger a printk while holding a write on the timekeeping
lock, the printk code will then try to aquire a read-lock on the
timekeeping lock and this will deadlock the machine.

The printk code already has trouble with the timekeeping code, but this
would make it worse.


>> I'd suggest you use monotonic_to_bootbased() here instead of hacking up this
>> hrtimer specific interface, but even so, right now that call doesn't take the
>> timekeeper lock, but probably should, so its not a good long term plan.
> It maybe doable, or whether we can add another function to only return sleep time.
> Then no read-lock is needed.

Well, you're returning a timespec, which cannot be read atomically, so
it would need to take the lock (that's why I was saying
monotonic_to_bootbased() should probably take the lock, and seems broken).

But using monotonic_to_bootbased would give you the same functionality
without having to modify get_xtime_and_monotonic_and_sleep_offset().

>> I'm still not convinced this change needs to be done, but a  better solution
>> here would be to add infrastructure that when the sleep time is updated we
>> update an offset that the is adding to the local_clock() however, you probably
>> want to be careful since you don't want sleep time in normal
>> local_clock/sched_clock calls since it would mess up scheduling.
>>
> Sometimes we need to compare the kernel log with user space log, 
> so it would be convenient to add the sleep time into kernel timestamp.

Which userspace log? You can have the syslog capture the kernel messages
and timestamp them properly. Also, if you are using your own logging,
you can use CLOCK_MONOTONIC which will provide the closest approximation
to the sched_clock based printk clock.

thanks
-john

RE: [PATCH] printk: add sleep time into timestamp

[Neil Zhang]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="gb2312", Size: 5387 bytes --]



> -----Original Message-----
> From: John Stultz [mailto:john.stultz@linaro.org]
> Sent: 2014Äê3ÔÂ29ÈÕ 1:37
> To: Neil Zhang
> Cc: Andrew Morton; Linux Kernel Mailing List
> Subject: Re: [PATCH] printk: add sleep time into timestamp
> 
> On 03/27/2014 11:45 PM, Neil Zhang wrote:
> > John,
> >
> >> -----Original Message-----
> >> From: johnstul.lkml@gmail.com [mailto:johnstul.lkml@gmail.com] On
> >> Behalf Of John Stultz
> >> Sent: 2014Äê3ÔÂ28ÈÕ 11:18
> >> To: Neil Zhang
> >> Cc: Andrew Morton; Linux Kernel Mailing List
> >> Subject: Re: [PATCH] printk: add sleep time into timestamp
> >>
> >> On Thu, Mar 27, 2014 at 1:17 AM, Neil Zhang <zhangwm@marvell.com>
> >> wrote:
> >>> Add sleep time into timestamp to reflect the actual time since
> >>> sched_clock will be stopped during suspend.
> >> So why is this change necessary?
> >>
> >> Further, since the sleep time may be updated a bit late in the resume
> >> cycle (in many cases we cannot access the RTC until irqs are enabled
> >> back on), you may see messages that show pre-suspend times when
> >> really they occur after we resume (but before the sleep time is
> incremented).
> >>
> > Thanks for the comments.
> > Yes, the sleep time will be update in RTC and the print in the resume
> procedure still w/o the sleep time.
> > But I think the messages are not too much at this stage.
> 
> Not sure I understand what you mean by "the messages are not too much",
> could you expand that a bit?

Sorry that I didn't make it clear.
I mean since most of the platform don't have the persistent clock support, 
so there is no good way to reflect the sleep time for the messages in the resume procedure before rtc_resume so far.
Fortunately this period only related to the resume procedure.
Anyway, other part of the kernel can benefit from this patch's change.

> 
> >> More comments below....
> >>
> >>> This patch depends on the following patch.
> >>> timekeeping: check params before use them
> >>>
> >>> Signed-off-by: Neil Zhang <zhangwm@marvell.com>
> >>> ---
> >>>  kernel/printk/printk.c |   15 +++++++++++++--
> >>>  1 file changed, 13 insertions(+), 2 deletions(-)
> >>>
> >>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index
> >>> 4dae9cb..2dc6145 100644
> >>> --- a/kernel/printk/printk.c
> >>> +++ b/kernel/printk/printk.c
> >>> @@ -250,6 +250,17 @@ static char __log_buf[__LOG_BUF_LEN]
> >>> __aligned(LOG_ALIGN);  static char *log_buf = __log_buf;  static u32
> >>> log_buf_len = __LOG_BUF_LEN;
> >>>
> >>> +static u64 print_clock(void)
> >>> +{
> >>> +       struct timespec ts;
> >>> +       u64 ts_nsec = local_clock();
> >>> +
> >>> +       get_xtime_and_monotonic_and_sleep_offset(NULL, NULL, &ts);
> >> So this will cause deadlocks anytime we print from the timekeeping
> >> core, since we may hold a write on the timekeeper lock, and this
> >> patch makes every printk try to take a read-lock on the timekeeper lock.
> >>
> > Sorry, I don't quite understand why it will cause deadlock.
> > Yes, it will take a read-lock, but it should not be expensive.
> 
> If we call or trigger a printk while holding a write on the timekeeping lock, the
> printk code will then try to aquire a read-lock on the timekeeping lock and this
> will deadlock the machine.
> 
> The printk code already has trouble with the timekeeping code, but this would
> make it worse.
> 	
Got it, thanks for the clarification.

> 
> >> I'd suggest you use monotonic_to_bootbased() here instead of hacking
> >> up this hrtimer specific interface, but even so, right now that call
> >> doesn't take the timekeeper lock, but probably should, so its not a good
> long term plan.
> > It maybe doable, or whether we can add another function to only return
> sleep time.
> > Then no read-lock is needed.
> 
> Well, you're returning a timespec, which cannot be read atomically, so it
> would need to take the lock (that's why I was saying
> monotonic_to_bootbased() should probably take the lock, and seems broken).
> 
> But using monotonic_to_bootbased would give you the same functionality
> without having to modify get_xtime_and_monotonic_and_sleep_offset().

Ok, I will use the following functions for printk, thanks for the suggestion.

ns_to_timespec()
monotonic_to_bootbased()
timespec_to_ns()

> 
> >> I'm still not convinced this change needs to be done, but a  better
> >> solution here would be to add infrastructure that when the sleep time
> >> is updated we update an offset that the is adding to the
> >> local_clock() however, you probably want to be careful since you
> >> don't want sleep time in normal local_clock/sched_clock calls since it would
> mess up scheduling.
> >>
> > Sometimes we need to compare the kernel log with user space log, so it
> > would be convenient to add the sleep time into kernel timestamp.
> 
> Which userspace log? You can have the syslog capture the kernel messages
> and timestamp them properly. Also, if you are using your own logging, you can
> use CLOCK_MONOTONIC which will provide the closest approximation to the
> sched_clock based printk clock.

There are many exist message in android or telephony code use the wall time.
It will include the sleep time.

> 
> thanks
> -john
> 
> 
Best Regards,
Neil Zhang

ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥