[SCSI] fnic: Fnic Trace Utility

Fnic Trace utility is a tracing functionality built directly into fnic driver
to trace events. The benefit that trace buffer brings to fnic driver is the
ability to see what it happening inside the fnic driver. It also provides the
capability to trace every IO event inside fnic driver to debug panics, hangs
and potentially IO corruption issues. This feature makes it easy to find
problems in fnic driver and it also helps in tracking down strange bugs in a
more manageable way. Trace buffer is shared across all fnic instances for
this implementation.

Signed-off-by: Hiral Patel <hiralpat@cisco.com>
Signed-off-by: James Bottomley <JBottomley@Parallels.com>

drivers/scsi/fnic/Makefile

@@ -7,6 +7,8 @@ fnic-y	:= \
 	fnic_res.o \
 	fnic_fcs.o \
 	fnic_scsi.o \
+	fnic_trace.o \
+	fnic_debugfs.o \
 	vnic_cq.o \
 	vnic_dev.o \
 	vnic_intr.o \

drivers/scsi/fnic/fnic.h

@@ -26,6 +26,7 @@
 #include <scsi/libfcoe.h>
 #include "fnic_io.h"
 #include "fnic_res.h"
+#include "fnic_trace.h"
 #include "vnic_dev.h"
 #include "vnic_wq.h"
 #include "vnic_rq.h"

drivers/scsi/fnic/fnic_debugfs.c

@@ -0,0 +1,314 @@
+/*
+ * Copyright 2012 Cisco Systems, Inc.  All rights reserved.
+ *
+ * This program is free software; you may redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; version 2 of the License.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
+ * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
+ * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
+ * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS
+ * BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN
+ * ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN
+ * CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+#include <linux/module.h>
+#include <linux/errno.h>
+#include <linux/debugfs.h>
+#include "fnic.h"
+
+static struct dentry *fnic_trace_debugfs_root;
+static struct dentry *fnic_trace_debugfs_file;
+static struct dentry *fnic_trace_enable;
+
+/*
+ * fnic_trace_ctrl_open - Open the trace_enable file
+ * @inode: The inode pointer.
+ * @file: The file pointer to attach the trace enable/disable flag.
+ *
+ * Description:
+ * This routine opens a debugsfs file trace_enable.
+ *
+ * Returns:
+ * This function returns zero if successful.
+ */
+static int fnic_trace_ctrl_open(struct inode *inode, struct file *filp)
+{
+	filp->private_data = inode->i_private;
+	return 0;
+}
+
+/*
+ * fnic_trace_ctrl_read - Read a trace_enable debugfs file
+ * @filp: The file pointer to read from.
+ * @ubuf: The buffer to copy the data to.
+ * @cnt: The number of bytes to read.
+ * @ppos: The position in the file to start reading from.
+ *
+ * Description:
+ * This routine reads value of variable fnic_tracing_enabled
+ * and stores into local @buf. It will start reading file at @ppos and
+ * copy up to @cnt of data to @ubuf from @buf.
+ *
+ * Returns:
+ * This function returns the amount of data that was read.
+ */
+static ssize_t fnic_trace_ctrl_read(struct file *filp,
+				  char __user *ubuf,
+				  size_t cnt, loff_t *ppos)
+{
+	char buf[64];
+	int len;
+	len = sprintf(buf, "%u\n", fnic_tracing_enabled);
+
+	return simple_read_from_buffer(ubuf, cnt, ppos, buf, len);
+}
+
+/*
+ * fnic_trace_ctrl_write - Write to trace_enable debugfs file
+ * @filp: The file pointer to write from.
+ * @ubuf: The buffer to copy the data from.
+ * @cnt: The number of bytes to write.
+ * @ppos: The position in the file to start writing to.
+ *
+ * Description:
+ * This routine writes data from user buffer @ubuf to buffer @buf and
+ * sets fnic_tracing_enabled value as per user input.
+ *
+ * Returns:
+ * This function returns the amount of data that was written.
+ */
+static ssize_t fnic_trace_ctrl_write(struct file *filp,
+				  const char __user *ubuf,
+				  size_t cnt, loff_t *ppos)
+{
+	char buf[64];
+	unsigned long val;
+	int ret;
+
+	if (cnt >= sizeof(buf))
+		return -EINVAL;
+
+	if (copy_from_user(&buf, ubuf, cnt))
+		return -EFAULT;
+
+	buf[cnt] = 0;
+
+	ret = kstrtoul(buf, 10, &val);
+	if (ret < 0)
+		return ret;
+
+	fnic_tracing_enabled = val;
+	(*ppos)++;
+
+	return cnt;
+}
+
+/*
+ * fnic_trace_debugfs_open - Open the fnic trace log
+ * @inode: The inode pointer
+ * @file: The file pointer to attach the log output
+ *
+ * Description:
+ * This routine is the entry point for the debugfs open file operation.
+ * It allocates the necessary buffer for the log, fills the buffer from
+ * the in-memory log and then returns a pointer to that log in
+ * the private_data field in @file.
+ *
+ * Returns:
+ * This function returns zero if successful. On error it will return
+ * a negative error value.
+ */
+static int fnic_trace_debugfs_open(struct inode *inode,
+				  struct file *file)
+{
+	fnic_dbgfs_t *fnic_dbg_prt;
+	fnic_dbg_prt = kzalloc(sizeof(fnic_dbgfs_t), GFP_KERNEL);
+	if (!fnic_dbg_prt)
+		return -ENOMEM;
+
+	fnic_dbg_prt->buffer = vmalloc((3*(trace_max_pages * PAGE_SIZE)));
+	if (!fnic_dbg_prt->buffer) {
+		kfree(fnic_dbg_prt);
+		return -ENOMEM;
+	}
+	memset((void *)fnic_dbg_prt->buffer, 0,
+			  (3*(trace_max_pages * PAGE_SIZE)));
+	fnic_dbg_prt->buffer_len = fnic_get_trace_data(fnic_dbg_prt);
+	file->private_data = fnic_dbg_prt;
+	return 0;
+}
+
+/*
+ * fnic_trace_debugfs_lseek - Seek through a debugfs file
+ * @file: The file pointer to seek through.
+ * @offset: The offset to seek to or the amount to seek by.
+ * @howto: Indicates how to seek.
+ *
+ * Description:
+ * This routine is the entry point for the debugfs lseek file operation.
+ * The @howto parameter indicates whether @offset is the offset to directly
+ * seek to, or if it is a value to seek forward or reverse by. This function
+ * figures out what the new offset of the debugfs file will be and assigns
+ * that value to the f_pos field of @file.
+ *
+ * Returns:
+ * This function returns the new offset if successful and returns a negative
+ * error if unable to process the seek.
+ */
+static loff_t fnic_trace_debugfs_lseek(struct file *file,
+					loff_t offset,
+					int howto)
+{
+	fnic_dbgfs_t *fnic_dbg_prt = file->private_data;
+	loff_t pos = -1;
+
+	switch (howto) {
+	case 0:
+		pos = offset;
+		break;
+	case 1:
+		pos = file->f_pos + offset;
+		break;
+	case 2:
+		pos = fnic_dbg_prt->buffer_len - offset;
+	}
+	return (pos < 0 || pos > fnic_dbg_prt->buffer_len) ?
+			  -EINVAL : (file->f_pos = pos);
+}
+
+/*
+ * fnic_trace_debugfs_read - Read a debugfs file
+ * @file: The file pointer to read from.
+ * @ubuf: The buffer to copy the data to.
+ * @nbytes: The number of bytes to read.
+ * @pos: The position in the file to start reading from.
+ *
+ * Description:
+ * This routine reads data from the buffer indicated in the private_data
+ * field of @file. It will start reading at @pos and copy up to @nbytes of
+ * data to @ubuf.
+ *
+ * Returns:
+ * This function returns the amount of data that was read (this could be
+ * less than @nbytes if the end of the file was reached).
+ */
+static ssize_t fnic_trace_debugfs_read(struct file *file,
+					char __user *ubuf,
+					size_t nbytes,
+					loff_t *pos)
+{
+	fnic_dbgfs_t *fnic_dbg_prt = file->private_data;
+	int rc = 0;
+	rc = simple_read_from_buffer(ubuf, nbytes, pos,
+				  fnic_dbg_prt->buffer,
+				  fnic_dbg_prt->buffer_len);
+	return rc;
+}
+
+/*
+ * fnic_trace_debugfs_release - Release the buffer used to store
+ * debugfs file data
+ * @inode: The inode pointer
+ * @file: The file pointer that contains the buffer to release
+ *
+ * Description:
+ * This routine frees the buffer that was allocated when the debugfs
+ * file was opened.
+ *
+ * Returns:
+ * This function returns zero.
+ */
+static int fnic_trace_debugfs_release(struct inode *inode,
+					  struct file *file)
+{
+	fnic_dbgfs_t *fnic_dbg_prt = file->private_data;
+
+	vfree(fnic_dbg_prt->buffer);
+	kfree(fnic_dbg_prt);
+	return 0;
+}
+
+static const struct file_operations fnic_trace_ctrl_fops = {
+	.owner = THIS_MODULE,
+	.open = fnic_trace_ctrl_open,
+	.read = fnic_trace_ctrl_read,
+	.write = fnic_trace_ctrl_write,
+};
+
+static const struct file_operations fnic_trace_debugfs_fops = {
+	.owner = THIS_MODULE,
+	.open = fnic_trace_debugfs_open,
+	.llseek = fnic_trace_debugfs_lseek,
+	.read = fnic_trace_debugfs_read,
+	.release = fnic_trace_debugfs_release,
+};
+
+/*
+ * fnic_trace_debugfs_init - Initialize debugfs for fnic trace logging
+ *
+ * Description:
+ * When Debugfs is configured this routine sets up the fnic debugfs
+ * file system. If not already created, this routine will create the
+ * fnic directory. It will create file trace to log fnic trace buffer
+ * output into debugfs and it will also create file trace_enable to
+ * control enable/disable of trace logging into trace buffer.
+ */
+int fnic_trace_debugfs_init(void)
+{
+	int rc = -1;
+	fnic_trace_debugfs_root = debugfs_create_dir("fnic", NULL);
+	if (!fnic_trace_debugfs_root) {
+		printk(KERN_DEBUG "Cannot create debugfs root\n");
+		return rc;
+	}
+	fnic_trace_enable = debugfs_create_file("tracing_enable",
+					  S_IFREG|S_IRUGO|S_IWUSR,
+					  fnic_trace_debugfs_root,
+					  NULL, &fnic_trace_ctrl_fops);
+
+	if (!fnic_trace_enable) {
+		printk(KERN_DEBUG "Cannot create trace_enable file"
+				  " under debugfs");
+		return rc;
+	}
+
+	fnic_trace_debugfs_file = debugfs_create_file("trace",
+						  S_IFREG|S_IRUGO|S_IWUSR,
+						  fnic_trace_debugfs_root,
+						  NULL,
+						  &fnic_trace_debugfs_fops);
+
+	if (!fnic_trace_debugfs_file) {
+		printk(KERN_DEBUG "Cannot create trace file under debugfs");
+		return rc;
+	}
+	rc = 0;
+	return rc;
+}
+
+/*
+ * fnic_trace_debugfs_terminate - Tear down debugfs infrastructure
+ *
+ * Description:
+ * When Debugfs is configured this routine removes debugfs file system
+ * elements that are specific to fnic trace logging.
+ */
+void fnic_trace_debugfs_terminate(void)
+{
+	if (fnic_trace_debugfs_file) {
+		debugfs_remove(fnic_trace_debugfs_file);
+		fnic_trace_debugfs_file = NULL;
+	}
+	if (fnic_trace_enable) {
+		debugfs_remove(fnic_trace_enable);
+		fnic_trace_enable = NULL;
+	}
+	if (fnic_trace_debugfs_root) {
+		debugfs_remove(fnic_trace_debugfs_root);
+		fnic_trace_debugfs_root = NULL;
+	}
+}

drivers/scsi/fnic/fnic_main.c

@@ -68,6 +68,10 @@ unsigned int fnic_log_level;
 module_param(fnic_log_level, int, S_IRUGO|S_IWUSR);
 MODULE_PARM_DESC(fnic_log_level, "bit mask of fnic logging levels");
 
+unsigned int fnic_trace_max_pages = 16;
+module_param(fnic_trace_max_pages, uint, S_IRUGO|S_IWUSR);
+MODULE_PARM_DESC(fnic_trace_max_pages, "Total allocated memory pages "
+					"for fnic trace buffer");
 
 static struct libfc_function_template fnic_transport_template = {
 	.frame_send = fnic_send,
@@ -861,6 +865,14 @@ static int __init fnic_init_module(void)
 
 	printk(KERN_INFO PFX "%s, ver %s\n", DRV_DESCRIPTION, DRV_VERSION);
 
+	/* Allocate memory for trace buffer */
+	err = fnic_trace_buf_init();
+	if (err < 0) {
+		printk(KERN_ERR PFX "Trace buffer initialization Failed "
+				  "Fnic Tracing utility is disabled\n");
+		fnic_trace_free();
+	}
+
 	/* Create a cache for allocation of default size sgls */
 	len = sizeof(struct fnic_dflt_sgl_list);
 	fnic_sgl_cache[FNIC_SGL_CACHE_DFLT] = kmem_cache_create
@@ -931,6 +943,7 @@ err_create_fnic_ioreq_slab:
 err_create_fnic_sgl_slab_max:
 	kmem_cache_destroy(fnic_sgl_cache[FNIC_SGL_CACHE_DFLT]);
 err_create_fnic_sgl_slab_dflt:
+	fnic_trace_free();
 	return err;
 }
 
@@ -942,6 +955,7 @@ static void __exit fnic_cleanup_module(void)
 	kmem_cache_destroy(fnic_sgl_cache[FNIC_SGL_CACHE_DFLT]);
 	kmem_cache_destroy(fnic_io_req_cache);
 	fc_release_transport(fnic_fc_transport);
+	fnic_trace_free();
 }
 
 module_init(fnic_init_module);

drivers/scsi/fnic/fnic_scsi.c

@@ -393,11 +393,12 @@ static int fnic_queuecommand_lck(struct scsi_cmnd *sc, void (*done)(struct scsi_
 {
 	struct fc_lport *lp = shost_priv(sc->device->host);
 	struct fc_rport *rport;
-	struct fnic_io_req *io_req;
+	struct fnic_io_req *io_req = NULL;
 	struct fnic *fnic = lport_priv(lp);
 	struct vnic_wq_copy *wq;
 	int ret;
-	int sg_count;
+	u64 cmd_trace;
+	int sg_count = 0;
 	unsigned long flags;
 	unsigned long ptr;
 
@@ -437,6 +438,9 @@ static int fnic_queuecommand_lck(struct scsi_cmnd *sc, void (*done)(struct scsi_
 	/* Map the data buffer */
 	sg_count = scsi_dma_map(sc);
 	if (sg_count < 0) {
+		FNIC_TRACE(fnic_queuecommand, sc->device->host->host_no,
+			  sc->request->tag, sc, 0, sc->cmnd[0],
+			  sg_count, CMD_STATE(sc));
 		mempool_free(io_req, fnic->io_req_pool);
 		goto out;
 	}
@@ -486,7 +490,9 @@ static int fnic_queuecommand_lck(struct scsi_cmnd *sc, void (*done)(struct scsi_
 		 * refetch the pointer under the lock.
 		 */
 		spinlock_t *io_lock = fnic_io_lock_hash(fnic, sc);
-
+		FNIC_TRACE(fnic_queuecommand, sc->device->host->host_no,
+			  sc->request->tag, sc, 0, 0, 0,
+			  (((u64)CMD_FLAGS(sc) << 32) | CMD_STATE(sc)));
 		spin_lock_irqsave(io_lock, flags);
 		io_req = (struct fnic_io_req *)CMD_SP(sc);
 		CMD_SP(sc) = NULL;
@@ -501,6 +507,15 @@ static int fnic_queuecommand_lck(struct scsi_cmnd *sc, void (*done)(struct scsi_
 		CMD_FLAGS(sc) |= FNIC_IO_ISSUED;
 	}
 out:
+	cmd_trace = ((u64)sc->cmnd[0] << 56 | (u64)sc->cmnd[7] << 40 |
+			(u64)sc->cmnd[8] << 32 | (u64)sc->cmnd[2] << 24 |
+			(u64)sc->cmnd[3] << 16 | (u64)sc->cmnd[4] << 8 |
+			sc->cmnd[5]);
+
+	FNIC_TRACE(fnic_queuecommand, sc->device->host->host_no,
+		  sc->request->tag, sc, io_req,
+		  sg_count, cmd_trace,
+		  (((u64)CMD_FLAGS(sc) >> 32) | CMD_STATE(sc)));
 	atomic_dec(&fnic->in_flight);
 	/* acquire host lock before returning to SCSI */
 	spin_lock(lp->host->host_lock);
@@ -674,6 +689,7 @@ static inline void fnic_fcpio_ack_handler(struct fnic *fnic,
 	struct vnic_wq_copy *wq;
 	u16 request_out = desc->u.ack.request_out;
 	unsigned long flags;
+	u64 *ox_id_tag = (u64 *)(void *)desc;
 
 	/* mark the ack state */
 	wq = &fnic->wq_copy[cq_index - fnic->raw_wq_count - fnic->rq_count];
@@ -684,6 +700,9 @@ static inline void fnic_fcpio_ack_handler(struct fnic *fnic,
 		fnic->fw_ack_recd[0] = 1;
 	}
 	spin_unlock_irqrestore(&fnic->wq_copy_lock[0], flags);
+	FNIC_TRACE(fnic_fcpio_ack_handler,
+		  fnic->lport->host->host_no, 0, 0, ox_id_tag[2], ox_id_tag[3],
+		  ox_id_tag[4], ox_id_tag[5]);
 }
 
 /*
@@ -703,6 +722,7 @@ static void fnic_fcpio_icmnd_cmpl_handler(struct fnic *fnic,
 	struct scsi_cmnd *sc;
 	unsigned long flags;
 	spinlock_t *io_lock;
+	u64 cmd_trace;
 	unsigned long start_time;
 
 	/* Decode the cmpl description to get the io_req id */
@@ -724,6 +744,14 @@ static void fnic_fcpio_icmnd_cmpl_handler(struct fnic *fnic,
 			  "icmnd_cmpl sc is null - "
 			  "hdr status = %s tag = 0x%x desc = 0x%p\n",
 			  fnic_fcpio_status_to_str(hdr_status), id, desc);
+		FNIC_TRACE(fnic_fcpio_icmnd_cmpl_handler,
+			  fnic->lport->host->host_no, id,
+			  ((u64)icmnd_cmpl->_resvd0[1] << 16 |
+			  (u64)icmnd_cmpl->_resvd0[0]),
+			  ((u64)hdr_status << 16 |
+			  (u64)icmnd_cmpl->scsi_status << 8 |
+			  (u64)icmnd_cmpl->flags), desc,
+			  (u64)icmnd_cmpl->residual, 0);
 		return;
 	}
 
@@ -864,6 +892,20 @@ static void fnic_fcpio_icmnd_cmpl_handler(struct fnic *fnic,
 
 	mempool_free(io_req, fnic->io_req_pool);
 
+	cmd_trace = ((u64)hdr_status << 56) |
+		  (u64)icmnd_cmpl->scsi_status << 48 |
+		  (u64)icmnd_cmpl->flags << 40 | (u64)sc->cmnd[0] << 32 |
+		  (u64)sc->cmnd[2] << 24 | (u64)sc->cmnd[3] << 16 |
+		  (u64)sc->cmnd[4] << 8 | sc->cmnd[5];
+
+	FNIC_TRACE(fnic_fcpio_icmnd_cmpl_handler,
+		  sc->device->host->host_no, id, sc,
+		  ((u64)icmnd_cmpl->_resvd0[1] << 56 |
+		  (u64)icmnd_cmpl->_resvd0[0] << 48 |
+		  jiffies_to_msecs(jiffies - start_time)),
+		  desc, cmd_trace,
+		  (((u64)CMD_FLAGS(sc) << 32) | CMD_STATE(sc)));
+
 	if (sc->sc_data_direction == DMA_FROM_DEVICE) {
 		fnic->lport->host_stats.fcp_input_requests++;
 		fnic->fcp_input_bytes += xfer_len;
@@ -876,7 +918,6 @@ static void fnic_fcpio_icmnd_cmpl_handler(struct fnic *fnic,
 	/* Call SCSI completion function to complete the IO */
 	if (sc->scsi_done)
 		sc->scsi_done(sc);
-
 }
 
 /* fnic_fcpio_itmf_cmpl_handler
@@ -974,8 +1015,21 @@ static void fnic_fcpio_itmf_cmpl_handler(struct fnic *fnic,
 
 			fnic_release_ioreq_buf(fnic, io_req, sc);
 			mempool_free(io_req, fnic->io_req_pool);
-			if (sc->scsi_done)
+			if (sc->scsi_done) {
+				FNIC_TRACE(fnic_fcpio_itmf_cmpl_handler,
+					sc->device->host->host_no, id,
+					sc,
+					jiffies_to_msecs(jiffies - start_time),
+					desc,
+					(((u64)hdr_status << 40) |
+					(u64)sc->cmnd[0] << 32 |
+					(u64)sc->cmnd[2] << 24 |
+					(u64)sc->cmnd[3] << 16 |
+					(u64)sc->cmnd[4] << 8 | sc->cmnd[5]),
+					(((u64)CMD_FLAGS(sc) << 32) |
+					CMD_STATE(sc)));
 				sc->scsi_done(sc);
+			}
 		}
 
 	} else if (id & FNIC_TAG_DEV_RST) {
@@ -984,6 +1038,11 @@ static void fnic_fcpio_itmf_cmpl_handler(struct fnic *fnic,
 		if (CMD_STATE(sc) == FNIC_IOREQ_ABTS_PENDING) {
 			spin_unlock_irqrestore(io_lock, flags);
 			CMD_FLAGS(sc) |= FNIC_DEV_RST_ABTS_PENDING;
+			FNIC_TRACE(fnic_fcpio_itmf_cmpl_handler,
+				  sc->device->host->host_no, id, sc,
+				  jiffies_to_msecs(jiffies - start_time),
+				  desc, 0,
+				  (((u64)CMD_FLAGS(sc) << 32) | CMD_STATE(sc)));
 			FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
 				"Terminate pending "
 				"dev reset cmpl recd. id %d status %s\n",
@@ -994,6 +1053,11 @@ static void fnic_fcpio_itmf_cmpl_handler(struct fnic *fnic,
 		if (CMD_FLAGS(sc) & FNIC_DEV_RST_TIMED_OUT) {
 			/* Need to wait for terminate completion */
 			spin_unlock_irqrestore(io_lock, flags);
+			FNIC_TRACE(fnic_fcpio_itmf_cmpl_handler,
+				  sc->device->host->host_no, id, sc,
+				  jiffies_to_msecs(jiffies - start_time),
+				  desc, 0,
+				  (((u64)CMD_FLAGS(sc) << 32) | CMD_STATE(sc)));
 			FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
 				"dev reset cmpl recd after time out. "
 				"id %d status %s\n",
@@ -1142,8 +1206,18 @@ cleanup_scsi_cmd:
 			      " DID_TRANSPORT_DISRUPTED\n");
 
 		/* Complete the command to SCSI */
-		if (sc->scsi_done)
+		if (sc->scsi_done) {
+			FNIC_TRACE(fnic_cleanup_io,
+				  sc->device->host->host_no, i, sc,
+				  jiffies_to_msecs(jiffies - start_time),
+				  0, ((u64)sc->cmnd[0] << 32 |
+				  (u64)sc->cmnd[2] << 24 |
+				  (u64)sc->cmnd[3] << 16 |
+				  (u64)sc->cmnd[4] << 8 | sc->cmnd[5]),
+				  (((u64)CMD_FLAGS(sc) << 32) | CMD_STATE(sc)));
+
 			sc->scsi_done(sc);
+		}
 	}
 }
 
@@ -1195,8 +1269,17 @@ wq_copy_cleanup_scsi_cmd:
 	FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host, "wq_copy_cleanup_handler:"
 		      " DID_NO_CONNECT\n");
 
-	if (sc->scsi_done)
+	if (sc->scsi_done) {
+		FNIC_TRACE(fnic_wq_copy_cleanup_handler,
+			  sc->device->host->host_no, id, sc,
+			  jiffies_to_msecs(jiffies - start_time),
+			  0, ((u64)sc->cmnd[0] << 32 |
+			  (u64)sc->cmnd[2] << 24 | (u64)sc->cmnd[3] << 16 |
+			  (u64)sc->cmnd[4] << 8 | sc->cmnd[5]),
+			  (((u64)CMD_FLAGS(sc) << 32) | CMD_STATE(sc)));
+
 		sc->scsi_done(sc);
+	}
 }
 
 static inline int fnic_queue_abort_io_req(struct fnic *fnic, int tag,
@@ -1476,7 +1559,7 @@ int fnic_abort_cmd(struct scsi_cmnd *sc)
 {
 	struct fc_lport *lp;
 	struct fnic *fnic;
-	struct fnic_io_req *io_req;
+	struct fnic_io_req *io_req = NULL;
 	struct fc_rport *rport;
 	spinlock_t *io_lock;
 	unsigned long flags;
@@ -1503,7 +1586,6 @@ int fnic_abort_cmd(struct scsi_cmnd *sc)
 
 	CMD_FLAGS(sc) = FNIC_NO_FLAGS;
 
-
 	if (lp->state != LPORT_ST_READY || !(lp->link_up)) {
 		ret = FAILED;
 		goto fnic_abort_cmd_end;
@@ -1621,6 +1703,14 @@ int fnic_abort_cmd(struct scsi_cmnd *sc)
 	mempool_free(io_req, fnic->io_req_pool);
 
 fnic_abort_cmd_end:
+	FNIC_TRACE(fnic_abort_cmd, sc->device->host->host_no,
+		  sc->request->tag, sc,
+		  jiffies_to_msecs(jiffies - start_time),
+		  0, ((u64)sc->cmnd[0] << 32 |
+		  (u64)sc->cmnd[2] << 24 | (u64)sc->cmnd[3] << 16 |
+		  (u64)sc->cmnd[4] << 8 | sc->cmnd[5]),
+		  (((u64)CMD_FLAGS(sc) << 32) | CMD_STATE(sc)));
+
 	FNIC_SCSI_DBG(KERN_DEBUG, fnic->lport->host,
 		      "Returning from abort cmd type %x %s\n", task_req,
 		      (ret == SUCCESS) ?
@@ -1891,7 +1981,7 @@ int fnic_device_reset(struct scsi_cmnd *sc)
 {
 	struct fc_lport *lp;
 	struct fnic *fnic;
-	struct fnic_io_req *io_req;
+	struct fnic_io_req *io_req = NULL;
 	struct fc_rport *rport;
 	int status;
 	int ret = FAILED;
@@ -1899,7 +1989,7 @@ int fnic_device_reset(struct scsi_cmnd *sc)
 	unsigned long flags;
 	unsigned long start_time = 0;
 	struct scsi_lun fc_lun;
-	int tag;
+	int tag = 0;
 	DECLARE_COMPLETION_ONSTACK(tm_done);
 	int tag_gen_flag = 0;   /*to track tags allocated by fnic driver*/
 
@@ -2094,6 +2184,14 @@ fnic_device_reset_clean:
 	}
 
 fnic_device_reset_end:
+	FNIC_TRACE(fnic_device_reset, sc->device->host->host_no,
+		  sc->request->tag, sc,
+		  jiffies_to_msecs(jiffies - start_time),
+		  0, ((u64)sc->cmnd[0] << 32 |
+		  (u64)sc->cmnd[2] << 24 | (u64)sc->cmnd[3] << 16 |
+		  (u64)sc->cmnd[4] << 8 | sc->cmnd[5]),
+		  (((u64)CMD_FLAGS(sc) << 32) | CMD_STATE(sc)));
+
 	/* free tag if it is allocated */
 	if (unlikely(tag_gen_flag))
 		fnic_scsi_host_end_tag(fnic, sc);

drivers/scsi/fnic/fnic_trace.c

@@ -0,0 +1,273 @@
+/*
+ * Copyright 2012 Cisco Systems, Inc.  All rights reserved.
+ *
+ * This program is free software; you may redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; version 2 of the License.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
+ * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
+ * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
+ * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS
+ * BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN
+ * ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN
+ * CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+#include <linux/module.h>
+#include <linux/mempool.h>
+#include <linux/errno.h>
+#include <linux/spinlock.h>
+#include <linux/kallsyms.h>
+#include "fnic_io.h"
+#include "fnic.h"
+
+unsigned int trace_max_pages;
+static int fnic_max_trace_entries;
+
+static unsigned long fnic_trace_buf_p;
+static DEFINE_SPINLOCK(fnic_trace_lock);
+
+static fnic_trace_dbg_t fnic_trace_entries;
+int fnic_tracing_enabled = 1;
+
+/*
+ * fnic_trace_get_buf - Give buffer pointer to user to fill up trace information
+ *
+ * Description:
+ * This routine gets next available trace buffer entry location @wr_idx
+ * from allocated trace buffer pages and give that memory location
+ * to user to store the trace information.
+ *
+ * Return Value:
+ * This routine returns pointer to next available trace entry
+ * @fnic_buf_head for user to fill trace information.
+ */
+fnic_trace_data_t *fnic_trace_get_buf(void)
+{
+	unsigned long fnic_buf_head;
+	unsigned long flags;
+
+	spin_lock_irqsave(&fnic_trace_lock, flags);
+
+	/*
+	 * Get next available memory location for writing trace information
+	 * at @wr_idx and increment @wr_idx
+	 */
+	fnic_buf_head =
+		fnic_trace_entries.page_offset[fnic_trace_entries.wr_idx];
+	fnic_trace_entries.wr_idx++;
+
+	/*
+	 * Verify if trace buffer is full then change wd_idx to
+	 * start from zero
+	 */
+	if (fnic_trace_entries.wr_idx >= fnic_max_trace_entries)
+		fnic_trace_entries.wr_idx = 0;
+
+	/*
+	 * Verify if write index @wr_idx and read index @rd_idx are same then
+	 * increment @rd_idx to move to next entry in trace buffer
+	 */
+	if (fnic_trace_entries.wr_idx == fnic_trace_entries.rd_idx) {
+		fnic_trace_entries.rd_idx++;
+		if (fnic_trace_entries.rd_idx >= fnic_max_trace_entries)
+			fnic_trace_entries.rd_idx = 0;
+	}
+	spin_unlock_irqrestore(&fnic_trace_lock, flags);
+	return (fnic_trace_data_t *)fnic_buf_head;
+}
+
+/*
+ * fnic_get_trace_data - Copy trace buffer to a memory file
+ * @fnic_dbgfs_t: pointer to debugfs trace buffer
+ *
+ * Description:
+ * This routine gathers the fnic trace debugfs data from the fnic_trace_data_t
+ * buffer and dumps it to fnic_dbgfs_t. It will start at the rd_idx entry in
+ * the log and process the log until the end of the buffer. Then it will gather
+ * from the beginning of the log and process until the current entry @wr_idx.
+ *
+ * Return Value:
+ * This routine returns the amount of bytes that were dumped into fnic_dbgfs_t
+ */
+int fnic_get_trace_data(fnic_dbgfs_t *fnic_dbgfs_prt)
+{
+	int rd_idx;
+	int wr_idx;
+	int len = 0;
+	unsigned long flags;
+	char str[KSYM_SYMBOL_LEN];
+	struct timespec val;
+	fnic_trace_data_t *tbp;
+
+	spin_lock_irqsave(&fnic_trace_lock, flags);
+	rd_idx = fnic_trace_entries.rd_idx;
+	wr_idx = fnic_trace_entries.wr_idx;
+	if (wr_idx < rd_idx) {
+		while (1) {
+			/* Start from read index @rd_idx */
+			tbp = (fnic_trace_data_t *)
+				  fnic_trace_entries.page_offset[rd_idx];
+			if (!tbp) {
+				spin_unlock_irqrestore(&fnic_trace_lock, flags);
+				return 0;
+			}
+			/* Convert function pointer to function name */
+			if (sizeof(unsigned long) < 8) {
+				sprint_symbol(str, tbp->fnaddr.low);
+				jiffies_to_timespec(tbp->timestamp.low, &val);
+			} else {
+				sprint_symbol(str, tbp->fnaddr.val);
+				jiffies_to_timespec(tbp->timestamp.val, &val);
+			}
+			/*
+			 * Dump trace buffer entry to memory file
+			 * and increment read index @rd_idx
+			 */
+			len += snprintf(fnic_dbgfs_prt->buffer + len,
+				  (trace_max_pages * PAGE_SIZE * 3) - len,
+				  "%16lu.%16lu %-50s %8x %8x %16llx %16llx "
+				  "%16llx %16llx %16llx\n", val.tv_sec,
+				  val.tv_nsec, str, tbp->host_no, tbp->tag,
+				  tbp->data[0], tbp->data[1], tbp->data[2],
+				  tbp->data[3], tbp->data[4]);
+			rd_idx++;
+			/*
+			 * If rd_idx is reached to maximum trace entries
+			 * then move rd_idx to zero
+			 */
+			if (rd_idx > (fnic_max_trace_entries-1))
+				rd_idx = 0;
+			/*
+			 * Continure dumpping trace buffer entries into
+			 * memory file till rd_idx reaches write index
+			 */
+			if (rd_idx == wr_idx)
+				break;
+		}
+	} else if (wr_idx > rd_idx) {
+		while (1) {
+			/* Start from read index @rd_idx */
+			tbp = (fnic_trace_data_t *)
+				  fnic_trace_entries.page_offset[rd_idx];
+			if (!tbp) {
+				spin_unlock_irqrestore(&fnic_trace_lock, flags);
+				return 0;
+			}
+			/* Convert function pointer to function name */
+			if (sizeof(unsigned long) < 8) {
+				sprint_symbol(str, tbp->fnaddr.low);
+				jiffies_to_timespec(tbp->timestamp.low, &val);
+			} else {
+				sprint_symbol(str, tbp->fnaddr.val);
+				jiffies_to_timespec(tbp->timestamp.val, &val);
+			}
+			/*
+			 * Dump trace buffer entry to memory file
+			 * and increment read index @rd_idx
+			 */
+			len += snprintf(fnic_dbgfs_prt->buffer + len,
+				  (trace_max_pages * PAGE_SIZE * 3) - len,
+				  "%16lu.%16lu %-50s %8x %8x %16llx %16llx "
+				  "%16llx %16llx %16llx\n", val.tv_sec,
+				  val.tv_nsec, str, tbp->host_no, tbp->tag,
+				  tbp->data[0], tbp->data[1], tbp->data[2],
+				  tbp->data[3], tbp->data[4]);
+			rd_idx++;
+			/*
+			 * Continue dumpping trace buffer entries into
+			 * memory file till rd_idx reaches write index
+			 */
+			if (rd_idx == wr_idx)
+				break;
+		}
+	}
+	spin_unlock_irqrestore(&fnic_trace_lock, flags);
+	return len;
+}
+
+/*
+ * fnic_trace_buf_init - Initialize fnic trace buffer logging facility
+ *
+ * Description:
+ * Initialize trace buffer data structure by allocating required memory and
+ * setting page_offset information for every trace entry by adding trace entry
+ * length to previous page_offset value.
+ */
+int fnic_trace_buf_init(void)
+{
+	unsigned long fnic_buf_head;
+	int i;
+	int err = 0;
+
+	trace_max_pages = fnic_trace_max_pages;
+	fnic_max_trace_entries = (trace_max_pages * PAGE_SIZE)/
+					  FNIC_ENTRY_SIZE_BYTES;
+
+	fnic_trace_buf_p = (unsigned long)vmalloc((trace_max_pages * PAGE_SIZE));
+	if (!fnic_trace_buf_p) {
+		printk(KERN_ERR PFX "Failed to allocate memory "
+				  "for fnic_trace_buf_p\n");
+		err = -ENOMEM;
+		goto err_fnic_trace_buf_init;
+	}
+	memset((void *)fnic_trace_buf_p, 0, (trace_max_pages * PAGE_SIZE));
+
+	fnic_trace_entries.page_offset = vmalloc(fnic_max_trace_entries *
+						  sizeof(unsigned long));
+	if (!fnic_trace_entries.page_offset) {
+		printk(KERN_ERR PFX "Failed to allocate memory for"
+				  " page_offset\n");
+		if (fnic_trace_buf_p) {
+			vfree((void *)fnic_trace_buf_p);
+			fnic_trace_buf_p = 0;
+		}
+		err = -ENOMEM;
+		goto err_fnic_trace_buf_init;
+	}
+	memset((void *)fnic_trace_entries.page_offset, 0,
+		  (fnic_max_trace_entries * sizeof(unsigned long)));
+	fnic_trace_entries.wr_idx = fnic_trace_entries.rd_idx = 0;
+	fnic_buf_head = fnic_trace_buf_p;
+
+	/*
+	 * Set page_offset field of fnic_trace_entries struct by
+	 * calculating memory location for every trace entry using
+	 * length of each trace entry
+	 */
+	for (i = 0; i < fnic_max_trace_entries; i++) {
+		fnic_trace_entries.page_offset[i] = fnic_buf_head;
+		fnic_buf_head += FNIC_ENTRY_SIZE_BYTES;
+	}
+	err = fnic_trace_debugfs_init();
+	if (err < 0) {
+		printk(KERN_ERR PFX "Failed to initialize debugfs for tracing\n");
+		goto err_fnic_trace_debugfs_init;
+	}
+	printk(KERN_INFO PFX "Successfully Initialized Trace Buffer\n");
+	return err;
+err_fnic_trace_debugfs_init:
+	fnic_trace_free();
+err_fnic_trace_buf_init:
+	return err;
+}
+
+/*
+ * fnic_trace_free - Free memory of fnic trace data structures.
+ */
+void fnic_trace_free(void)
+{
+	fnic_tracing_enabled = 0;
+	fnic_trace_debugfs_terminate();
+	if (fnic_trace_entries.page_offset) {
+		vfree((void *)fnic_trace_entries.page_offset);
+		fnic_trace_entries.page_offset = NULL;
+	}
+	if (fnic_trace_buf_p) {
+		vfree((void *)fnic_trace_buf_p);
+		fnic_trace_buf_p = 0;
+	}
+	printk(KERN_INFO PFX "Successfully Freed Trace Buffer\n");
+}

drivers/scsi/fnic/fnic_trace.h

@@ -0,0 +1,90 @@
+/*
+ * Copyright 2012 Cisco Systems, Inc.  All rights reserved.
+ *
+ * This program is free software; you may redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; version 2 of the License.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
+ * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
+ * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
+ * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS
+ * BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN
+ * ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN
+ * CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+#ifndef __FNIC_TRACE_H__
+#define __FNIC_TRACE_H__
+
+#define FNIC_ENTRY_SIZE_BYTES 64
+
+extern ssize_t simple_read_from_buffer(void __user *to,
+					  size_t count,
+					  loff_t *ppos,
+					  const void *from,
+					  size_t available);
+
+extern unsigned int fnic_trace_max_pages;
+extern int fnic_tracing_enabled;
+extern unsigned int trace_max_pages;
+
+typedef struct fnic_trace_dbg {
+	int wr_idx;
+	int rd_idx;
+	unsigned long *page_offset;
+} fnic_trace_dbg_t;
+
+typedef struct fnic_dbgfs {
+	int buffer_len;
+	char *buffer;
+} fnic_dbgfs_t;
+
+struct fnic_trace_data {
+	union {
+		struct {
+			u32 low;
+			u32 high;
+		};
+		u64 val;
+	} timestamp, fnaddr;
+	u32 host_no;
+	u32 tag;
+	u64 data[5];
+} __attribute__((__packed__));
+
+typedef struct fnic_trace_data fnic_trace_data_t;
+
+#define FNIC_TRACE_ENTRY_SIZE \
+		  (FNIC_ENTRY_SIZE_BYTES - sizeof(fnic_trace_data_t))
+
+#define FNIC_TRACE(_fn, _hn, _t, _a, _b, _c, _d, _e)           \
+	if (unlikely(fnic_tracing_enabled)) {                   \
+		fnic_trace_data_t *trace_buf = fnic_trace_get_buf(); \
+		if (trace_buf) { \
+			if (sizeof(unsigned long) < 8) { \
+				trace_buf->timestamp.low = jiffies; \
+				trace_buf->fnaddr.low = (u32)(unsigned long)_fn; \
+			} else { \
+				trace_buf->timestamp.val = jiffies; \
+				trace_buf->fnaddr.val = (u64)(unsigned long)_fn; \
+			} \
+			trace_buf->host_no = _hn; \
+			trace_buf->tag = _t; \
+			trace_buf->data[0] = (u64)(unsigned long)_a; \
+			trace_buf->data[1] = (u64)(unsigned long)_b; \
+			trace_buf->data[2] = (u64)(unsigned long)_c; \
+			trace_buf->data[3] = (u64)(unsigned long)_d; \
+			trace_buf->data[4] = (u64)(unsigned long)_e; \
+		} \
+	}
+
+fnic_trace_data_t *fnic_trace_get_buf(void);
+int fnic_get_trace_data(fnic_dbgfs_t *);
+int fnic_trace_buf_init(void);
+void fnic_trace_free(void);
+int fnic_trace_debugfs_init(void);
+void fnic_trace_debugfs_terminate(void);
+
+#endif