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

Asutosh Das (asd)
2020-01-20T18:46:57Z

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@codeaurora.org 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