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/arch/arm/mach-msm/include/mach/usb_bridge.h b/arch/arm/mach-msm/include/mach/usb_bridge.h
index effa395..1a1c23b 100644
--- a/arch/arm/mach-msm/include/mach/usb_bridge.h
+++ b/arch/arm/mach-msm/include/mach/usb_bridge.h
@@ -1,4 +1,4 @@
-/* Copyright (c) 2011, Code Aurora Forum. All rights reserved.
+/* Copyright (c) 2011-2012, Code Aurora Forum. All rights reserved.
*
* This program is free software; you can redistribute it and/or modify
* it under the terms of the GNU General Public License version 2 and
@@ -49,6 +49,43 @@
struct bridge_ops ops;
};
+/**
+ * timestamp_info: stores timestamp info for skb life cycle during data
+ * transfer for tethered rmnet/DUN.
+ * @created: stores timestamp at the time of creation of SKB.
+ * @rx_queued: stores timestamp when SKB queued to HW to receive
+ * data.
+ * @rx_done: stores timestamp when skb queued to h/w is completed.
+ * @rx_done_sent: stores timestamp when SKB is sent from gadget rmnet/DUN
+ * driver to bridge rmnet/DUN driver or vice versa.
+ * @tx_queued: stores timestamp when SKB is queued to send data.
+ *
+ * note that size of this struct shouldnt exceed 48bytes that's the max skb->cb
+ * holds.
+ */
+struct timestamp_info {
+ struct data_bridge *dev;
+
+ unsigned int created;
+ unsigned int rx_queued;
+ unsigned int rx_done;
+ unsigned int rx_done_sent;
+ unsigned int tx_queued;
+};
+
+/* Maximum timestamp message length */
+#define DBG_DATA_MSG 128UL
+
+/* Maximum timestamp messages */
+#define DBG_DATA_MAX 32UL
+
+/* timestamp buffer descriptor */
+struct timestamp_buf {
+ char (buf[DBG_DATA_MAX])[DBG_DATA_MSG]; /* buffer */
+ unsigned idx; /* index */
+ rwlock_t lck; /* lock */
+};
+
#if defined(CONFIG_USB_QCOM_MDM_BRIDGE) || \
defined(CONFIG_USB_QCOM_MDM_BRIDGE_MODULE)
@@ -115,4 +152,5 @@
}
#endif
+
#endif
diff --git a/drivers/usb/gadget/u_data_hsic.c b/drivers/usb/gadget/u_data_hsic.c
index 46109f2..7b77a1d 100644
--- a/drivers/usb/gadget/u_data_hsic.c
+++ b/drivers/usb/gadget/u_data_hsic.c
@@ -131,6 +131,8 @@
struct platform_driver pdrv;
} gdata_ports[NUM_PORTS];
+static unsigned int get_timestamp(void);
+static void dbg_timestamp(char *, struct sk_buff *);
static void ghsic_data_start_rx(struct gdata_port *port);
static void ghsic_data_free_requests(struct usb_ep *ep, struct list_head *head)
@@ -194,6 +196,7 @@
struct usb_request *req;
struct usb_ep *ep;
struct gdata_port *port;
+ struct timestamp_info *info;
port = container_of(w, struct gdata_port, write_tohost_w);
@@ -226,6 +229,8 @@
list_del(&req->list);
+ info = (struct timestamp_info *)skb->cb;
+ info->tx_queued = get_timestamp();
spin_unlock_irqrestore(&port->port_lock, flags);
ret = usb_ep_queue(ep, req, GFP_KERNEL);
spin_lock_irqsave(&port->port_lock, flags);
@@ -295,6 +300,7 @@
{
struct gdata_port *port;
struct sk_buff *skb;
+ struct timestamp_info *info;
unsigned long flags;
int ret;
@@ -315,6 +321,8 @@
pr_debug("%s: port:%p tom:%lu pno:%d\n", __func__,
port, port->to_modem, port->port_num);
+ info = (struct timestamp_info *)skb->cb;
+ info->rx_done_sent = get_timestamp();
spin_unlock_irqrestore(&port->port_lock, flags);
ret = data_bridge_write(port->brdg.ch_id, skb);
spin_lock_irqsave(&port->port_lock, flags);
@@ -346,6 +354,7 @@
switch (status) {
case 0:
/* successful completion */
+ dbg_timestamp("DL", skb);
break;
case -ECONNRESET:
case -ESHUTDOWN:
@@ -373,6 +382,7 @@
{
struct gdata_port *port = ep->driver_data;
struct sk_buff *skb = req->context;
+ struct timestamp_info *info = (struct timestamp_info *)skb->cb;
int status = req->status;
int queue = 0;
@@ -398,6 +408,7 @@
spin_lock(&port->port_lock);
if (queue) {
+ info->rx_done = get_timestamp();
__skb_queue_tail(&port->rx_skb_q, skb);
list_add_tail(&req->list, &port->rx_idle);
queue_work(port->wq, &port->write_tomdm_w);
@@ -412,6 +423,8 @@
unsigned long flags;
int ret;
struct sk_buff *skb;
+ struct timestamp_info *info;
+ unsigned int created;
pr_debug("%s: port:%p\n", __func__, port);
spin_lock_irqsave(&port->port_lock, flags);
@@ -429,15 +442,18 @@
req = list_first_entry(&port->rx_idle,
struct usb_request, list);
+ created = get_timestamp();
skb = alloc_skb(ghsic_data_rx_req_size, GFP_ATOMIC);
if (!skb)
break;
-
+ info = (struct timestamp_info *)skb->cb;
+ info->created = created;
list_del(&req->list);
req->buf = skb->data;
req->length = ghsic_data_rx_req_size;
req->context = skb;
+ info->rx_queued = get_timestamp();
spin_unlock_irqrestore(&port->port_lock, flags);
ret = usb_ep_queue(ep, req, GFP_KERNEL);
spin_lock_irqsave(&port->port_lock, flags);
@@ -799,6 +815,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: "DL": Downlink 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 gdata_timestamp_ops = {
+ .read = show_timestamp,
+};
+
static ssize_t ghsic_data_read_stats(struct file *file,
char __user *ubuf, size_t count, loff_t *ppos)
{
@@ -896,7 +1009,8 @@
};
static struct dentry *gdata_dent;
-static struct dentry *gdata_dfile;
+static struct dentry *gdata_dfile_stats;
+static struct dentry *gdata_dfile_tstamp;
static void ghsic_data_debugfs_init(void)
{
@@ -904,21 +1018,37 @@
if (IS_ERR(gdata_dent))
return;
- gdata_dfile = debugfs_create_file("status", 0444, gdata_dent, 0,
+ gdata_dfile_stats = debugfs_create_file("status", 0444, gdata_dent, 0,
&ghsic_stats_ops);
- if (!gdata_dfile || IS_ERR(gdata_dfile))
+ if (!gdata_dfile_stats || IS_ERR(gdata_dfile_stats)) {
debugfs_remove(gdata_dent);
+ return;
+ }
+
+ gdata_dfile_tstamp = debugfs_create_file("timestamp", 0644, gdata_dent,
+ 0, &gdata_timestamp_ops);
+ if (!gdata_dfile_tstamp || IS_ERR(gdata_dfile_tstamp))
+ debugfs_remove(gdata_dent);
}
static void ghsic_data_debugfs_exit(void)
{
- debugfs_remove(gdata_dfile);
+ debugfs_remove(gdata_dfile_stats);
+ debugfs_remove(gdata_dfile_tstamp);
debugfs_remove(gdata_dent);
}
#else
static void ghsic_data_debugfs_init(void) { }
static void ghsic_data_debugfs_exit(void) { }
+static void dbg_timestamp(char *event, struct sk_buff * skb)
+{
+ return;
+}
+static unsigned int get_timestamp(void)
+{
+ return 0;
+}
#endif
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