Re: Time stamp value in printk records

[Sergey Senozhatsky <sergey.senozhatsky@gmail.com>]

Hi,

On (09/30/19 06:33), Sodagudi Prasad wrote:
> From Qualcomm side, we would like to check with upstream team about adding
> Raw time stamp value to printk records. On Qualcomm soc, there are various
> DSPs subsystems are there - for example audio, video and modem DSPs.
> Adding raw timer value(along with sched_clock()) in the printk record helps
> in the following use cases –
> 1)	To find out which subsystem  crashed first  -  Whether application
> processor crashed first or DSP subsystem?
> 2)	If there are any system stability issues on the DSP side, what is the
> activity on the APPS processor side during that time?
>
> Initially during the device boot up, printk shed_clock value can be matched
> with timer raw value used on the dsp subsystem, but after APPS processor
> suspends several times, we don’t have way to correlate the time stamp  value
> on the DSP and APPS processor. All timers(both apps processor timer and dsp
> timers) are derived from globally always on timer on Qualcomm soc, So
> keeping global timer raw values in printk records and dsp logs help to
> correlate the activity of all the processors in SoC.

Off the top of my head - timestamps are really hard.

Not only because, as of now, we serialize printk() internally. But also
because a lot of things can happen on any CPU between the moment when event
occurs - printk() - and the moment when we read clocks. NMI, IRQ, preemption.

Consider the following case

CPU0			CPU1			CPU2			CPU3
printk()		printk()		printk()		printk()
			<<preemption>>					<<irq>>
 spin_lock(logbuf)
 clock()
 spin_unlock(logbuf)				spin_lock(logbuf)
 						clock()			<<iret>>
						spin_unlock(logbuf)	spin_lock(logbuf)
									clock()
			spin_lock(logbuf)				spin_unlock(logbuf)
			clock()
			spin_unlock(logbuf)

	-ss