log.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 <assert.h>
   8 #include "list.h"
   9 #include "fio.h"
  10
  11 static const char iolog_ver2[] = "fio version 2 iolog";
  12
  13 void queue_io_piece(struct thread_data *td, struct io_piece *ipo)
  14 {
  15         list_add_tail(&ipo->list, &td->io_log_list);
  16         td->total_io_size += ipo->len;
  17 }
  18
  19 void log_io_u(struct thread_data *td, struct io_u *io_u)
  20 {
  21         const char *act[] = { "read", "write", "sync" };
  22
  23         assert(io_u->ddir < 3);
  24
  25         if (!td->o.write_iolog_file)
  26                 return;
  27
  28         fprintf(td->iolog_f, "%s %s %llu %lu\n", io_u->file->file_name,
  29                                                 act[io_u->ddir], io_u->offset,
  30                                                 io_u->buflen);
  31 }
  32
  33 void log_file(struct thread_data *td, struct fio_file *f,
  34               enum file_log_act what)
  35 {
  36         const char *act[] = { "add", "open", "close" };
  37
  38         assert(what < 3);
  39
  40         if (!td->o.write_iolog_file)
  41                 return;
  42
  43         fprintf(td->iolog_f, "%s %s\n", f->file_name, act[what]);
  44 }
  45
  46 static void iolog_delay(struct thread_data *td, unsigned long delay)
  47 {
  48         unsigned long usec = utime_since_now(&td->last_issue);
  49
  50         if (delay < usec)
  51                 return;
  52
  53         delay -= usec;
  54
  55         /*
  56          * less than 100 usec delay, just regard it as noise
  57          */
  58         if (delay < 100)
  59                 return;
  60
  61         usec_sleep(td, delay);
  62 }
  63
  64 int read_iolog_get(struct thread_data *td, struct io_u *io_u)
  65 {
  66         struct io_piece *ipo;
  67
  68         while (!list_empty(&td->io_log_list)) {
  69                 ipo = list_entry(td->io_log_list.next, struct io_piece, list);
  70                 list_del(&ipo->list);
  71
  72                 /*
  73                  * invalid ddir, this is a file action
  74                  */
  75                 if (ipo->ddir == DDIR_INVAL) {
  76                         struct fio_file *f = td->files[ipo->fileno];
  77
  78                         if (ipo->file_action == FIO_LOG_OPEN_FILE) {
  79                                 int ret;
  80
  81                                 ret = td_io_open_file(td, f);
  82                                 if (!ret) {
  83                                         free(ipo);
  84                                         continue;
  85                                 }
  86                                 td_verror(td, ret, "iolog open file");
  87                                 return 1;
  88                         } else if (ipo->file_action == FIO_LOG_CLOSE_FILE) {
  89                                 td_io_close_file(td, f);
  90                                 free(ipo);
  91                                 continue;
  92                         }
  93                 }
  94
  95                 io_u->offset = ipo->offset;
  96                 io_u->buflen = ipo->len;
  97                 io_u->ddir = ipo->ddir;
  98                 io_u->file = td->files[ipo->fileno];
  99                 get_file(io_u->file);
 100
 101                 dprint(FD_IO, "iolog: get %llu/%lu/%s\n", io_u->offset,
 102                                         io_u->buflen, io_u->file->file_name);
 103
 104                 if (ipo->delay)
 105                         iolog_delay(td, ipo->delay);
 106
 107                 free(ipo);
 108                 return 0;
 109         }
 110
 111         td->done = 1;
 112         return 1;
 113 }
 114
 115 void prune_io_piece_log(struct thread_data *td)
 116 {
 117         struct io_piece *ipo;
 118         struct rb_node *n;
 119
 120         while ((n = rb_first(&td->io_hist_tree)) != NULL) {
 121                 ipo = rb_entry(n, struct io_piece, rb_node);
 122                 rb_erase(n, &td->io_hist_tree);
 123                 free(ipo);
 124         }
 125
 126         while (!list_empty(&td->io_hist_list)) {
 127                 ipo = list_entry(td->io_hist_list.next, struct io_piece, list);
 128                 list_del(&ipo->list);
 129                 free(ipo);
 130         }
 131 }
 132
 133 /*
 134  * log a successful write, so we can unwind the log for verify
 135  */
 136 void log_io_piece(struct thread_data *td, struct io_u *io_u)
 137 {
 138         struct rb_node **p, *parent;
 139         struct io_piece *ipo, *__ipo;
 140
 141         ipo = malloc(sizeof(struct io_piece));
 142         ipo->file = io_u->file;
 143         ipo->offset = io_u->offset;
 144         ipo->len = io_u->buflen;
 145
 146         /*
 147          * We don't need to sort the entries, if:
 148          *
 149          *      Sequential writes, or
 150          *      Random writes that lay out the file as it goes along
 151          *
 152          * For both these cases, just reading back data in the order we
 153          * wrote it out is the fastest.
 154          */
 155         if (!td_random(td) || !td->o.overwrite) {
 156                 INIT_LIST_HEAD(&ipo->list);
 157                 list_add_tail(&ipo->list, &td->io_hist_list);
 158                 return;
 159         }
 160
 161         RB_CLEAR_NODE(&ipo->rb_node);
 162         p = &td->io_hist_tree.rb_node;
 163         parent = NULL;
 164
 165         /*
 166          * Sort the entry into the verification list
 167          */
 168         while (*p) {
 169                 parent = *p;
 170
 171                 __ipo = rb_entry(parent, struct io_piece, rb_node);
 172                 if (ipo->offset <= __ipo->offset)
 173                         p = &(*p)->rb_left;
 174                 else
 175                         p = &(*p)->rb_right;
 176         }
 177
 178         rb_link_node(&ipo->rb_node, parent, p);
 179         rb_insert_color(&ipo->rb_node, &td->io_hist_tree);
 180 }
 181
 182 void write_iolog_close(struct thread_data *td)
 183 {
 184         fflush(td->iolog_f);
 185         fclose(td->iolog_f);
 186         free(td->iolog_buf);
 187         td->iolog_f = NULL;
 188         td->iolog_buf = NULL;
 189 }
 190
 191 /*
 192  * Read version 2 iolog data. It is enhanced to include per-file logging,
 193  * syncs, etc.
 194  */
 195 static int read_iolog2(struct thread_data *td, FILE *f)
 196 {
 197         unsigned long long offset;
 198         unsigned int bytes;
 199         int reads, writes, fileno = 0, file_action = 0; /* stupid gcc */
 200         char *fname, *act;
 201         char *str, *p;
 202         enum fio_ddir rw;
 203
 204         free_release_files(td);
 205
 206         /*
 207          * Read in the read iolog and store it, reuse the infrastructure
 208          * for doing verifications.
 209          */
 210         str = malloc(4096);
 211         fname = malloc(256+16);
 212         act = malloc(256+16);
 213
 214         reads = writes = 0;
 215         while ((p = fgets(str, 4096, f)) != NULL) {
 216                 struct io_piece *ipo;
 217                 int r;
 218
 219                 r = sscanf(p, "%256s %256s %llu %u", fname, act, &offset,
 220                                                                         &bytes);
 221                 if (r == 4) {
 222                         /*
 223                          * Check action first
 224                          */
 225                         if (!strcmp(act, "read"))
 226                                 rw = DDIR_READ;
 227                         else if (!strcmp(act, "write"))
 228                                 rw = DDIR_WRITE;
 229                         else if (!strcmp(act, "sync"))
 230                                 rw = DDIR_SYNC;
 231                         else {
 232                                 log_err("fio: bad iolog file action: %s\n",
 233                                                                         act);
 234                                 continue;
 235                         }
 236                 } else if (r == 2) {
 237                         rw = DDIR_INVAL;
 238                         if (!strcmp(act, "add")) {
 239                                 td->o.nr_files++;
 240                                 fileno = add_file(td, fname);
 241                                 file_action = FIO_LOG_ADD_FILE;
 242                                 continue;
 243                         } else if (!strcmp(act, "open")) {
 244                                 fileno = get_fileno(td, fname);
 245                                 file_action = FIO_LOG_OPEN_FILE;
 246                         } else if (!strcmp(act, "close")) {
 247                                 fileno = get_fileno(td, fname);
 248                                 file_action = FIO_LOG_CLOSE_FILE;
 249                         } else {
 250                                 log_err("fio: bad iolog file action: %s\n",
 251                                                                         act);
 252                                 continue;
 253                         }
 254                 } else {
 255                         log_err("bad iolog2: %s", p);
 256                         continue;
 257                 }
 258
 259                 if (rw == DDIR_READ)
 260                         reads++;
 261                 else if (rw == DDIR_WRITE) {
 262                         /*
 263                          * Don't add a write for ro mode
 264                          */
 265                         if (read_only)
 266                                 continue;
 267                         writes++;
 268                 } else if (rw != DDIR_SYNC && rw != DDIR_INVAL) {
 269                         log_err("bad ddir: %d\n", rw);
 270                         continue;
 271                 }
 272
 273                 /*
 274                  * Make note of file
 275                  */
 276                 ipo = malloc(sizeof(*ipo));
 277                 memset(ipo, 0, sizeof(*ipo));
 278                 INIT_LIST_HEAD(&ipo->list);
 279                 ipo->offset = offset;
 280                 ipo->len = bytes;
 281                 ipo->ddir = rw;
 282                 if (bytes > td->o.max_bs[rw])
 283                         td->o.max_bs[rw] = bytes;
 284                 if (rw == DDIR_INVAL) {
 285                         ipo->fileno = fileno;
 286                         ipo->file_action = file_action;
 287                 }
 288                 queue_io_piece(td, ipo);
 289         }
 290
 291         free(str);
 292         free(act);
 293         free(fname);
 294
 295         if (writes && read_only) {
 296                 log_err("fio: <%s> skips replay of %d writes due to"
 297                         " read-only\n", td->o.name, writes);
 298                 writes = 0;
 299         }
 300
 301         if (!reads && !writes)
 302                 return 1;
 303         else if (reads && !writes)
 304                 td->o.td_ddir = TD_DDIR_READ;
 305         else if (!reads && writes)
 306                 td->o.td_ddir = TD_DDIR_WRITE;
 307         else
 308                 td->o.td_ddir = TD_DDIR_RW;
 309
 310         return 0;
 311 }
 312
 313 /*
 314  * Read version 1 iolog data.
 315  */
 316 static int read_iolog(struct thread_data *td, FILE *f)
 317 {
 318         log_err("fio: iolog version 1 is no longer supported\n");
 319         return 1;
 320 }
 321
 322 /*
 323  * open iolog, check version, and call appropriate parser
 324  */
 325 static int init_iolog_read(struct thread_data *td)
 326 {
 327         char buffer[256], *p;
 328         FILE *f;
 329         int ret;
 330
 331         f = fopen(td->o.read_iolog_file, "r");
 332         if (!f) {
 333                 perror("fopen read iolog");
 334                 return 1;
 335         }
 336
 337         p = fgets(buffer, sizeof(buffer), f);
 338         if (!p) {
 339                 td_verror(td, errno, "iolog read");
 340                 log_err("fio: unable to read iolog\n");
 341                 return 1;
 342         }
 343
 344         /*
 345          * version 2 of the iolog stores a specific string as the
 346          * first line, check for that
 347          */
 348         if (!strncmp(iolog_ver2, buffer, strlen(iolog_ver2)))
 349                 ret = read_iolog2(td, f);
 350         else {
 351                 /*
 352                  * seek back to the beginning
 353                  */
 354                 if (fseek(f, 0, SEEK_SET) < 0) {
 355                         td_verror(td, errno, "iolog read");
 356                         log_err("fio: unable to read iolog\n");
 357                         return 1;
 358                 }
 359
 360                 ret = read_iolog(td, f);
 361         }
 362
 363         fclose(f);
 364         return ret;
 365 }
 366
 367 /*
 368  * Setup a log for storing io patterns.
 369  */
 370 static int init_iolog_write(struct thread_data *td)
 371 {
 372         struct fio_file *ff;
 373         FILE *f;
 374         unsigned int i;
 375
 376         f = fopen(td->o.write_iolog_file, "w+");
 377         if (!f) {
 378                 perror("fopen write iolog");
 379                 return 1;
 380         }
 381
 382         /*
 383          * That's it for writing, setup a log buffer and we're done.
 384           */
 385         td->iolog_f = f;
 386         td->iolog_buf = malloc(8192);
 387         setvbuf(f, td->iolog_buf, _IOFBF, 8192);
 388
 389         /*
 390          * write our version line
 391          */
 392         if (fprintf(f, "%s\n", iolog_ver2) < 0) {
 393                 perror("iolog init\n");
 394                 return 1;
 395         }
 396
 397         /*
 398          * add all known files
 399          */
 400         for_each_file(td, ff, i)
 401                 log_file(td, ff, FIO_LOG_ADD_FILE);
 402
 403         return 0;
 404 }
 405
 406 int init_iolog(struct thread_data *td)
 407 {
 408         int ret = 0;
 409
 410         if (td->io_ops->flags & FIO_DISKLESSIO)
 411                 return 0;
 412
 413         if (td->o.read_iolog_file) {
 414                 /*
 415                  * Check if it's a blktrace file and load that if possible.
 416                  * Otherwise assume it's a normal log file and load that.
 417                  */
 418                 if (is_blktrace(td->o.read_iolog_file))
 419                         ret = load_blktrace(td, td->o.read_iolog_file);
 420                 else
 421                         ret = init_iolog_read(td);
 422         } else if (td->o.write_iolog_file)
 423                 ret = init_iolog_write(td);
 424
 425         return ret;
 426 }
 427
 428 void setup_log(struct io_log **log)
 429 {
 430         struct io_log *l = malloc(sizeof(*l));
 431
 432         l->nr_samples = 0;
 433         l->max_samples = 1024;
 434         l->log = malloc(l->max_samples * sizeof(struct io_sample));
 435         *log = l;
 436 }
 437
 438 void __finish_log(struct io_log *log, const char *name)
 439 {
 440         unsigned int i;
 441         FILE *f;
 442
 443         f = fopen(name, "w");
 444         if (!f) {
 445                 perror("fopen log");
 446                 return;
 447         }
 448
 449         for (i = 0; i < log->nr_samples; i++) {
 450                 fprintf(f, "%lu, %lu, %u\n", log->log[i].time, log->log[i].val,
 451                                                 log->log[i].ddir);
 452         }
 453
 454         fclose(f);
 455         free(log->log);
 456         free(log);
 457 }
 458
 459 void finish_log(struct thread_data *td, struct io_log *log, const char *name)
 460 {
 461         char file_name[256];
 462
 463         snprintf(file_name, 200, "client%d_%s.log", td->thread_number, name);
 464         __finish_log(log, file_name);
 465 }