Add missing trailing \n in log_err/info()
[fio.git] / backend.c
index d98658606d772ed7d31b1355571ee2566b53a213..a46101ca5aebc04d51523f3e4eb61c01c907c368 100644 (file)
--- a/backend.c
+++ b/backend.c
@@ -180,8 +180,8 @@ static bool __check_min_rate(struct thread_data *td, struct timeval *now,
                         * check bandwidth specified rate
                         */
                        if (bytes < td->rate_bytes[ddir]) {
-                               log_err("%s: min rate %u not met\n", td->o.name,
-                                                               ratemin);
+                               log_err("%s: rate_min=%uB/s not met, only transferred %lluB\n",
+                                       td->o.name, ratemin, bytes);
                                return true;
                        } else {
                                if (spent)
@@ -191,9 +191,8 @@ static bool __check_min_rate(struct thread_data *td, struct timeval *now,
 
                                if (rate < ratemin ||
                                    bytes < td->rate_bytes[ddir]) {
-                                       log_err("%s: min rate %u not met, got"
-                                               " %luKB/sec\n", td->o.name,
-                                                       ratemin, rate);
+                                       log_err("%s: rate_min=%uB/s not met, got %luB/s\n",
+                                               td->o.name, ratemin, rate);
                                        return true;
                                }
                        }
@@ -202,8 +201,8 @@ static bool __check_min_rate(struct thread_data *td, struct timeval *now,
                         * checks iops specified rate
                         */
                        if (iops < rate_iops) {
-                               log_err("%s: min iops rate %u not met\n",
-                                               td->o.name, rate_iops);
+                               log_err("%s: rate_iops_min=%u not met, only performed %lu IOs\n",
+                                               td->o.name, rate_iops, iops);
                                return true;
                        } else {
                                if (spent)
@@ -213,9 +212,8 @@ static bool __check_min_rate(struct thread_data *td, struct timeval *now,
 
                                if (rate < rate_iops_min ||
                                    iops < td->rate_blocks[ddir]) {
-                                       log_err("%s: min iops rate %u not met,"
-                                               " got %lu\n", td->o.name,
-                                                       rate_iops_min, rate);
+                                       log_err("%s: rate_iops_min=%u not met, got %lu IOPS\n",
+                                               td->o.name, rate_iops_min, rate);
                                        return true;
                                }
                        }
@@ -441,11 +439,8 @@ static int wait_for_completions(struct thread_data *td, struct timeval *time)
        int min_evts = 0;
        int ret;
 
-       if (td->flags & TD_F_REGROW_LOGS) {
-               ret = io_u_quiesce(td);
-               regrow_logs(td);
-               return ret;
-       }
+       if (td->flags & TD_F_REGROW_LOGS)
+               return io_u_quiesce(td);
 
        /*
         * if the queue is full, we MUST reap at least 1 event
@@ -771,18 +766,18 @@ static bool exceeds_number_ios(struct thread_data *td)
        return number_ios >= (td->o.number_ios * td->loops);
 }
 
-static bool io_issue_bytes_exceeded(struct thread_data *td)
+static bool io_bytes_exceeded(struct thread_data *td, uint64_t *this_bytes)
 {
        unsigned long long bytes, limit;
 
        if (td_rw(td))
-               bytes = td->io_issue_bytes[DDIR_READ] + td->io_issue_bytes[DDIR_WRITE];
+               bytes = this_bytes[DDIR_READ] + this_bytes[DDIR_WRITE];
        else if (td_write(td))
-               bytes = td->io_issue_bytes[DDIR_WRITE];
+               bytes = this_bytes[DDIR_WRITE];
        else if (td_read(td))
-               bytes = td->io_issue_bytes[DDIR_READ];
+               bytes = this_bytes[DDIR_READ];
        else
-               bytes = td->io_issue_bytes[DDIR_TRIM];
+               bytes = this_bytes[DDIR_TRIM];
 
        if (td->o.io_limit)
                limit = td->o.io_limit;
@@ -793,26 +788,14 @@ static bool io_issue_bytes_exceeded(struct thread_data *td)
        return bytes >= limit || exceeds_number_ios(td);
 }
 
-static bool io_complete_bytes_exceeded(struct thread_data *td)
+static bool io_issue_bytes_exceeded(struct thread_data *td)
 {
-       unsigned long long bytes, limit;
-
-       if (td_rw(td))
-               bytes = td->this_io_bytes[DDIR_READ] + td->this_io_bytes[DDIR_WRITE];
-       else if (td_write(td))
-               bytes = td->this_io_bytes[DDIR_WRITE];
-       else if (td_read(td))
-               bytes = td->this_io_bytes[DDIR_READ];
-       else
-               bytes = td->this_io_bytes[DDIR_TRIM];
-
-       if (td->o.io_limit)
-               limit = td->o.io_limit;
-       else
-               limit = td->o.size;
+       return io_bytes_exceeded(td, td->io_issue_bytes);
+}
 
-       limit *= td->loops;
-       return bytes >= limit || exceeds_number_ios(td);
+static bool io_complete_bytes_exceeded(struct thread_data *td)
+{
+       return io_bytes_exceeded(td, td->this_io_bytes);
 }
 
 /*
@@ -1471,6 +1454,7 @@ static void *thread_main(void *data)
        struct thread_data *td = fd->td;
        struct thread_options *o = &td->o;
        struct sk_out *sk_out = fd->sk_out;
+       int deadlock_loop_cnt;
        int clear_state;
        int ret;
 
@@ -1679,6 +1663,7 @@ static void *thread_main(void *data)
        fio_getrusage(&td->ru_start);
        memcpy(&td->bw_sample_time, &td->epoch, sizeof(td->epoch));
        memcpy(&td->iops_sample_time, &td->epoch, sizeof(td->epoch));
+       memcpy(&td->ss.prev_time, &td->epoch, sizeof(td->epoch));
 
        if (o->ratemin[DDIR_READ] || o->ratemin[DDIR_WRITE] ||
                        o->ratemin[DDIR_TRIM]) {
@@ -1722,6 +1707,14 @@ static void *thread_main(void *data)
                        }
                }
 
+               /*
+                * If we took too long to shut down, the main thread could
+                * already consider us reaped/exited. If that happens, break
+                * out and clean up.
+                */
+               if (td->runstate >= TD_EXITED)
+                       break;
+
                clear_state = 1;
 
                /*
@@ -1731,9 +1724,19 @@ static void *thread_main(void *data)
                 * the rusage_sem, which would never get upped because
                 * this thread is waiting for the stat mutex.
                 */
-               check_update_rusage(td);
+               deadlock_loop_cnt = 0;
+               do {
+                       check_update_rusage(td);
+                       if (!fio_mutex_down_trylock(stat_mutex))
+                               break;
+                       usleep(1000);
+                       if (deadlock_loop_cnt++ > 5000) {
+                               log_err("fio seems to be stuck grabbing stat_mutex, forcibly exiting\n");
+                               td->error = EDEADLK;
+                               goto err;
+                       }
+               } while (1);
 
-               fio_mutex_down(stat_mutex);
                if (td_read(td) && td->io_bytes[DDIR_READ])
                        update_runtime(td, elapsed_us, DDIR_READ);
                if (td_write(td) && td->io_bytes[DDIR_WRITE])
@@ -1857,8 +1860,8 @@ static void dump_td_info(struct thread_data *td)
 /*
  * Run over the job map and reap the threads that have exited, if any.
  */
-static void reap_threads(unsigned int *nr_running, unsigned int *t_rate,
-                        unsigned int *m_rate)
+static void reap_threads(unsigned int *nr_running, uint64_t *t_rate,
+                        uint64_t *m_rate)
 {
        struct thread_data *td;
        unsigned int cputhreads, realthreads, pending;
@@ -2060,7 +2063,7 @@ static bool check_mount_writes(struct thread_data *td)
 
        return false;
 mounted:
-       log_err("fio: %s appears mounted, and 'allow_mounted_write' isn't set. Aborting.", f->file_name);
+       log_err("fio: %s appears mounted, and 'allow_mounted_write' isn't set. Aborting.\n", f->file_name);
        return true;
 }
 
@@ -2096,7 +2099,8 @@ static bool waitee_running(struct thread_data *me)
 static void run_threads(struct sk_out *sk_out)
 {
        struct thread_data *td;
-       unsigned int i, todo, nr_running, m_rate, t_rate, nr_started;
+       unsigned int i, todo, nr_running, nr_started;
+       uint64_t m_rate, t_rate;
        uint64_t spent;
 
        if (fio_gtod_offload && fio_start_gtod_thread())
@@ -2410,6 +2414,12 @@ int fio_backend(struct sk_out *sk_out)
        }
 
        for_each_td(td, i) {
+               if (td->ss.dur) {
+                       if (td->ss.iops_data != NULL) {
+                               free(td->ss.iops_data);
+                               free(td->ss.bw_data);
+                       }
+               }
                fio_options_free(td);
                if (td->rusage_sem) {
                        fio_mutex_remove(td->rusage_sem);