From patchwork Mon Jan 6 19:21:36 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218451 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5vF3Wlgz9sNH for ; Tue, 7 Jan 2020 06:59:37 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5vF0yVHzDqG8 for ; Tue, 7 Jan 2020 06:59:37 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.158.5; helo=mx0b-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0b-001b2d01.pphosted.com (mx0b-001b2d01.pphosted.com [148.163.158.5]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5lB6ZR0zDqGn for ; Tue, 7 Jan 2020 06:52:38 +1100 (AEDT) Received: from pps.filterd (m0127361.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqEL3080512 for ; Mon, 6 Jan 2020 14:52:35 -0500 Received: from ppma01dal.us.ibm.com (83.d6.3fa9.ip4.static.sl-reverse.com [169.63.214.131]) by mx0a-001b2d01.pphosted.com with ESMTP id 2xapd5k13c-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:35 -0500 Received: from pps.filterd (ppma01dal.us.ibm.com [127.0.0.1]) by ppma01dal.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006Jo9xx020937 for ; Mon, 6 Jan 2020 19:52:34 GMT Received: from b01cxnp23032.gho.pok.ibm.com (b01cxnp23032.gho.pok.ibm.com [9.57.198.27]) by ppma01dal.us.ibm.com with ESMTP id 2xajb6a2fq-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:34 +0000 Received: from b01ledav006.gho.pok.ibm.com (b01ledav006.gho.pok.ibm.com [9.57.199.111]) by b01cxnp23032.gho.pok.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqW9b49414634 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK); Mon, 6 Jan 2020 19:52:32 GMT Received: from b01ledav006.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 0A82CAC05E; Mon, 6 Jan 2020 19:52:32 +0000 (GMT) Received: from b01ledav006.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id E2AE2AC059; Mon, 6 Jan 2020 19:52:31 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b01ledav006.gho.pok.ibm.com (Postfix) with ESMTP; Mon, 6 Jan 2020 19:52:31 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 2D00DAE0494; Mon, 6 Jan 2020 13:22:28 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:36 -0600 Message-Id: <1578338508-13424-2-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 impostorscore=0 malwarescore=0 clxscore=1015 suspectscore=1 adultscore=0 phishscore=0 priorityscore=1501 bulkscore=0 mlxlogscore=999 mlxscore=0 spamscore=0 lowpriorityscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 01/13] core/flash: Allow OPAL flash calls for size equal to flash X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Cyril Bur MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" From: Cyril Bur A bounds checking mistake prevents opal_flash_{read,write,erase} calls from having a length equal to the size of the flash. This bug has been present since the beginning (e7d1f60e core/flash: Add flash API) of these calls. Until before d6a5b53f libflash/blocklevel: Add blocklevel_smart_erase() 6/4/2017 none of our tools would have performed a single command for the full size of the flash. It would still have been possible to persuade `dd` to do this by using a block size equal to the size of the flash or other mtd related tools. Any pflash built with blocklevel_smart_erase() will perform one call to Linux and then Skiboot for the size of flash. Signed-off-by: Cyril Bur Acked-by: Samuel Mendoza-Jonas Reviewed-By: Alistair Popple Signed-off-by: Stewart Smith --- core/flash.c | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/core/flash.c b/core/flash.c index 7fbfca2..2f041db 100644 --- a/core/flash.c +++ b/core/flash.c @@ -10,6 +10,7 @@ #include #include +#include #include #include #include @@ -436,8 +437,10 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, goto err; } - if (size >= flash->size || offset >= flash->size + if (size > flash->size || offset >= flash->size || offset + size > flash->size) { + prlog(PR_DEBUG, "Requested flash op %d beyond flash size %" PRIu64 "\n", + op, flash->size); rc = OPAL_PARAMETER; goto err; } From patchwork Mon Jan 6 19:21:37 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218452 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5vY1L4Fz9sNH for ; Tue, 7 Jan 2020 06:59:53 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5vX6vDwzDqKh for ; Tue, 7 Jan 2020 06:59:52 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.156.1; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0a-001b2d01.pphosted.com [148.163.156.1]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5lC0PzqzDqFw for ; Tue, 7 Jan 2020 06:52:38 +1100 (AEDT) Received: from pps.filterd (m0098410.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqKcB001783 for ; Mon, 6 Jan 2020 14:52:36 -0500 Received: from ppma05wdc.us.ibm.com (1b.90.2fa9.ip4.static.sl-reverse.com [169.47.144.27]) by mx0a-001b2d01.pphosted.com with ESMTP id 2xar481d10-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:36 -0500 Received: from pps.filterd (ppma05wdc.us.ibm.com [127.0.0.1]) by ppma05wdc.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006Jq4RG031381 for ; Mon, 6 Jan 2020 19:52:35 GMT Received: from b01cxnp23032.gho.pok.ibm.com (b01cxnp23032.gho.pok.ibm.com [9.57.198.27]) by ppma05wdc.us.ibm.com with ESMTP id 2xajb5vvc7-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:35 +0000 Received: from b01ledav002.gho.pok.ibm.com (b01ledav002.gho.pok.ibm.com [9.57.199.107]) by b01cxnp23032.gho.pok.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqXLm50332068 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK); Mon, 6 Jan 2020 19:52:33 GMT Received: from b01ledav002.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id B20F7124055; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from b01ledav002.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 967E6124052; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b01ledav002.gho.pok.ibm.com (Postfix) with ESMTP; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 50F63AE04B3; Mon, 6 Jan 2020 13:22:30 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:37 -0600 Message-Id: <1578338508-13424-3-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 malwarescore=0 mlxlogscore=864 impostorscore=0 mlxscore=0 priorityscore=1501 lowpriorityscore=0 suspectscore=1 clxscore=1015 bulkscore=0 phishscore=0 adultscore=0 spamscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 02/13] core/flash: Make flash_reserve() and flash_release() use any flash X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Cyril Bur MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" From: Cyril Bur Now that skiboot can have multiple flashes it doesn't make sense for flash_reserve() and flash_release() to only operate on system_flash. New functions system_flash_reserve() and system_flash_release() preserve the current functionality of flash_reserve() and flash_release() and flash_reserve() and flash_releasei() can now be used to mark any flash as busy. Signed-off-by: Cyril Bur Reviewed-by: Alistair Popple Signed-off-by: Stewart Smith --- core/flash.c | 20 +++++++++++++++----- hw/ipmi/ipmi-sel.c | 4 ++-- include/skiboot.h | 4 ++-- 3 files changed, 19 insertions(+), 9 deletions(-) diff --git a/core/flash.c b/core/flash.c index 2f041db..78e0023 100644 --- a/core/flash.c +++ b/core/flash.c @@ -60,15 +60,15 @@ static struct lock flash_lock; static struct flash *nvram_flash; static u32 nvram_offset, nvram_size; -bool flash_reserve(void) +static bool flash_reserve(struct flash *flash) { bool rc = false; if (!try_lock(&flash_lock)) return false; - if (!system_flash->busy) { - system_flash->busy = true; + if (!flash->busy) { + flash->busy = true; rc = true; } unlock(&flash_lock); @@ -76,10 +76,10 @@ bool flash_reserve(void) return rc; } -void flash_release(void) +static void flash_release(struct flash *flash) { lock(&flash_lock); - system_flash->busy = false; + flash->busy = false; unlock(&flash_lock); } @@ -94,6 +94,16 @@ bool flash_unregister(void) return true; } +bool system_flash_reserve(void) +{ + return flash_reserve(system_flash); +} + +void system_flash_release(void) +{ + flash_release(system_flash); +} + static int flash_nvram_info(uint32_t *total_size) { int rc; diff --git a/hw/ipmi/ipmi-sel.c b/hw/ipmi/ipmi-sel.c index 794aa38..ec4a318 100644 --- a/hw/ipmi/ipmi-sel.c +++ b/hw/ipmi/ipmi-sel.c @@ -463,7 +463,7 @@ static void sel_pnor(uint8_t access, void *context __unused) break; } - granted = flash_reserve(); + granted = system_flash_reserve(); if (granted) occ_pnor_set_owner(PNOR_OWNER_EXTERNAL); /* Ack the request */ @@ -472,7 +472,7 @@ static void sel_pnor(uint8_t access, void *context __unused) break; case RELEASE_PNOR: prlog(PR_NOTICE, "PNOR access released\n"); - flash_release(); + system_flash_release(); occ_pnor_set_owner(PNOR_OWNER_HOST); break; default: diff --git a/include/skiboot.h b/include/skiboot.h index e9d57de..2cb4160 100644 --- a/include/skiboot.h +++ b/include/skiboot.h @@ -217,8 +217,8 @@ extern int flash_register(struct blocklevel_device *bl); extern int flash_start_preload_resource(enum resource_id id, uint32_t subid, void *buf, size_t *len); extern int flash_resource_loaded(enum resource_id id, uint32_t idx); -extern bool flash_reserve(void); -extern void flash_release(void); +extern bool system_flash_reserve(void); +extern void system_flash_release(void); extern bool flash_unregister(void); #define FLASH_SUBPART_ALIGNMENT 0x1000 #define FLASH_SUBPART_HEADER_SIZE FLASH_SUBPART_ALIGNMENT From patchwork Mon Jan 6 19:21:38 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218453 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5vs05sVz9sNH for ; Tue, 7 Jan 2020 07:00:09 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5vr5c30zDqJV for ; Tue, 7 Jan 2020 07:00:08 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.158.5; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0b-001b2d01.pphosted.com [148.163.158.5]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5lC0pvmzDqGv for ; Tue, 7 Jan 2020 06:52:38 +1100 (AEDT) Received: from pps.filterd (m0098420.ppops.net [127.0.0.1]) by mx0b-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqMN7167405 for ; Mon, 6 Jan 2020 14:52:35 -0500 Received: from ppma03wdc.us.ibm.com (ba.79.3fa9.ip4.static.sl-reverse.com [169.63.121.186]) by mx0b-001b2d01.pphosted.com with ESMTP id 2xb8s8wu2a-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:35 -0500 Received: from pps.filterd (ppma03wdc.us.ibm.com [127.0.0.1]) by ppma03wdc.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006Jope9021033 for ; Mon, 6 Jan 2020 19:52:34 GMT Received: from b03cxnp08026.gho.boulder.ibm.com (b03cxnp08026.gho.boulder.ibm.com [9.17.130.18]) by ppma03wdc.us.ibm.com with ESMTP id 2xajb64t4h-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:34 +0000 Received: from b03ledav004.gho.boulder.ibm.com (b03ledav004.gho.boulder.ibm.com [9.17.130.235]) by b03cxnp08026.gho.boulder.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqWme13304178 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK); Mon, 6 Jan 2020 19:52:32 GMT Received: from b03ledav004.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 01F527805F; Mon, 6 Jan 2020 19:52:32 +0000 (GMT) Received: from b03ledav004.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id DA8A07805E; Mon, 6 Jan 2020 19:52:31 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b03ledav004.gho.boulder.ibm.com (Postfix) with ESMTP; Mon, 6 Jan 2020 19:52:31 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 281A8AE0965; Mon, 6 Jan 2020 13:22:32 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:38 -0600 Message-Id: <1578338508-13424-4-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 bulkscore=0 malwarescore=0 spamscore=0 clxscore=1015 impostorscore=0 lowpriorityscore=0 priorityscore=1501 mlxlogscore=879 adultscore=0 mlxscore=0 phishscore=0 suspectscore=1 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 03/13] core/flash: Don't hold flash_lock for the entirety of an opal_flash_op() X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Cyril Bur MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" From: Cyril Bur It doesn't make sense to hold the lock to the flash for an entire flash op. The flash_lock provides mutual exclusion to the flashes structure and each flash element has a busy boolean which ensures that mutual exclusion on access of the flash. Signed-off-by: Cyril Bur Reviewed-By: Alistair Popple Signed-off-by: Stewart Smith --- core/flash.c | 19 ++++++------------- 1 file changed, 6 insertions(+), 13 deletions(-) diff --git a/core/flash.c b/core/flash.c index 78e0023..d97d88e 100644 --- a/core/flash.c +++ b/core/flash.c @@ -429,23 +429,16 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, struct flash *flash = NULL; int rc; - if (!try_lock(&flash_lock)) - return OPAL_BUSY; - list_for_each(&flashes, flash, list) if (flash->id == id) break; - if (flash->id != id) { + if (flash->id != id) /* Couldn't find the flash */ - rc = OPAL_PARAMETER; - goto err; - } + return OPAL_PARAMETER; - if (flash->busy) { - rc = OPAL_BUSY; - goto err; - } + if (!flash_reserve(flash)) + return OPAL_BUSY; if (size > flash->size || offset >= flash->size || offset + size > flash->size) { @@ -481,13 +474,13 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, goto err; } - unlock(&flash_lock); + flash_release(flash); opal_queue_msg(OPAL_MSG_ASYNC_COMP, NULL, NULL, token, rc); return OPAL_ASYNC_COMPLETION; err: - unlock(&flash_lock); + flash_release(flash); return rc; } From patchwork Mon Jan 6 19:21:39 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218455 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5wt3xrJz9sNH for ; Tue, 7 Jan 2020 07:01:02 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5wt1k9jzDqJK for ; Tue, 7 Jan 2020 07:01:02 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.158.5; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0b-001b2d01.pphosted.com [148.163.158.5]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5lC5DF6zDqGn for ; Tue, 7 Jan 2020 06:52:39 +1100 (AEDT) Received: from pps.filterd (m0098417.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqKNk112409 for ; Mon, 6 Jan 2020 14:52:37 -0500 Received: from ppma01dal.us.ibm.com (83.d6.3fa9.ip4.static.sl-reverse.com [169.63.214.131]) by mx0a-001b2d01.pphosted.com with ESMTP id 2xb91p6bwp-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:37 -0500 Received: from pps.filterd (ppma01dal.us.ibm.com [127.0.0.1]) by ppma01dal.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006Jo904020937 for ; Mon, 6 Jan 2020 19:52:36 GMT Received: from b03cxnp08026.gho.boulder.ibm.com (b03cxnp08026.gho.boulder.ibm.com [9.17.130.18]) by ppma01dal.us.ibm.com with ESMTP id 2xajb6a2g0-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:36 +0000 Received: from b03ledav002.gho.boulder.ibm.com (b03ledav002.gho.boulder.ibm.com [9.17.130.233]) by b03cxnp08026.gho.boulder.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqX1h44958150 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK); Mon, 6 Jan 2020 19:52:33 GMT Received: from b03ledav002.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id ABD1513604F; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from b03ledav002.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 88282136053; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b03ledav002.gho.boulder.ibm.com (Postfix) with ESMTP; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 4A56FAE0472; Mon, 6 Jan 2020 13:22:35 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:39 -0600 Message-Id: <1578338508-13424-5-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 lowpriorityscore=0 suspectscore=1 adultscore=0 malwarescore=0 clxscore=1015 mlxlogscore=999 bulkscore=0 impostorscore=0 priorityscore=1501 spamscore=0 mlxscore=0 phishscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 04/13] core/flash: Make opal_flash_op() actually asynchronous X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Cyril Bur MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" From: Cyril Bur This patch provides a simple (although not particularly efficient) asynchronous capability to the opal_flash interface. The advantage of this approach is that it doesn't require any changing of blocklevel or its backends to provide an asynchronous implementation. This is also the disadvantage of this implementation as all it actually does is break the work up in chunks that it can performed quickly, but still synchronously. Only a backend could provide a more asynchronous implementation. This solves a problem we have right now with the opal_flash_erase call where it can block in Skiboot for around three minutes. This causes a variety of problems in Linux due to a processor being gone for a long time. For example: [ 98.610043] INFO: rcu_sched detected stalls on CPUs/tasks: [ 98.610050] 113-...: (1 GPs behind) idle=96f/140000000000000/0 softirq=527/528 fqs=1044 [ 98.610051] (detected by 112, t=2102 jiffies, g=223, c=222, q=123) [ 98.610060] Task dump for CPU 113: [ 98.610062] pflash R running task 0 3335 3333 0x00040004 [ 98.610066] Call Trace: [ 98.610070] [c000001fdd847730] [0000000000000001] 0x1 (unreliable) [ 98.610076] [c000001fdd847900] [c000000000013854] __switch_to+0x1e8/0x1f4 [ 98.610081] [c000001fdd847960] [c0000000006122c4] __schedule+0x32c/0x874 [ 98.610083] [c000001fdd847a30] [c000001fdd847b40] 0xc000001fdd847b40 It is for this reason that breaking the work up in smaller chunks solves this problem as Skiboot can return the CPU to Linux between chunks to avoid Linux getting upset. Reported-By: Samuel Mendoza-Jonas Signed-off-by: Cyril Bur Signed-off-by: Stewart Smith --- core/flash.c | 117 ++++++++++++++++++++++++++++++++++++++++++++++++++--------- core/timer.c | 8 ++++ 2 files changed, 108 insertions(+), 17 deletions(-) diff --git a/core/flash.c b/core/flash.c index d97d88e..e98c8e0 100644 --- a/core/flash.c +++ b/core/flash.c @@ -25,8 +25,24 @@ #include #include #include +#include #include +enum flash_op { + FLASH_OP_READ, + FLASH_OP_WRITE, + FLASH_OP_ERASE, +}; + +struct flash_async_info { + enum flash_op op; + struct timer poller; + uint64_t token; + uint64_t pos; + uint64_t len; + uint64_t buf; +}; + struct flash { struct list_node list; bool busy; @@ -35,6 +51,7 @@ struct flash { uint64_t size; uint32_t block_size; int id; + struct flash_async_info async; }; static struct { @@ -234,6 +251,54 @@ static int flash_nvram_probe(struct flash *flash, struct ffs_handle *ffs) /* core flash support */ +/* + * Called with flash lock held, drop it on async completion + */ +static void flash_poll(struct timer *t __unused, void *data, uint64_t now __unused) +{ + struct flash *flash = data; + uint64_t offset, buf, len; + int rc; + + offset = flash->async.pos; + buf = flash->async.buf; + len = MIN(flash->async.len, flash->block_size*10); + printf("Flash poll op %d len %llu\n", flash->async.op, len); + + switch (flash->async.op) { + case FLASH_OP_READ: + rc = blocklevel_raw_read(flash->bl, offset, (void *)buf, len); + break; + case FLASH_OP_WRITE: + rc = blocklevel_raw_write(flash->bl, offset, (void *)buf, len); + break; + case FLASH_OP_ERASE: + rc = blocklevel_erase(flash->bl, offset, len); + break; + default: + assert(0); + } + + if (rc) + rc = OPAL_HARDWARE; + + flash->async.pos += len; + flash->async.buf += len; + flash->async.len -= len; + if (!rc && flash->async.len) { + /* + * We want to get called pretty much straight away, just have + * to be sure that we jump back out to Linux so that if this + * very long we don't cause RCU or the scheduler to freak + */ + schedule_timer(&flash->async.poller, 0); + return; + } + + opal_queue_msg(OPAL_MSG_ASYNC_COMP, NULL, NULL, flash->async.token, rc); + flash_release(flash); +} + static struct dt_node *flash_add_dt_node(struct flash *flash, int id) { int i; @@ -389,6 +454,7 @@ int flash_register(struct blocklevel_device *bl) flash->size = size; flash->block_size = block_size; flash->id = num_flashes(); + init_timer(&flash->async.poller, flash_poll, flash); rc = ffs_init(0, flash->size, bl, &ffs, 1); if (rc) { @@ -417,16 +483,11 @@ int flash_register(struct blocklevel_device *bl) return OPAL_SUCCESS; } -enum flash_op { - FLASH_OP_READ, - FLASH_OP_WRITE, - FLASH_OP_ERASE, -}; - static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, uint64_t buf, uint64_t size, uint64_t token) { struct flash *flash = NULL; + uint64_t len; int rc; list_for_each(&flashes, flash, list) @@ -445,9 +506,17 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, prlog(PR_DEBUG, "Requested flash op %d beyond flash size %" PRIu64 "\n", op, flash->size); rc = OPAL_PARAMETER; - goto err; + goto out; } + len = MIN(size, flash->block_size*10); + printf("Flash op %d len %llu\n", op, len); + flash->async.op = op; + flash->async.token = token; + flash->async.buf = buf + len; + flash->async.len = size - len; + flash->async.pos = offset + len; + /* * These ops intentionally have no smarts (ecc correction or erase * before write) to them. @@ -457,29 +526,43 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, */ switch (op) { case FLASH_OP_READ: - rc = blocklevel_raw_read(flash->bl, offset, (void *)buf, size); + rc = blocklevel_raw_read(flash->bl, offset, (void *)buf, len); break; case FLASH_OP_WRITE: - rc = blocklevel_raw_write(flash->bl, offset, (void *)buf, size); + rc = blocklevel_raw_write(flash->bl, offset, (void *)buf, len); break; case FLASH_OP_ERASE: - rc = blocklevel_erase(flash->bl, offset, size); + rc = blocklevel_erase(flash->bl, offset, len); break; default: assert(0); } if (rc) { + prlog(PR_ERR, "%s: Op %d failed with rc %d\n", __func__, op, rc); rc = OPAL_HARDWARE; - goto err; + goto out; } - flash_release(flash); - - opal_queue_msg(OPAL_MSG_ASYNC_COMP, NULL, NULL, token, rc); - return OPAL_ASYNC_COMPLETION; - -err: + if (size - len) { + /* Work remains */ + schedule_timer(&flash->async.poller, 0); + /* Don't release the flash */ + return OPAL_ASYNC_COMPLETION; + } else { + /* + * As tempting as it might be here to return OPAL_SUCCESS + * here, don't! As of 1/07/2017 the powernv_flash driver in + * Linux will handle OPAL_SUCCESS as an error, the only thing + * that makes it handle things as though they're working is + * receiving OPAL_ASYNC_COMPLETION. + * + * XXX TODO: Revisit this in a few years *sigh* + */ + opal_queue_msg(OPAL_MSG_ASYNC_COMP, NULL, NULL, flash->async.token, rc); + } + rc = OPAL_ASYNC_COMPLETION; +out: flash_release(flash); return rc; } diff --git a/core/timer.c b/core/timer.c index 5cf9069..53b6616 100644 --- a/core/timer.c +++ b/core/timer.c @@ -210,6 +210,7 @@ static void __check_poll_timers(uint64_t now) static void __check_timers(uint64_t now) { struct timer *t; + uint64_t stop = now + msecs_to_tb(50); /* Run timers for max 5ms */ for (;;) { t = list_top(&timer_list, struct timer, link); @@ -240,6 +241,13 @@ static void __check_timers(uint64_t now) /* Update time stamp */ now = mftb(); + + /* Only run timers for a limited time to avoid jitter */ + if (now > stop) { + prlog(PR_TRACE, "Run timers for > 50ms total elapsed time=%lu\n", + tb_to_msecs(now - stop)+50); + break; + } } } From patchwork Mon Jan 6 19:21:40 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218443 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5rt4dV3z9sNH for ; Tue, 7 Jan 2020 06:57:34 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5rt2mCkzDqH5 for ; Tue, 7 Jan 2020 06:57:34 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.158.5; helo=mx0b-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0b-001b2d01.pphosted.com (mx0b-001b2d01.pphosted.com [148.163.158.5]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5l86WM8zDqG0 for ; Tue, 7 Jan 2020 06:52:36 +1100 (AEDT) Received: from pps.filterd (m0127361.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqEKx080512 for ; Mon, 6 Jan 2020 14:52:34 -0500 Received: from ppma04dal.us.ibm.com (7a.29.35a9.ip4.static.sl-reverse.com [169.53.41.122]) by mx0a-001b2d01.pphosted.com with ESMTP id 2xapd5k12u-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:34 -0500 Received: from pps.filterd (ppma04dal.us.ibm.com [127.0.0.1]) by ppma04dal.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006JpP4f030746 for ; Mon, 6 Jan 2020 19:52:33 GMT Received: from b01cxnp23032.gho.pok.ibm.com (b01cxnp23032.gho.pok.ibm.com [9.57.198.27]) by ppma04dal.us.ibm.com with ESMTP id 2xajb6a1gx-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:33 +0000 Received: from b01ledav004.gho.pok.ibm.com (b01ledav004.gho.pok.ibm.com [9.57.199.109]) by b01cxnp23032.gho.pok.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqWUs10224044 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 6 Jan 2020 19:52:32 GMT Received: from b01ledav004.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 1C336112067 for ; Mon, 6 Jan 2020 19:52:32 +0000 (GMT) Received: from b01ledav004.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id EF1E1112064 for ; Mon, 6 Jan 2020 19:52:31 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b01ledav004.gho.pok.ibm.com (Postfix) with ESMTP for ; Mon, 6 Jan 2020 19:52:31 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 2A785AE0504; Mon, 6 Jan 2020 13:22:37 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:40 -0600 Message-Id: <1578338508-13424-6-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 impostorscore=0 malwarescore=0 clxscore=1015 suspectscore=1 adultscore=0 phishscore=0 priorityscore=1501 bulkscore=0 mlxlogscore=783 mlxscore=0 spamscore=0 lowpriorityscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 05/13] qemu: 1ms heartbeat time X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" From: Stewart Smith Signed-off-by: Stewart Smith --- platforms/qemu/qemu.c | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/platforms/qemu/qemu.c b/platforms/qemu/qemu.c index cbd6c27..8f7d942 100644 --- a/platforms/qemu/qemu.c +++ b/platforms/qemu/qemu.c @@ -75,6 +75,14 @@ static bool qemu_probe_powernv10(void) return qemu_probe_common("qemu,powernv10"); } +static int qemu_heartbeat_time(void) +{ + /* + * Fast polling to make up for lack of SBE timers + */ + return 1; +} + static void qemu_init(void) { if (!bt_device_present) { @@ -94,6 +102,7 @@ DECLARE_PLATFORM(qemu) = { .pci_get_slot_info = slot_table_get_slot_info, .start_preload_resource = flash_start_preload_resource, .resource_loaded = flash_resource_loaded, + .heartbeat_time = qemu_heartbeat_time, .terminate = ipmi_terminate, }; From patchwork Mon Jan 6 19:21:41 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218444 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [203.11.71.2]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5sB2y1pz9sNH for ; Tue, 7 Jan 2020 06:57:50 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5sB1ZT0zDqHb for ; Tue, 7 Jan 2020 06:57:50 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.158.5; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0b-001b2d01.pphosted.com [148.163.158.5]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5l86bW4zDqG1 for ; Tue, 7 Jan 2020 06:52:36 +1100 (AEDT) Received: from pps.filterd (m0098416.ppops.net [127.0.0.1]) by mx0b-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqUI7068233 for ; Mon, 6 Jan 2020 14:52:34 -0500 Received: from ppma04dal.us.ibm.com (7a.29.35a9.ip4.static.sl-reverse.com [169.53.41.122]) by mx0b-001b2d01.pphosted.com with ESMTP id 2xb8wx65kc-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:33 -0500 Received: from pps.filterd (ppma04dal.us.ibm.com [127.0.0.1]) by ppma04dal.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006JpP4g030746 for ; Mon, 6 Jan 2020 19:52:33 GMT Received: from b01cxnp22036.gho.pok.ibm.com (b01cxnp22036.gho.pok.ibm.com [9.57.198.26]) by ppma04dal.us.ibm.com with ESMTP id 2xajb6a1gw-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:33 +0000 Received: from b01ledav002.gho.pok.ibm.com (b01ledav002.gho.pok.ibm.com [9.57.199.107]) by b01cxnp22036.gho.pok.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqWxh12845940 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 6 Jan 2020 19:52:32 GMT Received: from b01ledav002.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 00A9F124053 for ; Mon, 6 Jan 2020 19:52:32 +0000 (GMT) Received: from b01ledav002.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id B7692124052 for ; Mon, 6 Jan 2020 19:52:31 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b01ledav002.gho.pok.ibm.com (Postfix) with ESMTP for ; Mon, 6 Jan 2020 19:52:31 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 2304DAE09A7; Mon, 6 Jan 2020 13:22:38 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:41 -0600 Message-Id: <1578338508-13424-7-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 malwarescore=0 suspectscore=4 phishscore=0 adultscore=0 priorityscore=1501 impostorscore=0 mlxlogscore=999 lowpriorityscore=0 bulkscore=0 mlxscore=0 clxscore=1015 spamscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 06/13] hiomap: Enable Async IPMI messaging X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" To provide higher layer async operations to access the target flash, enable hiomap to perform async ipmi messaging for call paths thru opal_flash_op. Special considerations and constraints are to prevent recursive locking and/or polling inside OPAL calls. Objective is to remove the hiomap_queue_msg_sync for moving windows (which already uses pollers) to allow async requests to perform their functions. Call paths thru opal_flash_op will determine if the requested operation needs to be re-queued, to allow skiboot to jump back out to Linux to prevent RCU or scheduler issues. For example, if a flash window move operation is needed to erase a very large flash segment, the time spent in opal firmware would be long enough that Linux would stall. To avoid the long running duration of various aspects of this inherent long running operation we divide up the tasks in smaller chunks to avoid cumulating time spent in opal firmware. The return codes are used to distinguish differences between cases where a re-queue of the transaction would be needed versus a true failure return code. PR_TRACE used since PR_DEBUG seems to always trigger, unable to figure out why. Due to the nature of redefining the sync versus async capabilities, this patch is larger than desired due to interrelationships of changes to functionality. Signed-off-by: Deb McLemore --- core/flash.c | 159 +++++++- libflash/blocklevel.h | 2 + libflash/errors.h | 1 + libflash/ipmi-hiomap.c | 1010 +++++++++++++++++++++++++++++++++++++----------- libflash/ipmi-hiomap.h | 41 +- 5 files changed, 983 insertions(+), 230 deletions(-) diff --git a/core/flash.c b/core/flash.c index e98c8e0..56b9118 100644 --- a/core/flash.c +++ b/core/flash.c @@ -28,6 +28,18 @@ #include #include +/* + * need to keep this under the BT queue limit + * causes are when ipmi to bmc gets bogged down + * delay allows for congestion to clear + */ +#define FLASH_RETRY_LIMIT 10 +/* + * schedule delay manages async flash + * transaction work for the block layer + */ +#define FLASH_SCHEDULE_DELAY 200 + enum flash_op { FLASH_OP_READ, FLASH_OP_WRITE, @@ -41,6 +53,9 @@ struct flash_async_info { uint64_t pos; uint64_t len; uint64_t buf; + int retry_counter; + int transaction_id; + int in_progress_schedule_delay; }; struct flash { @@ -80,13 +95,63 @@ static u32 nvram_offset, nvram_size; static bool flash_reserve(struct flash *flash) { bool rc = false; + int lock_try_counter = 10; + uint64_t now; + uint64_t start_time; + uint64_t wait_time; + uint64_t flash_reserve_ticks = 10; + uint64_t timeout_counter; + + start_time = mftb(); + now = mftb(); + wait_time = tb_to_msecs(now - start_time); + timeout_counter = 0; + + + while (wait_time < flash_reserve_ticks) { + ++timeout_counter; + if (timeout_counter % 4 == 0) { + now = mftb(); + wait_time = tb_to_msecs(now - start_time); + } + if (flash->busy == false) { + break; + } + } - if (!try_lock(&flash_lock)) + while (!try_lock(&flash_lock)) { + --lock_try_counter; + if (lock_try_counter == 0) { + break; + } + } + + if (lock_try_counter == 0) { return false; + } + + /* we have the lock if we got here */ if (!flash->busy) { flash->busy = true; rc = true; + } else { + /* probably beat a flash_release and grabbed the lock */ + unlock(&flash_lock); + while (!try_lock(&flash_lock)) { + --lock_try_counter; + if (lock_try_counter == 0) { + break; + } + } + if (lock_try_counter == 0) { + return false; + } + /* we have the lock if we are here */ + if (!flash->busy) { + flash->busy = true; + rc = true; + } } unlock(&flash_lock); @@ -279,12 +344,32 @@ static void flash_poll(struct timer *t __unused, void *data, uint64_t now __unus assert(0); } - if (rc) - rc = OPAL_HARDWARE; + if (rc == 0) { + /* + * if we are good to proceed forward + * otherwise we may have to try again + */ + flash->async.pos += len; + flash->async.buf += len; + flash->async.len -= len; + /* if we good clear */ + flash->async.retry_counter = 0; + /* + * clear the IN_PROGRESS flags + * we only need IN_PROGRESS active on missed_cc + */ + flash->bl->flags &= ~IN_PROGRESS; + /* reset time for scheduling gap */ + flash->async.in_progress_schedule_delay = FLASH_SCHEDULE_DELAY; + } + + /* + * corner cases if the move window misses and + * the chunk straddles the current window we will + * adjust the size down to allow forward progress + * if timing good on move_cb the world is good + */ - flash->async.pos += len; - flash->async.buf += len; - flash->async.len -= len; if (!rc && flash->async.len) { /* * We want to get called pretty much straight away, just have @@ -293,10 +378,36 @@ static void flash_poll(struct timer *t __unused, void *data, uint64_t now __unus */ schedule_timer(&flash->async.poller, 0); return; + } else { + if (rc == FLASH_ERR_ASYNC_WORK) { + ++flash->async.retry_counter; + flash->async.in_progress_schedule_delay += FLASH_SCHEDULE_DELAY; + if (flash->async.retry_counter >= FLASH_RETRY_LIMIT) { + rc = OPAL_HARDWARE; + prlog(PR_TRACE, "flash_poll PROBLEM FLASH_RETRY_LIMIT of %i reached on transaction_id=%i\n", + FLASH_RETRY_LIMIT, + flash->async.transaction_id); + } else { + /* + * give the BT time to work and receive response + * throttle back to allow for congestion to clear + * cases observed were complete lack of ipmi response until very late + * or cases immediately following an unaligned window read/move (so slow) + */ + flash->bl->flags |= IN_PROGRESS; + schedule_timer(&flash->async.poller, msecs_to_tb(flash->async.in_progress_schedule_delay)); + return; + } + } else if (rc != 0) { + rc = OPAL_HARDWARE; + } } - opal_queue_msg(OPAL_MSG_ASYNC_COMP, NULL, NULL, flash->async.token, rc); + flash->bl->flags &= ~IN_PROGRESS; + flash->bl->flags &= ~ASYNC_REQUIRED; + /* release the flash before we allow next opal entry */ flash_release(flash); + opal_queue_msg(OPAL_MSG_ASYNC_COMP, NULL, NULL, flash->async.token, rc); } static struct dt_node *flash_add_dt_node(struct flash *flash, int id) @@ -454,6 +565,7 @@ int flash_register(struct blocklevel_device *bl) flash->size = size; flash->block_size = block_size; flash->id = num_flashes(); + flash->async.transaction_id = 0; init_timer(&flash->async.poller, flash_poll, flash); rc = ffs_init(0, flash->size, bl, &ffs, 1); @@ -487,7 +599,7 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, uint64_t buf, uint64_t size, uint64_t token) { struct flash *flash = NULL; - uint64_t len; + uint64_t len = 0; int rc; list_for_each(&flashes, flash, list) @@ -516,6 +628,10 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, flash->async.buf = buf + len; flash->async.len = size - len; flash->async.pos = offset + len; + flash->async.retry_counter = 0; + flash->async.in_progress_schedule_delay = FLASH_SCHEDULE_DELAY; + flash->bl->flags |= ASYNC_REQUIRED; + ++flash->async.transaction_id; /* * These ops intentionally have no smarts (ecc correction or erase @@ -539,15 +655,34 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, } if (rc) { - prlog(PR_ERR, "%s: Op %d failed with rc %d\n", __func__, op, rc); - rc = OPAL_HARDWARE; + if (rc == FLASH_ERR_ASYNC_WORK) { + ++flash->async.retry_counter; + flash->async.buf = buf; + flash->async.len = size; + flash->async.pos = offset; + /* for completeness, opal_flash_op is first time pass so unless the retry limit set to 1 */ + if (flash->async.retry_counter >= FLASH_RETRY_LIMIT) { + rc = OPAL_HARDWARE; + prlog(PR_TRACE, "opal_flash_op PROBLEM FLASH_RETRY_LIMIT of %i reached on transaction_id=%i\n", + FLASH_RETRY_LIMIT, + flash->async.transaction_id); + goto out; + } + flash->bl->flags |= IN_PROGRESS; + schedule_timer(&flash->async.poller, msecs_to_tb(FLASH_SCHEDULE_DELAY)); + /* Don't release the flash, we need to hold lock to continue transaction */ + return OPAL_ASYNC_COMPLETION; + } else { + prlog(PR_ERR, "%s: Op %d failed with rc %d\n", __func__, op, rc); + rc = OPAL_HARDWARE; + } goto out; } if (size - len) { /* Work remains */ schedule_timer(&flash->async.poller, 0); - /* Don't release the flash */ + /* Don't release the flash, we need to hold lock to continue transaction */ return OPAL_ASYNC_COMPLETION; } else { /* @@ -564,6 +699,8 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, rc = OPAL_ASYNC_COMPLETION; out: flash_release(flash); + flash->bl->flags &= ~IN_PROGRESS; + flash->bl->flags &= ~ASYNC_REQUIRED; return rc; } diff --git a/libflash/blocklevel.h b/libflash/blocklevel.h index 492918e..b18c9e1 100644 --- a/libflash/blocklevel.h +++ b/libflash/blocklevel.h @@ -20,6 +20,8 @@ struct blocklevel_range { enum blocklevel_flags { WRITE_NEED_ERASE = 1, + ASYNC_REQUIRED = 4, + IN_PROGRESS = 8, }; /* diff --git a/libflash/errors.h b/libflash/errors.h index c800ada..b7e4bcc 100644 --- a/libflash/errors.h +++ b/libflash/errors.h @@ -21,6 +21,7 @@ #define FLASH_ERR_BAD_READ 15 #define FLASH_ERR_DEVICE_GONE 16 #define FLASH_ERR_AGAIN 17 +#define FLASH_ERR_ASYNC_WORK 18 #ifdef __SKIBOOT__ #include diff --git a/libflash/ipmi-hiomap.c b/libflash/ipmi-hiomap.c index 0328101..2e288b3 100644 --- a/libflash/ipmi-hiomap.c +++ b/libflash/ipmi-hiomap.c @@ -11,6 +11,10 @@ #include #include #include +#include +#include +#include +#include #include @@ -24,7 +28,7 @@ struct ipmi_hiomap_result { int16_t cc; }; -#define RESULT_INIT(_name, _ctx) struct ipmi_hiomap_result _name = { _ctx, -1 } +static struct hiomap_v2_create_window *window_parms; static inline uint32_t blocks_to_bytes(struct ipmi_hiomap *ctx, uint16_t blocks) { @@ -62,9 +66,23 @@ static int hiomap_protocol_ready(struct ipmi_hiomap *ctx) return 0; } -static int hiomap_queue_msg_sync(struct ipmi_hiomap *ctx, struct ipmi_msg *msg) +static int hiomap_queue_msg(struct ipmi_hiomap *ctx, struct ipmi_msg *msg) { int rc; + int bl_flags; + + lock(&ctx->lock); + bl_flags = ctx->bl.flags; + unlock(&ctx->lock); + + /* + * during boot caution to stay duration within skiboot + * no exit re-entry due to poller conflicts with synchronous window moves + * asynchronous usage intended for opal_flash_op and flash_poll paths + * this comment mostly for awareness that during boot any future + * modifications for transition from booting (sync) to async ops + * available need to make sure to take proper care + */ /* * There's an unavoidable TOCTOU race here with the BMC sending an @@ -73,17 +91,23 @@ static int hiomap_queue_msg_sync(struct ipmi_hiomap *ctx, struct ipmi_msg *msg) * hiomap_queue_msg_sync() exists to capture the race in a single * location. */ - lock(&ctx->lock); - rc = hiomap_protocol_ready(ctx); - unlock(&ctx->lock); - if (rc) { - ipmi_free_msg(msg); - return rc; - } - ipmi_queue_msg_sync(msg); + if ((opal_booting()) || (!(bl_flags & ASYNC_REQUIRED))) { + lock(&ctx->lock); + rc = hiomap_protocol_ready(ctx); + unlock(&ctx->lock); + if (rc) { + ipmi_free_msg(msg); + return rc; + } + prlog(PR_TRACE, "%s SENDING SYNC\n", __func__); + ipmi_queue_msg_sync(msg); + } else { + prlog(PR_TRACE, "%s SENDING ASYNC\n", __func__); + rc = ipmi_queue_msg(msg); + } - return 0; + return rc; } /* Call under ctx->lock */ @@ -100,12 +124,192 @@ static int hiomap_window_valid(struct ipmi_hiomap *ctx, uint64_t pos, return FLASH_ERR_PARM_ERROR; if (pos < ctx->current.cur_pos) return FLASH_ERR_PARM_ERROR; - if ((pos + len) > (ctx->current.cur_pos + ctx->current.size)) - return FLASH_ERR_PARM_ERROR; + if ((pos + len) > (ctx->current.cur_pos + ctx->current.size)) { + /* + * we will compensate the proper values in the caller + * which manages the transaction due to chunk size that + * may be straddling the current window so store values + */ + if ((pos + ctx->current.size) <= (ctx->current.cur_pos + ctx->current.size)) { + prlog(PR_TRACE, "%s OK pos=%llu " + "ctx->current.size=0x%x " + "ctx->current.cur_pos=0x%x\n", + __func__, + pos, + ctx->current.size, + ctx->current.cur_pos); + } else { + prlog(PR_TRACE, "%s CHECKING further pos=%llu " + "for len=%llu ctx->current.size=0x%x " + "ctx->current.cur_pos=0x%x\n", + __func__, + pos, + len, + ctx->current.size, + ctx->current.cur_pos); + if ((pos + ctx->current.adjusted_window_size) <= (ctx->current.cur_pos + ctx->current.size)) { + prlog(PR_TRACE, "%s OK use ADJUSTED pos=%llu " + "adjusted_len=%i for len=%llu " + "ctx->current.size=0x%x " + "ctx->current.cur_pos=0x%x\n", + __func__, + pos, + ctx->current.adjusted_window_size, + len, + ctx->current.size, + ctx->current.cur_pos); + } else { + prlog(PR_TRACE, "%s we need to MOVE the window\n", __func__); + return FLASH_ERR_PARM_ERROR; + } + } + } + prlog(PR_TRACE, "%s ALL GOOD, no move needed\n", __func__); return 0; } +static void move_cb(struct ipmi_msg *msg) +{ + /* + * we leave the move_cb outside of the ipmi_hiomap_cmd_cb + * based on the command we need to special close the window + * async request may take minutes + */ + + struct ipmi_hiomap_result *res = msg->user_data; + struct ipmi_hiomap *ctx = res->ctx; + /* + * only a few iterations to try for lock + * contention is probably hiomap_window_move trying to setup again + */ + int lock_try_counter = 10; + + if ((msg->resp_size != 8) || (msg->cc != IPMI_CC_NO_ERROR) || (msg->data[1] != ctx->inflight_seq)) { + prlog(PR_TRACE, "Command %u (4=READ 6=WRITE): move_cb " + "Unexpected results to check: response size we " + "expect 8 but received %u, ipmi cc=%d " + "(should be zero), expected ipmi seq %i but got " + "wrong ipmi seq %i\n", + msg->data[0], + msg->resp_size, + msg->cc, + ctx->inflight_seq, + msg->data[1]); + lock(&ctx->lock); + ctx->cc = OPAL_HARDWARE; + ctx->window_state = closed_window; + goto out; + } else { + prlog(PR_TRACE, "Entered %s for %s window from " + "OLD block pos 0x%x for 0x%x bytes at " + "lpc_addr 0x%x ipmi seq=%i\n", + __func__, + (msg->data[0] == HIOMAP_C_CREATE_READ_WINDOW) ? "read" : "write", + ctx->current.cur_pos, + ctx->current.size, + ctx->current.lpc_addr, + ctx->inflight_seq); + } + + window_parms = (struct hiomap_v2_create_window *)&msg->data[2]; + + /* + * due to optimization issues the following logic + * allows the execution of the logic "x" times + */ + while (!try_lock(&ctx->lock)) { + --lock_try_counter; + if (lock_try_counter == 0) { + break; + } + } + if (lock_try_counter == 0) { + /* + * we cannot get the lock, but update anyway + * because we cannot communicate this completion + * and someone will need to retry + * contention usually with handle_events or window_move + * this code path is the critical path that will open the window + */ + ctx->window_state = closed_window; + ctx->cc = OPAL_PARAMETER; + goto out2; + } + + /* If here, we got the lock, cc consumed higher up so need in ctx */ + + ctx->cc = IPMI_CC_NO_ERROR; + ctx->current.lpc_addr = + blocks_to_bytes(ctx, le16_to_cpu(window_parms->lpc_addr)); + ctx->current.size = + blocks_to_bytes(ctx, le16_to_cpu(window_parms->size)); + ctx->current.cur_pos = + blocks_to_bytes(ctx, le16_to_cpu(window_parms->offset)); + /* refresh to current */ + ctx->current.adjusted_window_size = ctx->current.size; + + /* + * now that we have moved stuff the values + * we may need to compensate the proper values in the caller + * which manages the transaction due to chunk size that + * may be straddling the current window so store values + */ + *ctx->active_size = ctx->requested_len; + + /* + * Is length past the end of the window? + * if this condition happens it can cause the async.retry_counter to fail + */ + if ((ctx->requested_pos + ctx->requested_len) > (ctx->current.cur_pos + ctx->current.size)) { + /* + * Adjust size to meet current window + * active_size goes back to caller, + * but caller may expire and we need to store for future use + */ + *ctx->active_size = (ctx->current.cur_pos + ctx->current.size) - ctx->requested_pos; + ctx->current.adjusted_window_size = (ctx->current.cur_pos + ctx->current.size) - ctx->requested_pos; + prlog(PR_TRACE, "%s VALID MOVE ADJUSTMENT " + "*ctx->active_size=%llu " + "ctx->requested_pos=%llu " + "ctx->current.adjusted_window_size=%i\n", + __func__, + *ctx->active_size, + ctx->requested_pos, + ctx->current.adjusted_window_size); + } + + if (ctx->requested_len != 0 && *ctx->active_size == 0) { + prlog(PR_NOTICE, "%s Invalid window properties: len: %llu, size: %llu\n", + __func__, ctx->requested_len, *ctx->active_size); + ctx->cc = OPAL_PARAMETER; + ctx->window_state = closed_window; + goto out; + } + + if (msg->data[0] == HIOMAP_C_CREATE_READ_WINDOW) + ctx->window_state = read_window; + else + ctx->window_state = write_window; + + prlog(PR_TRACE, "Opened %s window to NEW block pos 0x%x for 0x%x bytes " + "at lpc_addr 0x%x ipmi seq=%i active size=%llu " + "adjusted_window_size=%i\n", + (msg->data[0] == HIOMAP_C_CREATE_READ_WINDOW) ? "read" : "write", + ctx->current.cur_pos, + ctx->current.size, + ctx->current.lpc_addr, + ctx->inflight_seq, + *ctx->active_size, + ctx->current.adjusted_window_size); + +out: prlog(PR_TRACE, "Exiting the move window callback " + "transaction ipmi seq=%i\n", + ctx->inflight_seq); + unlock(&ctx->lock); +out2: ipmi_free_msg(msg); +} + static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) { struct ipmi_hiomap_result *res = msg->user_data; @@ -125,9 +329,9 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) return; } - if (msg->data[1] != ctx->seq) { + if (msg->data[1] != ctx->inflight_seq) { prerror("Unmatched sequence number: wanted %u got %u\n", - ctx->seq, msg->data[1]); + ctx->inflight_seq, msg->data[1]); res->cc = IPMI_ERR_UNSPECIFIED; ipmi_free_msg(msg); return; @@ -138,6 +342,7 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) { struct hiomap_v2_info *parms; + ctx->cc = IPMI_CC_NO_ERROR; if (msg->resp_size != 6) { prerror("%u: Unexpected response size: %u\n", msg->data[0], msg->resp_size); @@ -162,6 +367,7 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) { struct hiomap_v2_flash_info *parms; + ctx->cc = IPMI_CC_NO_ERROR; if (msg->resp_size != 6) { prerror("%u: Unexpected response size: %u\n", msg->data[0], msg->resp_size); @@ -176,36 +382,6 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) blocks_to_bytes(ctx, le16_to_cpu(parms->erase_granule)); break; } - case HIOMAP_C_CREATE_READ_WINDOW: - case HIOMAP_C_CREATE_WRITE_WINDOW: - { - struct hiomap_v2_create_window *parms; - - if (msg->resp_size != 8) { - prerror("%u: Unexpected response size: %u\n", msg->data[0], - msg->resp_size); - res->cc = IPMI_ERR_UNSPECIFIED; - break; - } - - parms = (struct hiomap_v2_create_window *)&msg->data[2]; - - ctx->current.lpc_addr = - blocks_to_bytes(ctx, le16_to_cpu(parms->lpc_addr)); - ctx->current.size = - blocks_to_bytes(ctx, le16_to_cpu(parms->size)); - ctx->current.cur_pos = - blocks_to_bytes(ctx, le16_to_cpu(parms->offset)); - - lock(&ctx->lock); - if (msg->data[0] == HIOMAP_C_CREATE_READ_WINDOW) - ctx->window_state = read_window; - else - ctx->window_state = write_window; - unlock(&ctx->lock); - - break; - } case HIOMAP_C_MARK_DIRTY: case HIOMAP_C_FLUSH: case HIOMAP_C_ACK: @@ -215,7 +391,15 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) prerror("%u: Unexpected response size: %u\n", msg->data[0], msg->resp_size); res->cc = IPMI_ERR_UNSPECIFIED; + ctx->cc = OPAL_HARDWARE; break; + } else { + prlog(PR_TRACE, "%s Command=%u 1=RESET 7=DIRTY 8=FLUSH 9=ACK 10=ERASE ipmi seq=%u ctx->inflight_seq=%u\n", + __func__, + msg->data[0], + msg->data[1], + ctx->inflight_seq); + ctx->cc = IPMI_CC_NO_ERROR; } break; default: @@ -237,57 +421,191 @@ static void hiomap_init(struct ipmi_hiomap *ctx) unlock(&ctx->lock); } +static int hiomap_wait_for_cc(struct ipmi_hiomap *ctx, int *cc, uint8_t *seq, uint64_t ticks) +{ + uint64_t now; + uint64_t start_time; + uint64_t wait_time; + uint64_t ipmi_hiomap_ticks; + uint64_t timeout_counter; + int rc; + + prlog(PR_TRACE, "Start wait for cc ipmi seq=%i *cc=%i ticks=%llu\n", *seq, *cc, ticks); + rc = 0; + if (this_cpu()->tb_invalid) { + /* + * SYNC paths already have *cc success + * ASYNC will RE-QUEUE and retry + * we just need to skip the tb logic handling + * we need to close the window to have the logic try the move again + */ + if (*cc != IPMI_CC_NO_ERROR) { + lock(&ctx->lock); + ctx->window_state = closed_window; + ++ctx->missed_cc_count; + prlog(PR_NOTICE, "%s tb_invalid, CLOSING WINDOW for cc " + "ipmi seq=%i ctx->missed_cc_count=%i\n", + __func__, *seq, ctx->missed_cc_count); + unlock(&ctx->lock); + rc = FLASH_ERR_ASYNC_WORK; + } + prlog(PR_NOTICE, "%s tb_invalid, hopefully this will " + "retry/recover rc=%i\n", + __func__, rc); + return rc; + } + start_time = mftb(); + now = mftb(); + wait_time = tb_to_msecs(now - start_time); + timeout_counter = 0; + + if (ticks != 0) { + ipmi_hiomap_ticks = ticks; + } else { + ipmi_hiomap_ticks = IPMI_HIOMAP_TICKS; + } + + prlog(PR_TRACE, "wait_time=%llu ipmi_hiomap_ticks=%llu ipmi seq=%i " + "ctx->missed_cc_count=%i\n", + wait_time, ticks, *seq, ctx->missed_cc_count); + /* + * due to optimization issues the following logic + * allows the execution of the logic "x" times + */ + while (wait_time < ipmi_hiomap_ticks) { + ++timeout_counter; + if (timeout_counter % IPMI_SKIP_INC == 0) { + now = mftb(); + wait_time = tb_to_msecs(now - start_time); + } + if (*cc == IPMI_CC_NO_ERROR) { + prlog(PR_TRACE, "Break cc ipmi seq=%i " + "ctx->missed_cc_count=%i\n", + *seq, ctx->missed_cc_count); + break; + } + } + prlog(PR_TRACE, "Status CHECK wait_for_cc wait_time=%llu *cc=%i " + "ipmi seq=%i ctx->missed_cc_count=%i\n", + wait_time, *cc, *seq, ctx->missed_cc_count); + if (*cc != IPMI_CC_NO_ERROR) { + lock(&ctx->lock); + ctx->window_state = closed_window; + ++ctx->missed_cc_count; + prlog(PR_TRACE, "CLOSING WINDOW for cc ipmi seq=%i " + "ctx->missed_cc_count=%i\n", + *seq, ctx->missed_cc_count); + unlock(&ctx->lock); + rc = FLASH_ERR_ASYNC_WORK; + } + + prlog(PR_TRACE, "Stop wait for *cc=%i ipmi seq=%i " + "ctx->missed_cc_count=%i\n", + *cc, *seq, ctx->missed_cc_count); + return rc; + +} + static int hiomap_get_info(struct ipmi_hiomap *ctx) { - RESULT_INIT(res, ctx); + static struct ipmi_hiomap_result info_res; unsigned char req[3]; struct ipmi_msg *msg; + uint8_t info_seq; + int orig_flags; + int tmp_sync_flags; int rc; + info_res.ctx = ctx; + info_res.cc = -1; + + lock(&ctx->lock); + orig_flags = ctx->bl.flags; + /* + * clear out async to always do sync + * we may be doing this under ASYNC_REQUIRED + * so we need to temporarily undo + */ + tmp_sync_flags = ctx->bl.flags &= ~ASYNC_REQUIRED; + ctx->bl.flags = tmp_sync_flags; + ctx->cc = -1; + info_seq = ++ctx->seq; + ctx->inflight_seq = info_seq; + unlock(&ctx->lock); + /* Negotiate protocol version 2 */ req[0] = HIOMAP_C_GET_INFO; - req[1] = ++ctx->seq; + req[1] = info_seq; req[2] = HIOMAP_V2; msg = ipmi_mkmsg(IPMI_DEFAULT_INTERFACE, bmc_platform->sw->ipmi_oem_hiomap_cmd, - ipmi_hiomap_cmd_cb, &res, req, sizeof(req), 6); + ipmi_hiomap_cmd_cb, &info_res, req, sizeof(req), 6); - rc = hiomap_queue_msg_sync(ctx, msg); + rc = hiomap_queue_msg(ctx, msg); + lock(&ctx->lock); + ctx->bl.flags = orig_flags; + unlock(&ctx->lock); if (rc) return rc; - if (res.cc != IPMI_CC_NO_ERROR) { - prerror("%s failed: %d\n", __func__, res.cc); - return FLASH_ERR_PARM_ERROR; /* XXX: Find something better? */ + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_ACK_DEFAULT); + + if (rc) { + prlog(PR_TRACE, "%s hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_ACK_DEFAULT); } - return 0; + return rc; } static int hiomap_get_flash_info(struct ipmi_hiomap *ctx) { - RESULT_INIT(res, ctx); + static struct ipmi_hiomap_result flash_info_res; unsigned char req[2]; struct ipmi_msg *msg; + uint8_t flash_info_seq; + int orig_flags; + int tmp_sync_flags; int rc; + flash_info_res.ctx = ctx; + flash_info_res.cc = -1; + + lock(&ctx->lock); + orig_flags = ctx->bl.flags; + /* + * clear out async to always do sync + * we may be doing this under ASYNC_REQUIRED + * so we need to temporarily undo + */ + tmp_sync_flags = ctx->bl.flags &= ~ASYNC_REQUIRED; + ctx->bl.flags = tmp_sync_flags; + ctx->cc = -1; + flash_info_seq = ++ctx->seq; + ctx->inflight_seq = flash_info_seq; + unlock(&ctx->lock); + req[0] = HIOMAP_C_GET_FLASH_INFO; - req[1] = ++ctx->seq; + req[1] = flash_info_seq; msg = ipmi_mkmsg(IPMI_DEFAULT_INTERFACE, bmc_platform->sw->ipmi_oem_hiomap_cmd, - ipmi_hiomap_cmd_cb, &res, req, sizeof(req), 2 + 2 + 2); + ipmi_hiomap_cmd_cb, &flash_info_res, req, sizeof(req), 2 + 2 + 2); - rc = hiomap_queue_msg_sync(ctx, msg); + rc = hiomap_queue_msg(ctx, msg); + lock(&ctx->lock); + ctx->bl.flags = orig_flags; + unlock(&ctx->lock); if (rc) return rc; - if (res.cc != IPMI_CC_NO_ERROR) { - prerror("%s failed: %d\n", __func__, res.cc); - return FLASH_ERR_PARM_ERROR; /* XXX: Find something better? */ + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_ACK_DEFAULT); + if (rc) { + prlog(PR_TRACE, "%s hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_ACK_DEFAULT); } - return 0; + return rc; } static int hiomap_window_move(struct ipmi_hiomap *ctx, uint8_t command, @@ -295,32 +613,65 @@ static int hiomap_window_move(struct ipmi_hiomap *ctx, uint8_t command, { enum lpc_window_state want_state; struct hiomap_v2_range *range; - RESULT_INIT(res, ctx); + static struct ipmi_hiomap_result move_res; unsigned char req[6]; struct ipmi_msg *msg; + uint8_t move_seq; bool valid_state; bool is_read; int rc; + move_res.ctx = ctx; + move_res.cc = -1; is_read = (command == HIOMAP_C_CREATE_READ_WINDOW); want_state = is_read ? read_window : write_window; + /* there will be lock contention between hiomap_window_move and move_cb */ + lock(&ctx->lock); + ctx->cc = -1; + + if (ctx->bl.flags & IN_PROGRESS) { + pos = ctx->tracking_pos; + len = ctx->tracking_len; + } else { + ctx->tracking_pos = pos; + ctx->tracking_len = len; + } valid_state = want_state == ctx->window_state; rc = hiomap_window_valid(ctx, pos, len); + if (valid_state && !rc) { + /* if its valid stuff the proper maybe modified size */ + if ((pos + len) > (ctx->current.cur_pos + ctx->current.size)) { + /* if we had bumped the adjusted_window_size down in move_cb */ + if ((ctx->current.adjusted_window_size != ctx->current.size)) { + *size = ctx->current.adjusted_window_size; + } else { + *size = (ctx->current.cur_pos + ctx->current.size) - pos; + } + } else { + *size = len; + } + ctx->cc = IPMI_CC_NO_ERROR; unlock(&ctx->lock); - *size = len; return 0; } - ctx->window_state = closed_window; + ctx->window_state = moving_window; - unlock(&ctx->lock); + ctx->active_size = size; + ctx->requested_pos = pos; + ctx->requested_len = len; + + move_seq = ++ctx->seq; + ctx->inflight_seq = move_seq; req[0] = command; - req[1] = ++ctx->seq; + req[1] = move_seq; + + unlock(&ctx->lock); range = (struct hiomap_v2_range *)&req[2]; range->offset = cpu_to_le16(bytes_to_blocks(ctx, pos)); @@ -328,38 +679,14 @@ static int hiomap_window_move(struct ipmi_hiomap *ctx, uint8_t command, msg = ipmi_mkmsg(IPMI_DEFAULT_INTERFACE, bmc_platform->sw->ipmi_oem_hiomap_cmd, - ipmi_hiomap_cmd_cb, &res, req, sizeof(req), + move_cb, &move_res, req, sizeof(req), 2 + 2 + 2 + 2); - rc = hiomap_queue_msg_sync(ctx, msg); + rc = hiomap_queue_msg(ctx, msg); + if (rc) return rc; - if (res.cc != IPMI_CC_NO_ERROR) { - prlog(PR_INFO, "%s failed: %d\n", __func__, res.cc); - return FLASH_ERR_PARM_ERROR; /* XXX: Find something better? */ - } - - lock(&ctx->lock); - *size = len; - /* Is length past the end of the window? */ - if ((pos + len) > (ctx->current.cur_pos + ctx->current.size)) - /* Adjust size to meet current window */ - *size = (ctx->current.cur_pos + ctx->current.size) - pos; - - if (len != 0 && *size == 0) { - unlock(&ctx->lock); - prerror("Invalid window properties: len: %"PRIu64", size: %"PRIu64"\n", - len, *size); - return FLASH_ERR_PARM_ERROR; - } - - prlog(PR_DEBUG, "Opened %s window from 0x%x for %u bytes at 0x%x\n", - (command == HIOMAP_C_CREATE_READ_WINDOW) ? "read" : "write", - ctx->current.cur_pos, ctx->current.size, ctx->current.lpc_addr); - - unlock(&ctx->lock); - return 0; } @@ -368,21 +695,27 @@ static int hiomap_mark_dirty(struct ipmi_hiomap *ctx, uint64_t offset, { struct hiomap_v2_range *range; enum lpc_window_state state; - RESULT_INIT(res, ctx); + static struct ipmi_hiomap_result dirty_res; unsigned char req[6]; struct ipmi_msg *msg; + uint8_t dirty_seq; uint32_t pos; int rc; + dirty_res.ctx = ctx; + dirty_res.cc = -1; lock(&ctx->lock); state = ctx->window_state; + dirty_seq = ++ctx->seq; + ctx->inflight_seq = dirty_seq; + ctx->cc = -1; unlock(&ctx->lock); if (state != write_window) return FLASH_ERR_PARM_ERROR; req[0] = HIOMAP_C_MARK_DIRTY; - req[1] = ++ctx->seq; + req[1] = dirty_seq; pos = offset - ctx->current.cur_pos; range = (struct hiomap_v2_range *)&req[2]; @@ -391,19 +724,15 @@ static int hiomap_mark_dirty(struct ipmi_hiomap *ctx, uint64_t offset, msg = ipmi_mkmsg(IPMI_DEFAULT_INTERFACE, bmc_platform->sw->ipmi_oem_hiomap_cmd, - ipmi_hiomap_cmd_cb, &res, req, sizeof(req), 2); + ipmi_hiomap_cmd_cb, &dirty_res, req, sizeof(req), 2); + + rc = hiomap_queue_msg(ctx, msg); - rc = hiomap_queue_msg_sync(ctx, msg); if (rc) return rc; - if (res.cc != IPMI_CC_NO_ERROR) { - prerror("%s failed: %d\n", __func__, res.cc); - return FLASH_ERR_PARM_ERROR; - } - prlog(PR_DEBUG, "Marked flash dirty at 0x%" PRIx64 " for %" PRIu64 "\n", - offset, size); + offset, size); return 0; } @@ -411,34 +740,36 @@ static int hiomap_mark_dirty(struct ipmi_hiomap *ctx, uint64_t offset, static int hiomap_flush(struct ipmi_hiomap *ctx) { enum lpc_window_state state; - RESULT_INIT(res, ctx); + static struct ipmi_hiomap_result flush_res; unsigned char req[2]; struct ipmi_msg *msg; + uint8_t flush_seq; int rc; + flush_res.ctx = ctx; + flush_res.cc = -1; lock(&ctx->lock); state = ctx->window_state; + flush_seq = ++ctx->seq; + ctx->inflight_seq = flush_seq; + ctx->cc = -1; unlock(&ctx->lock); if (state != write_window) return FLASH_ERR_PARM_ERROR; req[0] = HIOMAP_C_FLUSH; - req[1] = ++ctx->seq; + req[1] = flush_seq; msg = ipmi_mkmsg(IPMI_DEFAULT_INTERFACE, bmc_platform->sw->ipmi_oem_hiomap_cmd, - ipmi_hiomap_cmd_cb, &res, req, sizeof(req), 2); + ipmi_hiomap_cmd_cb, &flush_res, req, sizeof(req), 2); + + rc = hiomap_queue_msg(ctx, msg); - rc = hiomap_queue_msg_sync(ctx, msg); if (rc) return rc; - if (res.cc != IPMI_CC_NO_ERROR) { - prerror("%s failed: %d\n", __func__, res.cc); - return FLASH_ERR_PARM_ERROR; - } - prlog(PR_DEBUG, "Flushed writes\n"); return 0; @@ -446,26 +777,51 @@ static int hiomap_flush(struct ipmi_hiomap *ctx) static int hiomap_ack(struct ipmi_hiomap *ctx, uint8_t ack) { - RESULT_INIT(res, ctx); + static struct ipmi_hiomap_result ack_res; unsigned char req[3]; struct ipmi_msg *msg; + uint8_t ack_seq; + int orig_flags; + int tmp_sync_flags; int rc; + ack_res.ctx = ctx; + ack_res.cc = -1; + + lock(&ctx->lock); + orig_flags = ctx->bl.flags; + /* + * clear out async to always do sync + * we may be doing this under ASYNC_REQUIRED + * so we need to temporarily undo + */ + tmp_sync_flags = ctx->bl.flags &= ~ASYNC_REQUIRED; + ctx->bl.flags = tmp_sync_flags; + ctx->cc = -1; + ack_seq = ++ctx->seq; + ctx->inflight_seq = ack_seq; + unlock(&ctx->lock); + req[0] = HIOMAP_C_ACK; - req[1] = ++ctx->seq; + req[1] = ack_seq; req[2] = ack; msg = ipmi_mkmsg(IPMI_DEFAULT_INTERFACE, bmc_platform->sw->ipmi_oem_hiomap_cmd, - ipmi_hiomap_cmd_cb, &res, req, sizeof(req), 2); + ipmi_hiomap_cmd_cb, &ack_res, req, sizeof(req), 2); - rc = hiomap_queue_msg_sync(ctx, msg); + rc = hiomap_queue_msg(ctx, msg); + lock(&ctx->lock); + ctx->bl.flags = orig_flags; + unlock(&ctx->lock); if (rc) return rc; - if (res.cc != IPMI_CC_NO_ERROR) { - prlog(PR_DEBUG, "%s failed: %d\n", __func__, res.cc); - return FLASH_ERR_PARM_ERROR; + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_ACK_DEFAULT); + if (rc) { + prlog(PR_TRACE, "%s hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_ACK_DEFAULT); + return rc; } prlog(PR_DEBUG, "Acked events: 0x%x\n", ack); @@ -478,21 +834,27 @@ static int hiomap_erase(struct ipmi_hiomap *ctx, uint64_t offset, { struct hiomap_v2_range *range; enum lpc_window_state state; - RESULT_INIT(res, ctx); + static struct ipmi_hiomap_result erase_res; unsigned char req[6]; struct ipmi_msg *msg; + uint8_t erase_seq; uint32_t pos; int rc; + erase_res.ctx = ctx; + erase_res.cc = -1; lock(&ctx->lock); state = ctx->window_state; + erase_seq = ++ctx->seq; + ctx->inflight_seq = erase_seq; + ctx->cc = -1; unlock(&ctx->lock); if (state != write_window) return FLASH_ERR_PARM_ERROR; req[0] = HIOMAP_C_ERASE; - req[1] = ++ctx->seq; + req[1] = erase_seq; pos = offset - ctx->current.cur_pos; range = (struct hiomap_v2_range *)&req[2]; @@ -501,16 +863,13 @@ static int hiomap_erase(struct ipmi_hiomap *ctx, uint64_t offset, msg = ipmi_mkmsg(IPMI_DEFAULT_INTERFACE, bmc_platform->sw->ipmi_oem_hiomap_cmd, - ipmi_hiomap_cmd_cb, &res, req, sizeof(req), 2); - rc = hiomap_queue_msg_sync(ctx, msg); + ipmi_hiomap_cmd_cb, &erase_res, req, sizeof(req), 2); + + rc = hiomap_queue_msg(ctx, msg); + if (rc) return rc; - if (res.cc != IPMI_CC_NO_ERROR) { - prerror("%s failed: %d\n", __func__, res.cc); - return FLASH_ERR_PARM_ERROR; - } - prlog(PR_DEBUG, "Erased flash at 0x%" PRIx64 " for %" PRIu64 "\n", offset, size); @@ -519,24 +878,57 @@ static int hiomap_erase(struct ipmi_hiomap *ctx, uint64_t offset, static bool hiomap_reset(struct ipmi_hiomap *ctx) { - RESULT_INIT(res, ctx); + static struct ipmi_hiomap_result reset_res; unsigned char req[2]; struct ipmi_msg *msg; + uint8_t reset_seq; + int orig_flags; + int tmp_sync_flags; + int rc; + + prlog(PR_NOTICE, "%s Reset ENTRY\n", __func__); + reset_res.ctx = ctx; + reset_res.cc = -1; - prlog(PR_NOTICE, "Reset\n"); + lock(&ctx->lock); + orig_flags = ctx->bl.flags; + /* + * clear out async to always do sync + * we may be doing this under ASYNC_REQUIRED + * so we need to temporarily undo + */ + tmp_sync_flags = ctx->bl.flags &= ~ASYNC_REQUIRED; + ctx->bl.flags = tmp_sync_flags; + reset_seq = ++ctx->seq; + ctx->cc = -1; + ctx->inflight_seq = reset_seq; + unlock(&ctx->lock); req[0] = HIOMAP_C_RESET; - req[1] = ++ctx->seq; + req[1] = reset_seq; msg = ipmi_mkmsg(IPMI_DEFAULT_INTERFACE, bmc_platform->sw->ipmi_oem_hiomap_cmd, - ipmi_hiomap_cmd_cb, &res, req, sizeof(req), 2); - ipmi_queue_msg_sync(msg); + ipmi_hiomap_cmd_cb, &reset_res, req, sizeof(req), 2); + + rc = hiomap_queue_msg(ctx, msg); + lock(&ctx->lock); + ctx->bl.flags = orig_flags; + unlock(&ctx->lock); + + if (rc) { + prlog(PR_NOTICE, "%s reset queue msg failed: rc=%d\n", __func__, rc); + return false; + } + + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_ACK_DEFAULT); - if (res.cc != IPMI_CC_NO_ERROR) { - prlog(PR_ERR, "%s failed: %d\n", __func__, res.cc); + if (rc) { + prlog(PR_NOTICE, "%s hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_ACK_DEFAULT); return false; } + prlog(PR_NOTICE, "%s Reset EXIT\n", __func__); return true; } @@ -666,6 +1058,7 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx) * Therefore it is enough to mark the window as closed to consider it * recovered. */ + if (status & (HIOMAP_E_PROTOCOL_RESET | HIOMAP_E_WINDOW_RESET)) ctx->window_state = closed_window; @@ -737,8 +1130,9 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos, void *buf, uint64_t len) { struct ipmi_hiomap *ctx; - uint64_t size; - int rc = 0; + enum lpc_window_state state; + static uint64_t size; + int rc; /* LPC is only 32bit */ if (pos > UINT_MAX || len > UINT_MAX) @@ -746,97 +1140,217 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos, ctx = container_of(bl, struct ipmi_hiomap, bl); + lock(&ctx->transaction_lock); + rc = ipmi_hiomap_handle_events(ctx); if (rc) - return rc; + goto out; + + lock(&ctx->lock); + if (ctx->bl.flags & IN_PROGRESS) { + buf = ctx->tracking_buf; + pos = ctx->tracking_pos; + len = ctx->tracking_len; + } else { + ctx->tracking_buf = buf; + ctx->tracking_pos = 0; + ctx->tracking_len = 0; + } + unlock(&ctx->lock); prlog(PR_TRACE, "Flash read at %#" PRIx64 " for %#" PRIx64 "\n", pos, len); while (len > 0) { - /* Move window and get a new size to read */ - rc = hiomap_window_move(ctx, HIOMAP_C_CREATE_READ_WINDOW, pos, - len, &size); - if (rc) - return rc; - - /* Perform the read for this window */ - rc = lpc_window_read(ctx, pos, buf, size); - if (rc) - return rc; - - /* Check we can trust what we read */ lock(&ctx->lock); - rc = hiomap_window_valid(ctx, pos, size); + state = ctx->window_state; unlock(&ctx->lock); - if (rc) - return rc; + if (state != moving_window) { + /* Move window and get a new size to read */ + rc = hiomap_window_move(ctx, HIOMAP_C_CREATE_READ_WINDOW, pos, + len, &size); + if (rc) { + prlog(PR_NOTICE, "%s hiomap_window_move failed: rc=%d\n", + __func__, rc); + goto out; + } + } else { + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_HIOMAP_TICKS_DEFAULT); + if (rc) { + prlog(PR_TRACE, "%s move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_HIOMAP_TICKS_DEFAULT); + goto out; + } + } - len -= size; - pos += size; - buf += size; + lock(&ctx->lock); + state = ctx->window_state; + unlock(&ctx->lock); + if (state == read_window) { + /* + * don't lock in case move_cb in progress + * if we get here the state is good + * just double-checking + */ + if (ctx->cc != IPMI_CC_NO_ERROR) { + prlog(PR_NOTICE, "%s failed: cc=%d\n", __func__, ctx->cc); + rc = OPAL_HARDWARE; + goto out; + } + /* Perform the read for this window */ + rc = lpc_window_read(ctx, pos, buf, size); + if (rc) { + prlog(PR_NOTICE, "%s lpc_window_read failed: rc=%d\n", __func__, rc); + goto out; + } + + /* Check we can trust what we read */ + lock(&ctx->lock); + rc = hiomap_window_valid(ctx, pos, size); + unlock(&ctx->lock); + if (rc) { + prlog(PR_NOTICE, "%s hiomap_window_valid failed: rc=%d\n", __func__, rc); + goto out; + } + + len -= size; + pos += size; + buf += size; + lock(&ctx->lock); + ctx->tracking_len = len; + ctx->tracking_pos = pos; + ctx->tracking_buf = buf; + unlock(&ctx->lock); + } } - return rc; +out: unlock(&ctx->transaction_lock); + return rc; } static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos, const void *buf, uint64_t len) { struct ipmi_hiomap *ctx; - uint64_t size; - int rc = 0; + enum lpc_window_state state; + static uint64_t size; + int rc; /* LPC is only 32bit */ if (pos > UINT_MAX || len > UINT_MAX) return FLASH_ERR_PARM_ERROR; ctx = container_of(bl, struct ipmi_hiomap, bl); + lock(&ctx->transaction_lock); rc = ipmi_hiomap_handle_events(ctx); if (rc) - return rc; + goto out; + + lock(&ctx->lock); + if (ctx->bl.flags & IN_PROGRESS) { + buf = ctx->tracking_buf; + pos = ctx->tracking_pos; + len = ctx->tracking_len; + } else { + ctx->tracking_buf = (void *) buf; + ctx->tracking_pos = 0; + ctx->tracking_len = 0; + } + unlock(&ctx->lock); prlog(PR_TRACE, "Flash write at %#" PRIx64 " for %#" PRIx64 "\n", pos, len); while (len > 0) { - /* Move window and get a new size to read */ - rc = hiomap_window_move(ctx, HIOMAP_C_CREATE_WRITE_WINDOW, pos, - len, &size); - if (rc) - return rc; - - /* Perform the write for this window */ - rc = lpc_window_write(ctx, pos, buf, size); - if (rc) - return rc; - - /* - * Unlike ipmi_hiomap_read() we don't explicitly test if the - * window is still valid after completing the LPC accesses as - * the following hiomap_mark_dirty() will implicitly check for - * us. In the case of a read operation there's no requirement - * that a command that validates window state follows, so the - * read implementation explicitly performs a check. - */ - - rc = hiomap_mark_dirty(ctx, pos, size); - if (rc) - return rc; + lock(&ctx->lock); + state = ctx->window_state; + unlock(&ctx->lock); + if (state != moving_window) { + /* Move window and get a new size to read */ + rc = hiomap_window_move(ctx, HIOMAP_C_CREATE_WRITE_WINDOW, pos, + len, &size); + if (rc) { + prlog(PR_NOTICE, "%s hiomap_window_move failed: rc=%d\n", + __func__, rc); + goto out; + } + } else { + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); + if (rc) { + prlog(PR_TRACE, "%s move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_LONG_TICKS); + goto out; + } + } - /* - * The BMC *should* flush if the window is implicitly closed, - * but do an explicit flush here to be sure. - * - * XXX: Removing this could improve performance - */ - rc = hiomap_flush(ctx); - if (rc) - return rc; + lock(&ctx->lock); + state = ctx->window_state; + unlock(&ctx->lock); - len -= size; - pos += size; - buf += size; + if (state == write_window) { + if (ctx->cc != IPMI_CC_NO_ERROR) { + prlog(PR_NOTICE, "%s failed: cc=%d\n", __func__, ctx->cc); + rc = OPAL_HARDWARE; + goto out; + } + + /* Perform the write for this window */ + rc = lpc_window_write(ctx, pos, buf, size); + if (rc) { + prlog(PR_NOTICE, "%s lpc_window_write failed: rc=%d\n", __func__, rc); + goto out; + } + + /* + * Unlike ipmi_hiomap_read() we don't explicitly test if the + * window is still valid after completing the LPC accesses as + * the following hiomap_mark_dirty() will implicitly check for + * us. In the case of a read operation there's no requirement + * that a command that validates window state follows, so the + * read implementation explicitly performs a check. + */ + + rc = hiomap_mark_dirty(ctx, pos, size); + if (rc) { + prlog(PR_NOTICE, "%s hiomap_mark_dirty failed: rc=%d\n", __func__, rc); + goto out; + } + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); + if (rc) { + prlog(PR_TRACE, "%s dirty hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_LONG_TICKS); + goto out; + } + + /* + * The BMC *should* flush if the window is implicitly closed, + * but do an explicit flush here to be sure. + * + * XXX: Removing this could improve performance + */ + rc = hiomap_flush(ctx); + if (rc) { + prlog(PR_NOTICE, "%s hiomap_flush failed: rc=%d\n", __func__, rc); + goto out; + } + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); + if (rc) { + prlog(PR_TRACE, "%s flush hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_LONG_TICKS); + goto out; + } + + len -= size; + pos += size; + buf += size; + lock(&ctx->lock); + ctx->tracking_len = len; + ctx->tracking_pos = pos; + ctx->tracking_buf = (void *) buf; + unlock(&ctx->lock); + } } + +out: unlock(&ctx->transaction_lock); return rc; } @@ -844,6 +1358,8 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos, uint64_t len) { struct ipmi_hiomap *ctx; + enum lpc_window_state state; + static uint64_t size; int rc; /* LPC is only 32bit */ @@ -851,39 +1367,94 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos, return FLASH_ERR_PARM_ERROR; ctx = container_of(bl, struct ipmi_hiomap, bl); + lock(&ctx->transaction_lock); rc = ipmi_hiomap_handle_events(ctx); if (rc) - return rc; + goto out; + + lock(&ctx->lock); + if (ctx->bl.flags & IN_PROGRESS) { + pos = ctx->tracking_pos; + len = ctx->tracking_len; + } else { + ctx->tracking_pos = 0; + ctx->tracking_len = 0; + } + unlock(&ctx->lock); prlog(PR_TRACE, "Flash erase at 0x%08x for 0x%08x\n", (u32) pos, (u32) len); while (len > 0) { - uint64_t size; - - /* Move window and get a new size to erase */ - rc = hiomap_window_move(ctx, HIOMAP_C_CREATE_WRITE_WINDOW, pos, - len, &size); - if (rc) - return rc; - - rc = hiomap_erase(ctx, pos, size); - if (rc) - return rc; - - /* - * Flush directly, don't mark that region dirty otherwise it - * isn't clear if a write happened there or not - */ - rc = hiomap_flush(ctx); - if (rc) - return rc; + lock(&ctx->lock); + state = ctx->window_state; + unlock(&ctx->lock); + if (state != moving_window) { + /* Move window and get a new size to erase */ + rc = hiomap_window_move(ctx, HIOMAP_C_CREATE_WRITE_WINDOW, pos, + len, &size); + if (rc) { + prlog(PR_NOTICE, "%s hiomap_window_move failed: rc=%d\n", + __func__, rc); + goto out; + } + } else { + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); + if (rc) { + prlog(PR_TRACE, "%s move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_LONG_TICKS); + goto out; + } + } - len -= size; - pos += size; + lock(&ctx->lock); + state = ctx->window_state; + unlock(&ctx->lock); + if (state == write_window) { + if (ctx->cc != IPMI_CC_NO_ERROR) { + prlog(PR_NOTICE, "%s failed: cc=%d\n", __func__, ctx->cc); + rc = OPAL_HARDWARE; + goto out; + } + rc = hiomap_erase(ctx, pos, size); + if (rc) { + prlog(PR_NOTICE, "%s hiomap_erase failed: rc=%d\n", __func__, rc); + goto out; + } + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); + if (rc) { + prlog(PR_TRACE, "%s move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_LONG_TICKS); + goto out; + } + + /* + * Flush directly, don't mark that region dirty otherwise it + * isn't clear if a write happened there or not + */ + rc = hiomap_flush(ctx); + if (rc) { + prlog(PR_NOTICE, "%s hiomap_flush failed: rc=%d\n", __func__, rc); + goto out; + } + rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); + if (rc) { + prlog(PR_TRACE, "%s move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + __func__, rc, IPMI_LONG_TICKS); + goto out; + } + + len -= size; + pos += size; + lock(&ctx->lock); + ctx->tracking_len = len; + ctx->tracking_pos = pos; + unlock(&ctx->lock); + } } - return 0; +out: unlock(&ctx->transaction_lock); + return rc; } static int ipmi_hiomap_get_flash_info(struct blocklevel_device *bl, @@ -894,6 +1465,7 @@ static int ipmi_hiomap_get_flash_info(struct blocklevel_device *bl, int rc; ctx = container_of(bl, struct ipmi_hiomap, bl); + lock(&ctx->transaction_lock); rc = ipmi_hiomap_handle_events(ctx); if (rc) @@ -912,6 +1484,7 @@ static int ipmi_hiomap_get_flash_info(struct blocklevel_device *bl, if (erase_granule) *erase_granule = ctx->erase_granule; + unlock(&ctx->transaction_lock); return 0; } @@ -934,6 +1507,7 @@ int ipmi_hiomap_init(struct blocklevel_device **bl) return FLASH_ERR_MALLOC_FAILED; init_lock(&ctx->lock); + init_lock(&ctx->transaction_lock); ctx->bl.read = &ipmi_hiomap_read; ctx->bl.write = &ipmi_hiomap_write; diff --git a/libflash/ipmi-hiomap.h b/libflash/ipmi-hiomap.h index 489d55e..21b9112 100644 --- a/libflash/ipmi-hiomap.h +++ b/libflash/ipmi-hiomap.h @@ -10,12 +10,36 @@ #include "blocklevel.h" -enum lpc_window_state { closed_window, read_window, write_window }; +/* + * we basically check for a quick response + * otherwise we catch the updated window in the next cycle + */ +#define IPMI_HIOMAP_TICKS 5 +#define IPMI_HIOMAP_TICKS_DEFAULT 0 + +/* time to wait for write/erase/dirty ops */ +#define IPMI_LONG_TICKS 500 + +/* + * default for ack'ing typically 1-10 wait_time's + * allow upper bounds because if we cannot ack + * we make no forward progress post protocol reset + * async paths will retry + * sync paths always hit with zero wait_time elapsed + * with ASYNC_REQUIRED masked out, this is not used + */ +#define IPMI_ACK_DEFAULT 500 + +/* increment to skip the waiting loop */ +#define IPMI_SKIP_INC 2 + +enum lpc_window_state { closed_window, read_window, write_window, moving_window }; struct lpc_window { uint32_t lpc_addr; /* Offset into LPC space */ uint32_t cur_pos; /* Current position of the window in the flash */ uint32_t size; /* Size of the window into the flash */ + uint32_t adjusted_window_size; /* store adjusted window size */ }; struct ipmi_hiomap { @@ -35,6 +59,21 @@ struct ipmi_hiomap { * three variables are protected by lock to avoid conflict. */ struct lock lock; + struct lock transaction_lock; + + /* callers transaction info */ + uint64_t *active_size; + uint64_t requested_len; + uint64_t requested_pos; + uint64_t tracking_len; + uint64_t tracking_pos; + void *tracking_buf; + + int missed_cc_count; + int cc; + /* inflight_seq used to aide debug */ + /* with other OPAL ipmi msg's */ + uint8_t inflight_seq; uint8_t bmc_state; enum lpc_window_state window_state; }; From patchwork Mon Jan 6 19:21:42 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218449 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [203.11.71.2]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5tf5s4wz9sNH for ; Tue, 7 Jan 2020 06:59:06 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5tf4lPlzDqHJ for ; Tue, 7 Jan 2020 06:59:06 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.156.1; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0a-001b2d01.pphosted.com [148.163.156.1]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5lB3r2mzDqG8 for ; Tue, 7 Jan 2020 06:52:38 +1100 (AEDT) Received: from pps.filterd (m0098396.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqKY9025162 for ; Mon, 6 Jan 2020 14:52:35 -0500 Received: from ppma01dal.us.ibm.com (83.d6.3fa9.ip4.static.sl-reverse.com [169.63.214.131]) by mx0a-001b2d01.pphosted.com with ESMTP id 2xb92mdguj-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:35 -0500 Received: from pps.filterd (ppma01dal.us.ibm.com [127.0.0.1]) by ppma01dal.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006Jo901020937 for ; Mon, 6 Jan 2020 19:52:34 GMT Received: from b01cxnp22035.gho.pok.ibm.com (b01cxnp22035.gho.pok.ibm.com [9.57.198.25]) by ppma01dal.us.ibm.com with ESMTP id 2xajb6a2ft-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:34 +0000 Received: from b01ledav005.gho.pok.ibm.com (b01ledav005.gho.pok.ibm.com [9.57.199.110]) by b01cxnp22035.gho.pok.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqXcv51446210 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 6 Jan 2020 19:52:33 GMT Received: from b01ledav005.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id ADE98AE063 for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from b01ledav005.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 922A2AE05C for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b01ledav005.gho.pok.ibm.com (Postfix) with ESMTP for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 3A683AE0436; Mon, 6 Jan 2020 13:22:39 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:42 -0600 Message-Id: <1578338508-13424-8-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 mlxscore=0 adultscore=0 lowpriorityscore=0 spamscore=0 phishscore=0 priorityscore=1501 impostorscore=0 bulkscore=0 malwarescore=0 mlxlogscore=884 suspectscore=1 clxscore=1015 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 07/13] lpc: Fix lpc probe irqmask handling X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" Properly handle the irqmask from the callers of lpc_probe_prepare and lpc_probe_test. lpc_probe_prepare reads the existing irqmask which is then later used to restore after lpc_probe_test clears the irqmask. Signed-off-by: Deb McLemore --- hw/lpc.c | 27 +++++++++++---------------- 1 file changed, 11 insertions(+), 16 deletions(-) diff --git a/hw/lpc.c b/hw/lpc.c index 354d2b4..fedceb4 100644 --- a/hw/lpc.c +++ b/hw/lpc.c @@ -461,30 +461,28 @@ static const struct lpc_error_entry lpc_error_table[] = { LPC_ERROR(LPC_HC_IRQ_SYNC_ABNORM_ERR, OPAL_WRONG_STATE, "Got SYNC abnormal error."), }; -static int64_t lpc_probe_prepare(struct lpcm *lpc) +static int64_t lpc_probe_prepare(struct lpcm *lpc, uint32_t *irqmask) { const uint32_t irqmask_addr = lpc_reg_opb_base + LPC_HC_IRQMASK; const uint32_t irqstat_addr = lpc_reg_opb_base + LPC_HC_IRQSTAT; - uint32_t irqmask; int rc; - rc = opb_read(lpc, irqmask_addr, &irqmask, 4); + rc = opb_read(lpc, irqmask_addr, irqmask, 4); if (rc) return rc; - irqmask &= ~LPC_HC_IRQ_SYNC_NORESP_ERR; - rc = opb_write(lpc, irqmask_addr, irqmask, 4); + rc = opb_write(lpc, irqmask_addr, 0, 4); if (rc) return rc; return opb_write(lpc, irqstat_addr, LPC_HC_IRQ_SYNC_NORESP_ERR, 4); } -static int64_t lpc_probe_test(struct lpcm *lpc) +static int64_t lpc_probe_test(struct lpcm *lpc, uint32_t irqmask) { const uint32_t irqmask_addr = lpc_reg_opb_base + LPC_HC_IRQMASK; const uint32_t irqstat_addr = lpc_reg_opb_base + LPC_HC_IRQSTAT; - uint32_t irqmask, irqstat; + uint32_t irqstat; int64_t idx; int rc; @@ -496,11 +494,6 @@ static int64_t lpc_probe_test(struct lpcm *lpc) if (rc) return rc; - rc = opb_read(lpc, irqmask_addr, &irqmask, 4); - if (rc) - return rc; - - irqmask |= LPC_HC_IRQ_SYNC_NORESP_ERR; rc = opb_write(lpc, irqmask_addr, irqmask, 4); if (rc) return rc; @@ -525,11 +518,12 @@ static int64_t __lpc_write(struct lpcm *lpc, enum OpalLPCAddressType addr_type, bool probe) { uint32_t opb_base; + uint32_t irqmask; int64_t rc; lock(&lpc->lock); if (probe) { - rc = lpc_probe_prepare(lpc); + rc = lpc_probe_prepare(lpc, &irqmask); if (rc) goto bail; } @@ -548,7 +542,7 @@ static int64_t __lpc_write(struct lpcm *lpc, enum OpalLPCAddressType addr_type, goto bail; if (probe) - rc = lpc_probe_test(lpc); + rc = lpc_probe_test(lpc, irqmask); bail: unlock(&lpc->lock); return rc; @@ -612,11 +606,12 @@ static int64_t __lpc_read(struct lpcm *lpc, enum OpalLPCAddressType addr_type, bool probe) { uint32_t opb_base; + uint32_t irqmask; int64_t rc; lock(&lpc->lock); if (probe) { - rc = lpc_probe_prepare(lpc); + rc = lpc_probe_prepare(lpc, &irqmask); if (rc) goto bail; } @@ -635,7 +630,7 @@ static int64_t __lpc_read(struct lpcm *lpc, enum OpalLPCAddressType addr_type, goto bail; if (probe) - rc = lpc_probe_test(lpc); + rc = lpc_probe_test(lpc, irqmask); bail: unlock(&lpc->lock); return rc; From patchwork Mon Jan 6 19:21:43 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218447 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [203.11.71.2]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5t36LVHz9sNH for ; Tue, 7 Jan 2020 06:58:35 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5t3531DzDqGT for ; Tue, 7 Jan 2020 06:58:35 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.156.1; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0a-001b2d01.pphosted.com [148.163.156.1]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5lB30p3zDqG1 for ; Tue, 7 Jan 2020 06:52:38 +1100 (AEDT) Received: from pps.filterd (m0098393.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqLTG022840 for ; Mon, 6 Jan 2020 14:52:36 -0500 Received: from ppma04dal.us.ibm.com (7a.29.35a9.ip4.static.sl-reverse.com [169.53.41.122]) by mx0a-001b2d01.pphosted.com with ESMTP id 2xb924nm6h-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:35 -0500 Received: from pps.filterd (ppma04dal.us.ibm.com [127.0.0.1]) by ppma04dal.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006JpP4i030746 for ; Mon, 6 Jan 2020 19:52:35 GMT Received: from b03cxnp08027.gho.boulder.ibm.com (b03cxnp08027.gho.boulder.ibm.com [9.17.130.19]) by ppma04dal.us.ibm.com with ESMTP id 2xajb6a1h5-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:35 +0000 Received: from b03ledav004.gho.boulder.ibm.com (b03ledav004.gho.boulder.ibm.com [9.17.130.235]) by b03cxnp08027.gho.boulder.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqXZU59048442 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 6 Jan 2020 19:52:33 GMT Received: from b03ledav004.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 9B3B878060 for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from b03ledav004.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 860AB7805E for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b03ledav004.gho.boulder.ibm.com (Postfix) with ESMTP for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 5ED5BAE04A8; Mon, 6 Jan 2020 13:22:40 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:43 -0600 Message-Id: <1578338508-13424-9-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 clxscore=1015 impostorscore=0 malwarescore=0 bulkscore=0 adultscore=0 phishscore=0 mlxscore=0 mlxlogscore=999 priorityscore=1501 suspectscore=1 lowpriorityscore=0 spamscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 08/13] hw/bt: Add some more queue debug X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" Enable some more BT_QUEUE_DEBUG. Signed-off-by: Deb McLemore --- hw/bt.c | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/hw/bt.c b/hw/bt.c index 2f3143f..824a1f2 100644 --- a/hw/bt.c +++ b/hw/bt.c @@ -463,8 +463,12 @@ static void bt_send_and_unlock(void) * Timeouts and retries happen in bt_expire_old_msg() * called from bt_poll() */ - if (bt_idle() && inflight_bt_msg->send_count == 0) + if (bt_idle() && inflight_bt_msg->send_count == 0) { +#if BT_QUEUE_DEBUG + BT_Q_DBG(inflight_bt_msg, "Sending inflight_bt_msg NOW"); +#endif bt_send_msg(inflight_bt_msg); + } out_unlock: unlock(&bt.lock); From patchwork Mon Jan 6 19:21:44 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218446 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [203.11.71.2]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5sn2nmPz9sNH for ; Tue, 7 Jan 2020 06:58:21 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5sn1CcSzDqJC for ; Tue, 7 Jan 2020 06:58:21 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.158.5; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0b-001b2d01.pphosted.com [148.163.158.5]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5l9651yzDqGN for ; Tue, 7 Jan 2020 06:52:37 +1100 (AEDT) Received: from pps.filterd (m0098421.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqRWr140408 for ; Mon, 6 Jan 2020 14:52:34 -0500 Received: from ppma02wdc.us.ibm.com (aa.5b.37a9.ip4.static.sl-reverse.com [169.55.91.170]) by mx0a-001b2d01.pphosted.com with ESMTP id 2xb97bx0x1-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:34 -0500 Received: from pps.filterd (ppma02wdc.us.ibm.com [127.0.0.1]) by ppma02wdc.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006Jo96c024842 for ; Mon, 6 Jan 2020 19:52:34 GMT Received: from b01cxnp23033.gho.pok.ibm.com (b01cxnp23033.gho.pok.ibm.com [9.57.198.28]) by ppma02wdc.us.ibm.com with ESMTP id 2xajb6mt22-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:34 +0000 Received: from b01ledav001.gho.pok.ibm.com (b01ledav001.gho.pok.ibm.com [9.57.199.106]) by b01cxnp23033.gho.pok.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqXnw53936580 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 6 Jan 2020 19:52:33 GMT Received: from b01ledav001.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id AAC932805C for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from b01ledav001.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 8E94D28059 for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b01ledav001.gho.pok.ibm.com (Postfix) with ESMTP for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 5954AAE0428; Mon, 6 Jan 2020 13:22:41 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:44 -0600 Message-Id: <1578338508-13424-10-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 phishscore=0 priorityscore=1501 malwarescore=0 adultscore=0 lowpriorityscore=0 spamscore=0 impostorscore=0 mlxscore=0 bulkscore=0 clxscore=1015 suspectscore=3 mlxlogscore=999 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 09/13] core/flash: Update some logging X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" Update some logging to help in problem determination. PR_TRACE used since PR_DEBUG seems to always trigger, unable to figure out why. Signed-off-by: Deb McLemore --- core/flash.c | 37 ++++++++++++++++++++++++++++++++----- 1 file changed, 32 insertions(+), 5 deletions(-) diff --git a/core/flash.c b/core/flash.c index 56b9118..ca4b448 100644 --- a/core/flash.c +++ b/core/flash.c @@ -44,8 +44,11 @@ enum flash_op { FLASH_OP_READ, FLASH_OP_WRITE, FLASH_OP_ERASE, + FLASH_MAX }; +const char flash_string[FLASH_MAX][10]={"READ", "WRITE", "ERASE"}; + struct flash_async_info { enum flash_op op; struct timer poller; @@ -328,7 +331,8 @@ static void flash_poll(struct timer *t __unused, void *data, uint64_t now __unus offset = flash->async.pos; buf = flash->async.buf; len = MIN(flash->async.len, flash->block_size*10); - printf("Flash poll op %d len %llu\n", flash->async.op, len); + prlog(PR_TRACE, "%s flash_poll transaction_id=%i flash->bl->flags=%i Async WORKING chunk len=%llu offset=%llu buf=%p\n", + flash_string[flash->async.op], flash->async.transaction_id, flash->bl->flags, len, offset, (void *)buf); switch (flash->async.op) { case FLASH_OP_READ: @@ -376,6 +380,8 @@ static void flash_poll(struct timer *t __unused, void *data, uint64_t now __unus * to be sure that we jump back out to Linux so that if this * very long we don't cause RCU or the scheduler to freak */ + prlog(PR_TRACE, "%s flash_poll transaction_id=%i Async work REMAINS working chunk len=%llu pos=%llu buf=%p\n", + flash_string[flash->async.op], flash->async.transaction_id, flash->async.len, flash->async.pos, (void *)flash->async.buf); schedule_timer(&flash->async.poller, 0); return; } else { @@ -395,6 +401,8 @@ static void flash_poll(struct timer *t __unused, void *data, uint64_t now __unus * or cases immediately following an unaligned window read/move (so slow) */ flash->bl->flags |= IN_PROGRESS; + prlog(PR_TRACE, "flash_poll RE-QUEUE transaction_id=%i flash->async.retry_counter=%i in_progress_schedule_delay=%i\n", + flash->async.transaction_id, flash->async.retry_counter, flash->async.in_progress_schedule_delay); schedule_timer(&flash->async.poller, msecs_to_tb(flash->async.in_progress_schedule_delay)); return; } @@ -403,6 +411,8 @@ static void flash_poll(struct timer *t __unused, void *data, uint64_t now __unus } } + prlog(PR_TRACE, "%s flash_poll transaction_id=%i END len=%llu pos=%llu buf=%p rc=%i\n", + flash_string[flash->async.op], flash->async.transaction_id, flash->async.len, flash->async.pos, (void *)flash->async.buf, rc); flash->bl->flags &= ~IN_PROGRESS; flash->bl->flags &= ~ASYNC_REQUIRED; /* release the flash before we allow next opal entry */ @@ -615,14 +625,13 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, if (size > flash->size || offset >= flash->size || offset + size > flash->size) { - prlog(PR_DEBUG, "Requested flash op %d beyond flash size %" PRIu64 "\n", + prlog(PR_NOTICE, "Requested flash op %d beyond flash size %" PRIu64 "\n", op, flash->size); rc = OPAL_PARAMETER; goto out; } len = MIN(size, flash->block_size*10); - printf("Flash op %d len %llu\n", op, len); flash->async.op = op; flash->async.token = token; flash->async.buf = buf + len; @@ -632,6 +641,8 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, flash->async.in_progress_schedule_delay = FLASH_SCHEDULE_DELAY; flash->bl->flags |= ASYNC_REQUIRED; ++flash->async.transaction_id; + prlog(PR_TRACE, "%s opal_flash_op transaction_id=%i flash->bl->flags=%i BEGIN total size=%llu Async WORKING chunk len=%llu offset=%llu buf=%p\n", + flash_string[op], flash->async.transaction_id, flash->bl->flags, size, len, offset, (void *)buf); /* * These ops intentionally have no smarts (ecc correction or erase @@ -669,11 +680,15 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, goto out; } flash->bl->flags |= IN_PROGRESS; + prlog(PR_TRACE, "opal_flash_op RE-QUEUE transaction_id=%i flash->async.retry_counter=%i\n", + flash->async.transaction_id, flash->async.retry_counter); schedule_timer(&flash->async.poller, msecs_to_tb(FLASH_SCHEDULE_DELAY)); /* Don't release the flash, we need to hold lock to continue transaction */ return OPAL_ASYNC_COMPLETION; } else { - prlog(PR_ERR, "%s: Op %d failed with rc %d\n", __func__, op, rc); + /* PR_NOTICE since invalid requests can produce problem which is not ERR */ + prlog(PR_NOTICE, "%s: %s (%d) failed rc=%d opal_flash_op transaction_id=%i\n", __func__, + flash_string[op], op, rc, flash->async.transaction_id); rc = OPAL_HARDWARE; } goto out; @@ -683,6 +698,8 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, /* Work remains */ schedule_timer(&flash->async.poller, 0); /* Don't release the flash, we need to hold lock to continue transaction */ + prlog(PR_TRACE, "%s opal_flash_op transaction_id=%i Async work REMAINS size=%llu working chunk len=%llu offset=%llu buf=%p\n", + flash_string[flash->async.op], flash->async.transaction_id, size, len, offset, (void *)buf); return OPAL_ASYNC_COMPLETION; } else { /* @@ -696,9 +713,19 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, */ opal_queue_msg(OPAL_MSG_ASYNC_COMP, NULL, NULL, flash->async.token, rc); } + prlog(PR_TRACE, "%s opal_flash_op transaction_id=%i Async work COMPLETE size=%llu chunk len=%llu offset=%llu buf=%p\n", + flash_string[flash->async.op], flash->async.transaction_id, size, len, offset, (void *)buf); rc = OPAL_ASYNC_COMPLETION; out: flash_release(flash); + if (rc != OPAL_ASYNC_COMPLETION) { + prlog(PR_NOTICE, "%s opal_flash_op transaction_id=%i retry_counter=%i PROBLEM rc=%d size=%llu chunk len=%llu offset=%llu buf=%p\n", + flash_string[flash->async.op], flash->async.transaction_id, flash->async.retry_counter, rc, size, len, offset, (void *)buf); + } else { + prlog(PR_TRACE, "%s opal_flash_op transaction_id=%i END retry_counter=%i size=%llu chunk len=%llu offset=%llu buf=%p\n", + flash_string[flash->async.op], flash->async.transaction_id, flash->async.retry_counter, size, len, offset, (void *)buf); + } + flash->bl->flags &= ~IN_PROGRESS; flash->bl->flags &= ~ASYNC_REQUIRED; return rc; @@ -901,7 +928,7 @@ static int flash_load_resource(enum resource_id id, uint32_t subid, } if (*len > ffs_part_size) { - prerror("FLASH: Cannot load %s. Content is larger than the partition\n", + prerror("Cannot load %s. Content is larger than the partition\n", name); rc = OPAL_PARAMETER; goto out_free_ffs; From patchwork Mon Jan 6 19:21:45 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218450 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [203.11.71.2]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5tx3ZlRz9sNH for ; Tue, 7 Jan 2020 06:59:21 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5tx2NfKzDqJj for ; Tue, 7 Jan 2020 06:59:21 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.156.1; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0a-001b2d01.pphosted.com [148.163.156.1]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5lC008XzDqGt for ; Tue, 7 Jan 2020 06:52:38 +1100 (AEDT) Received: from pps.filterd (m0098396.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqKYA025162 for ; Mon, 6 Jan 2020 14:52:36 -0500 Received: from ppma04dal.us.ibm.com (7a.29.35a9.ip4.static.sl-reverse.com [169.53.41.122]) by mx0a-001b2d01.pphosted.com with ESMTP id 2xb92mdgur-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:36 -0500 Received: from pps.filterd (ppma04dal.us.ibm.com [127.0.0.1]) by ppma04dal.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006JpP4j030746 for ; Mon, 6 Jan 2020 19:52:35 GMT Received: from b03cxnp08025.gho.boulder.ibm.com (b03cxnp08025.gho.boulder.ibm.com [9.17.130.17]) by ppma04dal.us.ibm.com with ESMTP id 2xajb6a1h6-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:35 +0000 Received: from b03ledav005.gho.boulder.ibm.com (b03ledav005.gho.boulder.ibm.com [9.17.130.236]) by b03cxnp08025.gho.boulder.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqX6J61931790 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 6 Jan 2020 19:52:34 GMT Received: from b03ledav005.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id DB988BE04F for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from b03ledav005.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 9448DBE051 for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b03ledav005.gho.boulder.ibm.com (Postfix) with ESMTP for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 44E61AE043A; Mon, 6 Jan 2020 13:22:42 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:45 -0600 Message-Id: <1578338508-13424-11-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 mlxscore=0 adultscore=0 lowpriorityscore=0 spamscore=0 phishscore=0 priorityscore=1501 impostorscore=0 bulkscore=0 malwarescore=0 mlxlogscore=999 suspectscore=3 clxscore=1015 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 10/13] libflash/ipmi-hiomap: Add some debug logging X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" Add some additional debug logging for problem determination. PR_TRACE used since PR_DEBUG seems to always trigger, unable to figure out why. Signed-off-by: Deb McLemore --- core/flash.c | 4 +- libflash/ipmi-hiomap.c | 177 ++++++++++++++++++++++++++++++++++--------------- 2 files changed, 125 insertions(+), 56 deletions(-) diff --git a/core/flash.c b/core/flash.c index ca4b448..482a5cd 100644 --- a/core/flash.c +++ b/core/flash.c @@ -680,8 +680,8 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, goto out; } flash->bl->flags |= IN_PROGRESS; - prlog(PR_TRACE, "opal_flash_op RE-QUEUE transaction_id=%i flash->async.retry_counter=%i\n", - flash->async.transaction_id, flash->async.retry_counter); + prlog(PR_TRACE, "opal_flash_op RE-QUEUE transaction_id=%i flash->async.retry_counter=%i in_progress_schedule_delay=%i\n", + flash->async.transaction_id, flash->async.retry_counter, FLASH_SCHEDULE_DELAY); schedule_timer(&flash->async.poller, msecs_to_tb(FLASH_SCHEDULE_DELAY)); /* Don't release the flash, we need to hold lock to continue transaction */ return OPAL_ASYNC_COMPLETION; diff --git a/libflash/ipmi-hiomap.c b/libflash/ipmi-hiomap.c index 2e288b3..c2db98f 100644 --- a/libflash/ipmi-hiomap.c +++ b/libflash/ipmi-hiomap.c @@ -58,10 +58,15 @@ static inline uint16_t bytes_to_blocks_align_up(struct ipmi_hiomap *ctx, /* Call under ctx->lock */ static int hiomap_protocol_ready(struct ipmi_hiomap *ctx) { - if (!(ctx->bmc_state & HIOMAP_E_DAEMON_READY)) + prlog(PR_TRACE, "%s ctx->bmc_state=%i\n", __func__, ctx->bmc_state); + if (!(ctx->bmc_state & HIOMAP_E_DAEMON_READY)) { + prlog(PR_NOTICE, "%s FLASH_ERR_DEVICE_GONE\n", __func__); return FLASH_ERR_DEVICE_GONE; - if (ctx->bmc_state & HIOMAP_E_FLASH_LOST) + } + if (ctx->bmc_state & HIOMAP_E_FLASH_LOST) { + prlog(PR_NOTICE, "%s HIOMAP_E_FLASH_LOST\n", __func__); return FLASH_ERR_AGAIN; + } return 0; } @@ -114,16 +119,27 @@ static int hiomap_queue_msg(struct ipmi_hiomap *ctx, struct ipmi_msg *msg) static int hiomap_window_valid(struct ipmi_hiomap *ctx, uint64_t pos, uint64_t len) { - if (ctx->bmc_state & HIOMAP_E_FLASH_LOST) + if (ctx->bmc_state & HIOMAP_E_FLASH_LOST) { + prlog(PR_NOTICE, "%s HIOMAP_E_FLASH_LOST\n", __func__); return FLASH_ERR_AGAIN; - if (ctx->bmc_state & HIOMAP_E_PROTOCOL_RESET) + } + if (ctx->bmc_state & HIOMAP_E_PROTOCOL_RESET) { + prlog(PR_NOTICE, "%s HIOMAP_E_PROTOCOL_RESET\n", __func__); return FLASH_ERR_AGAIN; - if (ctx->bmc_state & HIOMAP_E_WINDOW_RESET) + } + if (ctx->bmc_state & HIOMAP_E_WINDOW_RESET) { + prlog(PR_NOTICE, "%s HIOMAP_E_WINDOW_RESET\n", __func__); return FLASH_ERR_AGAIN; - if (ctx->window_state == closed_window) + } + if (ctx->window_state == closed_window) { + prlog(PR_TRACE, "%s window_state=closed_window\n", __func__); return FLASH_ERR_PARM_ERROR; - if (pos < ctx->current.cur_pos) + } + if (pos < ctx->current.cur_pos) { + prlog(PR_TRACE, "%s we need to move the window pos=%llu < ctx->current.cur_pos=0x%x\n", + __func__, pos, ctx->current.cur_pos); return FLASH_ERR_PARM_ERROR; + } if ((pos + len) > (ctx->current.cur_pos + ctx->current.size)) { /* * we will compensate the proper values in the caller @@ -330,8 +346,10 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) } if (msg->data[1] != ctx->inflight_seq) { - prerror("Unmatched sequence number: wanted %u got %u\n", - ctx->inflight_seq, msg->data[1]); + prlog(PR_TRACE, "%s Unmatched ipmi sequence number: wanted %u got %u\n", + __func__, + ctx->inflight_seq, + msg->data[1]); res->cc = IPMI_ERR_UNSPECIFIED; ipmi_free_msg(msg); return; @@ -388,7 +406,9 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) case HIOMAP_C_ERASE: case HIOMAP_C_RESET: if (msg->resp_size != 2) { - prerror("%u: Unexpected response size: %u\n", msg->data[0], + prerror("%s %u: Unexpected response size: %u\n", + __func__, + msg->data[0], msg->resp_size); res->cc = IPMI_ERR_UNSPECIFIED; ctx->cc = OPAL_HARDWARE; @@ -403,8 +423,8 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) } break; default: - prlog(PR_WARNING, "Unimplemented command handler: %u\n", - msg->data[0]); + prlog(PR_WARNING, "%s Unimplemented command handler: %u\n", + __func__, msg->data[0]); break; }; ipmi_free_msg(msg); @@ -684,8 +704,10 @@ static int hiomap_window_move(struct ipmi_hiomap *ctx, uint8_t command, rc = hiomap_queue_msg(ctx, msg); - if (rc) + if (rc) { + prlog(PR_NOTICE, "%s move queue msg failed: rc=%d\n", __func__, rc); return rc; + } return 0; } @@ -711,8 +733,10 @@ static int hiomap_mark_dirty(struct ipmi_hiomap *ctx, uint64_t offset, ctx->cc = -1; unlock(&ctx->lock); - if (state != write_window) + if (state != write_window) { + prlog(PR_NOTICE, "%s failed: state=%i\n", __func__, state); return FLASH_ERR_PARM_ERROR; + } req[0] = HIOMAP_C_MARK_DIRTY; req[1] = dirty_seq; @@ -728,11 +752,13 @@ static int hiomap_mark_dirty(struct ipmi_hiomap *ctx, uint64_t offset, rc = hiomap_queue_msg(ctx, msg); - if (rc) + if (rc) { + prlog(PR_NOTICE, "%s dirty queue msg failed: rc=%d\n", __func__, rc); return rc; + } - prlog(PR_DEBUG, "Marked flash dirty at 0x%" PRIx64 " for %" PRIu64 "\n", - offset, size); + prlog(PR_TRACE, "%s Start to mark flash dirty at pos %llu size %llu bytes ipmi seq=%i\n", + __func__, offset, size, dirty_seq); return 0; } @@ -755,8 +781,10 @@ static int hiomap_flush(struct ipmi_hiomap *ctx) ctx->cc = -1; unlock(&ctx->lock); - if (state != write_window) + if (state != write_window) { + prlog(PR_NOTICE, "%s failed: state=%i\n", __func__, state); return FLASH_ERR_PARM_ERROR; + } req[0] = HIOMAP_C_FLUSH; req[1] = flush_seq; @@ -767,10 +795,12 @@ static int hiomap_flush(struct ipmi_hiomap *ctx) rc = hiomap_queue_msg(ctx, msg); - if (rc) + if (rc) { + prlog(PR_NOTICE, "%s flush queue msg failed: rc=%d\n", __func__, rc); return rc; + } - prlog(PR_DEBUG, "Flushed writes\n"); + prlog(PR_TRACE, "%s Start to flush writes ipmi seq=%i\n", __func__, flush_seq); return 0; } @@ -810,12 +840,15 @@ static int hiomap_ack(struct ipmi_hiomap *ctx, uint8_t ack) bmc_platform->sw->ipmi_oem_hiomap_cmd, ipmi_hiomap_cmd_cb, &ack_res, req, sizeof(req), 2); + prlog(PR_TRACE, "%s SENDING req[1]=%i\n", __func__, req[1]); rc = hiomap_queue_msg(ctx, msg); lock(&ctx->lock); ctx->bl.flags = orig_flags; unlock(&ctx->lock); - if (rc) + if (rc) { + prlog(PR_NOTICE, "%s queue msg failed: rc=%d\n", __func__, rc); return rc; + } rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_ACK_DEFAULT); if (rc) { @@ -824,7 +857,7 @@ static int hiomap_ack(struct ipmi_hiomap *ctx, uint8_t ack) return rc; } - prlog(PR_DEBUG, "Acked events: 0x%x\n", ack); + prlog(PR_NOTICE, "%s Acked events: 0x%x\n", __func__, ack); return 0; } @@ -850,8 +883,10 @@ static int hiomap_erase(struct ipmi_hiomap *ctx, uint64_t offset, ctx->cc = -1; unlock(&ctx->lock); - if (state != write_window) + if (state != write_window) { + prlog(PR_NOTICE, "%s failed: state=%i\n", __func__, state); return FLASH_ERR_PARM_ERROR; + } req[0] = HIOMAP_C_ERASE; req[1] = erase_seq; @@ -867,11 +902,14 @@ static int hiomap_erase(struct ipmi_hiomap *ctx, uint64_t offset, rc = hiomap_queue_msg(ctx, msg); - if (rc) + if (rc) { + prlog(PR_NOTICE, "%s erase queue msg failed: rc=%d\n", __func__, rc); return rc; + } - prlog(PR_DEBUG, "Erased flash at 0x%" PRIx64 " for %" PRIu64 "\n", - offset, size); + prlog(PR_TRACE, "%s Erasing flash at pos %llu for size %llu\n", + __func__, + offset, size); return 0; } @@ -936,10 +974,17 @@ static void hiomap_event(uint8_t events, void *context) { struct ipmi_hiomap *ctx = context; - prlog(PR_DEBUG, "Received events: 0x%x\n", events); + prlog(PR_NOTICE, "%s Received events: 0x%x ctx->bmc_state=%i\n", + __func__, + events, + ctx->bmc_state); lock(&ctx->lock); ctx->bmc_state = events | (ctx->bmc_state & HIOMAP_E_ACK_MASK); + prlog(PR_NOTICE, "%s Updated bmc_state Received events: 0x%x ctx->bmc_state=%i\n", + __func__, + events, + ctx->bmc_state); unlock(&ctx->lock); } @@ -952,7 +997,7 @@ static int lpc_window_read(struct ipmi_hiomap *ctx, uint32_t pos, if ((ctx->current.lpc_addr + ctx->current.size) < (off + len)) return FLASH_ERR_PARM_ERROR; - prlog(PR_TRACE, "Reading at 0x%08x for 0x%08x offset: 0x%08x\n", + prlog(PR_TRACE, "LPC Reading at 0x%08x for 0x%08x offset: 0x%08x\n", pos, len, off); while(len) { @@ -1000,7 +1045,7 @@ static int lpc_window_write(struct ipmi_hiomap *ctx, uint32_t pos, if ((ctx->current.lpc_addr + ctx->current.size) < (off + len)) return FLASH_ERR_PARM_ERROR; - prlog(PR_TRACE, "Writing at 0x%08x for 0x%08x offset: 0x%08x\n", + prlog(PR_TRACE, "LPC Writing at 0x%08x for 0x%08x offset: 0x%08x\n", pos, len, off); while(len) { @@ -1016,7 +1061,7 @@ static int lpc_window_write(struct ipmi_hiomap *ctx, uint32_t pos, chunk = 1; } if (rc) { - prlog(PR_ERR, "lpc_write failure %d to FW 0x%08x\n", rc, off); + prlog(PR_ERR, "%s failure %d to FW 0x%08x\n", __func__, rc, off); return rc; } len -= chunk; @@ -1036,6 +1081,7 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx) lock(&ctx->lock); status = ctx->bmc_state; + prlog(PR_TRACE, "%s status=%i\n", __func__, status); /* * Immediately clear the ackable events to make sure we don't race to @@ -1058,9 +1104,18 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx) * Therefore it is enough to mark the window as closed to consider it * recovered. */ + if (status & HIOMAP_E_PROTOCOL_RESET) { + prlog(PR_TRACE, "%s status=HIOMAP_E_PROTOCOL_RESET\n", __func__); + } - if (status & (HIOMAP_E_PROTOCOL_RESET | HIOMAP_E_WINDOW_RESET)) + if (status & HIOMAP_E_WINDOW_RESET) { + prlog(PR_TRACE, "%s status=HIOMAP_E_WINDOW_RESET\n", __func__); + } + + if (status & (HIOMAP_E_PROTOCOL_RESET | HIOMAP_E_WINDOW_RESET)) { ctx->window_state = closed_window; + prlog(PR_TRACE, "%s closed_window\n", __func__); + } unlock(&ctx->lock); @@ -1078,21 +1133,22 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx) * the BMC's cache must be valid if opening the window is successful. */ if (status & HIOMAP_E_ACK_MASK) { + prlog(PR_TRACE, "%s status=%i HIOMAP_E_ACK_MASK so TRY to ACK\n", __func__, status); /* ACK is unversioned, can send it if the daemon is ready */ rc = hiomap_ack(ctx, status & HIOMAP_E_ACK_MASK); if (rc) { - prlog(PR_DEBUG, "Failed to ack events: 0x%x\n", - status & HIOMAP_E_ACK_MASK); + prlog(PR_NOTICE, "%s Failed to ack events rc=%i: status & HIOMAP_E_ACK_MASK=0x%x status=%i\n", + __func__, rc, (status & HIOMAP_E_ACK_MASK), status); goto restore; } } if (status & HIOMAP_E_PROTOCOL_RESET) { - prlog(PR_INFO, "Protocol was reset\n"); + prlog(PR_INFO, "%s Protocol was reset\n", __func__); rc = hiomap_get_info(ctx); if (rc) { - prerror("Failure to renegotiate after protocol reset\n"); + prerror("%s Failure to renegotiate after protocol reset\n", __func__); goto restore; } @@ -1102,7 +1158,7 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx) goto restore; } - prlog(PR_INFO, "Restored state after protocol reset\n"); + prlog(PR_INFO, "%s Restored state after protocol reset\n", __func__); } /* @@ -1120,7 +1176,9 @@ restore: * than necessary, but never less than necessary. */ lock(&ctx->lock); + prlog(PR_TRACE, "%s PRE restore status=%i PRE ctx->bmc_state=%i rc=%i\n", __func__, status, ctx->bmc_state, rc); ctx->bmc_state |= (status & HIOMAP_E_ACK_MASK); + prlog(PR_TRACE, "%s POST restored status=%i POST ctx->bmc_state=%i rc=%i\n", __func__, status, ctx->bmc_state, rc); unlock(&ctx->lock); return rc; @@ -1136,15 +1194,17 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos, /* LPC is only 32bit */ if (pos > UINT_MAX || len > UINT_MAX) - return FLASH_ERR_PARM_ERROR; + return OPAL_PARAMETER; ctx = container_of(bl, struct ipmi_hiomap, bl); lock(&ctx->transaction_lock); rc = ipmi_hiomap_handle_events(ctx); - if (rc) + if (rc) { + prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc); goto out; + } lock(&ctx->lock); if (ctx->bl.flags & IN_PROGRESS) { @@ -1158,8 +1218,7 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos, } unlock(&ctx->lock); - prlog(PR_TRACE, "Flash read at %#" PRIx64 " for %#" PRIx64 "\n", pos, - len); + prlog(PR_TRACE, "Flash READ at pos %llu for %llu bytes\n", pos, len); while (len > 0) { lock(&ctx->lock); state = ctx->window_state; @@ -1243,8 +1302,10 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos, lock(&ctx->transaction_lock); rc = ipmi_hiomap_handle_events(ctx); - if (rc) + if (rc) { + prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc); goto out; + } lock(&ctx->lock); if (ctx->bl.flags & IN_PROGRESS) { @@ -1258,8 +1319,7 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos, } unlock(&ctx->lock); - prlog(PR_TRACE, "Flash write at %#" PRIx64 " for %#" PRIx64 "\n", pos, - len); + prlog(PR_TRACE, "Flash WRITE at pos %llu for %llu bytes\n", pos, len); while (len > 0) { lock(&ctx->lock); state = ctx->window_state; @@ -1364,14 +1424,17 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos, /* LPC is only 32bit */ if (pos > UINT_MAX || len > UINT_MAX) - return FLASH_ERR_PARM_ERROR; + return OPAL_PARAMETER; ctx = container_of(bl, struct ipmi_hiomap, bl); lock(&ctx->transaction_lock); rc = ipmi_hiomap_handle_events(ctx); - if (rc) + if (rc) { + prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc); goto out; + } + lock(&ctx->lock); if (ctx->bl.flags & IN_PROGRESS) { @@ -1383,8 +1446,8 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos, } unlock(&ctx->lock); - prlog(PR_TRACE, "Flash erase at 0x%08x for 0x%08x\n", (u32) pos, - (u32) len); + prlog(PR_TRACE, "Flash ERASE at pos %llu for %llu bytes\n", pos, len); + while (len > 0) { lock(&ctx->lock); state = ctx->window_state; @@ -1468,12 +1531,16 @@ static int ipmi_hiomap_get_flash_info(struct blocklevel_device *bl, lock(&ctx->transaction_lock); rc = ipmi_hiomap_handle_events(ctx); - if (rc) + if (rc) { + prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc); return rc; + } rc = hiomap_get_flash_info(ctx); - if (rc) + if (rc) { + prlog(PR_NOTICE, "%s hiomap_get_flash failed: rc=%d\n", __func__, rc); return rc; + } ctx->bl.erase_mask = ctx->erase_granule - 1; @@ -1520,26 +1587,28 @@ int ipmi_hiomap_init(struct blocklevel_device **bl) /* Ack all pending ack-able events to avoid spurious failures */ rc = hiomap_ack(ctx, HIOMAP_E_ACK_MASK); if (rc) { - prlog(PR_DEBUG, "Failed to ack events: 0x%x\n", - HIOMAP_E_ACK_MASK); + prlog(PR_NOTICE, "%s Failed to ack events: 0x%x\n", + __func__, HIOMAP_E_ACK_MASK); goto err; } rc = ipmi_sel_register(CMD_OP_HIOMAP_EVENT, hiomap_event, ctx); - if (rc < 0) + if (rc < 0) { + prerror("%s Failed ipmi_sel_register: %d\n", __func__, rc); goto err; + } /* Negotiate protocol behaviour */ rc = hiomap_get_info(ctx); if (rc) { - prerror("Failed to get hiomap parameters: %d\n", rc); + prerror("%s Failed to get hiomap parameters: %d\n", __func__, rc); goto err; } /* Grab the flash parameters */ rc = hiomap_get_flash_info(ctx); if (rc) { - prerror("Failed to get flash parameters: %d\n", rc); + prerror("%s Failed to get flash parameters: %d\n", __func__, rc); goto err; } From patchwork Mon Jan 6 19:21:46 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218442 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [203.11.71.2]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5rZ1YK8z9sNH for ; Tue, 7 Jan 2020 06:57:18 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5rZ0NtvzDqGN for ; Tue, 7 Jan 2020 06:57:18 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.156.1; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0a-001b2d01.pphosted.com [148.163.156.1]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5l84dkHzDqFw for ; Tue, 7 Jan 2020 06:52:36 +1100 (AEDT) Received: from pps.filterd (m0098410.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqK7Y001791 for ; Mon, 6 Jan 2020 14:52:34 -0500 Received: from ppma02dal.us.ibm.com (a.bd.3ea9.ip4.static.sl-reverse.com [169.62.189.10]) by mx0a-001b2d01.pphosted.com with ESMTP id 2xar481d07-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:34 -0500 Received: from pps.filterd (ppma02dal.us.ibm.com [127.0.0.1]) by ppma02dal.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006JpwR6003028 for ; Mon, 6 Jan 2020 19:52:33 GMT Received: from b03cxnp08027.gho.boulder.ibm.com (b03cxnp08027.gho.boulder.ibm.com [9.17.130.19]) by ppma02dal.us.ibm.com with ESMTP id 2xajb6j098-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:33 +0000 Received: from b03ledav006.gho.boulder.ibm.com (b03ledav006.gho.boulder.ibm.com [9.17.130.237]) by b03cxnp08027.gho.boulder.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqWNX61145534 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 6 Jan 2020 19:52:32 GMT Received: from b03ledav006.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 06325C6055 for ; Mon, 6 Jan 2020 19:52:32 +0000 (GMT) Received: from b03ledav006.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id E1002C6057 for ; Mon, 6 Jan 2020 19:52:31 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b03ledav006.gho.boulder.ibm.com (Postfix) with ESMTP for ; Mon, 6 Jan 2020 19:52:31 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 28EF3AE0941; Mon, 6 Jan 2020 13:22:43 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:46 -0600 Message-Id: <1578338508-13424-12-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 malwarescore=0 mlxlogscore=999 impostorscore=0 mlxscore=0 priorityscore=1501 lowpriorityscore=0 suspectscore=1 clxscore=1015 bulkscore=0 phishscore=0 adultscore=0 spamscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 11/13] lpc: Add logging for hardware diagnostics X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" Add some logging to help in problem determination for hardware failure cases to aide in triage. Signed-off-by: Deb McLemore --- hw/lpc.c | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/hw/lpc.c b/hw/lpc.c index fedceb4..b835f14 100644 --- a/hw/lpc.c +++ b/hw/lpc.c @@ -504,12 +504,16 @@ static int64_t lpc_probe_test(struct lpcm *lpc, uint32_t irqmask) /* Ensure we can perform a valid lookup in the error table */ idx = LPC_ERROR_IDX(irqstat); if (idx < 0 || idx >= ARRAY_SIZE(lpc_error_table)) { - prerror("LPC bus error translation failed with status 0x%x\n", - irqstat); + prlog(PR_ERR, "%s bus error translation failed with idx=%llu irqstat=0x%x\n", + __func__, idx, irqstat); return OPAL_PARAMETER; } rc = lpc_error_table[idx].rc; + /* purpose here is to log for any anomalies, something other than the expected NORESP_ERR */ + if (idx != LPC_ERROR_IDX(LPC_HC_IRQ_SYNC_NORESP_ERR)) { + prlog(PR_NOTICE, "%s LOOKUP rc=0x%x idx=%llu\n", __func__, rc, idx); + } return rc; } @@ -1032,6 +1036,10 @@ static void lpc_dispatch_err_irqs(struct lpcm *lpc, uint32_t irqs) /* Find and report the error */ err = &lpc_error_table[idx]; lpc_bus_err_count++; + /* purpose here is to log for any anomalies, e.g. hardware issues */ + prlog(PR_NOTICE, "%s lpc_bus_err_count=%i\n", + __func__, + lpc_bus_err_count); if (manufacturing_mode && (lpc_bus_err_count > LPC_BUS_DEGRADED_PERF_THRESHOLD)) info = &e_info(OPAL_RC_LPC_SYNC_PERF); else From patchwork Mon Jan 6 19:21:47 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218445 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [203.11.71.2]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5sT1sXCz9sNH for ; Tue, 7 Jan 2020 06:58:05 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5sT0DF0zDqG1 for ; Tue, 7 Jan 2020 06:58:05 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.158.5; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0b-001b2d01.pphosted.com [148.163.158.5]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5l92r9PzDqG8 for ; Tue, 7 Jan 2020 06:52:37 +1100 (AEDT) Received: from pps.filterd (m0098419.ppops.net [127.0.0.1]) by mx0b-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqLwi092325 for ; Mon, 6 Jan 2020 14:52:35 -0500 Received: from ppma03dal.us.ibm.com (b.bd.3ea9.ip4.static.sl-reverse.com [169.62.189.11]) by mx0b-001b2d01.pphosted.com with ESMTP id 2xb8s7xce2-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:35 -0500 Received: from pps.filterd (ppma03dal.us.ibm.com [127.0.0.1]) by ppma03dal.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006JowSw032471 for ; Mon, 6 Jan 2020 19:52:34 GMT Received: from b01cxnp23032.gho.pok.ibm.com (b01cxnp23032.gho.pok.ibm.com [9.57.198.27]) by ppma03dal.us.ibm.com with ESMTP id 2xajb72311-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:34 +0000 Received: from b01ledav002.gho.pok.ibm.com (b01ledav002.gho.pok.ibm.com [9.57.199.107]) by b01cxnp23032.gho.pok.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqXD927590988 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 6 Jan 2020 19:52:33 GMT Received: from b01ledav002.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id BB059124058 for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from b01ledav002.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id A060E124053 for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b01ledav002.gho.pok.ibm.com (Postfix) with ESMTP for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 5A473AE0492; Mon, 6 Jan 2020 13:22:44 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:47 -0600 Message-Id: <1578338508-13424-13-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 adultscore=0 phishscore=0 malwarescore=0 lowpriorityscore=0 bulkscore=0 clxscore=1015 impostorscore=0 mlxlogscore=786 spamscore=0 mlxscore=0 priorityscore=1501 suspectscore=1 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 12/13] hw/bt: Allow ipmi regular intervals X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" Found during investigation of slow ipmi messages in OPAL_FLASH_READ/WRITE operations. When bt irqs are operational perform default timer scheduling. Signed-off-by: Deb McLemore --- hw/bt.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/hw/bt.c b/hw/bt.c index 824a1f2..72393a2 100644 --- a/hw/bt.c +++ b/hw/bt.c @@ -518,7 +518,7 @@ static void bt_poll(struct timer *t __unused, void *data __unused, bt_send_and_unlock(); schedule_timer(&bt.poller, - bt.irq_ok ? TIMER_POLL : msecs_to_tb(BT_DEFAULT_POLL_MS)); + bt.irq_ok ? msecs_to_tb(BT_DEFAULT_POLL_MS) : TIMER_POLL); } static void bt_ipmi_poll(void) From patchwork Mon Jan 6 19:21:48 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1218448 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 47s5tN0KyHz9sR0 for ; Tue, 7 Jan 2020 06:58:52 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 47s5tM6BPWzDqHl for ; Tue, 7 Jan 2020 06:58:51 +1100 (AEDT) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Authentication-Results: lists.ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=linux.ibm.com (client-ip=148.163.158.5; helo=mx0a-001b2d01.pphosted.com; envelope-from=debmc@linux.ibm.com; receiver=) Authentication-Results: lists.ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from mx0a-001b2d01.pphosted.com (mx0b-001b2d01.pphosted.com [148.163.158.5]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 47s5lB0q9kzDqFw for ; Tue, 7 Jan 2020 06:52:37 +1100 (AEDT) Received: from pps.filterd (m0098413.ppops.net [127.0.0.1]) by mx0b-001b2d01.pphosted.com (8.16.0.42/8.16.0.42) with SMTP id 006JqScu102182 for ; Mon, 6 Jan 2020 14:52:35 -0500 Received: from ppma03wdc.us.ibm.com (ba.79.3fa9.ip4.static.sl-reverse.com [169.63.121.186]) by mx0b-001b2d01.pphosted.com with ESMTP id 2xb8wfvup2-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 14:52:34 -0500 Received: from pps.filterd (ppma03wdc.us.ibm.com [127.0.0.1]) by ppma03wdc.us.ibm.com (8.16.0.27/8.16.0.27) with SMTP id 006Jp0kX021087 for ; Mon, 6 Jan 2020 19:52:34 GMT Received: from b01cxnp22035.gho.pok.ibm.com (b01cxnp22035.gho.pok.ibm.com [9.57.198.25]) by ppma03wdc.us.ibm.com with ESMTP id 2xajb64t4j-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 06 Jan 2020 19:52:34 +0000 Received: from b01ledav005.gho.pok.ibm.com (b01ledav005.gho.pok.ibm.com [9.57.199.110]) by b01cxnp22035.gho.pok.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id 006JqX1K50987288 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 6 Jan 2020 19:52:33 GMT Received: from b01ledav005.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id D20C9AE060 for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from b01ledav005.gho.pok.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 93FD1AE05F for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: from oc4402612711.ibm.com (unknown [9.41.175.242]) by b01ledav005.gho.pok.ibm.com (Postfix) with ESMTP for ; Mon, 6 Jan 2020 19:52:33 +0000 (GMT) Received: by oc4402612711.ibm.com (Postfix, from userid 1000) id 4FFDCAE0470; Mon, 6 Jan 2020 13:22:46 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 6 Jan 2020 13:21:48 -0600 Message-Id: <1578338508-13424-14-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> References: <1578338508-13424-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.95, 18.0.572 definitions=2020-01-06_06:2020-01-06, 2020-01-06 signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 malwarescore=0 bulkscore=0 clxscore=1015 suspectscore=4 phishscore=0 priorityscore=1501 spamscore=0 lowpriorityscore=0 mlxscore=0 mlxlogscore=999 adultscore=0 impostorscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-1910280000 definitions=main-2001060165 Subject: [Skiboot] [PATCH v3 13/13] libflash/ipmi-hiomap: Add helpers for logging X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Mailing list for skiboot development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , MIME-Version: 1.0 Errors-To: skiboot-bounces+incoming=patchwork.ozlabs.org@lists.ozlabs.org Sender: "Skiboot" Add some logging helpers. Signed-off-by: Deb McLemore --- libflash/ipmi-hiomap.c | 287 ++++++++++++++++++++++++------------------------- 1 file changed, 140 insertions(+), 147 deletions(-) diff --git a/libflash/ipmi-hiomap.c b/libflash/ipmi-hiomap.c index c2db98f..c9662ff 100644 --- a/libflash/ipmi-hiomap.c +++ b/libflash/ipmi-hiomap.c @@ -1,8 +1,6 @@ // SPDX-License-Identifier: Apache-2.0 /* Copyright 2018-2019 IBM Corp. */ -#define pr_fmt(fmt) "HIOMAP: " fmt - #include #include #include @@ -23,6 +21,12 @@ #define CMD_OP_HIOMAP_EVENT 0x0f +#define hiomap_trace(fmt, a...) prlog(PR_TRACE,"HIOMAP: %s " fmt, __func__, ## a) +#define hiomap_info(fmt, a...) prlog(PR_INFO,"HIOMAP: %s " fmt, __func__, ## a) +#define hiomap_notice(fmt, a...) prlog(PR_NOTICE,"HIOMAP: %s " fmt, __func__, ## a) +#define hiomap_warn(fmt, a...) prlog(PR_WARNING,"HIOMAP: %s " fmt, __func__, ## a) +#define hiomap_error(fmt, a...) prlog(PR_ERR,"HIOMAP: %s " fmt, __func__, ## a) + struct ipmi_hiomap_result { struct ipmi_hiomap *ctx; int16_t cc; @@ -58,13 +62,13 @@ static inline uint16_t bytes_to_blocks_align_up(struct ipmi_hiomap *ctx, /* Call under ctx->lock */ static int hiomap_protocol_ready(struct ipmi_hiomap *ctx) { - prlog(PR_TRACE, "%s ctx->bmc_state=%i\n", __func__, ctx->bmc_state); + hiomap_trace("ctx->bmc_state=%i\n", ctx->bmc_state); if (!(ctx->bmc_state & HIOMAP_E_DAEMON_READY)) { - prlog(PR_NOTICE, "%s FLASH_ERR_DEVICE_GONE\n", __func__); + hiomap_notice("FLASH_ERR_DEVICE_GONE\n"); return FLASH_ERR_DEVICE_GONE; } if (ctx->bmc_state & HIOMAP_E_FLASH_LOST) { - prlog(PR_NOTICE, "%s HIOMAP_E_FLASH_LOST\n", __func__); + hiomap_notice("HIOMAP_E_FLASH_LOST\n"); return FLASH_ERR_AGAIN; } @@ -105,10 +109,10 @@ static int hiomap_queue_msg(struct ipmi_hiomap *ctx, struct ipmi_msg *msg) ipmi_free_msg(msg); return rc; } - prlog(PR_TRACE, "%s SENDING SYNC\n", __func__); + hiomap_trace("SENDING SYNC\n"); ipmi_queue_msg_sync(msg); } else { - prlog(PR_TRACE, "%s SENDING ASYNC\n", __func__); + hiomap_trace("SENDING ASYNC\n"); rc = ipmi_queue_msg(msg); } @@ -120,24 +124,24 @@ static int hiomap_window_valid(struct ipmi_hiomap *ctx, uint64_t pos, uint64_t len) { if (ctx->bmc_state & HIOMAP_E_FLASH_LOST) { - prlog(PR_NOTICE, "%s HIOMAP_E_FLASH_LOST\n", __func__); + hiomap_notice("HIOMAP_E_FLASH_LOST\n"); return FLASH_ERR_AGAIN; } if (ctx->bmc_state & HIOMAP_E_PROTOCOL_RESET) { - prlog(PR_NOTICE, "%s HIOMAP_E_PROTOCOL_RESET\n", __func__); + hiomap_notice("HIOMAP_E_PROTOCOL_RESET\n"); return FLASH_ERR_AGAIN; } if (ctx->bmc_state & HIOMAP_E_WINDOW_RESET) { - prlog(PR_NOTICE, "%s HIOMAP_E_WINDOW_RESET\n", __func__); + hiomap_notice("HIOMAP_E_WINDOW_RESET\n"); return FLASH_ERR_AGAIN; } if (ctx->window_state == closed_window) { - prlog(PR_TRACE, "%s window_state=closed_window\n", __func__); + hiomap_trace("window_state=closed_window\n"); return FLASH_ERR_PARM_ERROR; } if (pos < ctx->current.cur_pos) { - prlog(PR_TRACE, "%s we need to move the window pos=%llu < ctx->current.cur_pos=0x%x\n", - __func__, pos, ctx->current.cur_pos); + hiomap_trace("we need to move the window pos=%llu < ctx->current.cur_pos=0x%x\n", + pos, ctx->current.cur_pos); return FLASH_ERR_PARM_ERROR; } if ((pos + len) > (ctx->current.cur_pos + ctx->current.size)) { @@ -147,41 +151,38 @@ static int hiomap_window_valid(struct ipmi_hiomap *ctx, uint64_t pos, * may be straddling the current window so store values */ if ((pos + ctx->current.size) <= (ctx->current.cur_pos + ctx->current.size)) { - prlog(PR_TRACE, "%s OK pos=%llu " + hiomap_trace("OK pos=%llu " "ctx->current.size=0x%x " "ctx->current.cur_pos=0x%x\n", - __func__, pos, ctx->current.size, ctx->current.cur_pos); } else { - prlog(PR_TRACE, "%s CHECKING further pos=%llu " + hiomap_trace("CHECKING further pos=%llu " "for len=%llu ctx->current.size=0x%x " "ctx->current.cur_pos=0x%x\n", - __func__, pos, len, ctx->current.size, ctx->current.cur_pos); if ((pos + ctx->current.adjusted_window_size) <= (ctx->current.cur_pos + ctx->current.size)) { - prlog(PR_TRACE, "%s OK use ADJUSTED pos=%llu " + hiomap_trace("OK use ADJUSTED pos=%llu " "adjusted_len=%i for len=%llu " "ctx->current.size=0x%x " "ctx->current.cur_pos=0x%x\n", - __func__, pos, ctx->current.adjusted_window_size, len, ctx->current.size, ctx->current.cur_pos); } else { - prlog(PR_TRACE, "%s we need to MOVE the window\n", __func__); + hiomap_trace("we need to MOVE the window\n"); return FLASH_ERR_PARM_ERROR; } } } - prlog(PR_TRACE, "%s ALL GOOD, no move needed\n", __func__); + hiomap_trace("ALL GOOD, no move needed\n"); return 0; } @@ -202,7 +203,7 @@ static void move_cb(struct ipmi_msg *msg) int lock_try_counter = 10; if ((msg->resp_size != 8) || (msg->cc != IPMI_CC_NO_ERROR) || (msg->data[1] != ctx->inflight_seq)) { - prlog(PR_TRACE, "Command %u (4=READ 6=WRITE): move_cb " + hiomap_trace("Command %u (4=READ 6=WRITE): " "Unexpected results to check: response size we " "expect 8 but received %u, ipmi cc=%d " "(should be zero), expected ipmi seq %i but got " @@ -217,10 +218,9 @@ static void move_cb(struct ipmi_msg *msg) ctx->window_state = closed_window; goto out; } else { - prlog(PR_TRACE, "Entered %s for %s window from " + hiomap_trace("Entered for %s window from " "OLD block pos 0x%x for 0x%x bytes at " "lpc_addr 0x%x ipmi seq=%i\n", - __func__, (msg->data[0] == HIOMAP_C_CREATE_READ_WINDOW) ? "read" : "write", ctx->current.cur_pos, ctx->current.size, @@ -285,19 +285,18 @@ static void move_cb(struct ipmi_msg *msg) */ *ctx->active_size = (ctx->current.cur_pos + ctx->current.size) - ctx->requested_pos; ctx->current.adjusted_window_size = (ctx->current.cur_pos + ctx->current.size) - ctx->requested_pos; - prlog(PR_TRACE, "%s VALID MOVE ADJUSTMENT " + hiomap_trace("VALID MOVE ADJUSTMENT " "*ctx->active_size=%llu " "ctx->requested_pos=%llu " "ctx->current.adjusted_window_size=%i\n", - __func__, *ctx->active_size, ctx->requested_pos, ctx->current.adjusted_window_size); } if (ctx->requested_len != 0 && *ctx->active_size == 0) { - prlog(PR_NOTICE, "%s Invalid window properties: len: %llu, size: %llu\n", - __func__, ctx->requested_len, *ctx->active_size); + hiomap_notice("Invalid window properties: len: %llu, size: %llu\n", + ctx->requested_len, *ctx->active_size); ctx->cc = OPAL_PARAMETER; ctx->window_state = closed_window; goto out; @@ -308,7 +307,7 @@ static void move_cb(struct ipmi_msg *msg) else ctx->window_state = write_window; - prlog(PR_TRACE, "Opened %s window to NEW block pos 0x%x for 0x%x bytes " + hiomap_trace("Opened %s window to NEW block pos 0x%x for 0x%x bytes " "at lpc_addr 0x%x ipmi seq=%i active size=%llu " "adjusted_window_size=%i\n", (msg->data[0] == HIOMAP_C_CREATE_READ_WINDOW) ? "read" : "write", @@ -319,7 +318,7 @@ static void move_cb(struct ipmi_msg *msg) *ctx->active_size, ctx->current.adjusted_window_size); -out: prlog(PR_TRACE, "Exiting the move window callback " +out: hiomap_trace("Exiting the move window callback " "transaction ipmi seq=%i\n", ctx->inflight_seq); unlock(&ctx->lock); @@ -339,15 +338,14 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) /* We at least need the command and sequence */ if (msg->resp_size < 2) { - prerror("Illegal response size: %u\n", msg->resp_size); + hiomap_error("Illegal response size: %u\n", msg->resp_size); res->cc = IPMI_ERR_UNSPECIFIED; ipmi_free_msg(msg); return; } if (msg->data[1] != ctx->inflight_seq) { - prlog(PR_TRACE, "%s Unmatched ipmi sequence number: wanted %u got %u\n", - __func__, + hiomap_trace("Unmatched ipmi sequence number: wanted %u got %u\n", ctx->inflight_seq, msg->data[1]); res->cc = IPMI_ERR_UNSPECIFIED; @@ -362,7 +360,7 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) ctx->cc = IPMI_CC_NO_ERROR; if (msg->resp_size != 6) { - prerror("%u: Unexpected response size: %u\n", msg->data[0], + hiomap_error("%u: Unexpected response size: %u\n", msg->data[0], msg->resp_size); res->cc = IPMI_ERR_UNSPECIFIED; break; @@ -370,7 +368,7 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) ctx->version = msg->data[2]; if (ctx->version < 2) { - prerror("Failed to negotiate protocol v2 or higher: %d\n", + hiomap_error("Failed to negotiate protocol v2 or higher: %d\n", ctx->version); res->cc = IPMI_ERR_UNSPECIFIED; break; @@ -387,7 +385,7 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) ctx->cc = IPMI_CC_NO_ERROR; if (msg->resp_size != 6) { - prerror("%u: Unexpected response size: %u\n", msg->data[0], + hiomap_error("%u: Unexpected response size: %u\n", msg->data[0], msg->resp_size); res->cc = IPMI_ERR_UNSPECIFIED; break; @@ -406,16 +404,14 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) case HIOMAP_C_ERASE: case HIOMAP_C_RESET: if (msg->resp_size != 2) { - prerror("%s %u: Unexpected response size: %u\n", - __func__, + hiomap_error("%u: Unexpected response size: %u\n", msg->data[0], msg->resp_size); res->cc = IPMI_ERR_UNSPECIFIED; ctx->cc = OPAL_HARDWARE; break; } else { - prlog(PR_TRACE, "%s Command=%u 1=RESET 7=DIRTY 8=FLUSH 9=ACK 10=ERASE ipmi seq=%u ctx->inflight_seq=%u\n", - __func__, + hiomap_trace("Command=%u 1=RESET 7=DIRTY 8=FLUSH 9=ACK 10=ERASE ipmi seq=%u ctx->inflight_seq=%u\n", msg->data[0], msg->data[1], ctx->inflight_seq); @@ -423,8 +419,8 @@ static void ipmi_hiomap_cmd_cb(struct ipmi_msg *msg) } break; default: - prlog(PR_WARNING, "%s Unimplemented command handler: %u\n", - __func__, msg->data[0]); + hiomap_warn("Unimplemented command handler: %u\n", + msg->data[0]); break; }; ipmi_free_msg(msg); @@ -450,7 +446,7 @@ static int hiomap_wait_for_cc(struct ipmi_hiomap *ctx, int *cc, uint8_t *seq, ui uint64_t timeout_counter; int rc; - prlog(PR_TRACE, "Start wait for cc ipmi seq=%i *cc=%i ticks=%llu\n", *seq, *cc, ticks); + hiomap_trace("Start wait for cc ipmi seq=%i *cc=%i ticks=%llu\n", *seq, *cc, ticks); rc = 0; if (this_cpu()->tb_invalid) { /* @@ -463,15 +459,15 @@ static int hiomap_wait_for_cc(struct ipmi_hiomap *ctx, int *cc, uint8_t *seq, ui lock(&ctx->lock); ctx->window_state = closed_window; ++ctx->missed_cc_count; - prlog(PR_NOTICE, "%s tb_invalid, CLOSING WINDOW for cc " + hiomap_notice("tb_invalid, CLOSING WINDOW for cc " "ipmi seq=%i ctx->missed_cc_count=%i\n", - __func__, *seq, ctx->missed_cc_count); + *seq, ctx->missed_cc_count); unlock(&ctx->lock); rc = FLASH_ERR_ASYNC_WORK; } - prlog(PR_NOTICE, "%s tb_invalid, hopefully this will " + hiomap_notice("tb_invalid, hopefully this will " "retry/recover rc=%i\n", - __func__, rc); + rc); return rc; } start_time = mftb(); @@ -485,7 +481,7 @@ static int hiomap_wait_for_cc(struct ipmi_hiomap *ctx, int *cc, uint8_t *seq, ui ipmi_hiomap_ticks = IPMI_HIOMAP_TICKS; } - prlog(PR_TRACE, "wait_time=%llu ipmi_hiomap_ticks=%llu ipmi seq=%i " + hiomap_trace("wait_time=%llu ipmi_hiomap_ticks=%llu ipmi seq=%i " "ctx->missed_cc_count=%i\n", wait_time, ticks, *seq, ctx->missed_cc_count); /* @@ -499,27 +495,27 @@ static int hiomap_wait_for_cc(struct ipmi_hiomap *ctx, int *cc, uint8_t *seq, ui wait_time = tb_to_msecs(now - start_time); } if (*cc == IPMI_CC_NO_ERROR) { - prlog(PR_TRACE, "Break cc ipmi seq=%i " + hiomap_trace("Break cc ipmi seq=%i " "ctx->missed_cc_count=%i\n", *seq, ctx->missed_cc_count); break; } } - prlog(PR_TRACE, "Status CHECK wait_for_cc wait_time=%llu *cc=%i " + hiomap_trace("Status CHECK wait_time=%llu *cc=%i " "ipmi seq=%i ctx->missed_cc_count=%i\n", wait_time, *cc, *seq, ctx->missed_cc_count); if (*cc != IPMI_CC_NO_ERROR) { lock(&ctx->lock); ctx->window_state = closed_window; ++ctx->missed_cc_count; - prlog(PR_TRACE, "CLOSING WINDOW for cc ipmi seq=%i " + hiomap_trace("CLOSING WINDOW for cc ipmi seq=%i " "ctx->missed_cc_count=%i\n", *seq, ctx->missed_cc_count); unlock(&ctx->lock); rc = FLASH_ERR_ASYNC_WORK; } - prlog(PR_TRACE, "Stop wait for *cc=%i ipmi seq=%i " + hiomap_trace("Stop wait for *cc=%i ipmi seq=%i " "ctx->missed_cc_count=%i\n", *cc, *seq, ctx->missed_cc_count); return rc; @@ -572,8 +568,8 @@ static int hiomap_get_info(struct ipmi_hiomap *ctx) rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_ACK_DEFAULT); if (rc) { - prlog(PR_TRACE, "%s hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_ACK_DEFAULT); + hiomap_trace("hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_ACK_DEFAULT); } return rc; @@ -621,8 +617,8 @@ static int hiomap_get_flash_info(struct ipmi_hiomap *ctx) rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_ACK_DEFAULT); if (rc) { - prlog(PR_TRACE, "%s hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_ACK_DEFAULT); + hiomap_trace("hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_ACK_DEFAULT); } return rc; @@ -705,7 +701,7 @@ static int hiomap_window_move(struct ipmi_hiomap *ctx, uint8_t command, rc = hiomap_queue_msg(ctx, msg); if (rc) { - prlog(PR_NOTICE, "%s move queue msg failed: rc=%d\n", __func__, rc); + hiomap_notice("move queue msg failed: rc=%d\n", rc); return rc; } @@ -734,7 +730,7 @@ static int hiomap_mark_dirty(struct ipmi_hiomap *ctx, uint64_t offset, unlock(&ctx->lock); if (state != write_window) { - prlog(PR_NOTICE, "%s failed: state=%i\n", __func__, state); + hiomap_notice("failed: state=%i\n", state); return FLASH_ERR_PARM_ERROR; } @@ -753,12 +749,12 @@ static int hiomap_mark_dirty(struct ipmi_hiomap *ctx, uint64_t offset, rc = hiomap_queue_msg(ctx, msg); if (rc) { - prlog(PR_NOTICE, "%s dirty queue msg failed: rc=%d\n", __func__, rc); + hiomap_notice("dirty queue msg failed: rc=%d\n", rc); return rc; } - prlog(PR_TRACE, "%s Start to mark flash dirty at pos %llu size %llu bytes ipmi seq=%i\n", - __func__, offset, size, dirty_seq); + hiomap_trace("Start to mark flash dirty at pos %llu size %llu bytes ipmi seq=%i\n", + offset, size, dirty_seq); return 0; } @@ -782,7 +778,7 @@ static int hiomap_flush(struct ipmi_hiomap *ctx) unlock(&ctx->lock); if (state != write_window) { - prlog(PR_NOTICE, "%s failed: state=%i\n", __func__, state); + hiomap_notice("failed: state=%i\n", state); return FLASH_ERR_PARM_ERROR; } @@ -796,11 +792,11 @@ static int hiomap_flush(struct ipmi_hiomap *ctx) rc = hiomap_queue_msg(ctx, msg); if (rc) { - prlog(PR_NOTICE, "%s flush queue msg failed: rc=%d\n", __func__, rc); + hiomap_notice("flush queue msg failed: rc=%d\n", rc); return rc; } - prlog(PR_TRACE, "%s Start to flush writes ipmi seq=%i\n", __func__, flush_seq); + hiomap_trace("Start to flush writes ipmi seq=%i\n", flush_seq); return 0; } @@ -840,24 +836,24 @@ static int hiomap_ack(struct ipmi_hiomap *ctx, uint8_t ack) bmc_platform->sw->ipmi_oem_hiomap_cmd, ipmi_hiomap_cmd_cb, &ack_res, req, sizeof(req), 2); - prlog(PR_TRACE, "%s SENDING req[1]=%i\n", __func__, req[1]); + hiomap_trace("SENDING req[1]=%i\n", req[1]); rc = hiomap_queue_msg(ctx, msg); lock(&ctx->lock); ctx->bl.flags = orig_flags; unlock(&ctx->lock); if (rc) { - prlog(PR_NOTICE, "%s queue msg failed: rc=%d\n", __func__, rc); + hiomap_notice("queue msg failed: rc=%d\n", rc); return rc; } rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_ACK_DEFAULT); if (rc) { - prlog(PR_TRACE, "%s hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_ACK_DEFAULT); + hiomap_trace("hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_ACK_DEFAULT); return rc; } - prlog(PR_NOTICE, "%s Acked events: 0x%x\n", __func__, ack); + hiomap_notice("Acked events: 0x%x\n", ack); return 0; } @@ -884,7 +880,7 @@ static int hiomap_erase(struct ipmi_hiomap *ctx, uint64_t offset, unlock(&ctx->lock); if (state != write_window) { - prlog(PR_NOTICE, "%s failed: state=%i\n", __func__, state); + hiomap_notice("failed: state=%i\n", state); return FLASH_ERR_PARM_ERROR; } @@ -903,12 +899,11 @@ static int hiomap_erase(struct ipmi_hiomap *ctx, uint64_t offset, rc = hiomap_queue_msg(ctx, msg); if (rc) { - prlog(PR_NOTICE, "%s erase queue msg failed: rc=%d\n", __func__, rc); + hiomap_notice("erase queue msg failed: rc=%d\n", rc); return rc; } - prlog(PR_TRACE, "%s Erasing flash at pos %llu for size %llu\n", - __func__, + hiomap_trace("Erasing flash at pos %llu for size %llu\n", offset, size); return 0; @@ -924,7 +919,7 @@ static bool hiomap_reset(struct ipmi_hiomap *ctx) int tmp_sync_flags; int rc; - prlog(PR_NOTICE, "%s Reset ENTRY\n", __func__); + hiomap_notice("Reset ENTRY\n"); reset_res.ctx = ctx; reset_res.cc = -1; @@ -954,19 +949,19 @@ static bool hiomap_reset(struct ipmi_hiomap *ctx) unlock(&ctx->lock); if (rc) { - prlog(PR_NOTICE, "%s reset queue msg failed: rc=%d\n", __func__, rc); + hiomap_notice("reset queue msg failed: rc=%d\n", rc); return false; } rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_ACK_DEFAULT); if (rc) { - prlog(PR_NOTICE, "%s hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_ACK_DEFAULT); + hiomap_notice("hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_ACK_DEFAULT); return false; } - prlog(PR_NOTICE, "%s Reset EXIT\n", __func__); + hiomap_notice("Reset EXIT\n"); return true; } @@ -974,15 +969,13 @@ static void hiomap_event(uint8_t events, void *context) { struct ipmi_hiomap *ctx = context; - prlog(PR_NOTICE, "%s Received events: 0x%x ctx->bmc_state=%i\n", - __func__, + hiomap_notice("Received events: 0x%x ctx->bmc_state=%i\n", events, ctx->bmc_state); lock(&ctx->lock); ctx->bmc_state = events | (ctx->bmc_state & HIOMAP_E_ACK_MASK); - prlog(PR_NOTICE, "%s Updated bmc_state Received events: 0x%x ctx->bmc_state=%i\n", - __func__, + hiomap_notice("Updated bmc_state Received events: 0x%x ctx->bmc_state=%i\n", events, ctx->bmc_state); unlock(&ctx->lock); @@ -997,7 +990,7 @@ static int lpc_window_read(struct ipmi_hiomap *ctx, uint32_t pos, if ((ctx->current.lpc_addr + ctx->current.size) < (off + len)) return FLASH_ERR_PARM_ERROR; - prlog(PR_TRACE, "LPC Reading at 0x%08x for 0x%08x offset: 0x%08x\n", + hiomap_trace("LPC Reading at 0x%08x for 0x%08x offset: 0x%08x\n", pos, len, off); while(len) { @@ -1017,7 +1010,7 @@ static int lpc_window_read(struct ipmi_hiomap *ctx, uint32_t pos, chunk = 1; } if (rc) { - prlog(PR_ERR, "lpc_read failure %d to FW 0x%08x\n", rc, off); + hiomap_error("lpc_read failure %d to FW 0x%08x\n", rc, off); return rc; } len -= chunk; @@ -1045,7 +1038,7 @@ static int lpc_window_write(struct ipmi_hiomap *ctx, uint32_t pos, if ((ctx->current.lpc_addr + ctx->current.size) < (off + len)) return FLASH_ERR_PARM_ERROR; - prlog(PR_TRACE, "LPC Writing at 0x%08x for 0x%08x offset: 0x%08x\n", + hiomap_trace("LPC Writing at 0x%08x for 0x%08x offset: 0x%08x\n", pos, len, off); while(len) { @@ -1061,7 +1054,7 @@ static int lpc_window_write(struct ipmi_hiomap *ctx, uint32_t pos, chunk = 1; } if (rc) { - prlog(PR_ERR, "%s failure %d to FW 0x%08x\n", __func__, rc, off); + hiomap_error("failure %d to FW 0x%08x\n", rc, off); return rc; } len -= chunk; @@ -1081,7 +1074,7 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx) lock(&ctx->lock); status = ctx->bmc_state; - prlog(PR_TRACE, "%s status=%i\n", __func__, status); + hiomap_trace("status=%i\n", status); /* * Immediately clear the ackable events to make sure we don't race to @@ -1105,16 +1098,16 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx) * recovered. */ if (status & HIOMAP_E_PROTOCOL_RESET) { - prlog(PR_TRACE, "%s status=HIOMAP_E_PROTOCOL_RESET\n", __func__); + hiomap_trace("status=HIOMAP_E_PROTOCOL_RESET\n"); } if (status & HIOMAP_E_WINDOW_RESET) { - prlog(PR_TRACE, "%s status=HIOMAP_E_WINDOW_RESET\n", __func__); + hiomap_trace("status=HIOMAP_E_WINDOW_RESET\n"); } if (status & (HIOMAP_E_PROTOCOL_RESET | HIOMAP_E_WINDOW_RESET)) { ctx->window_state = closed_window; - prlog(PR_TRACE, "%s closed_window\n", __func__); + hiomap_trace("closed_window\n"); } unlock(&ctx->lock); @@ -1133,32 +1126,32 @@ static int ipmi_hiomap_handle_events(struct ipmi_hiomap *ctx) * the BMC's cache must be valid if opening the window is successful. */ if (status & HIOMAP_E_ACK_MASK) { - prlog(PR_TRACE, "%s status=%i HIOMAP_E_ACK_MASK so TRY to ACK\n", __func__, status); + hiomap_trace("status=%i HIOMAP_E_ACK_MASK so TRY to ACK\n", status); /* ACK is unversioned, can send it if the daemon is ready */ rc = hiomap_ack(ctx, status & HIOMAP_E_ACK_MASK); if (rc) { - prlog(PR_NOTICE, "%s Failed to ack events rc=%i: status & HIOMAP_E_ACK_MASK=0x%x status=%i\n", - __func__, rc, (status & HIOMAP_E_ACK_MASK), status); + hiomap_notice("Failed to ack events rc=%i: status & HIOMAP_E_ACK_MASK=0x%x status=%i\n", + rc, (status & HIOMAP_E_ACK_MASK), status); goto restore; } } if (status & HIOMAP_E_PROTOCOL_RESET) { - prlog(PR_INFO, "%s Protocol was reset\n", __func__); + hiomap_info("Protocol was reset\n"); rc = hiomap_get_info(ctx); if (rc) { - prerror("%s Failure to renegotiate after protocol reset\n", __func__); + hiomap_error("Failure to renegotiate after protocol reset\n"); goto restore; } rc = hiomap_get_flash_info(ctx); if (rc) { - prerror("Failure to fetch flash info after protocol reset\n"); + hiomap_error("Failure to fetch flash info after protocol reset\n"); goto restore; } - prlog(PR_INFO, "%s Restored state after protocol reset\n", __func__); + hiomap_info("Restored state after protocol reset\n"); } /* @@ -1176,9 +1169,9 @@ restore: * than necessary, but never less than necessary. */ lock(&ctx->lock); - prlog(PR_TRACE, "%s PRE restore status=%i PRE ctx->bmc_state=%i rc=%i\n", __func__, status, ctx->bmc_state, rc); + hiomap_trace("PRE restore status=%i PRE ctx->bmc_state=%i rc=%i\n", status, ctx->bmc_state, rc); ctx->bmc_state |= (status & HIOMAP_E_ACK_MASK); - prlog(PR_TRACE, "%s POST restored status=%i POST ctx->bmc_state=%i rc=%i\n", __func__, status, ctx->bmc_state, rc); + hiomap_trace("POST restored status=%i POST ctx->bmc_state=%i rc=%i\n", status, ctx->bmc_state, rc); unlock(&ctx->lock); return rc; @@ -1202,7 +1195,7 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos, rc = ipmi_hiomap_handle_events(ctx); if (rc) { - prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc); + hiomap_notice("ipmi_hiomap_handle_events failed: rc=%d\n", rc); goto out; } @@ -1218,7 +1211,7 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos, } unlock(&ctx->lock); - prlog(PR_TRACE, "Flash READ at pos %llu for %llu bytes\n", pos, len); + hiomap_trace("Flash READ at pos %llu for %llu bytes\n", pos, len); while (len > 0) { lock(&ctx->lock); state = ctx->window_state; @@ -1228,15 +1221,15 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos, rc = hiomap_window_move(ctx, HIOMAP_C_CREATE_READ_WINDOW, pos, len, &size); if (rc) { - prlog(PR_NOTICE, "%s hiomap_window_move failed: rc=%d\n", - __func__, rc); + hiomap_notice("hiomap_window_move failed: rc=%d\n", + rc); goto out; } } else { rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_HIOMAP_TICKS_DEFAULT); if (rc) { - prlog(PR_TRACE, "%s move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_HIOMAP_TICKS_DEFAULT); + hiomap_trace("move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_HIOMAP_TICKS_DEFAULT); goto out; } } @@ -1251,14 +1244,14 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos, * just double-checking */ if (ctx->cc != IPMI_CC_NO_ERROR) { - prlog(PR_NOTICE, "%s failed: cc=%d\n", __func__, ctx->cc); + hiomap_notice("failed: cc=%d\n", ctx->cc); rc = OPAL_HARDWARE; goto out; } /* Perform the read for this window */ rc = lpc_window_read(ctx, pos, buf, size); if (rc) { - prlog(PR_NOTICE, "%s lpc_window_read failed: rc=%d\n", __func__, rc); + hiomap_notice("lpc_window_read failed: rc=%d\n", rc); goto out; } @@ -1267,7 +1260,7 @@ static int ipmi_hiomap_read(struct blocklevel_device *bl, uint64_t pos, rc = hiomap_window_valid(ctx, pos, size); unlock(&ctx->lock); if (rc) { - prlog(PR_NOTICE, "%s hiomap_window_valid failed: rc=%d\n", __func__, rc); + hiomap_notice("hiomap_window_valid failed: rc=%d\n", rc); goto out; } @@ -1303,7 +1296,7 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos, rc = ipmi_hiomap_handle_events(ctx); if (rc) { - prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc); + hiomap_notice("ipmi_hiomap_handle_events failed: rc=%d\n", rc); goto out; } @@ -1319,7 +1312,7 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos, } unlock(&ctx->lock); - prlog(PR_TRACE, "Flash WRITE at pos %llu for %llu bytes\n", pos, len); + hiomap_trace("Flash WRITE at pos %llu for %llu bytes\n", pos, len); while (len > 0) { lock(&ctx->lock); state = ctx->window_state; @@ -1329,15 +1322,15 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos, rc = hiomap_window_move(ctx, HIOMAP_C_CREATE_WRITE_WINDOW, pos, len, &size); if (rc) { - prlog(PR_NOTICE, "%s hiomap_window_move failed: rc=%d\n", - __func__, rc); + hiomap_notice("hiomap_window_move failed: rc=%d\n", + rc); goto out; } } else { rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); if (rc) { - prlog(PR_TRACE, "%s move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_LONG_TICKS); + hiomap_trace("move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_LONG_TICKS); goto out; } } @@ -1348,7 +1341,7 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos, if (state == write_window) { if (ctx->cc != IPMI_CC_NO_ERROR) { - prlog(PR_NOTICE, "%s failed: cc=%d\n", __func__, ctx->cc); + hiomap_notice("failed: cc=%d\n", ctx->cc); rc = OPAL_HARDWARE; goto out; } @@ -1356,7 +1349,7 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos, /* Perform the write for this window */ rc = lpc_window_write(ctx, pos, buf, size); if (rc) { - prlog(PR_NOTICE, "%s lpc_window_write failed: rc=%d\n", __func__, rc); + hiomap_notice("lpc_window_write failed: rc=%d\n", rc); goto out; } @@ -1371,13 +1364,13 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos, rc = hiomap_mark_dirty(ctx, pos, size); if (rc) { - prlog(PR_NOTICE, "%s hiomap_mark_dirty failed: rc=%d\n", __func__, rc); + hiomap_notice("hiomap_mark_dirty failed: rc=%d\n", rc); goto out; } rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); if (rc) { - prlog(PR_TRACE, "%s dirty hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_LONG_TICKS); + hiomap_trace("dirty hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_LONG_TICKS); goto out; } @@ -1389,13 +1382,13 @@ static int ipmi_hiomap_write(struct blocklevel_device *bl, uint64_t pos, */ rc = hiomap_flush(ctx); if (rc) { - prlog(PR_NOTICE, "%s hiomap_flush failed: rc=%d\n", __func__, rc); + hiomap_notice("hiomap_flush failed: rc=%d\n", rc); goto out; } rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); if (rc) { - prlog(PR_TRACE, "%s flush hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_LONG_TICKS); + hiomap_trace("flush hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_LONG_TICKS); goto out; } @@ -1431,7 +1424,7 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos, rc = ipmi_hiomap_handle_events(ctx); if (rc) { - prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc); + hiomap_notice("ipmi_hiomap_handle_events failed: rc=%d\n", rc); goto out; } @@ -1446,7 +1439,7 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos, } unlock(&ctx->lock); - prlog(PR_TRACE, "Flash ERASE at pos %llu for %llu bytes\n", pos, len); + hiomap_trace("Flash ERASE at pos %llu for %llu bytes\n", pos, len); while (len > 0) { lock(&ctx->lock); @@ -1457,15 +1450,15 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos, rc = hiomap_window_move(ctx, HIOMAP_C_CREATE_WRITE_WINDOW, pos, len, &size); if (rc) { - prlog(PR_NOTICE, "%s hiomap_window_move failed: rc=%d\n", - __func__, rc); + hiomap_notice("hiomap_window_move failed: rc=%d\n", + rc); goto out; } } else { rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); if (rc) { - prlog(PR_TRACE, "%s move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_LONG_TICKS); + hiomap_trace("move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_LONG_TICKS); goto out; } } @@ -1475,19 +1468,19 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos, unlock(&ctx->lock); if (state == write_window) { if (ctx->cc != IPMI_CC_NO_ERROR) { - prlog(PR_NOTICE, "%s failed: cc=%d\n", __func__, ctx->cc); + hiomap_notice("failed: cc=%d\n", ctx->cc); rc = OPAL_HARDWARE; goto out; } rc = hiomap_erase(ctx, pos, size); if (rc) { - prlog(PR_NOTICE, "%s hiomap_erase failed: rc=%d\n", __func__, rc); + hiomap_notice("hiomap_erase failed: rc=%d\n", rc); goto out; } rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); if (rc) { - prlog(PR_TRACE, "%s move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_LONG_TICKS); + hiomap_trace("move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_LONG_TICKS); goto out; } @@ -1497,13 +1490,13 @@ static int ipmi_hiomap_erase(struct blocklevel_device *bl, uint64_t pos, */ rc = hiomap_flush(ctx); if (rc) { - prlog(PR_NOTICE, "%s hiomap_flush failed: rc=%d\n", __func__, rc); + hiomap_notice("hiomap_flush failed: rc=%d\n", rc); goto out; } rc = hiomap_wait_for_cc(ctx, &ctx->cc, &ctx->inflight_seq, IPMI_LONG_TICKS); if (rc) { - prlog(PR_TRACE, "%s move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", - __func__, rc, IPMI_LONG_TICKS); + hiomap_trace("move hiomap_wait_for_cc failed: rc=%d ticks=%i\n", + rc, IPMI_LONG_TICKS); goto out; } @@ -1532,13 +1525,13 @@ static int ipmi_hiomap_get_flash_info(struct blocklevel_device *bl, rc = ipmi_hiomap_handle_events(ctx); if (rc) { - prlog(PR_NOTICE, "%s ipmi_hiomap_handle_events failed: rc=%d\n", __func__, rc); + hiomap_notice("ipmi_hiomap_handle_events failed: rc=%d\n", rc); return rc; } rc = hiomap_get_flash_info(ctx); if (rc) { - prlog(PR_NOTICE, "%s hiomap_get_flash failed: rc=%d\n", __func__, rc); + hiomap_notice("hiomap_get_flash_info failed: rc=%d\n", rc); return rc; } @@ -1587,37 +1580,37 @@ int ipmi_hiomap_init(struct blocklevel_device **bl) /* Ack all pending ack-able events to avoid spurious failures */ rc = hiomap_ack(ctx, HIOMAP_E_ACK_MASK); if (rc) { - prlog(PR_NOTICE, "%s Failed to ack events: 0x%x\n", - __func__, HIOMAP_E_ACK_MASK); + hiomap_notice("Failed to ack events: 0x%x\n", + HIOMAP_E_ACK_MASK); goto err; } rc = ipmi_sel_register(CMD_OP_HIOMAP_EVENT, hiomap_event, ctx); if (rc < 0) { - prerror("%s Failed ipmi_sel_register: %d\n", __func__, rc); + hiomap_error("Failed ipmi_sel_register: %d\n", rc); goto err; } /* Negotiate protocol behaviour */ rc = hiomap_get_info(ctx); if (rc) { - prerror("%s Failed to get hiomap parameters: %d\n", __func__, rc); + hiomap_error("Failed to get hiomap parameters: %d\n", rc); goto err; } /* Grab the flash parameters */ rc = hiomap_get_flash_info(ctx); if (rc) { - prerror("%s Failed to get flash parameters: %d\n", __func__, rc); + hiomap_error("Failed to get flash parameters: %d\n", rc); goto err; } - prlog(PR_NOTICE, "Negotiated hiomap protocol v%u\n", ctx->version); - prlog(PR_NOTICE, "Block size is %uKiB\n", + hiomap_notice("Negotiated hiomap protocol v%u\n", ctx->version); + hiomap_notice("Block size is %uKiB\n", 1 << (ctx->block_size_shift - 10)); - prlog(PR_NOTICE, "BMC suggested flash timeout of %us\n", ctx->timeout); - prlog(PR_NOTICE, "Flash size is %uMiB\n", ctx->total_size >> 20); - prlog(PR_NOTICE, "Erase granule size is %uKiB\n", + hiomap_notice("BMC suggested flash timeout of %us\n", ctx->timeout); + hiomap_notice("Flash size is %uMiB\n", ctx->total_size >> 20); + hiomap_notice("Erase granule size is %uKiB\n", ctx->erase_granule >> 10); ctx->bl.keep_alive = 0;