Received: by 2002:a25:824b:0:0:0:0:0 with SMTP id d11csp3591408ybn; Fri, 27 Sep 2019 08:30:19 -0700 (PDT) X-Google-Smtp-Source: APXvYqyoKgzc8ySErHi18CZEAQRBAW29G/jT77fvxhHkW7c9BjelRbRZDxH28AKHPf3UK0+WGxTl X-Received: by 2002:a17:906:b742:: with SMTP id fx2mr8166395ejb.205.1569598219164; Fri, 27 Sep 2019 08:30:19 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1569598219; cv=none; d=google.com; s=arc-20160816; b=qSF2coqibEP9I9ArltzlEtAumbEcCBECQxyo1B2MtEw8PRWdKrr6qH0k7I/+LzKBlP JKnZ9nsBwj/qFcNurA0Nf43kcVJORD/jX47QedwT5srTrpkwPLwBA+xS35JvHzaCWTQ/ LhAkiFQWoD4yz0EMz5LeRlslgvllY+5Adi/Ysk9ysVNOkpYJNZh5Cf97swB2WP44xeOJ VlNs+ebXTghLoFOZ71bwaDpxOYwEtfucTrezqVK2uWeuK+cIyQZCWjs32svFVtzUHkez 3NTo2LSqnkF6nFq/kjadZ0wI3ohFTeFZrWsPbOKuuG3+/Ercnh7WoiyyvwoCC13O4Mva 3t2g== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:sender:content-transfer-encoding:mime-version :user-agent:references:in-reply-to:date:cc:to:from:subject :message-id; bh=6fEDFD5O6Fbi5FieFbrWOsZz3/POrKqYsPB45wSb0DM=; b=csakQ7nEMSUlukgwa466TZXhKrlkE4W4qd4ylEyxS+UMzpmrDSFj+2hvrip7bmpugh MX/Qm0JTYXexpxKlo7fc0jjEa6+/FElrIVmdzwInUCnvec6eLtRxqLePy3dyWm7PlYPT Te6ZTTCdlT9HZFTMozsF235u6Jc8TBng7DPdqw9TSN9JVS7q9p6BNrDotEe6+BU3CuNL eLV8IoC28YfMgrSJkKXH1hyOJZxZolAjCYHCPCDbuj22wdcR23OVgpRtK7TtxYdmnOkA g5ghNJ8WnUs6v5YLk9+AOx5upEYWGjGjHceqhy/dg2v1xac88pn9gQZn3/Aej5JgEt+8 hSeg== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id k24si2877931ejz.284.2019.09.27.08.29.53; Fri, 27 Sep 2019 08:30:19 -0700 (PDT) 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; Authentication-Results: mx.google.com; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1727825AbfI0P0o (ORCPT + 99 others); Fri, 27 Sep 2019 11:26:44 -0400 Received: from mx2.suse.de ([195.135.220.15]:38580 "EHLO mx1.suse.de" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1727319AbfI0P0o (ORCPT ); Fri, 27 Sep 2019 11:26:44 -0400 X-Virus-Scanned: by amavisd-new at test-mx.suse.de Received: from relay2.suse.de (unknown [195.135.220.254]) by mx1.suse.de (Postfix) with ESMTP id 3D241AB7D; Fri, 27 Sep 2019 15:26:42 +0000 (UTC) Message-ID: <471732f03049a1528df1d144013d723041f0a419.camel@suse.de> Subject: Re: [PATCH] scsi: core: Log SCSI command age with errors From: Martin Wilck To: "Milan P. Gandhi" , linux-kernel@vger.kernel.org, linux-scsi@vger.kernel.org Cc: jejb@linux.ibm.com, martin.petersen@oracle.com Date: Fri, 27 Sep 2019 17:26:46 +0200 In-Reply-To: <20190923060122.GA9603@machine1> References: <20190923060122.GA9603@machine1> Content-Type: text/plain; charset="UTF-8" User-Agent: Evolution 3.32.4 MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Mon, 2019-09-23 at 11:31 +0530, Milan P. Gandhi wrote: > Couple of users had requested to print the SCSI command age along > with command failure errors. This is a small change, but allows > users to get more important information about the command that was > failed, it would help the users in debugging the command failures: > > Signed-off-by: Milan P. Gandhi > --- > diff --git a/drivers/scsi/scsi_logging.c > b/drivers/scsi/scsi_logging.c > index ecc5918e372a..ca2182bc53c6 100644 > --- a/drivers/scsi/scsi_logging.c > +++ b/drivers/scsi/scsi_logging.c > @@ -437,6 +437,7 @@ void scsi_print_result(const struct scsi_cmnd > *cmd, const char *msg, > const char *mlret_string = scsi_mlreturn_string(disposition); > const char *hb_string = scsi_hostbyte_string(cmd->result); > const char *db_string = scsi_driverbyte_string(cmd->result); > + unsigned long cmd_age = (jiffies - cmd->jiffies_at_alloc) / HZ; This comes down to pretty coarse time resolution, does it not? More often than not, the time difference shown will be 0. I'd recommend at least millisecond resolution. > > logbuf = scsi_log_reserve_buffer(&logbuf_len); > if (!logbuf) > @@ -478,10 +479,15 @@ void scsi_print_result(const struct scsi_cmnd > *cmd, const char *msg, > > if (db_string) > off += scnprintf(logbuf + off, logbuf_len - off, > - "driverbyte=%s", db_string); > + "driverbyte=%s ", db_string); > else > off += scnprintf(logbuf + off, logbuf_len - off, > - "driverbyte=0x%02x", driver_byte(cmd- > >result)); > + "driverbyte=0x%02x ", > + driver_byte(cmd->result)); > + > + off += scnprintf(logbuf + off, logbuf_len - off, > + "cmd-age=%lus", cmd_age); This is certainly helpful in some situations. Yet I am unsure if it should *always* be printed. I wouldn't say it's as important as the other stuff scsi_print_result() provides. After all, by activating MLQUEUE+MLCOMPLETE, the time on-wire can be extracted with better accuracy from currently available logs. So perhaps make this depend on a module parameter? Also, we should carefully ponder if we want to put this on the same line as the driver byte, as users may have created scripts for parsing this output. Regards, Martin