- all stats gatherd in OSC debugging time (cache loading, etc.) moved to proc. Added...

- some RPCs related new stats added to ./rpc_stats

diff --git a/lustre/ldlm/ldlm_lib.c b/lustre/ldlm/ldlm_lib.c
index 8d1fd6f..6fd8d1f 100644 (file)
--- a/lustre/ldlm/ldlm_lib.c
+++ b/lustre/ldlm/ldlm_lib.c
@@ -259,19 +259,19 @@ int client_obd_setup(struct obd_device *obddev, obd_count len, void *buf)
         memset(&cli->cl_last_write_time, 0,
                sizeof(cli->cl_last_write_time));
         
+        cli->cl_cache_wait_num = 0;
+        cli->cl_cache_wait_sum = 0;
         cli->cl_write_gap_sum = 0;
         cli->cl_write_gaps = 0;
         cli->cl_write_num = 0;
         cli->cl_read_num = 0;
-        cli->cl_cache_wait_num = 0;
-        cli->cl_cache_wait_sum = 0;
 
         cli->cl_dirty_num = 0;
         cli->cl_dirty_sum = 0;
         cli->cl_dirty_av = 0;
+        cli->cl_sync_rpcs = 0;
         cli->cl_dirty_dmax = 0;
         cli->cl_dirty_dmin = 0;
-        cli->cl_sync_rpcs = 0;
 
         if (num_physpages >> (20 - PAGE_SHIFT) <= 128) { /* <= 128 MB */
                 cli->cl_max_pages_per_rpc = PTLRPC_MAX_BRW_PAGES / 4;
@@ -385,30 +385,6 @@ int client_obd_cleanup(struct obd_device *obddev, int flags)
                 symbol_put("mgmtcli_deregister_for_events");
         }
 
-        if (cli->cl_write_gaps) {
-                CWARN("%s: [writes num: %lu, reads num: %lu]: %lu write gaps: %lu "
-                      "av. (usec), %lu total (usec), %lu rpcs falled back to sync\n",
-                      obddev->obd_name, cli->cl_write_num, cli->cl_read_num,
-                      cli->cl_write_gaps, cli->cl_write_gap_sum / cli->cl_write_gaps,
-                      cli->cl_write_gap_sum, cli->cl_sync_rpcs);
-        }
-        
-        if (cli->cl_cache_wait_num) {
-                CWARN("%s: [cache waits num: %lu]: cache wait av. %lu (usec)\n",
-                      obddev->obd_name, cli->cl_cache_wait_num,
-                      cli->cl_cache_wait_sum / cli->cl_cache_wait_num);
-        }
-
-        if (cli->cl_dirty_av) {
-                CWARN("%s: pipe loading av. %lu (b), max pipe room %lu (b), pipe "
-                      "loading av. ratio %lu%%, pipe dirty max %lu (b), pipe dirty "
-                      "min %lu (b), pipe loading max ratio %lu%%\n", obddev->obd_name,
-                      cli->cl_dirty_av, cli->cl_dirty_max,
-                      (cli->cl_dirty_av * 100) / cli->cl_dirty_max,
-                      cli->cl_dirty_dmax, cli->cl_dirty_dmin,
-                      (cli->cl_dirty_dmax * 100) / cli->cl_dirty_max);
-        }
-
         /* Here we try to drop the security structure after destroy import,
          * to avoid issue of "sleep in spinlock".
          */

diff --git a/lustre/osc/lproc_osc.c b/lustre/osc/lproc_osc.c
index cda20af..b70efe1 100644 (file)
--- a/lustre/osc/lproc_osc.c
+++ b/lustre/osc/lproc_osc.c
@@ -197,21 +197,27 @@ static struct lprocfs_vars lprocfs_module_vars[] = {
 #define PRINTF_STIME(stime) (unsigned long)(stime)->st_num,     \
         lprocfs_stime_avg_ms(stime), lprocfs_stime_avg_us(stime)
 
-
 static int osc_rpc_stats_seq_show(struct seq_file *seq, void *v)
 {
-        struct timeval now;
+        unsigned long read_tot = 0, write_tot = 0, read_cum, write_cum;
         struct obd_device *dev = seq->private;
         struct client_obd *cli = &dev->u.cli;
+        unsigned long gap_av, wait_av;
         unsigned long flags;
-        unsigned long read_tot = 0, write_tot = 0, read_cum, write_cum;
+        struct timeval now;
         int i;
 
         do_gettimeofday(&now);
 
         spin_lock_irqsave(&cli->cl_loi_list_lock, flags);
 
-        seq_printf(seq, "snapshot_time:         %lu.%lu (secs.usecs)\n",
+        wait_av = cli->cl_cache_wait_num ?
+                cli->cl_cache_wait_sum / cli->cl_cache_wait_num : 0;
+        
+        gap_av = cli->cl_write_gaps ?
+                cli->cl_write_gap_sum / cli->cl_write_gaps : 0;
+
+        seq_printf(seq, "snapshot_time:        %lu.%lu (secs.usecs)\n",
                    now.tv_sec, now.tv_usec);
 
         seq_printf(seq, "read RPCs in flight:  %d\n",
@@ -223,10 +229,15 @@ static int osc_rpc_stats_seq_show(struct seq_file *seq, void *v)
         seq_printf(seq, "pending read pages:   %d\n",
                    cli->cl_pending_r_pages);
 
+        /* cache or grant waiting stats */
+        seq_printf(seq, "write waits num:      %lu\n",
+                   cli->cl_cache_wait_num);
+        seq_printf(seq, "av. wait time:        %lu (usec)\n",
+                   wait_av);
 
         seq_printf(seq, "\n\t\t\tread\t\t\twrite\n");
-        seq_printf(seq, "pages per rpc         rpcs   %% cum %% |");
-        seq_printf(seq, "       rpcs   %% cum %%\n");
+        seq_printf(seq, "pages per RPC         RPCs   %% cum %% |");
+        seq_printf(seq, "       RPCs   %% cum %%\n");
 
         read_tot = lprocfs_oh_sum(&cli->cl_read_page_hist);
         write_tot = lprocfs_oh_sum(&cli->cl_write_page_hist);
@@ -247,9 +258,15 @@ static int osc_rpc_stats_seq_show(struct seq_file *seq, void *v)
                         break;
         }
 
+        /* different RPC related stats like av gap time between two write RPCs,
+         * number of sync RPCs, etc. */
+        seq_printf(seq, "\nsync RPCs:            %lu\n", cli->cl_sync_rpcs);
+        seq_printf(seq, "write gaps:           %lu\n", cli->cl_write_gaps);
+        seq_printf(seq, "av. gap time:         %lu (usec)\n", gap_av);
+        
         seq_printf(seq, "\n\t\t\tread\t\t\twrite\n");
-        seq_printf(seq, "rpcs in flight        rpcs   %% cum %% |");
-        seq_printf(seq, "       rpcs   %% cum %%\n");
+        seq_printf(seq, "RPCs in flight        RPCs   %% cum %% |");
+        seq_printf(seq, "       RPCs   %% cum %%\n");
 
         read_tot = lprocfs_oh_sum(&cli->cl_read_rpc_hist);
         write_tot = lprocfs_oh_sum(&cli->cl_write_rpc_hist);
@@ -270,7 +287,7 @@ static int osc_rpc_stats_seq_show(struct seq_file *seq, void *v)
                         break;
         }
 
-        seq_printf(seq, "\nrpc service time: (rpcs, average ms)\n");
+        seq_printf(seq, "\nRPC service time: (RPCs, average ms)\n");
         seq_printf(seq, "\tread\t%lu\t%lu.%04lu\n",
                         PRINTF_STIME(&cli->cl_read_stime));
         seq_printf(seq, "\twrite\t%lu\t%lu.%04lu\n\n",
@@ -284,7 +301,6 @@ static int osc_rpc_stats_seq_show(struct seq_file *seq, void *v)
 
         return 0;
 }
-#undef pct
 
 static void *osc_rpc_stats_seq_start(struct seq_file *p, loff_t *pos)
 {
@@ -300,6 +316,7 @@ static void *osc_rpc_stats_seq_next(struct seq_file *p, void *v, loff_t *pos)
 static void osc_rpc_stats_seq_stop(struct seq_file *p, void *v)
 {
 }
+
 struct seq_operations osc_rpc_stats_seq_sops = {
         .start = osc_rpc_stats_seq_start,
         .stop = osc_rpc_stats_seq_stop,
@@ -337,6 +354,13 @@ static ssize_t osc_rpc_stats_seq_write(struct file *file, const char *buf,
         memset(&cli->cl_write_stime, 0, sizeof(cli->cl_write_stime));
         memset(&cli->cl_enter_stime, 0, sizeof(cli->cl_enter_stime));
 
+        cli->cl_cache_wait_num = 0;
+        cli->cl_cache_wait_sum = 0;
+        cli->cl_write_gap_sum = 0;
+        cli->cl_write_gaps = 0;
+        cli->cl_write_num = 0;
+        cli->cl_read_num = 0;
+
         return len;
 }
 
@@ -349,10 +373,115 @@ struct file_operations osc_rpc_stats_fops = {
         .release = seq_release,
 };
 
+/* cache stats */
+static int osc_cache_stats_seq_show(struct seq_file *seq, void *v)
+{
+        struct obd_device *dev = seq->private;
+        struct client_obd *cli = &dev->u.cli;
+        unsigned long flags;
+        struct timeval now;
+
+        do_gettimeofday(&now);
+
+        spin_lock_irqsave(&cli->cl_loi_list_lock, flags);
+
+        seq_printf(seq, "snapshot_time:         %lu.%lu (secs.usecs)\n",
+                   now.tv_sec, now.tv_usec);
+
+        seq_printf(seq, "cache size:            %lu (b)\n", cli->cl_dirty_max);
+        seq_printf(seq, "max loading:           %lu (b)\n", cli->cl_dirty_dmax);
+        seq_printf(seq, "min loading:           %lu (b)\n", cli->cl_dirty_dmin);
+        seq_printf(seq, "av. cache loading:     %lu (b)\n", cli->cl_dirty_av);
+
+        seq_printf(seq, "\nav. loading ratio:     %lu%%\n",
+                   pct(cli->cl_dirty_av, cli->cl_dirty_max));
+        seq_printf(seq, "max loading ratio:     %lu%%\n",
+                   pct(cli->cl_dirty_dmax, cli->cl_dirty_max));
+
+        spin_unlock_irqrestore(&cli->cl_loi_list_lock, flags);
+        
+        return 0;
+}
+#undef pct
+
+static void *osc_cache_stats_seq_start(struct seq_file *p, loff_t *pos)
+{
+        if (*pos == 0)
+                return (void *)1;
+        return NULL;
+}
+static void *osc_cache_stats_seq_next(struct seq_file *p, void *v, loff_t *pos)
+{
+        ++*pos;
+        return NULL;
+}
+static void osc_cache_stats_seq_stop(struct seq_file *p, void *v)
+{
+}
+
+struct seq_operations osc_cache_stats_seq_sops = {
+        .start = osc_cache_stats_seq_start,
+        .stop = osc_cache_stats_seq_stop,
+        .next = osc_cache_stats_seq_next,
+        .show = osc_cache_stats_seq_show,
+};
+
+static int osc_cache_stats_seq_open(struct inode *inode, struct file *file)
+{
+        struct proc_dir_entry *dp = PDE(inode);
+        struct seq_file *seq;
+        int rc;
+
+        rc = seq_open(file, &osc_cache_stats_seq_sops);
+        if (rc)
+                return rc;
+        seq = file->private_data;
+        seq->private = dp->data;
+        return 0;
+}
+
+static ssize_t osc_cache_stats_seq_write(struct file *file, const char *buf,
+                                         size_t len, loff_t *off)
+{
+        struct seq_file *seq = file->private_data;
+        struct obd_device *dev = seq->private;
+        struct client_obd *cli = &dev->u.cli;
+
+        cli->cl_dirty_num = 0;
+        cli->cl_dirty_sum = 0;
+        cli->cl_dirty_av = 0;
+        cli->cl_dirty_dmax = 0;
+        cli->cl_dirty_dmin = 0;
+
+        return len;
+}
+
+struct file_operations osc_cache_stats_fops = {
+        .owner   = THIS_MODULE,
+        .open    = osc_cache_stats_seq_open,
+        .read    = seq_read,
+        .write   = osc_cache_stats_seq_write,
+        .llseek  = seq_lseek,
+        .release = seq_release,
+};
+
 int lproc_osc_attach_seqstat(struct obd_device *dev)
 {
-        return lprocfs_obd_seq_create(dev, "rpc_stats", 0444,
-                                      &osc_rpc_stats_fops, dev);
+        int rc;
+        
+        rc = lprocfs_obd_seq_create(dev, "rpc_stats", 0444,
+                                    &osc_rpc_stats_fops, dev);
+        if (rc) {
+                CERROR("can't init \"rpc_stats\", err %d\n", rc);
+                return rc;
+        }
+
+        rc = lprocfs_obd_seq_create(dev, "cache_stats", 0444,
+                                    &osc_cache_stats_fops, dev);
+        if (rc)
+                CERROR("can't init \"cache_stats\", err %d\n", rc);
+
+        return rc;
 }
 
 #endif /* LPROCFS */

diff --git a/lustre/osc/osc_request.c b/lustre/osc/osc_request.c
index f0fdeca..7472bc8 100644 (file)
--- a/lustre/osc/osc_request.c
+++ b/lustre/osc/osc_request.c
@@ -1893,7 +1893,7 @@ static int osc_enter_cache(struct client_obd *cli, struct lov_oinfo *loi,
 
         if (cli->cl_dirty > cli->cl_dirty_dmax)
                 cli->cl_dirty_dmax = cli->cl_dirty;
-        if (cli->cl_dirty < cli->cl_dirty_dmin)
+        if (cli->cl_dirty < cli->cl_dirty_dmin || !cli->cl_dirty_dmin)
                 cli->cl_dirty_dmin = cli->cl_dirty;
 
         /* Hopefully normal case - cache space and write credits available */
@@ -1968,7 +1968,7 @@ static void osc_exit_cache(struct client_obd *cli, struct osc_async_page *oap,
 
         if (cli->cl_dirty > cli->cl_dirty_dmax)
                 cli->cl_dirty_dmax = cli->cl_dirty;
-        if (cli->cl_dirty < cli->cl_dirty_dmin)
+        if (cli->cl_dirty < cli->cl_dirty_dmin || !cli->cl_dirty_dmin)
                 cli->cl_dirty_dmin = cli->cl_dirty;
 
         oap->oap_brw_flags &= ~OBD_BRW_FROM_GRANT;