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