Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
From:   Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Date:   Tue, 1 Oct 2019 00:08:48 +0900
To:     Sodagudi Prasad <psodagud@codeaurora.org>
Cc:     pmladek@suse.com, sergey.senozhatsky@gmail.com,
        rostedt@goodmis.org, linux-kernel@vger.kernel.org
Subject: Re: Time stamp value in printk records
Message-ID: <20190930150848.GA303191@tigerII.localdomain>
References: <7d1aee8505b91c460fee347ed4204b9a@codeaurora.org>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <7d1aee8505b91c460fee347ed4204b9a@codeaurora.org>
User-Agent: Mutt/1.12.2 (2019-09-21)
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

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