linux-kernel - Re: Time stamp value in printk records

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20190930150848.GA303191@tigerII.localdomain>
Date:   Tue, 1 Oct 2019 00:08:48 +0900
From:   Sergey Senozhatsky <sergey.senozhatsky@...il.com>
To:     Sodagudi Prasad <psodagud@...eaurora.org>
Cc:     pmladek@...e.com, sergey.senozhatsky@...il.com,
        rostedt@...dmis.org, linux-kernel@...r.kernel.org
Subject: Re: Time stamp value in printk records

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