96afec665c73a81c7c37286b77e2b3143e38be53
[fio.git] / iolog.c
1 /*
2  * Code related to writing an iolog of what a thread is doing, and to
3  * later read that back and replay
4  */
5 #include <stdio.h>
6 #include <stdlib.h>
7 #include <libgen.h>
8 #include <assert.h>
9 #include "flist.h"
10 #include "fio.h"
11 #include "verify.h"
12 #include "trim.h"
13 #include "filelock.h"
14
15 static const char iolog_ver2[] = "fio version 2 iolog";
16
17 void queue_io_piece(struct thread_data *td, struct io_piece *ipo)
18 {
19         flist_add_tail(&ipo->list, &td->io_log_list);
20         td->total_io_size += ipo->len;
21 }
22
23 void log_io_u(struct thread_data *td, struct io_u *io_u)
24 {
25         const char *act[] = { "read", "write", "sync", "datasync",
26                                 "sync_file_range", "wait", "trim" };
27
28         assert(io_u->ddir <= 6);
29
30         if (!td->o.write_iolog_file)
31                 return;
32
33         fprintf(td->iolog_f, "%s %s %llu %lu\n", io_u->file->file_name,
34                                                 act[io_u->ddir], io_u->offset,
35                                                 io_u->buflen);
36 }
37
38 void log_file(struct thread_data *td, struct fio_file *f,
39               enum file_log_act what)
40 {
41         const char *act[] = { "add", "open", "close" };
42
43         assert(what < 3);
44
45         if (!td->o.write_iolog_file)
46                 return;
47
48
49         /*
50          * this happens on the pre-open/close done before the job starts
51          */
52         if (!td->iolog_f)
53                 return;
54
55         fprintf(td->iolog_f, "%s %s\n", f->file_name, act[what]);
56 }
57
58 static void iolog_delay(struct thread_data *td, unsigned long delay)
59 {
60         unsigned long usec = utime_since_now(&td->last_issue);
61         unsigned long this_delay;
62
63         if (delay < usec)
64                 return;
65
66         delay -= usec;
67
68         /*
69          * less than 100 usec delay, just regard it as noise
70          */
71         if (delay < 100)
72                 return;
73
74         while (delay && !td->terminate) {
75                 this_delay = delay;
76                 if (this_delay > 500000)
77                         this_delay = 500000;
78
79                 usec_sleep(td, this_delay);
80                 delay -= this_delay;
81         }
82 }
83
84 static int ipo_special(struct thread_data *td, struct io_piece *ipo)
85 {
86         struct fio_file *f;
87         int ret;
88
89         /*
90          * Not a special ipo
91          */
92         if (ipo->ddir != DDIR_INVAL)
93                 return 0;
94
95         f = td->files[ipo->fileno];
96
97         switch (ipo->file_action) {
98         case FIO_LOG_OPEN_FILE:
99                 ret = td_io_open_file(td, f);
100                 if (!ret)
101                         break;
102                 td_verror(td, ret, "iolog open file");
103                 return -1;
104         case FIO_LOG_CLOSE_FILE:
105                 td_io_close_file(td, f);
106                 break;
107         case FIO_LOG_UNLINK_FILE:
108                 unlink(f->file_name);
109                 break;
110         default:
111                 log_err("fio: bad file action %d\n", ipo->file_action);
112                 break;
113         }
114
115         return 1;
116 }
117
118 int read_iolog_get(struct thread_data *td, struct io_u *io_u)
119 {
120         struct io_piece *ipo;
121         unsigned long elapsed;
122
123         while (!flist_empty(&td->io_log_list)) {
124                 int ret;
125
126                 ipo = flist_entry(td->io_log_list.next, struct io_piece, list);
127                 flist_del(&ipo->list);
128                 remove_trim_entry(td, ipo);
129
130                 ret = ipo_special(td, ipo);
131                 if (ret < 0) {
132                         free(ipo);
133                         break;
134                 } else if (ret > 0) {
135                         free(ipo);
136                         continue;
137                 }
138
139                 io_u->ddir = ipo->ddir;
140                 if (ipo->ddir != DDIR_WAIT) {
141                         io_u->offset = ipo->offset;
142                         io_u->buflen = ipo->len;
143                         io_u->file = td->files[ipo->fileno];
144                         get_file(io_u->file);
145                         dprint(FD_IO, "iolog: get %llu/%lu/%s\n", io_u->offset,
146                                                 io_u->buflen, io_u->file->file_name);
147                         if (ipo->delay)
148                                 iolog_delay(td, ipo->delay);
149                 } else {
150                         elapsed = mtime_since_genesis();
151                         if (ipo->delay > elapsed)
152                                 usec_sleep(td, (ipo->delay - elapsed) * 1000);
153                 }
154
155                 free(ipo);
156
157                 if (io_u->ddir != DDIR_WAIT)
158                         return 0;
159         }
160
161         td->done = 1;
162         return 1;
163 }
164
165 void prune_io_piece_log(struct thread_data *td)
166 {
167         struct io_piece *ipo;
168         struct rb_node *n;
169
170         while ((n = rb_first(&td->io_hist_tree)) != NULL) {
171                 ipo = rb_entry(n, struct io_piece, rb_node);
172                 rb_erase(n, &td->io_hist_tree);
173                 remove_trim_entry(td, ipo);
174                 td->io_hist_len--;
175                 free(ipo);
176         }
177
178         while (!flist_empty(&td->io_hist_list)) {
179                 ipo = flist_entry(td->io_hist_list.next, struct io_piece, list);
180                 flist_del(&ipo->list);
181                 remove_trim_entry(td, ipo);
182                 td->io_hist_len--;
183                 free(ipo);
184         }
185 }
186
187 /*
188  * log a successful write, so we can unwind the log for verify
189  */
190 void log_io_piece(struct thread_data *td, struct io_u *io_u)
191 {
192         struct rb_node **p, *parent;
193         struct io_piece *ipo, *__ipo;
194
195         ipo = malloc(sizeof(struct io_piece));
196         init_ipo(ipo);
197         ipo->file = io_u->file;
198         ipo->offset = io_u->offset;
199         ipo->len = io_u->buflen;
200         ipo->numberio = io_u->numberio;
201         ipo->flags = IP_F_IN_FLIGHT;
202
203         io_u->ipo = ipo;
204
205         if (io_u_should_trim(td, io_u)) {
206                 flist_add_tail(&ipo->trim_list, &td->trim_list);
207                 td->trim_entries++;
208         }
209
210         /*
211          * We don't need to sort the entries, if:
212          *
213          *      Sequential writes, or
214          *      Random writes that lay out the file as it goes along
215          *
216          * For both these cases, just reading back data in the order we
217          * wrote it out is the fastest.
218          *
219          * One exception is if we don't have a random map AND we are doing
220          * verifies, in that case we need to check for duplicate blocks and
221          * drop the old one, which we rely on the rb insert/lookup for
222          * handling.
223          */
224         if (((!td->o.verifysort) || !td_random(td) || !td->o.overwrite) &&
225               (file_randommap(td, ipo->file) || td->o.verify == VERIFY_NONE)) {
226                 INIT_FLIST_HEAD(&ipo->list);
227                 flist_add_tail(&ipo->list, &td->io_hist_list);
228                 ipo->flags |= IP_F_ONLIST;
229                 td->io_hist_len++;
230                 return;
231         }
232
233         RB_CLEAR_NODE(&ipo->rb_node);
234
235         /*
236          * Sort the entry into the verification list
237          */
238 restart:
239         p = &td->io_hist_tree.rb_node;
240         parent = NULL;
241         while (*p) {
242                 parent = *p;
243
244                 __ipo = rb_entry(parent, struct io_piece, rb_node);
245                 if (ipo->file < __ipo->file)
246                         p = &(*p)->rb_left;
247                 else if (ipo->file > __ipo->file)
248                         p = &(*p)->rb_right;
249                 else if (ipo->offset < __ipo->offset)
250                         p = &(*p)->rb_left;
251                 else if (ipo->offset > __ipo->offset)
252                         p = &(*p)->rb_right;
253                 else {
254                         dprint(FD_IO, "iolog: overlap %llu/%lu, %llu/%lu",
255                                 __ipo->offset, __ipo->len,
256                                 ipo->offset, ipo->len);
257                         td->io_hist_len--;
258                         rb_erase(parent, &td->io_hist_tree);
259                         remove_trim_entry(td, __ipo);
260                         free(__ipo);
261                         goto restart;
262                 }
263         }
264
265         rb_link_node(&ipo->rb_node, parent, p);
266         rb_insert_color(&ipo->rb_node, &td->io_hist_tree);
267         ipo->flags |= IP_F_ONRB;
268         td->io_hist_len++;
269 }
270
271 void unlog_io_piece(struct thread_data *td, struct io_u *io_u)
272 {
273         struct io_piece *ipo = io_u->ipo;
274
275         if (!ipo)
276                 return;
277
278         if (ipo->flags & IP_F_ONRB)
279                 rb_erase(&ipo->rb_node, &td->io_hist_tree);
280         else if (ipo->flags & IP_F_ONLIST)
281                 flist_del(&ipo->list);
282
283         free(ipo);
284         io_u->ipo = NULL;
285         td->io_hist_len--;
286 }
287
288 void trim_io_piece(struct thread_data *td, struct io_u *io_u)
289 {
290         struct io_piece *ipo = io_u->ipo;
291
292         if (!ipo)
293                 return;
294
295         ipo->len = io_u->xfer_buflen - io_u->resid;
296 }
297
298 void write_iolog_close(struct thread_data *td)
299 {
300         fflush(td->iolog_f);
301         fclose(td->iolog_f);
302         free(td->iolog_buf);
303         td->iolog_f = NULL;
304         td->iolog_buf = NULL;
305 }
306
307 /*
308  * Read version 2 iolog data. It is enhanced to include per-file logging,
309  * syncs, etc.
310  */
311 static int read_iolog2(struct thread_data *td, FILE *f)
312 {
313         unsigned long long offset;
314         unsigned int bytes;
315         int reads, writes, waits, fileno = 0, file_action = 0; /* stupid gcc */
316         char *fname, *act;
317         char *str, *p;
318         enum fio_ddir rw;
319
320         free_release_files(td);
321
322         /*
323          * Read in the read iolog and store it, reuse the infrastructure
324          * for doing verifications.
325          */
326         str = malloc(4096);
327         fname = malloc(256+16);
328         act = malloc(256+16);
329
330         reads = writes = waits = 0;
331         while ((p = fgets(str, 4096, f)) != NULL) {
332                 struct io_piece *ipo;
333                 int r;
334
335                 r = sscanf(p, "%256s %256s %llu %u", fname, act, &offset,
336                                                                         &bytes);
337                 if (r == 4) {
338                         /*
339                          * Check action first
340                          */
341                         if (!strcmp(act, "wait"))
342                                 rw = DDIR_WAIT;
343                         else if (!strcmp(act, "read"))
344                                 rw = DDIR_READ;
345                         else if (!strcmp(act, "write"))
346                                 rw = DDIR_WRITE;
347                         else if (!strcmp(act, "sync"))
348                                 rw = DDIR_SYNC;
349                         else if (!strcmp(act, "datasync"))
350                                 rw = DDIR_DATASYNC;
351                         else if (!strcmp(act, "trim"))
352                                 rw = DDIR_TRIM;
353                         else {
354                                 log_err("fio: bad iolog file action: %s\n",
355                                                                         act);
356                                 continue;
357                         }
358                         fileno = get_fileno(td, fname);
359                 } else if (r == 2) {
360                         rw = DDIR_INVAL;
361                         if (!strcmp(act, "add")) {
362                                 fileno = add_file(td, fname, 0, 1);
363                                 file_action = FIO_LOG_ADD_FILE;
364                                 continue;
365                         } else if (!strcmp(act, "open")) {
366                                 fileno = get_fileno(td, fname);
367                                 file_action = FIO_LOG_OPEN_FILE;
368                         } else if (!strcmp(act, "close")) {
369                                 fileno = get_fileno(td, fname);
370                                 file_action = FIO_LOG_CLOSE_FILE;
371                         } else {
372                                 log_err("fio: bad iolog file action: %s\n",
373                                                                         act);
374                                 continue;
375                         }
376                 } else {
377                         log_err("bad iolog2: %s", p);
378                         continue;
379                 }
380
381                 if (rw == DDIR_READ)
382                         reads++;
383                 else if (rw == DDIR_WRITE) {
384                         /*
385                          * Don't add a write for ro mode
386                          */
387                         if (read_only)
388                                 continue;
389                         writes++;
390                 } else if (rw == DDIR_WAIT) {
391                         waits++;
392                 } else if (rw == DDIR_INVAL) {
393                 } else if (!ddir_sync(rw)) {
394                         log_err("bad ddir: %d\n", rw);
395                         continue;
396                 }
397
398                 /*
399                  * Make note of file
400                  */
401                 ipo = malloc(sizeof(*ipo));
402                 init_ipo(ipo);
403                 ipo->ddir = rw;
404                 if (rw == DDIR_WAIT) {
405                         ipo->delay = offset;
406                 } else {
407                         ipo->offset = offset;
408                         ipo->len = bytes;
409                         if (rw != DDIR_INVAL && bytes > td->o.max_bs[rw])
410                                 td->o.max_bs[rw] = bytes;
411                         ipo->fileno = fileno;
412                         ipo->file_action = file_action;
413                         td->o.size += bytes;
414                 }
415
416                 queue_io_piece(td, ipo);
417         }
418
419         free(str);
420         free(act);
421         free(fname);
422
423         if (writes && read_only) {
424                 log_err("fio: <%s> skips replay of %d writes due to"
425                         " read-only\n", td->o.name, writes);
426                 writes = 0;
427         }
428
429         if (!reads && !writes && !waits)
430                 return 1;
431         else if (reads && !writes)
432                 td->o.td_ddir = TD_DDIR_READ;
433         else if (!reads && writes)
434                 td->o.td_ddir = TD_DDIR_WRITE;
435         else
436                 td->o.td_ddir = TD_DDIR_RW;
437
438         return 0;
439 }
440
441 /*
442  * open iolog, check version, and call appropriate parser
443  */
444 static int init_iolog_read(struct thread_data *td)
445 {
446         char buffer[256], *p;
447         FILE *f;
448         int ret;
449
450         f = fopen(td->o.read_iolog_file, "r");
451         if (!f) {
452                 perror("fopen read iolog");
453                 return 1;
454         }
455
456         p = fgets(buffer, sizeof(buffer), f);
457         if (!p) {
458                 td_verror(td, errno, "iolog read");
459                 log_err("fio: unable to read iolog\n");
460                 fclose(f);
461                 return 1;
462         }
463
464         /*
465          * version 2 of the iolog stores a specific string as the
466          * first line, check for that
467          */
468         if (!strncmp(iolog_ver2, buffer, strlen(iolog_ver2)))
469                 ret = read_iolog2(td, f);
470         else {
471                 log_err("fio: iolog version 1 is no longer supported\n");
472                 ret = 1;
473         }
474
475         fclose(f);
476         return ret;
477 }
478
479 /*
480  * Set up a log for storing io patterns.
481  */
482 static int init_iolog_write(struct thread_data *td)
483 {
484         struct fio_file *ff;
485         FILE *f;
486         unsigned int i;
487
488         f = fopen(td->o.write_iolog_file, "a");
489         if (!f) {
490                 perror("fopen write iolog");
491                 return 1;
492         }
493
494         /*
495          * That's it for writing, setup a log buffer and we're done.
496           */
497         td->iolog_f = f;
498         td->iolog_buf = malloc(8192);
499         setvbuf(f, td->iolog_buf, _IOFBF, 8192);
500
501         /*
502          * write our version line
503          */
504         if (fprintf(f, "%s\n", iolog_ver2) < 0) {
505                 perror("iolog init\n");
506                 return 1;
507         }
508
509         /*
510          * add all known files
511          */
512         for_each_file(td, ff, i)
513                 log_file(td, ff, FIO_LOG_ADD_FILE);
514
515         return 0;
516 }
517
518 int init_iolog(struct thread_data *td)
519 {
520         int ret = 0;
521
522         if (td->o.read_iolog_file) {
523                 int need_swap;
524
525                 /*
526                  * Check if it's a blktrace file and load that if possible.
527                  * Otherwise assume it's a normal log file and load that.
528                  */
529                 if (is_blktrace(td->o.read_iolog_file, &need_swap))
530                         ret = load_blktrace(td, td->o.read_iolog_file, need_swap);
531                 else
532                         ret = init_iolog_read(td);
533         } else if (td->o.write_iolog_file)
534                 ret = init_iolog_write(td);
535
536         if (ret)
537                 td_verror(td, EINVAL, "failed initializing iolog");
538
539         return ret;
540 }
541
542 void setup_log(struct io_log **log, unsigned long avg_msec, int log_type,
543                int log_offset, const char *filename)
544 {
545         struct io_log *l = malloc(sizeof(*l));
546
547         memset(l, 0, sizeof(*l));
548         l->nr_samples = 0;
549         l->max_samples = 1024;
550         l->log_type = log_type;
551         l->log_offset = log_offset;
552         l->log = malloc(l->max_samples * log_entry_sz(l));
553         l->avg_msec = avg_msec;
554         l->filename = strdup(filename);
555         *log = l;
556 }
557
558 #ifdef CONFIG_SETVBUF
559 static void *set_file_buffer(FILE *f)
560 {
561         size_t size = 1048576;
562         void *buf;
563
564         buf = malloc(size);
565         setvbuf(f, buf, _IOFBF, size);
566         return buf;
567 }
568
569 static void clear_file_buffer(void *buf)
570 {
571         free(buf);
572 }
573 #else
574 static void *set_file_buffer(FILE *f)
575 {
576         return NULL;
577 }
578
579 static void clear_file_buffer(void *buf)
580 {
581 }
582 #endif
583
584 void free_log(struct io_log *log)
585 {
586         free(log->log);
587         free(log->filename);
588         free(log);
589 }
590
591 void __finish_log(struct io_log *log)
592 {
593         uint64_t i;
594         void *buf;
595         FILE *f;
596
597         f = fopen(log->filename, "a");
598         if (!f) {
599                 perror("fopen log");
600                 return;
601         }
602
603         buf = set_file_buffer(f);
604
605         for (i = 0; i < log->nr_samples; i++) {
606                 struct io_sample *s = get_sample(log, i);
607
608                 if (!log->log_offset) {
609                         fprintf(f, "%lu, %lu, %u, %u\n",
610                                         (unsigned long) s->time,
611                                         (unsigned long) s->val,
612                                         s->ddir, s->bs);
613                 } else {
614                         struct io_sample_offset *so = (void *) s;
615
616                         fprintf(f, "%lu, %lu, %u, %u, %llu\n",
617                                         (unsigned long) s->time,
618                                         (unsigned long) s->val,
619                                         s->ddir, s->bs,
620                                         (unsigned long long) so->offset);
621                 }
622         }
623
624         fclose(f);
625         clear_file_buffer(buf);
626 }
627
628 static int finish_log(struct thread_data *td, struct io_log *log, int trylock)
629 {
630         if (trylock) {
631                 if (fio_trylock_file(log->filename))
632                         return 1;
633         } else
634                 fio_lock_file(log->filename);
635
636         if (td->client_type == FIO_CLIENT_TYPE_GUI) {
637                 fio_send_iolog(td, log, log->filename);
638         } else
639                 __finish_log(log);
640
641         fio_unlock_file(log->filename);
642         free_log(log);
643         return 0;
644 }
645
646 static int write_iops_log(struct thread_data *td, int try)
647 {
648         struct io_log *log = td->iops_log;
649
650         if (!log)
651                 return 0;
652
653         return finish_log(td, log, try);
654 }
655
656 static int write_slat_log(struct thread_data *td, int try)
657 {
658         struct io_log *log = td->slat_log;
659
660         if (!log)
661                 return 0;
662
663         return finish_log(td, log, try);
664 }
665
666 static int write_clat_log(struct thread_data *td, int try)
667 {
668         struct io_log *log = td->clat_log;
669
670         if (!log)
671                 return 0;
672
673         return finish_log(td, log, try);
674 }
675
676 static int write_lat_log(struct thread_data *td, int try)
677 {
678         struct io_log *log = td->lat_log;
679
680         if (!log)
681                 return 0;
682
683         return finish_log(td, log, try);
684 }
685
686 static int write_bandw_log(struct thread_data *td, int try)
687 {
688         struct io_log *log = td->bw_log;
689
690         if (!log)
691                 return 0;
692
693         return finish_log(td, log, try);
694 }
695
696 enum {
697         BW_LOG_MASK     = 1,
698         LAT_LOG_MASK    = 2,
699         SLAT_LOG_MASK   = 4,
700         CLAT_LOG_MASK   = 8,
701         IOPS_LOG_MASK   = 16,
702
703         ALL_LOG_NR      = 5,
704 };
705
706 struct log_type {
707         unsigned int mask;
708         int (*fn)(struct thread_data *, int);
709 };
710
711 static struct log_type log_types[] = {
712         {
713                 .mask   = BW_LOG_MASK,
714                 .fn     = write_bandw_log,
715         },
716         {
717                 .mask   = LAT_LOG_MASK,
718                 .fn     = write_lat_log,
719         },
720         {
721                 .mask   = SLAT_LOG_MASK,
722                 .fn     = write_slat_log,
723         },
724         {
725                 .mask   = CLAT_LOG_MASK,
726                 .fn     = write_clat_log,
727         },
728         {
729                 .mask   = IOPS_LOG_MASK,
730                 .fn     = write_iops_log,
731         },
732 };
733
734 void fio_writeout_logs(struct thread_data *td)
735 {
736         unsigned int log_mask = 0;
737         unsigned int log_left = ALL_LOG_NR;
738         int old_state, i;
739
740         old_state = td_bump_runstate(td, TD_FINISHING);
741
742         finalize_logs(td);
743
744         while (log_left) {
745                 int prev_log_left = log_left;
746
747                 for (i = 0; i < ALL_LOG_NR && log_left; i++) {
748                         struct log_type *lt = &log_types[i];
749                         int ret;
750
751                         if (!(log_mask & lt->mask)) {
752                                 ret = lt->fn(td, log_left != 1);
753                                 if (!ret) {
754                                         log_left--;
755                                         log_mask |= lt->mask;
756                                 }
757                         }
758                 }
759
760                 if (prev_log_left == log_left)
761                         usleep(5000);
762         }
763
764         td_restore_runstate(td, old_state);
765 }