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;