msm: bam_dmux: Enable IPC logging for bam_dmux
Currently a kfifo is used for internal BAM DMUX logging
and crash dump analysis. With this change, kfifo is
replaced with the IPC logging framework.
CRs-Fixed: 483128
Change-Id: Ic5ac32490d1afb22990ba460a3fcae2b160a408c
Signed-off-by: Zaheerulla Meer <zmeer@codeaurora.org>
diff --git a/arch/arm/mach-msm/bam_dmux.c b/arch/arm/mach-msm/bam_dmux.c
index d3b2122..67c3914 100644
--- a/arch/arm/mach-msm/bam_dmux.c
+++ b/arch/arm/mach-msm/bam_dmux.c
@@ -28,7 +28,7 @@
#include <linux/wakelock.h>
#include <linux/kfifo.h>
#include <linux/of.h>
-
+#include <mach/msm_ipc_logging.h>
#include <mach/sps.h>
#include <mach/bam_dmux.h>
#include <mach/msm_smsm.h>
@@ -300,93 +300,57 @@
#define bam_ch_is_in_reset(x) \
(bam_ch[(x)].status & BAM_CH_IN_RESET)
-#define LOG_MESSAGE_MAX_SIZE 80
struct kfifo bam_dmux_state_log;
-static uint32_t bam_dmux_state_logging_disabled;
-static DEFINE_SPINLOCK(bam_dmux_logging_spinlock);
static int bam_dmux_uplink_vote;
static int bam_dmux_power_state;
-static void bam_dmux_log(const char *fmt, ...)
- __printf(1, 2);
-
#define DMUX_LOG_KERR(fmt...) \
do { \
- bam_dmux_log(fmt); \
+ BAM_DMUX_LOG(fmt); \
pr_err(fmt); \
} while (0)
+static void *bam_ipc_log_txt;
+
+#define BAM_IPC_LOG_PAGES 5
+
/**
* Log a state change along with a small message.
- *
* Complete size of messsage is limited to @todo.
+ * Logging is done using IPC Logging infrastructure.
+ *
+ * States
+ * D: 1 = Power collapse disabled
+ * R: 1 = in global reset
+ * P: 1 = BAM is powered up
+ * A: 1 = BAM initialized and ready for data
+ * V: 1 = Uplink vote for power
+ * U: 1 = Uplink active
+ * W: 1 = Uplink Wait-for-ack
+ * A: 1 = Uplink ACK received
+ * #: >=1 On-demand uplink vote
+ * D: 1 = Disconnect ACK active
*/
-static void bam_dmux_log(const char *fmt, ...)
-{
- char buff[LOG_MESSAGE_MAX_SIZE];
- unsigned long flags;
- va_list arg_list;
- unsigned long long t_now;
- unsigned long nanosec_rem;
- int len = 0;
- if (bam_dmux_state_logging_disabled)
- return;
-
- t_now = sched_clock();
- nanosec_rem = do_div(t_now, 1000000000U);
-
- /*
- * States
- * D: 1 = Power collapse disabled
- * R: 1 = in global reset
- * P: 1 = BAM is powered up
- * A: 1 = BAM initialized and ready for data
- *
- * V: 1 = Uplink vote for power
- * U: 1 = Uplink active
- * W: 1 = Uplink Wait-for-ack
- * A: 1 = Uplink ACK received
- * #: >=1 On-demand uplink vote
- * D: 1 = Disconnect ACK active
- */
- len += scnprintf(buff, sizeof(buff),
- "<DMUX> %u.%09lu %c%c%c%c %c%c%c%c%d%c ",
- (unsigned)t_now, nanosec_rem,
- a2_pc_disabled ? 'D' : 'd',
- in_global_reset ? 'R' : 'r',
- bam_dmux_power_state ? 'P' : 'p',
- bam_connection_is_active ? 'A' : 'a',
- bam_dmux_uplink_vote ? 'V' : 'v',
- bam_is_connected ? 'U' : 'u',
- wait_for_ack ? 'W' : 'w',
- ul_wakeup_ack_completion.done ? 'A' : 'a',
- atomic_read(&ul_ondemand_vote),
- disconnect_ack ? 'D' : 'd'
- );
-
- va_start(arg_list, fmt);
- len += vscnprintf(buff + len, sizeof(buff) - len, fmt, arg_list);
- va_end(arg_list);
- memset(buff + len, 0x0, sizeof(buff) - len);
-
- spin_lock_irqsave(&bam_dmux_logging_spinlock, flags);
- if (kfifo_avail(&bam_dmux_state_log) < LOG_MESSAGE_MAX_SIZE) {
- char junk[LOG_MESSAGE_MAX_SIZE];
- int ret;
-
- ret = kfifo_out(&bam_dmux_state_log, junk, sizeof(junk));
- if (ret != LOG_MESSAGE_MAX_SIZE) {
- pr_err("%s: unable to empty log %d\n", __func__, ret);
- spin_unlock_irqrestore(&bam_dmux_logging_spinlock,
- flags);
- return;
- }
- }
- kfifo_in(&bam_dmux_state_log, buff, sizeof(buff));
- spin_unlock_irqrestore(&bam_dmux_logging_spinlock, flags);
-}
+#define BAM_DMUX_LOG(fmt, args...) \
+do { \
+ if (bam_ipc_log_txt) { \
+ ipc_log_string(bam_ipc_log_txt, \
+ "<DMUX> %c%c%c%c %c%c%c%c%d%c " fmt, \
+ a2_pc_disabled ? 'D' : 'd', \
+ in_global_reset ? 'R' : 'r', \
+ bam_dmux_power_state ? 'P' : 'p', \
+ bam_connection_is_active ? 'A' : 'a', \
+ bam_dmux_uplink_vote ? 'V' : 'v', \
+ bam_is_connected ? 'U' : 'u', \
+ wait_for_ack ? 'W' : 'w', \
+ ul_wakeup_ack_completion.done ? 'A' : 'a', \
+ atomic_read(&ul_ondemand_vote), \
+ disconnect_ack ? 'D' : 'd', \
+ args); \
+ } \
+} while (0)
static inline void set_tx_timestamp(struct tx_pkt_info *pkt)
{
@@ -406,12 +370,12 @@
spin_lock_irqsave(&bam_tx_pool_spinlock, flags);
list_for_each_entry(info, &bam_tx_pool, list_node) {
if (!reported) {
- bam_dmux_log("%s: tx pool not empty\n", func);
+ BAM_DMUX_LOG("%s: tx pool not empty\n", func);
if (!in_global_reset)
pr_err("%s: tx pool not empty\n", func);
reported = 1;
}
- bam_dmux_log("%s: node=%p ts=%u.%09lu\n", __func__,
+ BAM_DMUX_LOG("%s: node=%p ts=%u.%09lu\n", __func__,
&info->list_node, info->ts_sec, info->ts_nsec);
if (!in_global_reset)
pr_err("%s: node=%p ts=%u.%09lu\n", __func__,
@@ -539,7 +503,7 @@
mutex_lock(&bam_pdev_mutexlock);
if (in_global_reset) {
- bam_dmux_log("%s: open cid %d aborted due to ssr\n",
+ BAM_DMUX_LOG("%s: open cid %d aborted due to ssr\n",
__func__, rx_hdr->ch_id);
mutex_unlock(&bam_pdev_mutexlock);
queue_rx();
@@ -603,18 +567,18 @@
bam_mux_process_data(rx_skb);
break;
case BAM_MUX_HDR_CMD_OPEN:
- bam_dmux_log("%s: opening cid %d PC enabled\n", __func__,
+ BAM_DMUX_LOG("%s: opening cid %d PC enabled\n", __func__,
rx_hdr->ch_id);
handle_bam_mux_cmd_open(rx_hdr);
if (!(rx_hdr->reserved & ENABLE_DISCONNECT_ACK)) {
- bam_dmux_log("%s: deactivating disconnect ack\n",
+ BAM_DMUX_LOG("%s: deactivating disconnect ack\n",
__func__);
disconnect_ack = 0;
}
dev_kfree_skb_any(rx_skb);
break;
case BAM_MUX_HDR_CMD_OPEN_NO_A2_PC:
- bam_dmux_log("%s: opening cid %d PC disabled\n", __func__,
+ BAM_DMUX_LOG("%s: opening cid %d PC disabled\n", __func__,
rx_hdr->ch_id);
if (!a2_pc_disabled) {
@@ -627,11 +591,11 @@
break;
case BAM_MUX_HDR_CMD_CLOSE:
/* probably should drop pending write */
- bam_dmux_log("%s: closing cid %d\n", __func__,
+ BAM_DMUX_LOG("%s: closing cid %d\n", __func__,
rx_hdr->ch_id);
mutex_lock(&bam_pdev_mutexlock);
if (in_global_reset) {
- bam_dmux_log("%s: close cid %d aborted due to ssr\n",
+ BAM_DMUX_LOG("%s: close cid %d aborted due to ssr\n",
__func__, rx_hdr->ch_id);
mutex_unlock(&bam_pdev_mutexlock);
break;
@@ -1376,60 +1340,6 @@
return i;
}
-static int debug_log(char *buff, int max, loff_t *ppos)
-{
- unsigned long flags;
- int i = 0;
-
- if (bam_dmux_state_logging_disabled) {
- i += scnprintf(buff - i, max - i, "Logging disabled\n");
- return i;
- }
-
- if (*ppos == 0) {
- i += scnprintf(buff - i, max - i,
- "<DMUX> timestamp FLAGS [Message]\n"
- "FLAGS:\n"
- "\tD: 1 = Power collapse disabled\n"
- "\tR: 1 = in global reset\n"
- "\tP: 1 = BAM is powered up\n"
- "\tA: 1 = BAM initialized and ready for data\n"
- "\n"
- "\tV: 1 = Uplink vote for power\n"
- "\tU: 1 = Uplink active\n"
- "\tW: 1 = Uplink Wait-for-ack\n"
- "\tA: 1 = Uplink ACK received\n"
- "\t#: >=1 On-demand uplink vote\n"
- "\tD: 1 = Disconnect ACK active\n"
- );
- buff += i;
- }
-
- spin_lock_irqsave(&bam_dmux_logging_spinlock, flags);
- while (kfifo_len(&bam_dmux_state_log)
- && (i + LOG_MESSAGE_MAX_SIZE) < max) {
- int k_len;
- k_len = kfifo_out(&bam_dmux_state_log,
- buff, LOG_MESSAGE_MAX_SIZE);
- if (k_len != LOG_MESSAGE_MAX_SIZE) {
- pr_err("%s: retrieve failure %d\n", __func__, k_len);
- break;
- }
-
- /* keep non-null portion of string and add line break */
- k_len = strnlen(buff, LOG_MESSAGE_MAX_SIZE);
- buff += k_len;
- i += k_len;
- if (k_len && *(buff - 1) != '\n') {
- *buff++ = '\n';
- ++i;
- }
- }
- spin_unlock_irqrestore(&bam_dmux_logging_spinlock, flags);
-
- return i;
-}
-
#define DEBUG_BUFMAX 4096
static char debug_buffer[DEBUG_BUFMAX];
@@ -1441,30 +1351,6 @@
return simple_read_from_buffer(buf, count, ppos, debug_buffer, bsize);
}
-static ssize_t debug_read_multiple(struct file *file, char __user *buff,
- size_t count, loff_t *ppos)
-{
- int (*util_func)(char *buf, int max, loff_t *) = file->private_data;
- char *buffer;
- int bsize;
-
- buffer = kmalloc(count, GFP_KERNEL);
- if (!buffer)
- return -ENOMEM;
-
- bsize = util_func(buffer, count, ppos);
-
- if (bsize >= 0) {
- if (copy_to_user(buff, buffer, bsize)) {
- kfree(buffer);
- return -EFAULT;
- }
- *ppos += bsize;
- }
- kfree(buffer);
- return bsize;
-}
-
static int debug_open(struct inode *inode, struct file *file)
{
file->private_data = inode->i_private;
@@ -1477,11 +1363,6 @@
.open = debug_open,
};
-static const struct file_operations debug_ops_multiple = {
- .read = debug_read_multiple,
- .open = debug_open,
-};
-
static void debug_create(const char *name, mode_t mode,
struct dentry *dent,
int (*fill)(char *buf, int max))
@@ -1494,17 +1375,6 @@
(int)PTR_ERR(file));
}
-static void debug_create_multiple(const char *name, mode_t mode,
- struct dentry *dent,
- int (*fill)(char *buf, int max, loff_t *ppos))
-{
- struct dentry *file;
-
- file = debugfs_create_file(name, mode, dent, fill, &debug_ops_multiple);
- if (IS_ERR(file))
- pr_err("%s: debugfs create failed %d\n", __func__,
- (int)PTR_ERR(file));
-}
#endif
static void notify_all(int event, unsigned long data)
@@ -1516,7 +1386,7 @@
for (i = 0; i < BAM_DMUX_NUM_CHANNELS; ++i) {
if (bam_ch_is_open(i)) {
bam_ch[i].notify(bam_ch[i].priv, event, data);
- bam_dmux_log("%s: cid=%d, event=%d, data=%lu\n",
+ BAM_DMUX_LOG("%s: cid=%d, event=%d, data=%lu\n",
__func__, i, event, data);
}
}
@@ -1559,11 +1429,11 @@
static void power_vote(int vote)
{
- bam_dmux_log("%s: curr=%d, vote=%d\n", __func__,
+ BAM_DMUX_LOG("%s: curr=%d, vote=%d\n", __func__,
bam_dmux_uplink_vote, vote);
if (bam_dmux_uplink_vote == vote)
- bam_dmux_log("%s: warning - duplicate power vote\n", __func__);
+ BAM_DMUX_LOG("%s: warning - duplicate power vote\n", __func__);
bam_dmux_uplink_vote = vote;
if (vote)
@@ -1577,7 +1447,7 @@
*/
static inline void ul_powerdown(void)
{
- bam_dmux_log("%s: powerdown\n", __func__);
+ BAM_DMUX_LOG("%s: powerdown\n", __func__);
verify_tx_queue_is_empty(__func__);
if (a2_pc_disabled) {
@@ -1689,7 +1559,7 @@
}
if (ul_packet_written || atomic_read(&ul_ondemand_vote)) {
- bam_dmux_log("%s: pkt written %d\n",
+ BAM_DMUX_LOG("%s: pkt written %d\n",
__func__, ul_packet_written);
ul_packet_written = 0;
schedule_delayed_work(&ul_timeout_work,
@@ -1718,7 +1588,7 @@
mutex_lock(&wakeup_lock);
if (bam_is_connected) { /* bam got connected before lock grabbed */
- bam_dmux_log("%s Already awake\n", __func__);
+ BAM_DMUX_LOG("%s Already awake\n", __func__);
mutex_unlock(&wakeup_lock);
return;
}
@@ -1781,35 +1651,35 @@
* instead of waiting
*/
if (wait_for_ack) {
- bam_dmux_log("%s waiting for previous ack\n", __func__);
+ BAM_DMUX_LOG("%s waiting for previous ack\n", __func__);
ret = wait_for_completion_timeout(
&ul_wakeup_ack_completion, HZ);
wait_for_ack = 0;
if (unlikely(ret == 0) && ssrestart_check()) {
mutex_unlock(&wakeup_lock);
- bam_dmux_log("%s timeout previous ack\n", __func__);
+ BAM_DMUX_LOG("%s timeout previous ack\n", __func__);
return;
}
}
INIT_COMPLETION(ul_wakeup_ack_completion);
power_vote(1);
- bam_dmux_log("%s waiting for wakeup ack\n", __func__);
+ BAM_DMUX_LOG("%s waiting for wakeup ack\n", __func__);
ret = wait_for_completion_timeout(&ul_wakeup_ack_completion, HZ);
if (unlikely(ret == 0) && ssrestart_check()) {
mutex_unlock(&wakeup_lock);
- bam_dmux_log("%s timeout wakeup ack\n", __func__);
+ BAM_DMUX_LOG("%s timeout wakeup ack\n", __func__);
return;
}
- bam_dmux_log("%s waiting completion\n", __func__);
+ BAM_DMUX_LOG("%s waiting completion\n", __func__);
ret = wait_for_completion_timeout(&bam_connection_completion, HZ);
if (unlikely(ret == 0) && ssrestart_check()) {
mutex_unlock(&wakeup_lock);
- bam_dmux_log("%s timeout power on\n", __func__);
+ BAM_DMUX_LOG("%s timeout power on\n", __func__);
return;
}
bam_is_connected = 1;
- bam_dmux_log("%s complete\n", __func__);
+ BAM_DMUX_LOG("%s complete\n", __func__);
schedule_delayed_work(&ul_timeout_work,
msecs_to_jiffies(UL_TIMEOUT_DELAY));
mutex_unlock(&wakeup_lock);
@@ -1866,7 +1736,7 @@
/* handle disconnect during active UL */
write_lock_irqsave(&ul_wakeup_lock, flags);
if (bam_is_connected) {
- bam_dmux_log("%s: UL active - forcing powerdown\n", __func__);
+ BAM_DMUX_LOG("%s: UL active - forcing powerdown\n", __func__);
ul_powerdown();
}
write_unlock_irqrestore(&ul_wakeup_lock, flags);
@@ -1905,10 +1775,10 @@
{
int rc;
- bam_dmux_log("%s\n", __func__);
+ BAM_DMUX_LOG("%s\n", __func__);
mutex_lock(&dfab_status_lock);
if (dfab_is_on) {
- bam_dmux_log("%s: dfab is already on\n", __func__);
+ BAM_DMUX_LOG("%s: dfab is already on\n", __func__);
mutex_unlock(&dfab_status_lock);
return;
}
@@ -1930,7 +1800,7 @@
static void unvote_dfab(void)
{
- bam_dmux_log("%s\n", __func__);
+ BAM_DMUX_LOG("%s\n", __func__);
mutex_lock(&dfab_status_lock);
if (!dfab_is_on) {
DMUX_LOG_KERR("%s: dfab is already off\n", __func__);
@@ -1952,7 +1822,7 @@
unsigned long flags;
spin_lock_irqsave(&wakelock_reference_lock, flags);
- bam_dmux_log("%s: ref count = %d\n", __func__,
+ BAM_DMUX_LOG("%s: ref count = %d\n", __func__,
wakelock_reference_count);
if (wakelock_reference_count == 0)
wake_lock(&bam_wakelock);
@@ -1971,7 +1841,7 @@
spin_unlock_irqrestore(&wakelock_reference_lock, flags);
return;
}
- bam_dmux_log("%s: ref count = %d\n", __func__,
+ BAM_DMUX_LOG("%s: ref count = %d\n", __func__,
wakelock_reference_count);
--wakelock_reference_count;
if (wakelock_reference_count == 0)
@@ -1992,7 +1862,7 @@
if (code != SUBSYS_AFTER_SHUTDOWN)
return NOTIFY_DONE;
- bam_dmux_log("%s: begin\n", __func__);
+ BAM_DMUX_LOG("%s: begin\n", __func__);
in_global_reset = 1;
/* Handle uplink Powerdown */
@@ -2050,7 +1920,7 @@
}
spin_unlock_irqrestore(&bam_tx_pool_spinlock, flags);
- bam_dmux_log("%s: complete\n", __func__);
+ BAM_DMUX_LOG("%s: complete\n", __func__);
return NOTIFY_DONE;
}
@@ -2297,7 +2167,7 @@
{
static unsigned int clear_bit; /* 0 = set the bit, else clear bit */
- bam_dmux_log("%s: apps ack %d->%d\n", __func__,
+ BAM_DMUX_LOG("%s: apps ack %d->%d\n", __func__,
clear_bit & 0x1, ~clear_bit & 0x1);
smsm_change_state(SMSM_APPS_STATE,
clear_bit & SMSM_A2_POWER_CONTROL_ACK,
@@ -2313,10 +2183,10 @@
mutex_lock(&smsm_cb_lock);
bam_dmux_power_state = new_state & SMSM_A2_POWER_CONTROL ? 1 : 0;
DBG_INC_A2_POWER_CONTROL_IN_CNT();
- bam_dmux_log("%s: 0x%08x -> 0x%08x\n", __func__, old_state,
+ BAM_DMUX_LOG("%s: 0x%08x -> 0x%08x\n", __func__, old_state,
new_state);
if (last_processed_state == (new_state & SMSM_A2_POWER_CONTROL)) {
- bam_dmux_log("%s: already processed this state\n", __func__);
+ BAM_DMUX_LOG("%s: already processed this state\n", __func__);
mutex_unlock(&smsm_cb_lock);
return;
}
@@ -2324,23 +2194,23 @@
last_processed_state = new_state & SMSM_A2_POWER_CONTROL;
if (bam_mux_initialized && new_state & SMSM_A2_POWER_CONTROL) {
- bam_dmux_log("%s: reconnect\n", __func__);
+ BAM_DMUX_LOG("%s: reconnect\n", __func__);
grab_wakelock();
reconnect_to_bam();
} else if (bam_mux_initialized &&
!(new_state & SMSM_A2_POWER_CONTROL)) {
- bam_dmux_log("%s: disconnect\n", __func__);
+ BAM_DMUX_LOG("%s: disconnect\n", __func__);
disconnect_to_bam();
release_wakelock();
} else if (new_state & SMSM_A2_POWER_CONTROL) {
- bam_dmux_log("%s: init\n", __func__);
+ BAM_DMUX_LOG("%s: init\n", __func__);
grab_wakelock();
if (cpu_is_msm9615())
msm9615_bam_init();
else
bam_init();
} else {
- bam_dmux_log("%s: bad state change\n", __func__);
+ BAM_DMUX_LOG("%s: bad state change\n", __func__);
pr_err("%s: unsupported state change\n", __func__);
}
mutex_unlock(&smsm_cb_lock);
@@ -2351,7 +2221,7 @@
uint32_t new_state)
{
DBG_INC_ACK_IN_CNT();
- bam_dmux_log("%s: 0x%08x -> 0x%08x\n", __func__, old_state,
+ BAM_DMUX_LOG("%s: 0x%08x -> 0x%08x\n", __func__, old_state,
new_state);
complete_all(&ul_wakeup_ack_completion);
}
@@ -2390,12 +2260,12 @@
xo_clk = clk_get(&pdev->dev, "xo");
if (IS_ERR(xo_clk)) {
- bam_dmux_log("%s: did not get xo clock\n", __func__);
+ BAM_DMUX_LOG("%s: did not get xo clock\n", __func__);
xo_clk = NULL;
}
dfab_clk = clk_get(&pdev->dev, "bus_clk");
if (IS_ERR(dfab_clk)) {
- bam_dmux_log("%s: did not get dfab clock\n", __func__);
+ BAM_DMUX_LOG("%s: did not get dfab clock\n", __func__);
dfab_clk = NULL;
} else {
rc = clk_set_rate(dfab_clk, 64000000);
@@ -2488,7 +2358,6 @@
static int __init bam_dmux_init(void)
{
- int ret;
#ifdef CONFIG_DEBUG_FS
struct dentry *dent;
@@ -2497,13 +2366,12 @@
debug_create("tbl", 0444, dent, debug_tbl);
debug_create("ul_pkt_cnt", 0444, dent, debug_ul_pkt_cnt);
debug_create("stats", 0444, dent, debug_stats);
- debug_create_multiple("log", 0444, dent, debug_log);
}
#endif
- ret = kfifo_alloc(&bam_dmux_state_log, PAGE_SIZE, GFP_KERNEL);
- if (ret) {
- pr_err("%s: failed to allocate log %d\n", __func__, ret);
- bam_dmux_state_logging_disabled = 1;
+
+ bam_ipc_log_txt = ipc_log_context_create(BAM_IPC_LOG_PAGES, "bam_dmux");
+ if (!bam_ipc_log_txt) {
+ pr_err("%s : unable to create IPC Logging Context", __func__);
}
rx_timer_interval = DEFAULT_POLLING_MIN_SLEEP;