Dump io_u on timeout

[fio.git] / io_u.c

diff --git a/io_u.c b/io_u.c
index b8f090bd536a5b3d2077e191684b18f062425c7b..ab85193d1c95166dfcbd4eeea45a28637c788d4c 100644 (file)
--- a/io_u.c
+++ b/io_u.c
@@ -3,10 +3,16 @@
 #include <string.h>
 #include <signal.h>
 #include <time.h>
+#include <assert.h>
 
 #include "fio.h"
 #include "os.h"
 
+/*
+ * Change this define to play with the timeout handling
+ */
+#undef FIO_USE_TIMEOUT
+
 struct io_completion_data {
        int nr;                         /* input */
        endio_handler *handler;         /* input */
@@ -193,6 +199,9 @@ static enum fio_ddir get_rw_ddir(struct thread_data *td)
 
 void put_io_u(struct thread_data *td, struct io_u *io_u)
 {
+       assert((io_u->flags & IO_U_F_FREE) == 0);
+       io_u->flags |= IO_U_F_FREE;
+
        io_u->file = NULL;
        list_del(&io_u->list);
        list_add(&io_u->list, &td->io_u_freelist);
@@ -289,23 +298,23 @@ static void io_u_mark_latency(struct thread_data *td, unsigned long msec)
        switch (msec) {
        default:
                index++;
-       case 1024 ... 2047:
+       case 1000 ... 1999:
                index++;
-       case 512 ... 1023:
+       case 750 ... 999:
                index++;
-       case 256 ... 511:
+       case 500 ... 749:
                index++;
-       case 128 ... 255:
+       case 250 ... 499:
                index++;
-       case 64 ... 127:
+       case 100 ... 249:
                index++;
-       case 32 ... 63:
+       case 50 ... 99:
                index++;
-       case 16 ... 31:
+       case 20 ... 49:
                index++;
-       case 8 ... 15:
+       case 10 ... 19:
                index++;
-       case 4 ... 7:
+       case 4 ... 9:
                index++;
        case 2 ... 3:
                index++;
@@ -352,6 +361,9 @@ struct io_u *__get_io_u(struct thread_data *td)
        }
 
        if (io_u) {
+               assert(io_u->flags & IO_U_F_FREE);
+               io_u->flags &= ~IO_U_F_FREE;
+
                io_u->error = 0;
                list_del(&io_u->list);
                list_add(&io_u->list, &td->io_u_busylist);
@@ -441,6 +453,9 @@ static void io_completed(struct thread_data *td, struct io_u *io_u,
 {
        unsigned long msec;
 
+       assert(io_u->flags & IO_U_F_FLIGHT);
+       io_u->flags &= ~IO_U_F_FLIGHT;
+
        if (io_u->ddir == DDIR_SYNC) {
                td->last_was_sync = 1;
                return;
@@ -538,7 +553,7 @@ long io_u_queued_complete(struct thread_data *td, int min_events,
        if (min_events > 0) {
                ret = td_io_commit(td);
                if (ret < 0) {
-                       td_verror(td, -ret);
+                       td_verror(td, -ret, "td_io_commit");
                        return ret;
                }
        } else {
@@ -549,7 +564,7 @@ long io_u_queued_complete(struct thread_data *td, int min_events,
 
        ret = td_io_getevents(td, min_events, td->cur_depth, tvp);
        if (ret < 0) {
-               td_verror(td, -ret);
+               td_verror(td, -ret, "td_io_getevents");
                return ret;
        } else if (!ret)
                return ret;
@@ -572,3 +587,83 @@ void io_u_queued(struct thread_data *td, struct io_u *io_u)
        slat_time = mtime_since(&io_u->start_time, &io_u->issue_time);
        add_slat_sample(td, io_u->ddir, slat_time);
 }
+
+#ifdef FIO_USE_TIMEOUT
+void io_u_set_timeout(struct thread_data *td)
+{
+       assert(td->cur_depth);
+
+       td->timer.it_interval.tv_sec = 0;
+       td->timer.it_interval.tv_usec = 0;
+       td->timer.it_value.tv_sec = IO_U_TIMEOUT + IO_U_TIMEOUT_INC;
+       td->timer.it_value.tv_usec = 0;
+       setitimer(ITIMER_REAL, &td->timer, NULL);
+       fio_gettime(&td->timeout_end, NULL);
+}
+
+static void io_u_dump(struct io_u *io_u)
+{
+       unsigned long t_start = mtime_since_now(&io_u->start_time);
+       unsigned long t_issue = mtime_since_now(&io_u->issue_time);
+
+       log_err("io_u=%p, t_start=%lu, t_issue=%lu\n", io_u, t_start, t_issue);
+       log_err("  buf=%p/%p, len=%lu/%lu, offset=%llu\n", io_u->buf, io_u->xfer_buf, io_u->buflen, io_u->xfer_buflen, io_u->offset);
+       log_err("  ddir=%d, fname=%s\n", io_u->ddir, io_u->file->file_name);
+}
+#else
+void io_u_set_timeout(struct thread_data fio_unused *td)
+{
+}
+#endif
+
+#ifdef FIO_USE_TIMEOUT
+static void io_u_timeout_handler(int fio_unused sig)
+{
+       struct thread_data *td, *__td;
+       pid_t pid = getpid();
+       struct list_head *entry;
+       struct io_u *io_u;
+       int i;
+
+       log_err("fio: io_u timeout\n");
+
+       /*
+        * TLS would be nice...
+        */
+       td = NULL;
+       for_each_td(__td, i) {
+               if (__td->pid == pid) {
+                       td = __td;
+                       break;
+               }
+       }
+
+       if (!td) {
+               log_err("fio: io_u timeout, can't find job\n");
+               exit(1);
+       }
+
+       if (!td->cur_depth) {
+               log_err("fio: timeout without pending work?\n");
+               return;
+       }
+
+       log_err("fio: io_u timeout: job=%s, pid=%d\n", td->name, td->pid);
+
+       list_for_each(entry, &td->io_u_busylist) {
+               io_u = list_entry(entry, struct io_u, list);
+
+               io_u_dump(io_u);
+       }
+
+       td_verror(td, ETIMEDOUT, "io_u timeout");
+       exit(1);
+}
+#endif
+
+void io_u_init_timeout(void)
+{
+#ifdef FIO_USE_TIMEOUT
+       signal(SIGALRM, io_u_timeout_handler);
+#endif
+}