Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
From:   Niklas Cassel <Niklas.Cassel@wdc.com>
To:     Wu Bo <wubo40@huawei.com>
CC:     Damien Le Moal <damien.lemoal@opensource.wdc.com>,
        "linux-ide@vger.kernel.org" <linux-ide@vger.kernel.org>,
        "linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>,
        "qiuchangqi.qiu@huawei.com" <qiuchangqi.qiu@huawei.com>,
        Wenchao Hao <haowenchao@huawei.com>,
        "chenchunxiao@huawei.com" <chenchunxiao@huawei.com>
Subject: Re: [RFC PATCH] ata: libata-eh: Retry the cmnd when normal complete
 occurrd after scsi timeout
Thread-Topic: [RFC PATCH] ata: libata-eh: Retry the cmnd when normal complete
 occurrd after scsi timeout
Thread-Index: AQHZGuYWLF0ErbPJak+5UhizCm3L1q6EMmCAgABls4A=
Date:   Thu, 29 Dec 2022 09:21:32 +0000
Message-ID: <Y61cG14nVB8j8Yax@x1-carbon>
References: <1672220216-46938-1-git-send-email-wubo40@huawei.com>
 <Y6yD7Jy0vNr2ZAmE@x1-carbon>
 <703686f3-19aa-eb15-dd54-00f463e6e620@huawei.com>
In-Reply-To: <703686f3-19aa-eb15-dd54-00f463e6e620@huawei.com>
Accept-Language: en-US
Content-Language: en-US
wdcipoutbound: EOP-TRUE
x-ms-exchange-antispam-messagedata-chunkcount: 1
x-ms-exchange-antispam-messagedata-0: =?us-ascii?Q?DDY29k4XDB1vwCaCI5/eh0QzQCtnzVHo3eKYq/HyyU+nY/10bYWGgD1IteBP?=
 =?us-ascii?Q?XSZ887eNIxvfA/zs2zpb7h9eqpkI1W3Cs9tVbkVxDK4YIKXgI0rFjGPivsFY?=
 =?us-ascii?Q?lhqbYsFj1zJa9PEWPLuq5wuJ/JW/5ti/xdzhO59DKhmZvc9PjAV7jw+K9fPk?=
 =?us-ascii?Q?PjDRJXE1kfsyeR2lzV0+RAQvEZQ26jyvgeJL4AhWStPBW+BQq7vkN2FIXMdA?=
 =?us-ascii?Q?JOMv2PbNxfKi9hcmNZztk1i4Kxm3YPDwvOCZJgqVUQtyT5yjrUh/93FtSv5N?=
 =?us-ascii?Q?f5jdd+fh7ulBaUM2DztpkbWmx5kUQVkMxIn9yqzhKXovk8nWKirH/3lnaVy3?=
 =?us-ascii?Q?rHD33Ch5vGnEEga6v5qpYxTmFkOUbZwrUd+mui22eGUIwdxMcQ9nlY94nJP6?=
 =?us-ascii?Q?QQOOYHHX3TxPbRl12WFOKbnHFJCBCgF2o6xbQGRiUQHGXr7lhSWc4whMk+/X?=
 =?us-ascii?Q?m/cBnzlPKGaftH9bZBAOUOOAJVZN+zPOfLOXRx5DQnKl4F9OcOwQzUYH3P6z?=
 =?us-ascii?Q?UIaPQhe6mDdlfdWz62YXrFJZSKx2NnAWiPUOgsucvgWHvg4ujTK8IAjdjUAk?=
 =?us-ascii?Q?D7f2vLYMEtLE/4X3kQRRyJNIzwuMYIFlKXVTd3aAgkUC+f3QPkHtrejGz4Gc?=
 =?us-ascii?Q?SNBrNsPl1OS2Vorjv2U07pmGGAwGFm16zTY4z3YrbBtUkTafeh764bzp26bq?=
 =?us-ascii?Q?rcxJ7/p4M4um/aBt6gMb2r+UJZ7DpFRfdPkNs2XdNmiuzwj2b20Oh0jROfLj?=
 =?us-ascii?Q?ULU/ge5FKWGGknCQ/tBDtqQ3bHKi0Z+EcLqDu8sai+UJ3nqCTCp4JdTUVq7q?=
 =?us-ascii?Q?vNnFB9hCHH43OEx9Tzecm7Q5HO5i80GAYp9IRVD4i6oIuis1YxMNaXEUtG1A?=
 =?us-ascii?Q?mvyRcHTG8VXqlzrnU4hwAA8s4at/YHrQSUqLkZtUkq5LuQM0YmZo/pZciM0w?=
 =?us-ascii?Q?pZH6H81uR8jQqhM1mQVH5+ZuBiSlwaG+IfhaW1oaBV4BXlFfU8JaZSc4/mCs?=
 =?us-ascii?Q?VLhkMgcNKsU2darcaECDUxbhZaXrsPmZIc9ZKrQtZ6AQnIFjblNZHWkdggBr?=
 =?us-ascii?Q?OcJfb4W7Wb2SHrIuBYfwJZ6sb8tkhQDVZ1AqzgSwIu1kJe7DR/sXIhHNfR1X?=
 =?us-ascii?Q?wySxFt79OXL/H4MZ7shf+C101a+0PLiYdqEzjulBnfI3HaeoYydEu4LV4DZR?=
 =?us-ascii?Q?pyOQMnD+6roeJChLKTi3ZnB8B44rdBtkzm0LQE6FjcDQawVMOQQp1l9981mO?=
 =?us-ascii?Q?zlxignWigJKumG2UBOZ6k+Tk0LiFTq/VoFKT4rTfCqf0Kk4dzI+dGS/sOIhe?=
 =?us-ascii?Q?wk20vhX6d8A2ynGGx7ycHCmFF6WNA/4X7czgFWK7oOajrqp6wu91iiuXwmNW?=
 =?us-ascii?Q?3W8uOxMQSyUMp39qzg89ar20eCFPwntcTCAKTMN3aXCWuWn+3EqLmGuLAvyu?=
 =?us-ascii?Q?3NiLBrOC8lUll3L60ekD2/yjujJVNlByCMjpRIQxMCaVKtcTbPzwUXzluy8Y?=
 =?us-ascii?Q?OQ93CWgFHlDjx0jOfFW9QlkF9gdZ8Ik5L47Ytd2k3IP84GGZiMGe6atibK0W?=
 =?us-ascii?Q?1Qc366OJ0woigp0WdntGHctLvs/+/uGA9mur+KK0pVpzD7tJ05t7qiTVbeJw?=
 =?us-ascii?Q?7g=3D=3D?=
Content-Type: text/plain; charset="us-ascii"
Content-ID: <7040D0AB4B63FC4FA84CC1FBE8CCBC65@namprd04.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-OriginatorOrg: wdc.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-AuthSource: MN2PR04MB6272.namprd04.prod.outlook.com
X-MS-Exchange-CrossTenant-Network-Message-Id: d485c34d-f2f3-4add-a7c0-08dae97e1343
X-MS-Exchange-CrossTenant-originalarrivaltime: 29 Dec 2022 09:21:32.4073
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: b61c8803-16f3-4c35-9b17-6f65f441df86
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: 4105Bf0vUvlSo31CL+aOdKh9IthRsfb9zg7R7c30IFFZ9goivUzjbA/TDfifiCWMdnCZjR4BmmwiDExZ5R2OrQ==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: DM5PR04MB0861
X-Spam-Status: No, score=-4.4 required=5.0 tests=BAYES_00,DKIM_SIGNED,
        DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,RCVD_IN_DNSWL_MED,SPF_HELO_PASS,
        SPF_NONE autolearn=ham autolearn_force=no version=3.4.6
X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on
        lindbergh.monkeyblade.net
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

On Thu, Dec 29, 2022 at 11:17:31AM +0800, Wu Bo wrote:
>=20
> Hi Niklas,
>=20
> Thanks for your detailed reply.
>=20
> The case where SCSI timeout wins,
> but there came a normal completion occurred after the SCSI timeout.
> in this scenario, The EH process cannot get the command status
> from the IRQ handler process.
>=20
> If the command is not retried, it can only be returned to the upper layer
> with timeout state.

So the possible scenarios are:
1) command completed normally via IRQ handler
2) command completed with error via the IRQ hander

3) SCSI timeout, which is by default 30 seconds. No IRQ came for this speci=
fic
   QC for 30 seconds. You should always get a completion for a command
   even if it is error. If the HBA did not send an IRQ for this specific QC
   for 30 seconds, it is obviously misbehaving. libata will reset the HBA,
   and outstanding QCs will be retried.
4) SCSI timeout, so no IRQ came for this specific QC for 30 seconds, so EH =
gets
   scheduled for this QC, however it takes some milliseconds before the EH
   thread starts running, and then it needs to call the EH ->eh_strategy_ha=
ndler()
   (ata_scsi_error()) which takes the ap->lock.
   Between the time EH gets scheduled and the ap->lock gets acquired,
   there comes a completion via the IRQ handler that completes the
   command normally.
5) Same as 4) but the IRQ handler completes the command with error.

Note that 4) and 5) are very rare cases.
3) is way more common than 4) and 5).

>=20
> Log as fllows:
> sd 1:0:0:0: [sda] tag#30 scsi_eh_1: flush retry cmd, scmd->retries:3,
> scmd->allowed:2
> sd 1:0:0:0: [sda] tag#30 FAILED Result: hostbyte=3DDID_OK
> driverbyte=3DDRIVER_TIMEOUT
> sd 1:0:0:0: [sda] tag#30 CDB: Read(10) 28 00 07 5e e6 7b 00 00 01 00
> print_req_error: I/O error, dev sda, sector 123659899

How do you know that this is for scenario 4) ?
You have no prints of the IRQ handler, and the QCs it completed.

To me, it actually looks like scenario 3),
especially since you have "flush retry cmd".

In scenario 3), timed out commands will be retried after the HBA is reset.
Do you see that the HBA gets reset in your log?

If it was scenario 4) or 5) I would have expected a "flush finish cmd"
print instead of a "flush retry cmd" print.


Kind regards,
Niklas=