[PATCH] nvme-tcp: add additional info for nvme_tcp_timeout log

[Engel, Amit]

Hi Sagi, 

Below is an example print of a read cmd that is timed out
Should I add this also to the commit msg?
nvme nvme0: queue 1: cntlid 1 timeout request 0x7 type 4 cid 28679 opcode 0x1 start time 5022008820ns io start time 5022008132ns request timeout 5000ms

Thanks
Amit


Internal Use - Confidential

-----Original Message-----
From: Sagi Grimberg <sagi at grimberg.me> 
Sent: Sunday, 20 November 2022 14:00
To: Engel, Amit <Amit.Engel at Dell.com>; linux-nvme at lists.infradead.org
Subject: Re: [PATCH] nvme-tcp: add additional info for nvme_tcp_timeout log


[EXTERNAL EMAIL] 


> From: Amit Engel <Amit.Engel at dell.com>
> 
> This provides additional details about the rq/cmd that is timed out

Please add an example print of the timeout log msg.

> 
> Signed-off-by: Amit Engel <Amit.Engel at dell.com>
> ---
>   drivers/nvme/host/tcp.c | 7 +++++--
>   1 file changed, 5 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/nvme/host/tcp.c b/drivers/nvme/host/tcp.c index 
> 1eed0fc26b3a..5abaff5d6f6e 100644
> --- a/drivers/nvme/host/tcp.c
> +++ b/drivers/nvme/host/tcp.c
> @@ -2277,8 +2277,11 @@ static enum blk_eh_timer_return nvme_tcp_timeout(struct request *rq)
>   	struct nvme_tcp_cmd_pdu *pdu = req->pdu;
>   
>   	dev_warn(ctrl->device,
> -		"queue %d: timeout request %#x type %d\n",
> -		nvme_tcp_queue_id(req->queue), rq->tag, pdu->hdr.type);
> +		"queue %d: cntlid %u timeout request %#x type %d cid %u opcode %#x "
> +		"start time %lluns io start time %lluns request timeout %ums\n",
> +		nvme_tcp_queue_id(req->queue), ctrl->cntlid, rq->tag, pdu->hdr.type,
> +		pdu->cmd.common.command_id, pdu->cmd.common.opcode,
> +		ktime_sub_ns(ktime_get(), rq->start_time_ns), 
> +ktime_sub_ns(ktime_get(), rq->io_start_time_ns), 
> +jiffies_to_msecs(rq->timeout));

You can get the cntlid from the controller device name which appears in dev_warn, no need for it here.

Why are you printing the timeout value (in ktime)? What info does it add? You can see the relative time in the log and you know what the io timeout is (30 seconds before by default)...

You can also easily retrieve the cid from the tag (lower 12 bits).

The nvme opcode is fine to add...

>   
>   	if (ctrl->state != NVME_CTRL_LIVE) {
>   		/*