From patchwork Mon Apr 24 04:45:41 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Benjamin Herrenschmidt X-Patchwork-Id: 754091 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.ozlabs.org (lists.ozlabs.org [103.22.144.68]) (using TLSv1.2 with cipher ADH-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 3wBDM3513Hz9s8T for ; Mon, 24 Apr 2017 14:46:23 +1000 (AEST) Received: from lists.ozlabs.org (lists.ozlabs.org [IPv6:2401:3900:2:1::3]) by lists.ozlabs.org (Postfix) with ESMTP id 3wBDM33X7zzDqFS for ; Mon, 24 Apr 2017 14:46:23 +1000 (AEST) X-Original-To: skiboot@lists.ozlabs.org Delivered-To: skiboot@lists.ozlabs.org Received: from gate.crashing.org (gate.crashing.org [63.228.1.57]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (No client certificate requested) by lists.ozlabs.org (Postfix) with ESMTPS id 3wBDLw0gQ3zDq5W for ; Mon, 24 Apr 2017 14:46:15 +1000 (AEST) Received: from pasglop.ozlabs.ibm.com (localhost.localdomain [127.0.0.1]) by gate.crashing.org (8.14.1/8.13.8) with ESMTP id v3O4jqAM018334; Sun, 23 Apr 2017 23:45:55 -0500 From: Benjamin Herrenschmidt To: skiboot@lists.ozlabs.org Date: Mon, 24 Apr 2017 14:45:41 +1000 Message-Id: <20170424044544.23810-2-benh@kernel.crashing.org> X-Mailer: git-send-email 2.9.3 In-Reply-To: <20170424044544.23810-1-benh@kernel.crashing.org> References: <20170424044544.23810-1-benh@kernel.crashing.org> Subject: [Skiboot] [PATCH 2/5] i2c: Improve logging X-BeenThere: skiboot@lists.ozlabs.org X-Mailman-Version: 2.1.23 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" Log more registers, cleanup the output alignment, and timestamp start/stop of requests Signed-off-by: Benjamin Herrenschmidt Reviewed-by: Oliver O'Halloran --- hw/p8-i2c.c | 46 +++++++++++++++++++++++++++++++--------------- 1 file changed, 31 insertions(+), 15 deletions(-) diff --git a/hw/p8-i2c.c b/hw/p8-i2c.c index 2216635..52520dd 100644 --- a/hw/p8-i2c.c +++ b/hw/p8-i2c.c @@ -229,10 +229,10 @@ struct p8_i2c_request { }; static void p8_i2c_print_debug_info(struct p8_i2c_master_port *port, - struct i2c_request *req) + struct i2c_request *req, uint64_t end_time) { struct p8_i2c_master *master = port->master; - uint64_t cmd, mode, stat, estat, intr; + uint64_t cmd, mode, stat, estat, intm, intc; int rc; /* Print master and request structure bits */ @@ -247,6 +247,10 @@ static void p8_i2c_print_debug_info(struct p8_i2c_master_port *port, req->dev_addr, req->offset_bytes, req->offset, req->rw_len); + log_simple_error(&e_info(OPAL_RC_I2C_TRANSFER), "I2C: " + " start_time=%016llx end_time=%016llx (duration=%016llx)\n", + master->start_time, end_time, end_time - master->start_time); + /* Dump the current state of i2c registers */ rc = xscom_read(master->chip_id, master->xscom_base + I2C_CMD_REG, &cmd); @@ -277,16 +281,23 @@ static void p8_i2c_print_debug_info(struct p8_i2c_master_port *port, } rc = xscom_read(master->chip_id, master->xscom_base + I2C_INTR_MASK_REG, - &intr); + &intm); if (rc) { prlog(PR_DEBUG, "I2C: Failed to read INTR_MASK_REG\n"); - intr = 0ull; + intm = 0ull; + } + + rc = xscom_read(master->chip_id, master->xscom_base + I2C_INTR_COND_REG, + &intc); + if (rc) { + prlog(PR_DEBUG, "I2C: Failed to read INTR_COND_REG\n"); + intc = 0ull; } log_simple_error(&e_info(OPAL_RC_I2C_TRANSFER), "I2C: Register dump--\n" - "cmd:0x%016llx\tmode:0x%016llx\tstat:0x%016llx\n" - "estat:0x%016llx\tintr:0x%016llx\n", cmd, mode, stat, - estat, intr); + " cmd:0x%016llx\tmode:0x%016llx\tstat:0x%016llx\n" + " estat:0x%016llx\tintm:0x%016llx\tintc:0x%016llx\n", + cmd, mode, stat, estat, intm, intc); } static bool p8_i2c_has_irqs(struct p8_i2c_master *master) @@ -618,7 +629,7 @@ static int p8_i2c_reset_engine(struct p8_i2c_master *master) static void p8_i2c_status_error(struct p8_i2c_master_port *port, struct i2c_request *req, - uint64_t status) + uint64_t status, uint64_t end_time) { struct p8_i2c_master *master = port->master; int rc; @@ -630,7 +641,7 @@ static void p8_i2c_status_error(struct p8_i2c_master_port *port, if (!(status & (I2C_STAT_NACK_RCVD_ERR | I2C_STAT_PSEUDO_TIMEOUT))) { log_simple_error(&e_info(OPAL_RC_I2C_TRANSFER), "I2C: Transfer error occurred\n"); - p8_i2c_print_debug_info(port, req); + p8_i2c_print_debug_info(port, req, end_time); } p8_i2c_translate_error(req, status); @@ -826,12 +837,15 @@ static void p8_i2c_complete_offset(struct p8_i2c_master *master, } static void p8_i2c_status_cmd_completion(struct p8_i2c_master *master, - struct i2c_request *req) + struct i2c_request *req, + uint64_t end_time __unused) { int rc; DBG("Command completion, state=%d bytes_sent=%d\n", master->state, master->bytes_sent); + DBG(" start_time=%016llx end_time=%016llx (duration=%016llx)\n", + master->start_time, end_time, end_time - master->start_time); /* If we complete an offset, we probably need to transition * do a data read, check if that all makes sense @@ -858,7 +872,7 @@ static void p8_i2c_check_status(struct p8_i2c_master *master) { struct p8_i2c_master_port *port; struct i2c_request *req; - uint64_t status; + uint64_t status, now = mftb(); int rc; /* If we are idle, just return, we'll catch error conditions @@ -913,11 +927,11 @@ static void p8_i2c_check_status(struct p8_i2c_master *master) /* Mask status to avoid some unrelated bit overwriting * our pseudo-status "timeout" bit 63 */ - p8_i2c_status_error(port, req, status & I2C_STAT_ANY_ERR); + p8_i2c_status_error(port, req, status & I2C_STAT_ANY_ERR, now); } else if (status & I2C_STAT_DATA_REQ) p8_i2c_status_data_request(master, req, status); else if (status & I2C_STAT_CMD_COMP) - p8_i2c_status_cmd_completion(master, req); + p8_i2c_status_cmd_completion(master, req, now); } static int p8_i2c_check_initial_status(struct p8_i2c_master_port *port) @@ -1093,6 +1107,8 @@ static int p8_i2c_start_request(struct p8_i2c_master *master, } DBG("Command: %016llx, state: %d\n", cmd, master->state); + master->start_time = mftb(); + /* Send command */ rc = xscom_write(master->chip_id, master->xscom_base + I2C_CMD_REG, cmd); @@ -1272,10 +1288,10 @@ static void p8_i2c_timeout(struct timer *t __unused, void *data, uint64_t now) /* Allright, we have a request and it has timed out ... */ log_simple_error(&e_info(OPAL_RC_I2C_TIMEOUT), "I2C: Request timeout !\n"); - p8_i2c_print_debug_info(port, req); + p8_i2c_print_debug_info(port, req, now); /* Use the standard error path */ - p8_i2c_status_error(port, req, I2C_STAT_PSEUDO_TIMEOUT); + p8_i2c_status_error(port, req, I2C_STAT_PSEUDO_TIMEOUT, now); exit: unlock(&master->lock); }