[Skiboot] [PATCH 2/5] i2c: Improve logging
Oliver O'Halloran
oohall at gmail.com
Thu Apr 27 18:47:40 AEST 2017
Reviewed-by: Oliver O'Halloran <oohall at gmail.com>
On Mon, Apr 24, 2017 at 2:45 PM, Benjamin Herrenschmidt
<benh at kernel.crashing.org> wrote:
> Log more registers, cleanup the output alignment,
> and timestamp start/stop of requests
>
> Signed-off-by: Benjamin Herrenschmidt <benh at kernel.crashing.org>
> ---
> 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);
> }
> --
> 2.9.3
>
> _______________________________________________
> Skiboot mailing list
> Skiboot at lists.ozlabs.org
> https://lists.ozlabs.org/listinfo/skiboot
More information about the Skiboot
mailing list