From patchwork Mon Nov 4 13:29:45 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Deb McLemore X-Patchwork-Id: 1188952 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 476DJz3Lbhz9sP6 for ; Tue, 5 Nov 2019 00:33:39 +1100 (AEDT) Authentication-Results: ozlabs.org; dmarc=none (p=none dis=none) header.from=linux.ibm.com Received: from bilbo.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 476DJz1p26zF45k for ; Tue, 5 Nov 2019 00:33:39 +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 476DFx1fznzF43n for ; Tue, 5 Nov 2019 00:31:00 +1100 (AEDT) Received: from pps.filterd (m0098421.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.27/8.16.0.27) with SMTP id xA4DUo3G114110 for ; Mon, 4 Nov 2019 08:30:57 -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 2w2m6u2q8h-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 04 Nov 2019 08:30:54 -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 xA4DUIQG012942 for ; Mon, 4 Nov 2019 13:30:25 GMT Received: from b03cxnp08025.gho.boulder.ibm.com (b03cxnp08025.gho.boulder.ibm.com [9.17.130.17]) by ppma02wdc.us.ibm.com with ESMTP id 2w11e6v3x0-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT) for ; Mon, 04 Nov 2019 13:30:25 +0000 Received: from b03ledav002.gho.boulder.ibm.com (b03ledav002.gho.boulder.ibm.com [9.17.130.233]) by b03cxnp08025.gho.boulder.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id xA4DUOah62128396 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Mon, 4 Nov 2019 13:30:24 GMT Received: from b03ledav002.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id C029C13605E for ; Mon, 4 Nov 2019 13:30:24 +0000 (GMT) Received: from b03ledav002.gho.boulder.ibm.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 8601D136051 for ; Mon, 4 Nov 2019 13:30:24 +0000 (GMT) Received: from debmc-p50.localdomain (unknown [9.80.210.252]) by b03ledav002.gho.boulder.ibm.com (Postfix) with ESMTP for ; Mon, 4 Nov 2019 13:30:24 +0000 (GMT) Received: by debmc-p50.localdomain (Postfix, from userid 1000) id D364F6602B1; Mon, 4 Nov 2019 07:30:22 -0600 (CST) From: Deb McLemore To: skiboot@lists.ozlabs.org Date: Mon, 4 Nov 2019 07:29:45 -0600 Message-Id: <1572874189-32264-10-git-send-email-debmc@linux.ibm.com> X-Mailer: git-send-email 2.7.4 In-Reply-To: <1572874189-32264-1-git-send-email-debmc@linux.ibm.com> References: <1572874189-32264-1-git-send-email-debmc@linux.ibm.com> X-TM-AS-GCONF: 00 X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:, , definitions=2019-11-04_08:, , signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 priorityscore=1501 malwarescore=0 suspectscore=3 phishscore=0 bulkscore=0 spamscore=0 clxscore=1015 lowpriorityscore=0 mlxscore=0 impostorscore=0 mlxlogscore=999 adultscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.0.1-1908290000 definitions=main-1911040133 Subject: [Skiboot] [PATCH v2 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 98614f7..579af7b 100644 --- a/core/flash.c +++ b/core/flash.c @@ -40,8 +40,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; @@ -324,7 +327,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: @@ -371,6 +375,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 { @@ -390,6 +396,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; } @@ -400,6 +408,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_MASK; flash->bl->flags &= ASYNC_REQUIRED_MASK; /* release the flash before we allow next opal entry */ @@ -612,14 +622,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; @@ -629,6 +638,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 @@ -666,11 +677,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 */ 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; @@ -679,6 +694,8 @@ static int64_t opal_flash_op(enum flash_op op, uint64_t id, uint64_t offset, if (size - len) { /* Work remains */ schedule_timer(&flash->async.poller, 0); + 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); /* Don't release the flash */ return OPAL_ASYNC_COMPLETION; } else { @@ -693,9 +710,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_MASK; flash->bl->flags &= ASYNC_REQUIRED_MASK; return rc; @@ -898,7 +925,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;