drivers: mailbox: qti-tcs: Update error logging
Provide more statistics when we are unable to send a RPMH message. Log
the time stamp when sending a request and receiving a response for each
TCS and print them, when we cannot find a free TCS to write to.
If the TCSes are busy to handle the request, return -EBUSY back to
mailbox framework which would then retry when the interrupt handler
finally gets a chance to run and schedules a tasklet. The tasklet calls
tx_done on the mailbox and retries the message.
Change-Id: I4452343e3ebcaabe3b3fc820489be722263135d8
Signed-off-by: Lina Iyer <ilina@codeaurora.org>
diff --git a/drivers/mailbox/qti-tcs.c b/drivers/mailbox/qti-tcs.c
index 6d0e913..aeee8d3 100644
--- a/drivers/mailbox/qti-tcs.c
+++ b/drivers/mailbox/qti-tcs.c
@@ -134,6 +134,9 @@
struct workqueue_struct *wq;
struct tcs_response_pool *resp_pool;
atomic_t tcs_in_use[MAX_POOL_SIZE];
+ /* Debug info */
+ u64 tcs_last_sent_ts[MAX_POOL_SIZE];
+ u64 tcs_last_recv_ts[MAX_POOL_SIZE];
atomic_t tcs_send_count[MAX_POOL_SIZE];
atomic_t tcs_irq_count[MAX_POOL_SIZE];
};
@@ -170,8 +173,9 @@
struct tcs_response_pool *pool = drv->resp_pool;
struct tcs_response *resp = ERR_PTR(-ENOMEM);
int pos;
+ unsigned long flags;
- spin_lock(&pool->lock);
+ spin_lock_irqsave(&pool->lock, flags);
pos = find_first_zero_bit(pool->avail, MAX_POOL_SIZE);
if (pos != MAX_POOL_SIZE) {
bitmap_set(pool->avail, pos, 1);
@@ -182,7 +186,7 @@
resp->err = err;
resp->in_use = false;
}
- spin_unlock(&pool->lock);
+ spin_unlock_irqrestore(&pool->lock, flags);
return resp;
}
@@ -190,34 +194,62 @@
static void free_response(struct tcs_response *resp)
{
struct tcs_response_pool *pool = resp->drv->resp_pool;
+ unsigned long flags;
- spin_lock(&pool->lock);
+ spin_lock_irqsave(&pool->lock, flags);
resp->err = -EINVAL;
bitmap_clear(pool->avail, resp->idx, 1);
- spin_unlock(&pool->lock);
+ spin_unlock_irqrestore(&pool->lock, flags);
}
-static inline struct tcs_response *get_response(struct tcs_drv *drv, u32 m)
+static inline struct tcs_response *get_response(struct tcs_drv *drv, u32 m,
+ bool for_use)
{
struct tcs_response_pool *pool = drv->resp_pool;
struct tcs_response *resp = NULL;
int pos = 0;
+ unsigned long flags;
+ spin_lock_irqsave(&pool->lock, flags);
do {
pos = find_next_bit(pool->avail, MAX_POOL_SIZE, pos);
if (pos == MAX_POOL_SIZE)
break;
+
resp = &pool->resp[pos];
if (resp->m == m && !resp->in_use) {
- resp->in_use = true;
+ resp->in_use = for_use;
break;
}
pos++;
+ udelay(1);
} while (1);
+ spin_unlock_irqrestore(&pool->lock, flags);
return resp;
}
+static void print_response(struct tcs_drv *drv, int m)
+{
+ struct tcs_response *resp;
+ struct tcs_mbox_msg *msg;
+ int i;
+
+ resp = get_response(drv, m, false);
+ if (!resp)
+ return;
+
+ msg = resp->msg;
+ pr_info("Response object idx=%d:\n\tfor-tcs=%d\tin-use=%d\n",
+ resp->idx, resp->m, resp->in_use);
+ pr_info("Msg: state=%d\n", msg->state);
+ for (i = 0; i < msg->num_payload; i++)
+ pr_info("addr=0x%x data=0x%x complete=0x%x\n",
+ msg->payload[i].addr,
+ msg->payload[i].data,
+ msg->payload[i].complete);
+}
+
static inline u32 read_drv_config(void __iomem *base)
{
return le32_to_cpu(readl_relaxed(base + DRV_PRNT_CHLD_CONFIG));
@@ -257,17 +289,19 @@
static inline struct tcs_mbox *get_tcs_from_index(struct tcs_drv *drv, int m)
{
- struct tcs_mbox *tcs;
+ struct tcs_mbox *tcs = NULL;
int i;
- for (i = 0; i < TCS_TYPE_NR; i++) {
+ for (i = 0; i < drv->num_tcs; i++) {
tcs = &drv->tcs[i];
- if (tcs->tcs_mask & BIT(m))
+ if (tcs->tcs_mask & (u32)BIT(m))
break;
}
- if (i == TCS_TYPE_NR)
+ if (i == drv->num_tcs) {
+ WARN(1, "Incorrect TCS index %d", m);
tcs = NULL;
+ }
return tcs;
}
@@ -369,16 +403,10 @@
continue;
atomic_inc(&drv->tcs_irq_count[m]);
- resp = get_response(drv, m);
+ resp = get_response(drv, m, true);
if (!resp) {
pr_err("No resp request for TCS-%d\n", m);
- continue;
- }
-
- tcs = get_tcs_from_index(drv, m);
- if (!tcs) {
- pr_err("TCS-%d doesn't exist in DRV\n", m);
- continue;
+ goto no_resp;
}
/* Check if all commands were completed */
@@ -404,7 +432,8 @@
resp->err);
/* Clear the AMC mode for non-ACTIVE TCSes */
- if (tcs->type != ACTIVE_TCS) {
+ tcs = get_tcs_from_index(drv, m);
+ if (tcs && tcs->type != ACTIVE_TCS) {
data = read_tcs_reg(base, TCS_DRV_CONTROL, m, 0);
data &= ~TCS_AMC_MODE_ENABLE;
write_tcs_reg(base, TCS_DRV_CONTROL, m, 0, data);
@@ -419,11 +448,16 @@
write_tcs_reg(base, TCS_DRV_CMD_ENABLE, m, 0, 0);
}
+no_resp:
+ /* Record the recvd time stamp */
+ drv->tcs_last_recv_ts[m] = arch_counter_get_cntvct();
+
/* Clear the TCS IRQ status */
write_tcs_reg(base, TCS_DRV_IRQ_CLEAR, 0, 0, BIT(m));
/* Clean up response object and notify mbox in tasklet */
- send_tcs_response(resp);
+ if (resp)
+ send_tcs_response(resp);
/* Notify the client that this request is completed. */
atomic_set(&drv->tcs_in_use[m], 0);
@@ -628,7 +662,6 @@
static int tcs_mbox_write(struct mbox_chan *chan, struct tcs_mbox_msg *msg,
bool trigger)
{
- const struct device *dev = chan->cl->dev;
struct tcs_drv *drv = container_of(chan->mbox, struct tcs_drv, mbox);
int d = drv->drv_id;
struct tcs_mbox *tcs;
@@ -647,7 +680,6 @@
spin_lock_irqsave(&tcs->tcs_lock, flags);
slot = find_slots(tcs, msg);
if (slot < 0) {
- dev_err(dev, "No TCS slot found.\n");
spin_unlock_irqrestore(&tcs->tcs_lock, flags);
if (resp)
free_response(resp);
@@ -683,6 +715,7 @@
/* Enable interrupt for active votes through wake TCS */
if (tcs->type != ACTIVE_TCS)
enable_tcs_irq(drv, m, true);
+ drv->tcs_last_sent_ts[m] = arch_counter_get_cntvct();
}
/* Write to the TCS or AMC */
@@ -725,6 +758,24 @@
return 0;
}
+static void dump_tcs_stats(struct tcs_drv *drv)
+{
+ int i;
+ unsigned long long curr = arch_counter_get_cntvct();
+
+ for (i = 0; i < drv->num_tcs; i++) {
+ if (!atomic_read(&drv->tcs_in_use[i]))
+ continue;
+ pr_info("Time: %llu: TCS-%d:\n\tReq Sent:%d Last Sent:%llu\n\tResp Recv:%d Last Recvd:%llu\n",
+ curr, i,
+ atomic_read(&drv->tcs_send_count[i]),
+ drv->tcs_last_sent_ts[i],
+ atomic_read(&drv->tcs_irq_count[i]),
+ drv->tcs_last_recv_ts[i]);
+ print_response(drv, i);
+ }
+}
+
/**
* chan_tcs_write: Validate the incoming message and write to the
* appropriate TCS block.
@@ -738,35 +789,41 @@
*/
static int chan_tcs_write(struct mbox_chan *chan, void *data)
{
+ struct tcs_drv *drv = container_of(chan->mbox, struct tcs_drv, mbox);
struct tcs_mbox_msg *msg = data;
const struct device *dev = chan->cl->dev;
- int ret = -EINVAL;
+ int ret = 0;
int count = 0;
if (!msg) {
dev_err(dev, "Payload error.\n");
+ ret = -EINVAL;
goto tx_fail;
}
if (!msg->payload || msg->num_payload > MAX_RPMH_PAYLOAD) {
dev_err(dev, "Payload error.\n");
+ ret = -EINVAL;
goto tx_fail;
}
if (msg->invalidate || msg->is_control) {
dev_err(dev, "Incorrect API.\n");
+ ret = -EINVAL;
goto tx_fail;
}
if (msg->state != RPMH_ACTIVE_ONLY_STATE &&
msg->state != RPMH_AWAKE_STATE) {
dev_err(dev, "Incorrect API.\n");
+ ret = -EINVAL;
goto tx_fail;
}
/* Read requests should always be single */
if (msg->is_read && msg->num_payload > 1) {
dev_err(dev, "Incorrect read request.\n");
+ ret = -EINVAL;
goto tx_fail;
}
@@ -780,25 +837,29 @@
/* Post the message to the TCS and trigger */
do {
ret = tcs_mbox_write(chan, msg, true);
- if (ret == -EBUSY) {
- ret = -EIO;
- udelay(10);
- } else
+ if (ret != -EBUSY)
break;
+ udelay(100);
} while (++count < 10);
tx_fail:
- if (ret) {
- struct tcs_drv *drv = container_of(chan->mbox,
- struct tcs_drv, mbox);
+ /* If there was an error in the request, schedule a response */
+ if (ret < 0 && ret != -EBUSY) {
struct tcs_response *resp = setup_response(
drv, msg, chan, TCS_M_INIT, ret);
dev_err(dev, "Error sending RPMH message %d\n", ret);
send_tcs_response(resp);
+ ret = 0;
}
- return 0;
+ /* If we were just busy waiting for TCS, dump the state and return */
+ if (ret == -EBUSY) {
+ dev_err(dev, "TCS Busy, retrying RPMH message send\n");
+ dump_tcs_stats(drv);
+ }
+
+ return ret;
}
static void __tcs_write_hidden(struct tcs_drv *drv, int d,