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

[Neil Zhang]

John,
 
> -----Original Message-----
> From: johnstul.lkml@xxxxxxxxx [mailto:johnstul.lkml@xxxxxxxxx] 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@xxxxxxxxxxx>
> 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@xxxxxxxxxxx>
> > ---
> >  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