Re: [PATCH v1 1/1] scsi: ufs: Add command logging infrastructure

From: Asutosh Das (asd)
Date: Mon Jan 20 2020 - 13:46:57 EST

On 1/16/2020 7:43 PM, Bart Van Assche wrote:
On 2020-01-16 15:03, Asutosh Das (asd) wrote:
On 10/28/2019 10:46 PM, Bjorn Andersson wrote:
On Mon 28 Oct 19:37 PDT 2019, cang@xxxxxxxxxxxxxx wrote:

On 2019-10-23 18:33, Avri Altman wrote:

Add the necessary infrastructure to keep timestamp history of
commands, events and other useful info for debugging complex issues.
This helps in diagnosing events leading upto failure.

Why not use tracepoints, for that?
Ack on Tomas's comment.
Are there any pieces of information that you need not provided by the
upiu tracer?

Thanks,
Avri

In extreme cases, when the UFS runs into bad state, system may crash.
There
may not be a chance to collect trace. If trace is not collected and
failure
is hard to be reproduced, some command logs prints would be very
helpful to
help understand what was going on before we run into failure.


This is a common problem shared among many/all subsystems, so it's
better to rely on a generic solution for this; such as using tracepoints
dumped into pstore/ramoops.

Regards,
Bjorn


Reviving this discussion.

Another issue with using ftrace is that several subsystems use it.
Consider a situation in which we store a history of 64 commands,
responses and some other required info in ftrace.

Say there's a command that's stuck for seconds until the software times
out. In this case, the other ftrace events are still enabled and keep
writing to ftrace buffer thus overwriting some/most of the ufs's command
history; thus the history is more or less lost. And there's a need to
reproduce the issue with other tracing disabled.

So what we need is a client specific logging mechanism, which is
lightweight as ftrace and can be parsed from ramdumps.

I'm open to ideas but ftrace in its current form may not be suitable for
this.

Hi Asutosh,

Are you aware that it is already possible today to figure out which SCSI
commands are pending? Are you familiar with the files under
/sys/kernel/debug/block/? An example:

$ (cd /sys/kernel/debug/block && grep -aH . */*/busy)
nvme0n1/hctx7/busy:0000000006f07009 {.op=READ, .cmd_flags=META|PRIO,
.rq_flags=DONTPREP|IO_STAT, .state=in_flight, .tag=275, .internal_tag=-1}

Bart.



Hi Bart,

No I was not aware of this. Thanks for letting me know.

However, it doesn't look like this stores the _history_ of commands that were already executed.

To put it in perspective, below is the output of the current command logging -:

[ 461.142124354s] dme: dme_send: seq_no= 738272 lun=0 cmd_id=0x018 lba= 0 txfer_len= 0 tag= 0 doorbell=0x0000 outstanding=0x0000 idn= 0
[ 461.142384823s] dme: dme_cmpl_2: seq_no= 738273 lun=0 cmd_id=0x018 lba= 0 txfer_len= 0 tag= 0 doorbell=0x0000 outstanding=0x0000 idn= 0
[ 461.142453052s] scsi: scsi_send: seq_no= 738274 lun=0 cmd_id=0x028 lba= 1360888 txfer_len= 77824 tag= 0 doorbell=0x0001 outstanding=0x0001 idn= 0
[ 461.142473000s] scsi: scsi_send: seq_no= 738275 lun=0 cmd_id=0x028 lba= 1361056 txfer_len= 12288 tag= 1 doorbell=0x0003 outstanding=0x0003 idn= 0
[ 461.142482270s] scsi: scsi_send: seq_no= 738276 lun=0 cmd_id=0x028 lba= 1361088 txfer_len= 4096 tag= 2 doorbell=0x0007 outstanding=0x0007 idn= 0
[ 461.142491020s] scsi: scsi_send: seq_no= 738277 lun=0 cmd_id=0x028 lba= 1361120 txfer_len= 4096 tag= 3 doorbell=0x000F outstanding=0x000F idn= 0
[ 461.142538208s] scsi: scsi_send: seq_no= 738278 lun=0 cmd_id=0x028 lba= 1361144 txfer_len= 4096 tag= 4 doorbell=0x001F outstanding=0x001F idn= 0
[ 461.142780083s] scsi: scsi_send: seq_no= 738279 lun=0 cmd_id=0x028 lba= 1361184 txfer_len= 20480 tag= 5 doorbell=0x003F outstanding=0x003F idn= 0
[ 461.142922791s] scsi: scsi_cmpl: seq_no= 738280 lun=0 cmd_id=0x028 lba= 1360888 txfer_len= 77824 tag= 0 doorbell=0x003E outstanding=0x003F idn= 0
[ 461.142982323s] scsi: scsi_cmpl: seq_no= 738281 lun=0 cmd_id=0x028 lba= 1361056 txfer_len= 12288 tag= 1 doorbell=0x003C outstanding=0x003E idn= 0
[ 461.142996958s] scsi: scsi_cmpl: seq_no= 738282 lun=0 cmd_id=0x028 lba= 1361088 txfer_len= 4096 tag= 2 doorbell=0x0038 outstanding=0x003C idn= 0
[ 461.143059406s] scsi: scsi_cmpl: seq_no= 738283 lun=0 cmd_id=0x028 lba= 1361120 txfer_len= 4096 tag= 3 doorbell=0x0020 outstanding=0x0038 idn= 0
[ 461.143064666s] scsi: scsi_cmpl: seq_no= 738284 lun=0 cmd_id=0x028 lba= 1361144 txfer_len= 4096 tag= 4 doorbell=0x0020 outstanding=0x0038 idn= 0

[...]

This output was extracted from ramdumps after a crash.
There're custom logs that come up as well, for e.g. scaling start and end etc.

In a nutshell, the high-level requirements of the logging would be -:
1. Light-weight
2. Extract from ram-dumps
3. Eliminate the need to reproduce an issue as much as possible

Ftrace ticks all the boxes except 3. There's a high chance of this data being overwritten by other loggers. And when this happens, the issue needs to be reproduced with ftrace logging enabled only for ufs.

*Motivation for this logging*:

There are several (read - all) UFS device vendors who need the sequence of commands leading up to the specific failure. They've asked for it every time. They still do.

There were 2 ways of doing this - either in device or in host.

1. In-Device-:
The device stores a ring buffer of commands that were received.
Upon error, host sends a command to device to read this ring buffer and dumps it out or can be extracted from ramdumps. It'd not be a universal solution anyway and would be very vendor-specific. Difficult to maintain etc. May have to be added to JEDEC to standardize it.

2. In-host-:
Ftrace was tried out and the previously highlighted issues popped up. Hence the need for a UFS (client)-specific implementation.

If there's a way to have a client-specific ftrace logging, it'd be the ideal thing to do.

How about modifying ftrace to make it client-specific?

Any suggestions to modify the current design such that it can use ftrace or any other better ideas or methods, please let me know.

-asd


--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
Linux Foundation Collaborative Project