Dump io_u on timeout
[fio.git] / io_u.c
1 #include <unistd.h>
2 #include <fcntl.h>
3 #include <string.h>
4 #include <signal.h>
5 #include <time.h>
6 #include <assert.h>
7
8 #include "fio.h"
9 #include "os.h"
10
11 /*
12  * Change this define to play with the timeout handling
13  */
14 #undef FIO_USE_TIMEOUT
15
16 struct io_completion_data {
17         int nr;                         /* input */
18         endio_handler *handler;         /* input */
19
20         int error;                      /* output */
21         unsigned long bytes_done[2];    /* output */
22         struct timeval time;            /* output */
23 };
24
25 /*
26  * The ->file_map[] contains a map of blocks we have or have not done io
27  * to yet. Used to make sure we cover the entire range in a fair fashion.
28  */
29 static int random_map_free(struct thread_data *td, struct fio_file *f,
30                            unsigned long long block)
31 {
32         unsigned int idx = RAND_MAP_IDX(td, f, block);
33         unsigned int bit = RAND_MAP_BIT(td, f, block);
34
35         return (f->file_map[idx] & (1UL << bit)) == 0;
36 }
37
38 /*
39  * Mark a given offset as used in the map.
40  */
41 static void mark_random_map(struct thread_data *td, struct fio_file *f,
42                             struct io_u *io_u)
43 {
44         unsigned int min_bs = td->rw_min_bs;
45         unsigned long long block;
46         unsigned int blocks;
47         unsigned int nr_blocks;
48
49         block = io_u->offset / (unsigned long long) min_bs;
50         blocks = 0;
51         nr_blocks = (io_u->buflen + min_bs - 1) / min_bs;
52
53         while (blocks < nr_blocks) {
54                 unsigned int idx, bit;
55
56                 if (!random_map_free(td, f, block))
57                         break;
58
59                 idx = RAND_MAP_IDX(td, f, block);
60                 bit = RAND_MAP_BIT(td, f, block);
61
62                 fio_assert(td, idx < f->num_maps);
63
64                 f->file_map[idx] |= (1UL << bit);
65                 block++;
66                 blocks++;
67         }
68
69         if ((blocks * min_bs) < io_u->buflen)
70                 io_u->buflen = blocks * min_bs;
71 }
72
73 /*
74  * Return the next free block in the map.
75  */
76 static int get_next_free_block(struct thread_data *td, struct fio_file *f,
77                                unsigned long long *b)
78 {
79         int i;
80
81         i = f->last_free_lookup;
82         *b = (i * BLOCKS_PER_MAP);
83         while ((*b) * td->rw_min_bs < f->real_file_size) {
84                 if (f->file_map[i] != -1UL) {
85                         *b += ffz(f->file_map[i]);
86                         f->last_free_lookup = i;
87                         return 0;
88                 }
89
90                 *b += BLOCKS_PER_MAP;
91                 i++;
92         }
93
94         return 1;
95 }
96
97 /*
98  * For random io, generate a random new block and see if it's used. Repeat
99  * until we find a free one. For sequential io, just return the end of
100  * the last io issued.
101  */
102 static int get_next_offset(struct thread_data *td, struct fio_file *f,
103                            struct io_u *io_u)
104 {
105         const int ddir = io_u->ddir;
106         unsigned long long b, rb;
107         long r;
108
109         if (!td->sequential) {
110                 unsigned long long max_blocks = f->file_size / td->min_bs[ddir];
111                 int loops = 5;
112
113                 do {
114                         r = os_random_long(&td->random_state);
115                         b = ((max_blocks - 1) * r / (unsigned long long) (RAND_MAX+1.0));
116                         if (td->norandommap)
117                                 break;
118                         rb = b + (f->file_offset / td->min_bs[ddir]);
119                         loops--;
120                 } while (!random_map_free(td, f, rb) && loops);
121
122                 /*
123                  * if we failed to retrieve a truly random offset within
124                  * the loops assigned, see if there are free ones left at all
125                  */
126                 if (!loops && get_next_free_block(td, f, &b))
127                         return 1;
128         } else
129                 b = f->last_pos / td->min_bs[ddir];
130
131         io_u->offset = (b * td->min_bs[ddir]) + f->file_offset;
132         if (io_u->offset >= f->real_file_size)
133                 return 1;
134
135         return 0;
136 }
137
138 static unsigned int get_next_buflen(struct thread_data *td, struct fio_file *f,
139                                     struct io_u *io_u)
140 {
141         const int ddir = io_u->ddir;
142         unsigned int buflen;
143         long r;
144
145         if (td->min_bs[ddir] == td->max_bs[ddir])
146                 buflen = td->min_bs[ddir];
147         else {
148                 r = os_random_long(&td->bsrange_state);
149                 buflen = (unsigned int) (1 + (double) (td->max_bs[ddir] - 1) * r / (RAND_MAX + 1.0));
150                 if (!td->bs_unaligned)
151                         buflen = (buflen + td->min_bs[ddir] - 1) & ~(td->min_bs[ddir] - 1);
152         }
153
154         while (buflen + io_u->offset > f->real_file_size) {
155                 if (buflen == td->min_bs[ddir])
156                         return 0;
157
158                 buflen = td->min_bs[ddir];
159         }
160
161         return buflen;
162 }
163
164 /*
165  * Return the data direction for the next io_u. If the job is a
166  * mixed read/write workload, check the rwmix cycle and switch if
167  * necessary.
168  */
169 static enum fio_ddir get_rw_ddir(struct thread_data *td)
170 {
171         if (td_rw(td)) {
172                 struct timeval now;
173                 unsigned long elapsed;
174
175                 fio_gettime(&now, NULL);
176                 elapsed = mtime_since_now(&td->rwmix_switch);
177
178                 /*
179                  * Check if it's time to seed a new data direction.
180                  */
181                 if (elapsed >= td->rwmixcycle) {
182                         unsigned int v;
183                         long r;
184
185                         r = os_random_long(&td->rwmix_state);
186                         v = 1 + (int) (100.0 * (r / (RAND_MAX + 1.0)));
187                         if (v < td->rwmixread)
188                                 td->rwmix_ddir = DDIR_READ;
189                         else
190                                 td->rwmix_ddir = DDIR_WRITE;
191                         memcpy(&td->rwmix_switch, &now, sizeof(now));
192                 }
193                 return td->rwmix_ddir;
194         } else if (td_read(td))
195                 return DDIR_READ;
196         else
197                 return DDIR_WRITE;
198 }
199
200 void put_io_u(struct thread_data *td, struct io_u *io_u)
201 {
202         assert((io_u->flags & IO_U_F_FREE) == 0);
203         io_u->flags |= IO_U_F_FREE;
204
205         io_u->file = NULL;
206         list_del(&io_u->list);
207         list_add(&io_u->list, &td->io_u_freelist);
208         td->cur_depth--;
209 }
210
211 void requeue_io_u(struct thread_data *td, struct io_u **io_u)
212 {
213         struct io_u *__io_u = *io_u;
214
215         list_del(&__io_u->list);
216         list_add_tail(&__io_u->list, &td->io_u_requeues);
217         td->cur_depth--;
218         *io_u = NULL;
219 }
220
221 static int fill_io_u(struct thread_data *td, struct fio_file *f,
222                      struct io_u *io_u)
223 {
224         /*
225          * If using an iolog, grab next piece if any available.
226          */
227         if (td->read_iolog)
228                 return read_iolog_get(td, io_u);
229
230         /*
231          * see if it's time to sync
232          */
233         if (td->fsync_blocks && !(td->io_issues[DDIR_WRITE] % td->fsync_blocks)
234             && td->io_issues[DDIR_WRITE] && should_fsync(td)) {
235                 io_u->ddir = DDIR_SYNC;
236                 io_u->file = f;
237                 return 0;
238         }
239
240         io_u->ddir = get_rw_ddir(td);
241
242         /*
243          * No log, let the seq/rand engine retrieve the next buflen and
244          * position.
245          */
246         if (get_next_offset(td, f, io_u))
247                 return 1;
248
249         io_u->buflen = get_next_buflen(td, f, io_u);
250         if (!io_u->buflen)
251                 return 1;
252
253         /*
254          * mark entry before potentially trimming io_u
255          */
256         if (!td->read_iolog && !td->sequential && !td->norandommap)
257                 mark_random_map(td, f, io_u);
258
259         /*
260          * If using a write iolog, store this entry.
261          */
262         if (td->write_iolog_file)
263                 write_iolog_put(td, io_u);
264
265         io_u->file = f;
266         return 0;
267 }
268
269 static void io_u_mark_depth(struct thread_data *td)
270 {
271         int index = 0;
272
273         switch (td->cur_depth) {
274         default:
275                 index++;
276         case 32 ... 63:
277                 index++;
278         case 16 ... 31:
279                 index++;
280         case 8 ... 15:
281                 index++;
282         case 4 ... 7:
283                 index++;
284         case 2 ... 3:
285                 index++;
286         case 1:
287                 break;
288         }
289
290         td->io_u_map[index]++;
291         td->total_io_u++;
292 }
293
294 static void io_u_mark_latency(struct thread_data *td, unsigned long msec)
295 {
296         int index = 0;
297
298         switch (msec) {
299         default:
300                 index++;
301         case 1000 ... 1999:
302                 index++;
303         case 750 ... 999:
304                 index++;
305         case 500 ... 749:
306                 index++;
307         case 250 ... 499:
308                 index++;
309         case 100 ... 249:
310                 index++;
311         case 50 ... 99:
312                 index++;
313         case 20 ... 49:
314                 index++;
315         case 10 ... 19:
316                 index++;
317         case 4 ... 9:
318                 index++;
319         case 2 ... 3:
320                 index++;
321         case 0 ... 1:
322                 break;
323         }
324
325         td->io_u_lat[index]++;
326 }
327
328 static struct fio_file *get_next_file(struct thread_data *td)
329 {
330         unsigned int old_next_file = td->next_file;
331         struct fio_file *f;
332
333         do {
334                 f = &td->files[td->next_file];
335
336                 td->next_file++;
337                 if (td->next_file >= td->nr_files)
338                         td->next_file = 0;
339
340                 if (f->fd != -1)
341                         break;
342
343                 f = NULL;
344         } while (td->next_file != old_next_file);
345
346         return f;
347 }
348
349 struct io_u *__get_io_u(struct thread_data *td)
350 {
351         struct io_u *io_u = NULL;
352
353         if (!list_empty(&td->io_u_requeues))
354                 io_u = list_entry(td->io_u_requeues.next, struct io_u, list);
355         else if (!queue_full(td)) {
356                 io_u = list_entry(td->io_u_freelist.next, struct io_u, list);
357
358                 io_u->buflen = 0;
359                 io_u->resid = 0;
360                 io_u->file = NULL;
361         }
362
363         if (io_u) {
364                 assert(io_u->flags & IO_U_F_FREE);
365                 io_u->flags &= ~IO_U_F_FREE;
366
367                 io_u->error = 0;
368                 list_del(&io_u->list);
369                 list_add(&io_u->list, &td->io_u_busylist);
370                 td->cur_depth++;
371                 io_u_mark_depth(td);
372         }
373
374         return io_u;
375 }
376
377 /*
378  * Return an io_u to be processed. Gets a buflen and offset, sets direction,
379  * etc. The returned io_u is fully ready to be prepped and submitted.
380  */
381 struct io_u *get_io_u(struct thread_data *td)
382 {
383         struct fio_file *f;
384         struct io_u *io_u;
385
386         io_u = __get_io_u(td);
387         if (!io_u)
388                 return NULL;
389
390         /*
391          * from a requeue, io_u already setup
392          */
393         if (io_u->file)
394                 goto out;
395
396         f = get_next_file(td);
397         if (!f) {
398                 put_io_u(td, io_u);
399                 return NULL;
400         }
401
402         io_u->file = f;
403
404         if (td->zone_bytes >= td->zone_size) {
405                 td->zone_bytes = 0;
406                 f->last_pos += td->zone_skip;
407         }
408
409         if (fill_io_u(td, f, io_u)) {
410                 put_io_u(td, io_u);
411                 return NULL;
412         }
413
414         if (io_u->buflen + io_u->offset > f->real_file_size) {
415                 if (td->io_ops->flags & FIO_RAWIO) {
416                         put_io_u(td, io_u);
417                         return NULL;
418                 }
419
420                 io_u->buflen = f->real_file_size - io_u->offset;
421         }
422
423         if (io_u->ddir != DDIR_SYNC) {
424                 if (!io_u->buflen) {
425                         put_io_u(td, io_u);
426                         return NULL;
427                 }
428
429                 f->last_pos = io_u->offset + io_u->buflen;
430
431                 if (td->verify != VERIFY_NONE)
432                         populate_verify_io_u(td, io_u);
433         }
434
435         /*
436          * Set io data pointers.
437          */
438 out:
439         io_u->xfer_buf = io_u->buf;
440         io_u->xfer_buflen = io_u->buflen;
441
442         if (td_io_prep(td, io_u)) {
443                 put_io_u(td, io_u);
444                 return NULL;
445         }
446
447         fio_gettime(&io_u->start_time, NULL);
448         return io_u;
449 }
450
451 static void io_completed(struct thread_data *td, struct io_u *io_u,
452                          struct io_completion_data *icd)
453 {
454         unsigned long msec;
455
456         assert(io_u->flags & IO_U_F_FLIGHT);
457         io_u->flags &= ~IO_U_F_FLIGHT;
458
459         if (io_u->ddir == DDIR_SYNC) {
460                 td->last_was_sync = 1;
461                 return;
462         }
463
464         td->last_was_sync = 0;
465
466         if (!io_u->error) {
467                 unsigned int bytes = io_u->buflen - io_u->resid;
468                 const enum fio_ddir idx = io_u->ddir;
469                 int ret;
470
471                 td->io_blocks[idx]++;
472                 td->io_bytes[idx] += bytes;
473                 td->zone_bytes += bytes;
474                 td->this_io_bytes[idx] += bytes;
475
476                 io_u->file->last_completed_pos = io_u->offset + io_u->buflen;
477
478                 msec = mtime_since(&io_u->issue_time, &icd->time);
479
480                 add_clat_sample(td, idx, msec);
481                 add_bw_sample(td, idx, &icd->time);
482                 io_u_mark_latency(td, msec);
483
484                 if ((td_rw(td) || td_write(td)) && idx == DDIR_WRITE)
485                         log_io_piece(td, io_u);
486
487                 icd->bytes_done[idx] += bytes;
488
489                 if (icd->handler) {
490                         ret = icd->handler(io_u);
491                         if (ret && !icd->error)
492                                 icd->error = ret;
493                 }
494         } else
495                 icd->error = io_u->error;
496 }
497
498 static void init_icd(struct io_completion_data *icd, endio_handler *handler,
499                      int nr)
500 {
501         fio_gettime(&icd->time, NULL);
502
503         icd->handler = handler;
504         icd->nr = nr;
505
506         icd->error = 0;
507         icd->bytes_done[0] = icd->bytes_done[1] = 0;
508 }
509
510 static void ios_completed(struct thread_data *td,
511                           struct io_completion_data *icd)
512 {
513         struct io_u *io_u;
514         int i;
515
516         for (i = 0; i < icd->nr; i++) {
517                 io_u = td->io_ops->event(td, i);
518
519                 io_completed(td, io_u, icd);
520                 put_io_u(td, io_u);
521         }
522 }
523
524 /*
525  * Complete a single io_u for the sync engines.
526  */
527 long io_u_sync_complete(struct thread_data *td, struct io_u *io_u,
528                         endio_handler *handler)
529 {
530         struct io_completion_data icd;
531
532         init_icd(&icd, handler, 1);
533         io_completed(td, io_u, &icd);
534         put_io_u(td, io_u);
535
536         if (!icd.error)
537                 return icd.bytes_done[0] + icd.bytes_done[1];
538
539         return -1;
540 }
541
542 /*
543  * Called to complete min_events number of io for the async engines.
544  */
545 long io_u_queued_complete(struct thread_data *td, int min_events,
546                           endio_handler *handler)
547
548 {
549         struct io_completion_data icd;
550         struct timespec *tvp = NULL;
551         int ret;
552
553         if (min_events > 0) {
554                 ret = td_io_commit(td);
555                 if (ret < 0) {
556                         td_verror(td, -ret, "td_io_commit");
557                         return ret;
558                 }
559         } else {
560                 struct timespec ts = { .tv_sec = 0, .tv_nsec = 0, };
561
562                 tvp = &ts;
563         }
564
565         ret = td_io_getevents(td, min_events, td->cur_depth, tvp);
566         if (ret < 0) {
567                 td_verror(td, -ret, "td_io_getevents");
568                 return ret;
569         } else if (!ret)
570                 return ret;
571
572         init_icd(&icd, handler, ret);
573         ios_completed(td, &icd);
574         if (!icd.error)
575                 return icd.bytes_done[0] + icd.bytes_done[1];
576
577         return -1;
578 }
579
580 /*
581  * Call when io_u is really queued, to update the submission latency.
582  */
583 void io_u_queued(struct thread_data *td, struct io_u *io_u)
584 {
585         unsigned long slat_time;
586
587         slat_time = mtime_since(&io_u->start_time, &io_u->issue_time);
588         add_slat_sample(td, io_u->ddir, slat_time);
589 }
590
591 #ifdef FIO_USE_TIMEOUT
592 void io_u_set_timeout(struct thread_data *td)
593 {
594         assert(td->cur_depth);
595
596         td->timer.it_interval.tv_sec = 0;
597         td->timer.it_interval.tv_usec = 0;
598         td->timer.it_value.tv_sec = IO_U_TIMEOUT + IO_U_TIMEOUT_INC;
599         td->timer.it_value.tv_usec = 0;
600         setitimer(ITIMER_REAL, &td->timer, NULL);
601         fio_gettime(&td->timeout_end, NULL);
602 }
603
604 static void io_u_dump(struct io_u *io_u)
605 {
606         unsigned long t_start = mtime_since_now(&io_u->start_time);
607         unsigned long t_issue = mtime_since_now(&io_u->issue_time);
608
609         log_err("io_u=%p, t_start=%lu, t_issue=%lu\n", io_u, t_start, t_issue);
610         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);
611         log_err("  ddir=%d, fname=%s\n", io_u->ddir, io_u->file->file_name);
612 }
613 #else
614 void io_u_set_timeout(struct thread_data fio_unused *td)
615 {
616 }
617 #endif
618
619 #ifdef FIO_USE_TIMEOUT
620 static void io_u_timeout_handler(int fio_unused sig)
621 {
622         struct thread_data *td, *__td;
623         pid_t pid = getpid();
624         struct list_head *entry;
625         struct io_u *io_u;
626         int i;
627
628         log_err("fio: io_u timeout\n");
629
630         /*
631          * TLS would be nice...
632          */
633         td = NULL;
634         for_each_td(__td, i) {
635                 if (__td->pid == pid) {
636                         td = __td;
637                         break;
638                 }
639         }
640
641         if (!td) {
642                 log_err("fio: io_u timeout, can't find job\n");
643                 exit(1);
644         }
645
646         if (!td->cur_depth) {
647                 log_err("fio: timeout without pending work?\n");
648                 return;
649         }
650
651         log_err("fio: io_u timeout: job=%s, pid=%d\n", td->name, td->pid);
652
653         list_for_each(entry, &td->io_u_busylist) {
654                 io_u = list_entry(entry, struct io_u, list);
655
656                 io_u_dump(io_u);
657         }
658
659         td_verror(td, ETIMEDOUT, "io_u timeout");
660         exit(1);
661 }
662 #endif
663
664 void io_u_init_timeout(void)
665 {
666 #ifdef FIO_USE_TIMEOUT
667         signal(SIGALRM, io_u_timeout_handler);
668 #endif
669 }