drbd: debugfs: add callback_history

Add a per-connection worker thread callback_history
with timing details, call site and callback function.

Signed-off-by: Philipp Reisner <philipp.reisner@linbit.com>
Signed-off-by: Lars Ellenberg <lars.ellenberg@linbit.com>

4 files changed, 144 insertions, 3 deletions

diff --git a/drivers/block/drbd/drbd_debugfs.c b/drivers/block/drbd/drbd_debugfs.c
index 12d072d9751f..230d9e1fc85c 100644
--- a/drivers/block/drbd/drbd_debugfs.c
+++ b/drivers/block/drbd/drbd_debugfs.c
@@ -521,6 +521,77 @@ void drbd_debugfs_resource_cleanup(struct drbd_resource *resource)
         drbd_debugfs_remove(&resource->debugfs_res);
 }
 
+static void seq_print_one_timing_detail(struct seq_file *m,
+        const struct drbd_thread_timing_details *tdp,
+        unsigned long now)
+{
+        struct drbd_thread_timing_details td;
+        /* No locking...
+         * use temporary assignment to get at consistent data. */
+        do {
+                td = *tdp;
+        } while (td.cb_nr != tdp->cb_nr);
+        if (!td.cb_addr)
+                return;
+        seq_printf(m, "%u\t%d\t%s:%u\t%ps\n",
+                        td.cb_nr,
+                        jiffies_to_msecs(now - td.start_jif),
+                        td.caller_fn, td.line,
+                        td.cb_addr);
+}
+
+static void seq_print_timing_details(struct seq_file *m,
+                const char *title,
+                unsigned int cb_nr, struct drbd_thread_timing_details *tdp, unsigned long now)
+{
+        unsigned int start_idx;
+        unsigned int i;
+
+        seq_printf(m, "%s\n", title);
+        /* If not much is going on, this will result in natural ordering.
+         * If it is very busy, we will possibly skip events, or even see wrap
+         * arounds, which could only be avoided with locking.
+         */
+        start_idx = cb_nr % DRBD_THREAD_DETAILS_HIST;
+        for (i = start_idx; i < DRBD_THREAD_DETAILS_HIST; i++)
+                seq_print_one_timing_detail(m, tdp+i, now);
+        for (i = 0; i < start_idx; i++)
+                seq_print_one_timing_detail(m, tdp+i, now);
+}
+
+static int callback_history_show(struct seq_file *m, void *ignored)
+{
+        struct drbd_connection *connection = m->private;
+        unsigned long jif = jiffies;
+
+        seq_puts(m, "n\tage\tcallsite\tfn\n");
+        seq_print_timing_details(m, "worker", connection->w_cb_nr, connection->w_timing_details, jif);
+        seq_print_timing_details(m, "receiver", connection->r_cb_nr, connection->r_timing_details, jif);
+        return 0;
+}
+
+static int callback_history_open(struct inode *inode, struct file *file)
+{
+        struct drbd_connection *connection = inode->i_private;
+        return drbd_single_open(file, callback_history_show, connection,
+                                &connection->kref, drbd_destroy_connection);
+}
+
+static int callback_history_release(struct inode *inode, struct file *file)
+{
+        struct drbd_connection *connection = inode->i_private;
+        kref_put(&connection->kref, drbd_destroy_connection);
+        return single_release(inode, file);
+}
+
+static const struct file_operations connection_callback_history_fops = {
+        .owner          = THIS_MODULE,
+        .open           = callback_history_open,
+        .read           = seq_read,
+        .llseek         = seq_lseek,
+        .release        = callback_history_release,
+};
+
 void drbd_debugfs_connection_add(struct drbd_connection *connection)
 {
         struct dentry *conns_dir = connection->resource->debugfs_res_connections;
@@ -535,6 +606,13 @@ void drbd_debugfs_connection_add(struct drbd_connection *connection)
         if (IS_ERR_OR_NULL(dentry))
                 goto fail;
         connection->debugfs_conn = dentry;
+
+        dentry = debugfs_create_file("callback_history", S_IRUSR|S_IRGRP,
+                        connection->debugfs_conn, connection,
+                        &connection_callback_history_fops);
+        if (IS_ERR_OR_NULL(dentry))
+                goto fail;
+        connection->debugfs_conn_callback_history = dentry;
         return;
 
 fail:
diff --git a/drivers/block/drbd/drbd_int.h b/drivers/block/drbd/drbd_int.h
index 30ed430f57bf..1a000016ccdf 100644
--- a/drivers/block/drbd/drbd_int.h
+++ b/drivers/block/drbd/drbd_int.h
@@ -697,6 +697,15 @@ struct drbd_resource {
         cpumask_var_t cpu_mask;
 };
 
+struct drbd_thread_timing_details
+{
+        unsigned long start_jif;
+        void *cb_addr;
+        const char *caller_fn;
+        unsigned int line;
+        unsigned int cb_nr;
+};
+
 struct drbd_connection {
         struct list_head connections;
         struct drbd_resource *resource;
@@ -759,6 +768,12 @@ struct drbd_connection {
         /* sender side */
         struct drbd_work_queue sender_work;
 
+#define DRBD_THREAD_DETAILS_HIST        16
+        unsigned int w_cb_nr; /* keeps counting up */
+        unsigned int r_cb_nr; /* keeps counting up */
+        struct drbd_thread_timing_details w_timing_details[DRBD_THREAD_DETAILS_HIST];
+        struct drbd_thread_timing_details r_timing_details[DRBD_THREAD_DETAILS_HIST];
+
         struct {
                 /* whether this sender thread
                  * has processed a single write yet. */
@@ -774,6 +789,17 @@ struct drbd_connection {
         } send;
 };
 
+void __update_timing_details(
+                struct drbd_thread_timing_details *tdp,
+                unsigned int *cb_nr,
+                void *cb,
+                const char *fn, const unsigned int line);
+
+#define update_worker_timing_details(c, cb) \
+        __update_timing_details(c->w_timing_details, &c->w_cb_nr, cb, __func__ , __LINE__ )
+#define update_receiver_timing_details(c, cb) \
+        __update_timing_details(c->r_timing_details, &c->r_cb_nr, cb, __func__ , __LINE__ )
+
 struct submit_worker {
         struct workqueue_struct *wq;
         struct work_struct worker;
diff --git a/drivers/block/drbd/drbd_receiver.c b/drivers/block/drbd/drbd_receiver.c
index 9f6ed240e075..f972988291c5 100644
--- a/drivers/block/drbd/drbd_receiver.c
+++ b/drivers/block/drbd/drbd_receiver.c
@@ -2682,9 +2682,11 @@ static int receive_DataRequest(struct drbd_connection *connection, struct packet
         list_add_tail(&peer_req->w.list, &device->read_ee);
         spin_unlock_irq(&device->resource->req_lock);
 
+        update_receiver_timing_details(connection, drbd_rs_should_slow_down);
         if (device->state.peer != R_PRIMARY
         && drbd_rs_should_slow_down(device, sector, false))
                 schedule_timeout_uninterruptible(HZ/10);
+        update_receiver_timing_details(connection, drbd_rs_begin_io);
         if (drbd_rs_begin_io(device, sector))
                 goto out_free_e;
 
@@ -2692,6 +2694,7 @@ submit_for_resync:
         atomic_add(size >> 9, &device->rs_sect_ev);
 
 submit:
+        update_receiver_timing_details(connection, drbd_submit_peer_request);
         inc_unacked(device);