[CIFS] CIFS Stats improvements

New cifs_writepages routine was not updated bytes written in cifs stats.
Also added ability to clear /proc/fs/cifs/Stats by writing (0 or 1) to it.
Signed-off-by: Steve French <sfrench@us.ibm.com>

9 files changed, 98 insertions, 8 deletions

diff --git a/fs/cifs/CHANGES b/fs/cifs/CHANGES
index b2a938378bef..f554a70c9cf3 100644
--- a/fs/cifs/CHANGES
+++ b/fs/cifs/CHANGES
@@ -9,7 +9,7 @@ wsize and rsize can now be larger than negotiated buffer size if server
 supports large readx/writex, even when directio mount flag not specified.
 Write size will in many cases now be 16K instead of 4K which greatly helps
 file copy performance on lightly loaded networks.  Fix oops in dnotify
-when experimental config flag enabled.
+when experimental config flag enabled. Make cifsFYI more granular.
 
 Version 1.37
 ------------
diff --git a/fs/cifs/README b/fs/cifs/README
index e7a3ce62d71b..bb90941826ad 100644
--- a/fs/cifs/README
+++ b/fs/cifs/README
@@ -482,9 +482,16 @@ These experimental features and tracing can be enabled by changing flags in
 kernel, e.g.  insmod cifs).  To enable a feature set it to 1 e.g.  to enable 
 tracing to the kernel message log type: 
 
-	echo 1 > /proc/fs/cifs/cifsFYI
+	echo 7 > /proc/fs/cifs/cifsFYI
 	
-and for more extensive tracing including the start of smb requests and responses
+cifsFYI functions as a bit mask. Setting it to 1 enables additional kernel
+logging of various informational messages.  2 enables logging of non-zero
+SMB return codes while 4 enables logging of requests that take longer
+than one second to complete (except for byte range lock requests). 
+Setting it to 4 requires defining CONFIG_CIFS_STATS2 manually in the
+source code (typically by setting it in the beginning of cifsglob.h),
+and setting it to seven enables all three.  Finally, tracing
+the start of smb requests and responses can be enabled via:
 
 	echo 1 > /proc/fs/cifs/traceSMB
 
diff --git a/fs/cifs/cifs_debug.c b/fs/cifs/cifs_debug.c
index 6f7810992db3..f4054d695f81 100644
--- a/fs/cifs/cifs_debug.c
+++ b/fs/cifs/cifs_debug.c
@@ -203,6 +203,49 @@ cifs_debug_data_read(char *buf, char **beginBuffer, off_t offset,
 }
 
 #ifdef CONFIG_CIFS_STATS
+
+static int
+cifs_stats_write(struct file *file, const char __user *buffer,
+               unsigned long count, void *data)
+{
+        char c;
+        int rc;
+	struct list_head *tmp;
+	struct cifsTconInfo *tcon;
+
+        rc = get_user(c, buffer);
+        if (rc)
+                return rc;
+
+        if (c == '1' || c == 'y' || c == 'Y') {
+		read_lock(&GlobalSMBSeslock);
+		list_for_each(tmp, &GlobalTreeConnectionList) {
+			tcon = list_entry(tmp, struct cifsTconInfo,
+					cifsConnectionList);
+			atomic_set(&tcon->num_smbs_sent, 0);
+			atomic_set(&tcon->num_writes, 0);
+			atomic_set(&tcon->num_reads, 0);
+			atomic_set(&tcon->num_oplock_brks, 0);
+			atomic_set(&tcon->num_opens, 0);
+			atomic_set(&tcon->num_closes, 0);
+			atomic_set(&tcon->num_deletes, 0);
+			atomic_set(&tcon->num_mkdirs, 0);
+			atomic_set(&tcon->num_rmdirs, 0);
+			atomic_set(&tcon->num_renames, 0);
+			atomic_set(&tcon->num_t2renames, 0);
+			atomic_set(&tcon->num_ffirst, 0);
+			atomic_set(&tcon->num_fnext, 0);
+			atomic_set(&tcon->num_fclose, 0);
+			atomic_set(&tcon->num_hardlinks, 0);
+			atomic_set(&tcon->num_symlinks, 0);
+			atomic_set(&tcon->num_locks, 0);
+		}
+		read_unlock(&GlobalSMBSeslock);
+	}
+
+        return count;
+}
+
 static int
 cifs_stats_read(char *buf, char **beginBuffer, off_t offset,
 		  int count, int *eof, void *data)
@@ -365,8 +408,10 @@ cifs_proc_init(void)
 				cifs_debug_data_read, NULL);
 
 #ifdef CONFIG_CIFS_STATS
-	create_proc_read_entry("Stats", 0, proc_fs_cifs,
+	pde = create_proc_read_entry("Stats", 0, proc_fs_cifs,
 				cifs_stats_read, NULL);
+	if (pde)
+		pde->write_proc = cifs_stats_write;
 #endif
 	pde = create_proc_read_entry("cifsFYI", 0, proc_fs_cifs,
 				cifsFYI_read, NULL);
@@ -483,6 +528,8 @@ cifsFYI_write(struct file *file, const char __user *buffer,
 		cifsFYI = 0;
 	else if (c == '1' || c == 'y' || c == 'Y')
 		cifsFYI = 1;
+	else if((c > '1') && (c <= '9'))
+		cifsFYI = (int) (c - '0'); /* see cifs_debug.h for meanings */
 
 	return count;
 }
diff --git a/fs/cifs/cifs_debug.h b/fs/cifs/cifs_debug.h
index bf24d2828f68..4304d9dcfb6c 100644
--- a/fs/cifs/cifs_debug.h
+++ b/fs/cifs/cifs_debug.h
@@ -26,6 +26,9 @@
 void cifs_dump_mem(char *label, void *data, int length);
 extern int traceSMB;		/* flag which enables the function below */
 void dump_smb(struct smb_hdr *, int);
+#define CIFS_INFO	0x01
+#define CIFS_RC  	0x02
+#define CIFS_TIMER	0x04
 
 /*
  *	debug ON
@@ -36,7 +39,7 @@ void dump_smb(struct smb_hdr *, int);
 
 /* information message: e.g., configuration, major event */
 extern int cifsFYI;
-#define cifsfyi(format,arg...) if (cifsFYI) printk(KERN_DEBUG " " __FILE__ ": " format "\n" "" , ## arg)
+#define cifsfyi(format,arg...) if (cifsFYI & CIFS_INFO) printk(KERN_DEBUG " " __FILE__ ": " format "\n" "" , ## arg)
 
 #define cFYI(button,prspec) if (button) cifsfyi prspec
 
diff --git a/fs/cifs/cifsglob.h b/fs/cifs/cifsglob.h
index 729717281b40..839a55667c3c 100644
--- a/fs/cifs/cifsglob.h
+++ b/fs/cifs/cifsglob.h
@@ -377,7 +377,11 @@ struct mid_q_entry {
 	__u16 mid;		/* multiplex id */
 	__u16 pid;		/* process id */
 	__u32 sequence_number;  /* for CIFS signing */
-	struct timeval when_sent;	/* time when smb sent */
+	unsigned long when_alloc;  /* when mid was created */
+#ifdef CONFIG_CIFS_STATS2
+	unsigned long when_sent; /* time when smb send finished */
+	unsigned long when_received; /* when demux complete (taken off wire) */
+#endif
 	struct cifsSesInfo *ses;	/* smb was sent to this server */
 	struct task_struct *tsk;	/* task waiting for response */
 	struct smb_hdr *resp_buf;	/* response buffer */
diff --git a/fs/cifs/connect.c b/fs/cifs/connect.c
index 177289771abe..a8f0cbada0f0 100644
--- a/fs/cifs/connect.c
+++ b/fs/cifs/connect.c
@@ -605,6 +605,9 @@ cifs_demultiplex_thread(struct TCP_Server_Info *server)
 multi_t2_fnd:
 				task_to_wake = mid_entry->tsk;
 				mid_entry->midState = MID_RESPONSE_RECEIVED;
+#ifdef CONFIG_CIFS_STATS2
+				mid_entry->when_received = jiffies;
+#endif
 				break;
 			}
 		}
diff --git a/fs/cifs/file.c b/fs/cifs/file.c
index 11806c879c47..585a62aebd59 100644
--- a/fs/cifs/file.c
+++ b/fs/cifs/file.c
@@ -1153,6 +1153,9 @@ retry:
 					  rc, bytes_written));
 				set_bit(AS_EIO, &mapping->flags);
 				SetPageError(page);
+			} else {
+				cifs_stats_bytes_written(cifs_sb->tcon,
+							 bytes_written);
 			}
 			for (i = 0; i < n_iov; i++) {
 				page = pvec.pages[first + i];
diff --git a/fs/cifs/netmisc.c b/fs/cifs/netmisc.c
index 29e6efc5597c..f7814689844b 100644
--- a/fs/cifs/netmisc.c
+++ b/fs/cifs/netmisc.c
@@ -813,7 +813,7 @@ map_smb_to_linux_error(struct smb_hdr *smb)
 	if (smb->Flags2 & SMBFLG2_ERR_STATUS) {
 		/* translate the newer STATUS codes to old style errors and then to POSIX errors */
 		__u32 err = le32_to_cpu(smb->Status.CifsError);
-		if(cifsFYI)
+		if(cifsFYI & CIFS_RC)
 			cifs_print_status(err);
 		ntstatus_to_dos(err, &smberrclass, &smberrcode);
 	} else {
diff --git a/fs/cifs/transport.c b/fs/cifs/transport.c
index d8865fbd876a..981ea0d8b9cd 100644
--- a/fs/cifs/transport.c
+++ b/fs/cifs/transport.c
@@ -59,7 +59,9 @@ AllocMidQEntry(struct smb_hdr *smb_buffer, struct cifsSesInfo *ses)
 		temp->pid = current->pid;
 		temp->command = smb_buffer->Command;
 		cFYI(1, ("For smb_command %d", temp->command));
-		do_gettimeofday(&temp->when_sent);
+	/*	do_gettimeofday(&temp->when_sent);*/ /* easier to use jiffies */
+		/* when mid allocated can be before when sent */
+		temp->when_alloc = jiffies;
 		temp->ses = ses;
 		temp->tsk = current;
 	}
@@ -75,6 +77,9 @@ AllocMidQEntry(struct smb_hdr *smb_buffer, struct cifsSesInfo *ses)
 static void
 DeleteMidQEntry(struct mid_q_entry *midEntry)
 {
+#ifdef CONFIG_CIFS_STATS2
+	unsigned long now;
+#endif
 	spin_lock(&GlobalMid_Lock);
 	midEntry->midState = MID_FREE;
 	list_del(&midEntry->qhead);
@@ -84,6 +89,22 @@ DeleteMidQEntry(struct mid_q_entry *midEntry)
 		cifs_buf_release(midEntry->resp_buf);
 	else
 		cifs_small_buf_release(midEntry->resp_buf);
+#ifdef CONFIG_CIFS_STATS2
+	now = jiffies;
+	/* commands taking longer than one second are indications that
+	   something is wrong, unless it is quite a slow link or server */
+	if((now - midEntry->when_alloc) > HZ) {
+		if((cifsFYI & CIFS_TIMER) && 
+		   (midEntry->command != SMB_COM_LOCKING_ANDX)) {
+			printk(KERN_DEBUG " CIFS slow rsp: cmd %d mid %d",
+			       midEntry->command, midEntry->mid);
+			printk(" A: 0x%lx S: 0x%lx R: 0x%lx\n",
+			       now - midEntry->when_alloc,
+			       now - midEntry->when_sent,
+			       now - midEntry->when_received);
+		}
+	}
+#endif
 	mempool_free(midEntry, cifs_mid_poolp);
 }
 
@@ -382,6 +403,7 @@ SendReceive2(const unsigned int xid, struct cifsSesInfo *ses,
 		      (struct sockaddr *) &(ses->server->addr.sockAddr));
 #ifdef CONFIG_CIFS_STATS2
 	atomic_dec(&ses->server->inSend);
+	midQ->when_sent = jiffies;
 #endif
 	if(rc < 0) {
 		DeleteMidQEntry(midQ);
@@ -646,6 +668,7 @@ SendReceive(const unsigned int xid, struct cifsSesInfo *ses,
 		      (struct sockaddr *) &(ses->server->addr.sockAddr));
 #ifdef CONFIG_CIFS_STATS2
 	atomic_dec(&ses->server->inSend);
+	midQ->when_sent = jiffies;
 #endif
 	if(rc < 0) {
 		DeleteMidQEntry(midQ);