usb: rmnet: Add timestamps for SKB life cycle in UL and DL directions
This change adds support to keep track of total time spent by a SKB in
UL and DL directions. Timestamps are recorded per SKB for the complete
life cycle at following stages:-
1) Creation: At the time of SKB allocation.
2) Submission: While SKB being submitted to HSIC HW by bridge driver/
HSUSB Core by rmnet gadget driver.
3) Completion: In completion handler of the driver(bridge driver/
gadget rmnet driver).
4) Sent: While sending SKB to bridge driver/rmnet gadget driver.
5) Queued: While SKB being queued to HSIC HW by bridge driver/
HSUSB Core by rmnet gadget driver.
6) Done: In completion handler while freeing the SKB.
debugfs node /sys/kernel/debug/data_hsic_bridge/timestamp represents the
listing of timestamp for last 34 SKBs submitted in UL direction.
debugfs node /sys/kernel/debug/ghsic_data_xport/timestamp represents the
listing of timestamp for last 34 SKBs submitted in DL direction.
Recording of the time stamp is controlled by the module parameter in
rmnet bridge driver and rmnet gadget driver.
To enable the recording of timestamp in rmnet bridge driver
echo 1 > /sys/module/mdm_bridge/parameters/record_timestamp
To enable the recording of timestamp in rmnet gadget driver
echo 1 > /sys/module/g_android/parameters/record_timestamp
Change-Id: I10e7c171eec6a01afbd48328ba006f776370ac92
Signed-off-by: Hemant Kumar <hemantk@codeaurora.org>
diff --git a/drivers/usb/misc/mdm_data_bridge.c b/drivers/usb/misc/mdm_data_bridge.c
index d03a4b7..687c8c5 100644
--- a/drivers/usb/misc/mdm_data_bridge.c
+++ b/drivers/usb/misc/mdm_data_bridge.c
@@ -103,6 +103,8 @@
/* counter used for indexing data bridge devices */
static int ch_id;
+static unsigned int get_timestamp(void);
+static void dbg_timestamp(char *, struct sk_buff *);
static int submit_rx_urb(struct data_bridge *dev, struct urb *urb,
gfp_t flags);
@@ -140,6 +142,7 @@
unsigned long flags;
struct urb *rx_idle;
struct sk_buff *skb;
+ struct timestamp_info *info;
struct data_bridge *dev =
container_of(work, struct data_bridge, process_rx_w);
@@ -150,6 +153,8 @@
while (!rx_throttled(brdg) && (skb = skb_dequeue(&dev->rx_done))) {
dev->to_host++;
+ info = (struct timestamp_info *)skb->cb;
+ info->rx_done_sent = get_timestamp();
/* hand off sk_buff to client,they'll need to free it */
retval = brdg->ops.send_pkt(brdg->ctx, skb, skb->len);
if (retval == -ENOTCONN || retval == -EINVAL) {
@@ -182,16 +187,17 @@
{
struct bridge *brdg;
struct sk_buff *skb = urb->context;
- struct data_bridge *dev = *(struct data_bridge **)skb->cb;
+ struct timestamp_info *info = (struct timestamp_info *)skb->cb;
+ struct data_bridge *dev = info->dev;
bool queue = 0;
brdg = dev->brdg;
-
skb_put(skb, urb->actual_length);
switch (urb->status) {
case 0: /* success */
queue = 1;
+ info->rx_done = get_timestamp();
spin_lock(&dev->rx_done.lock);
__skb_queue_tail(&dev->rx_done, skb);
spin_unlock(&dev->rx_done.lock);
@@ -231,14 +237,19 @@
static int submit_rx_urb(struct data_bridge *dev, struct urb *rx_urb,
gfp_t flags)
{
- struct sk_buff *skb;
- int retval = -EINVAL;
+ struct sk_buff *skb;
+ struct timestamp_info *info;
+ int retval = -EINVAL;
+ unsigned int created;
+ created = get_timestamp();
skb = alloc_skb(RMNET_RX_BUFSIZE, flags);
if (!skb)
return -ENOMEM;
- *((struct data_bridge **)skb->cb) = dev;
+ info = (struct timestamp_info *)skb->cb;
+ info->dev = dev;
+ info->created = created;
usb_fill_bulk_urb(rx_urb, dev->udev, dev->bulk_in,
skb->data, RMNET_RX_BUFSIZE,
@@ -248,6 +259,7 @@
goto suspended;
usb_anchor_urb(rx_urb, &dev->rx_active);
+ info->rx_queued = get_timestamp();
retval = usb_submit_urb(rx_urb, flags);
if (retval)
goto fail;
@@ -395,7 +407,8 @@
static void data_bridge_write_cb(struct urb *urb)
{
struct sk_buff *skb = urb->context;
- struct data_bridge *dev = *(struct data_bridge **)skb->cb;
+ struct timestamp_info *info = (struct timestamp_info *)skb->cb;
+ struct data_bridge *dev = info->dev;
struct bridge *brdg = dev->brdg;
int pending;
@@ -403,6 +416,7 @@
switch (urb->status) {
case 0: /*success*/
+ dbg_timestamp("UL", skb);
break;
case -EPROTO:
dev->err = -EPROTO;
@@ -446,6 +460,7 @@
int size = skb->len;
int pending;
struct urb *txurb;
+ struct timestamp_info *info = (struct timestamp_info *)skb->cb;
struct data_bridge *dev = __dev[id];
struct bridge *brdg;
@@ -473,7 +488,8 @@
}
/* store dev pointer in skb */
- *((struct data_bridge **)skb->cb) = dev;
+ info->dev = dev;
+ info->tx_queued = get_timestamp();
usb_fill_bulk_urb(txurb, dev->udev, dev->bulk_out,
skb->data, skb->len, data_bridge_write_cb, skb);
@@ -657,6 +673,103 @@
#if defined(CONFIG_DEBUG_FS)
#define DEBUG_BUF_SIZE 1024
+
+static unsigned int record_timestamp;
+module_param(record_timestamp, uint, S_IRUGO | S_IWUSR);
+
+static struct timestamp_buf dbg_data = {
+ .idx = 0,
+ .lck = __RW_LOCK_UNLOCKED(lck)
+};
+
+/*get_timestamp - returns time of day in us */
+static unsigned int get_timestamp(void)
+{
+ struct timeval tval;
+ unsigned int stamp;
+
+ if (!record_timestamp)
+ return 0;
+
+ do_gettimeofday(&tval);
+ /* 2^32 = 4294967296. Limit to 4096s. */
+ stamp = tval.tv_sec & 0xFFF;
+ stamp = stamp * 1000000 + tval.tv_usec;
+ return stamp;
+}
+
+static void dbg_inc(unsigned *idx)
+{
+ *idx = (*idx + 1) & (DBG_DATA_MAX-1);
+}
+
+/**
+* dbg_timestamp - Stores timestamp values of a SKB life cycle
+* to debug buffer
+* @event: "UL": Uplink Data
+* @skb: SKB used to store timestamp values to debug buffer
+*/
+static void dbg_timestamp(char *event, struct sk_buff * skb)
+{
+ unsigned long flags;
+ struct timestamp_info *info = (struct timestamp_info *)skb->cb;
+
+ if (!record_timestamp)
+ return;
+
+ write_lock_irqsave(&dbg_data.lck, flags);
+
+ scnprintf(dbg_data.buf[dbg_data.idx], DBG_DATA_MSG,
+ "%p %u[%s] %u %u %u %u %u %u\n",
+ skb, skb->len, event, info->created, info->rx_queued,
+ info->rx_done, info->rx_done_sent, info->tx_queued,
+ get_timestamp());
+
+ dbg_inc(&dbg_data.idx);
+
+ write_unlock_irqrestore(&dbg_data.lck, flags);
+}
+
+/* show_timestamp: displays the timestamp buffer */
+static ssize_t show_timestamp(struct file *file, char __user *ubuf,
+ size_t count, loff_t *ppos)
+{
+ unsigned long flags;
+ unsigned i;
+ unsigned j = 0;
+ char *buf;
+ int ret = 0;
+
+ if (!record_timestamp)
+ return 0;
+
+ buf = kzalloc(sizeof(char) * 4 * DEBUG_BUF_SIZE, GFP_KERNEL);
+ if (!buf)
+ return -ENOMEM;
+
+ read_lock_irqsave(&dbg_data.lck, flags);
+
+ i = dbg_data.idx;
+ for (dbg_inc(&i); i != dbg_data.idx; dbg_inc(&i)) {
+ if (!strnlen(dbg_data.buf[i], DBG_DATA_MSG))
+ continue;
+ j += scnprintf(buf + j, (4 * DEBUG_BUF_SIZE) - j,
+ "%s\n", dbg_data.buf[i]);
+ }
+
+ read_unlock_irqrestore(&dbg_data.lck, flags);
+
+ ret = simple_read_from_buffer(ubuf, count, ppos, buf, j);
+
+ kfree(buf);
+
+ return ret;
+}
+
+const struct file_operations data_timestamp_ops = {
+ .read = show_timestamp,
+};
+
static ssize_t data_bridge_read_stats(struct file *file, char __user *ubuf,
size_t count, loff_t *ppos)
{
@@ -741,29 +854,49 @@
.write = data_bridge_reset_stats,
};
-struct dentry *data_dent;
-struct dentry *data_dfile;
+static struct dentry *data_dent;
+static struct dentry *data_dfile_stats;
+static struct dentry *data_dfile_tstamp;
+
static void data_bridge_debugfs_init(void)
{
data_dent = debugfs_create_dir("data_hsic_bridge", 0);
if (IS_ERR(data_dent))
return;
- data_dfile = debugfs_create_file("status", 0644, data_dent, 0,
- &data_stats_ops);
- if (!data_dfile || IS_ERR(data_dfile))
+ data_dfile_stats = debugfs_create_file("status", 0644, data_dent, 0,
+ &data_stats_ops);
+ if (!data_dfile_stats || IS_ERR(data_dfile_stats)) {
+ debugfs_remove(data_dent);
+ return;
+ }
+
+ data_dfile_tstamp = debugfs_create_file("timestamp", 0644, data_dent,
+ 0, &data_timestamp_ops);
+ if (!data_dfile_tstamp || IS_ERR(data_dfile_tstamp))
debugfs_remove(data_dent);
}
static void data_bridge_debugfs_exit(void)
{
- debugfs_remove(data_dfile);
+ debugfs_remove(data_dfile_stats);
+ debugfs_remove(data_dfile_tstamp);
debugfs_remove(data_dent);
}
#else
static void data_bridge_debugfs_init(void) { }
static void data_bridge_debugfs_exit(void) { }
+static void dbg_timestamp(char *event, struct sk_buff * skb)
+{
+ return;
+}
+
+static unsigned int get_timestamp(void)
+{
+ return 0;
+}
+
#endif
static int __devinit