iolog: more compression debugging/fixes
[fio.git] / blktrace.c
1 /*
2  * blktrace support code for fio
3  */
4 #include <stdio.h>
5 #include <stdlib.h>
6 #include <sys/stat.h>
7 #include <sys/ioctl.h>
8 #include <linux/fs.h>
9 #include <dirent.h>
10
11 #include "flist.h"
12 #include "fio.h"
13 #include "blktrace_api.h"
14 #include "oslib/linux-dev-lookup.h"
15
16 #define TRACE_FIFO_SIZE 8192
17
18 /*
19  * fifo refill frontend, to avoid reading data in trace sized bites
20  */
21 static int refill_fifo(struct thread_data *td, struct fifo *fifo, int fd)
22 {
23         char buf[TRACE_FIFO_SIZE];
24         unsigned int total;
25         int ret;
26
27         total = sizeof(buf);
28         if (total > fifo_room(fifo))
29                 total = fifo_room(fifo);
30
31         ret = read(fd, buf, total);
32         if (ret < 0) {
33                 td_verror(td, errno, "read blktrace file");
34                 return -1;
35         }
36
37         if (ret > 0)
38                 ret = fifo_put(fifo, buf, ret);
39
40         dprint(FD_BLKTRACE, "refill: filled %d bytes\n", ret);
41         return ret;
42 }
43
44 /*
45  * Retrieve 'len' bytes from the fifo, refilling if necessary.
46  */
47 static int trace_fifo_get(struct thread_data *td, struct fifo *fifo, int fd,
48                           void *buf, unsigned int len)
49 {
50         if (fifo_len(fifo) < len) {
51                 int ret = refill_fifo(td, fifo, fd);
52
53                 if (ret < 0)
54                         return ret;
55         }
56
57         return fifo_get(fifo, buf, len);
58 }
59
60 /*
61  * Just discard the pdu by seeking past it.
62  */
63 static int discard_pdu(struct thread_data *td, struct fifo *fifo, int fd,
64                        struct blk_io_trace *t)
65 {
66         if (t->pdu_len == 0)
67                 return 0;
68
69         dprint(FD_BLKTRACE, "discard pdu len %u\n", t->pdu_len);
70         return trace_fifo_get(td, fifo, fd, NULL, t->pdu_len);
71 }
72
73 /*
74  * Check if this is a blktrace binary data file. We read a single trace
75  * into memory and check for the magic signature.
76  */
77 int is_blktrace(const char *filename, int *need_swap)
78 {
79         struct blk_io_trace t;
80         int fd, ret;
81
82         fd = open(filename, O_RDONLY);
83         if (fd < 0)
84                 return 0;
85
86         ret = read(fd, &t, sizeof(t));
87         close(fd);
88
89         if (ret < 0) {
90                 perror("read blktrace");
91                 return 0;
92         } else if (ret != sizeof(t)) {
93                 log_err("fio: short read on blktrace file\n");
94                 return 0;
95         }
96
97         if ((t.magic & 0xffffff00) == BLK_IO_TRACE_MAGIC) {
98                 *need_swap = 0;
99                 return 1;
100         }
101
102         /*
103          * Maybe it needs to be endian swapped...
104          */
105         t.magic = fio_swap32(t.magic);
106         if ((t.magic & 0xffffff00) == BLK_IO_TRACE_MAGIC) {
107                 *need_swap = 1;
108                 return 1;
109         }
110
111         return 0;
112 }
113
114 #define FMINORBITS      20
115 #define FMINORMASK      ((1U << FMINORBITS) - 1)
116 #define FMAJOR(dev)     ((unsigned int) ((dev) >> FMINORBITS))
117 #define FMINOR(dev)     ((unsigned int) ((dev) & FMINORMASK))
118
119 static void trace_add_open_close_event(struct thread_data *td, int fileno, enum file_log_act action)
120 {
121         struct io_piece *ipo;
122
123         ipo = calloc(1, sizeof(*ipo));
124         init_ipo(ipo);
125
126         ipo->ddir = DDIR_INVAL;
127         ipo->fileno = fileno;
128         ipo->file_action = action;
129         flist_add_tail(&ipo->list, &td->io_log_list);
130 }
131
132 static int get_dev_blocksize(const char *dev, unsigned int *bs)
133 {
134         int fd;
135
136         fd = open(dev, O_RDONLY);
137         if (fd < 0)
138                 return 1;
139
140         if (ioctl(fd, BLKSSZGET, bs) < 0) {
141                 close(fd);
142                 return 1;
143         }
144
145         close(fd);
146         return 0;
147 }
148
149 static int trace_add_file(struct thread_data *td, __u32 device,
150                           unsigned int *bs)
151 {
152         static unsigned int last_maj, last_min, last_fileno, last_bs;
153         unsigned int maj = FMAJOR(device);
154         unsigned int min = FMINOR(device);
155         struct fio_file *f;
156         unsigned int i;
157         char dev[256];
158
159         if (last_maj == maj && last_min == min) {
160                 *bs = last_bs;
161                 return last_fileno;
162         }
163
164         last_maj = maj;
165         last_min = min;
166
167         /*
168          * check for this file in our list
169          */
170         for_each_file(td, f, i) {
171                 if (f->major == maj && f->minor == min) {
172                         last_fileno = f->fileno;
173                         last_bs = f->bs;
174                         goto out;
175                 }
176         }
177
178         strcpy(dev, "/dev");
179         if (blktrace_lookup_device(td->o.replay_redirect, dev, maj, min)) {
180                 unsigned int this_bs;
181                 int fileno;
182
183                 if (td->o.replay_redirect)
184                         dprint(FD_BLKTRACE, "device lookup: %d/%d\n overridden"
185                                         " with: %s\n", maj, min,
186                                         td->o.replay_redirect);
187                 else
188                         dprint(FD_BLKTRACE, "device lookup: %d/%d\n", maj, min);
189
190                 dprint(FD_BLKTRACE, "add devices %s\n", dev);
191                 fileno = add_file_exclusive(td, dev);
192
193                 if (get_dev_blocksize(dev, &this_bs))
194                         this_bs = 512;
195
196                 td->o.open_files++;
197                 td->files[fileno]->major = maj;
198                 td->files[fileno]->minor = min;
199                 td->files[fileno]->bs = this_bs;
200                 trace_add_open_close_event(td, fileno, FIO_LOG_OPEN_FILE);
201
202                 last_fileno = fileno;
203                 last_bs = this_bs;
204         }
205
206 out:
207         *bs = last_bs;
208         return last_fileno;
209 }
210
211 static void t_bytes_align(struct thread_options *o, struct blk_io_trace *t)
212 {
213         if (!o->replay_align)
214                 return;
215
216         t->bytes = (t->bytes + o->replay_align - 1) & ~(o->replay_align - 1);
217 }
218
219 static void ipo_bytes_align(struct thread_options *o, struct io_piece *ipo)
220 {
221         if (!o->replay_align)
222                 return;
223
224         ipo->offset &= ~(o->replay_align - 1);
225 }
226
227
228 /*
229  * Store blk_io_trace data in an ipo for later retrieval.
230  */
231 static void store_ipo(struct thread_data *td, unsigned long long offset,
232                       unsigned int bytes, int rw, unsigned long long ttime,
233                       int fileno, unsigned int bs)
234 {
235         struct io_piece *ipo = malloc(sizeof(*ipo));
236
237         init_ipo(ipo);
238
239         ipo->offset = offset * bs;
240         if (td->o.replay_scale)
241                 ipo->offset = ipo->offset / td->o.replay_scale;
242         ipo_bytes_align(&td->o, ipo);
243         ipo->len = bytes;
244         ipo->delay = ttime / 1000;
245         if (rw)
246                 ipo->ddir = DDIR_WRITE;
247         else
248                 ipo->ddir = DDIR_READ;
249         ipo->fileno = fileno;
250
251         dprint(FD_BLKTRACE, "store ddir=%d, off=%llu, len=%lu, delay=%lu\n",
252                                                         ipo->ddir, ipo->offset,
253                                                         ipo->len, ipo->delay);
254         queue_io_piece(td, ipo);
255 }
256
257 static void handle_trace_notify(struct blk_io_trace *t)
258 {
259         switch (t->action) {
260         case BLK_TN_PROCESS:
261                 dprint(FD_BLKTRACE, "got process notify: %x, %d\n",
262                                 t->action, t->pid);
263                 break;
264         case BLK_TN_TIMESTAMP:
265                 dprint(FD_BLKTRACE, "got timestamp notify: %x, %d\n",
266                                 t->action, t->pid);
267                 break;
268         case BLK_TN_MESSAGE:
269                 break;
270         default:
271                 dprint(FD_BLKTRACE, "unknown trace act %x\n", t->action);
272                 break;
273         }
274 }
275
276 static void handle_trace_discard(struct thread_data *td,
277                                  struct blk_io_trace *t,
278                                  unsigned long long ttime,
279                                  unsigned long *ios, unsigned int *rw_bs)
280 {
281         struct io_piece *ipo = malloc(sizeof(*ipo));
282         unsigned int bs;
283         int fileno;
284
285         init_ipo(ipo);
286         fileno = trace_add_file(td, t->device, &bs);
287
288         ios[DDIR_TRIM]++;
289         if (t->bytes > rw_bs[DDIR_TRIM])
290                 rw_bs[DDIR_TRIM] = t->bytes;
291
292         td->o.size += t->bytes;
293
294         memset(ipo, 0, sizeof(*ipo));
295         INIT_FLIST_HEAD(&ipo->list);
296
297         ipo->offset = t->sector * bs;
298         if (td->o.replay_scale)
299                 ipo->offset = ipo->offset / td->o.replay_scale;
300         ipo_bytes_align(&td->o, ipo);
301         ipo->len = t->bytes;
302         ipo->delay = ttime / 1000;
303         ipo->ddir = DDIR_TRIM;
304         ipo->fileno = fileno;
305
306         dprint(FD_BLKTRACE, "store discard, off=%llu, len=%lu, delay=%lu\n",
307                                                         ipo->offset, ipo->len,
308                                                         ipo->delay);
309         queue_io_piece(td, ipo);
310 }
311
312 static void handle_trace_fs(struct thread_data *td, struct blk_io_trace *t,
313                             unsigned long long ttime, unsigned long *ios,
314                             unsigned int *rw_bs)
315 {
316         unsigned int bs;
317         int rw;
318         int fileno;
319
320         fileno = trace_add_file(td, t->device, &bs);
321
322         rw = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
323
324         if (t->bytes > rw_bs[rw])
325                 rw_bs[rw] = t->bytes;
326
327         ios[rw]++;
328         td->o.size += t->bytes;
329         store_ipo(td, t->sector, t->bytes, rw, ttime, fileno, bs);
330 }
331
332 /*
333  * We only care for queue traces, most of the others are side effects
334  * due to internal workings of the block layer.
335  */
336 static void handle_trace(struct thread_data *td, struct blk_io_trace *t,
337                          unsigned long *ios, unsigned int *bs)
338 {
339         static unsigned long long last_ttime;
340         unsigned long long delay = 0;
341
342         if ((t->action & 0xffff) != __BLK_TA_QUEUE)
343                 return;
344
345         if (!(t->action & BLK_TC_ACT(BLK_TC_NOTIFY))) {
346                 if (!last_ttime || td->o.no_stall) {
347                         last_ttime = t->time;
348                         delay = 0;
349                 } else {
350                         delay = t->time - last_ttime;
351                         last_ttime = t->time;
352                 }
353         }
354
355         t_bytes_align(&td->o, t);
356
357         if (t->action & BLK_TC_ACT(BLK_TC_NOTIFY))
358                 handle_trace_notify(t);
359         else if (t->action & BLK_TC_ACT(BLK_TC_DISCARD))
360                 handle_trace_discard(td, t, delay, ios, bs);
361         else
362                 handle_trace_fs(td, t, delay, ios, bs);
363 }
364
365 static void byteswap_trace(struct blk_io_trace *t)
366 {
367         t->magic = fio_swap32(t->magic);
368         t->sequence = fio_swap32(t->sequence);
369         t->time = fio_swap64(t->time);
370         t->sector = fio_swap64(t->sector);
371         t->bytes = fio_swap32(t->bytes);
372         t->action = fio_swap32(t->action);
373         t->pid = fio_swap32(t->pid);
374         t->device = fio_swap32(t->device);
375         t->cpu = fio_swap32(t->cpu);
376         t->error = fio_swap16(t->error);
377         t->pdu_len = fio_swap16(t->pdu_len);
378 }
379
380 static int t_is_write(struct blk_io_trace *t)
381 {
382         return (t->action & BLK_TC_ACT(BLK_TC_WRITE | BLK_TC_DISCARD)) != 0;
383 }
384
385 static enum fio_ddir t_get_ddir(struct blk_io_trace *t)
386 {
387         if (t->action & BLK_TC_ACT(BLK_TC_READ))
388                 return DDIR_READ;
389         else if (t->action & BLK_TC_ACT(BLK_TC_WRITE))
390                 return DDIR_WRITE;
391         else if (t->action & BLK_TC_ACT(BLK_TC_DISCARD))
392                 return DDIR_TRIM;
393
394         return DDIR_INVAL;
395 }
396
397 static void depth_inc(struct blk_io_trace *t, int *depth)
398 {
399         enum fio_ddir ddir;
400
401         ddir = t_get_ddir(t);
402         if (ddir != DDIR_INVAL)
403                 depth[ddir]++;
404 }
405
406 static void depth_dec(struct blk_io_trace *t, int *depth)
407 {
408         enum fio_ddir ddir;
409
410         ddir = t_get_ddir(t);
411         if (ddir != DDIR_INVAL)
412                 depth[ddir]--;
413 }
414
415 static void depth_end(struct blk_io_trace *t, int *this_depth, int *depth)
416 {
417         enum fio_ddir ddir = DDIR_INVAL;
418
419         ddir = t_get_ddir(t);
420         if (ddir != DDIR_INVAL) {
421                 depth[ddir] = max(depth[ddir], this_depth[ddir]);
422                 this_depth[ddir] = 0;
423         }
424 }
425
426 /*
427  * Load a blktrace file by reading all the blk_io_trace entries, and storing
428  * them as io_pieces like the fio text version would do.
429  */
430 int load_blktrace(struct thread_data *td, const char *filename, int need_swap)
431 {
432         struct blk_io_trace t;
433         unsigned long ios[DDIR_RWDIR_CNT], skipped_writes;
434         unsigned int rw_bs[DDIR_RWDIR_CNT];
435         struct fifo *fifo;
436         int fd, i, old_state;
437         struct fio_file *f;
438         int this_depth[DDIR_RWDIR_CNT], depth[DDIR_RWDIR_CNT], max_depth;
439
440         fd = open(filename, O_RDONLY);
441         if (fd < 0) {
442                 td_verror(td, errno, "open blktrace file");
443                 return 1;
444         }
445
446         fifo = fifo_alloc(TRACE_FIFO_SIZE);
447
448         old_state = td_bump_runstate(td, TD_SETTING_UP);
449
450         td->o.size = 0;
451
452         for (i = 0; i < DDIR_RWDIR_CNT; i++) {
453                 ios[i] = 0;
454                 rw_bs[i] = 0;
455                 this_depth[i] = 0;
456                 depth[i] = 0;
457         }
458
459         skipped_writes = 0;
460         do {
461                 int ret = trace_fifo_get(td, fifo, fd, &t, sizeof(t));
462
463                 if (ret < 0)
464                         goto err;
465                 else if (!ret)
466                         break;
467                 else if (ret < (int) sizeof(t)) {
468                         log_err("fio: short fifo get\n");
469                         break;
470                 }
471
472                 if (need_swap)
473                         byteswap_trace(&t);
474
475                 if ((t.magic & 0xffffff00) != BLK_IO_TRACE_MAGIC) {
476                         log_err("fio: bad magic in blktrace data: %x\n",
477                                                                 t.magic);
478                         goto err;
479                 }
480                 if ((t.magic & 0xff) != BLK_IO_TRACE_VERSION) {
481                         log_err("fio: bad blktrace version %d\n",
482                                                                 t.magic & 0xff);
483                         goto err;
484                 }
485                 ret = discard_pdu(td, fifo, fd, &t);
486                 if (ret < 0) {
487                         td_verror(td, ret, "blktrace lseek");
488                         goto err;
489                 } else if (t.pdu_len != ret) {
490                         log_err("fio: discarded %d of %d\n", ret, t.pdu_len);
491                         goto err;
492                 }
493                 if ((t.action & BLK_TC_ACT(BLK_TC_NOTIFY)) == 0) {
494                         if ((t.action & 0xffff) == __BLK_TA_QUEUE)
495                                 depth_inc(&t, this_depth);
496                         else if (((t.action & 0xffff) == __BLK_TA_BACKMERGE) ||
497                                 ((t.action & 0xffff) == __BLK_TA_FRONTMERGE))
498                                 depth_dec(&t, this_depth);
499                         else if ((t.action & 0xffff) == __BLK_TA_COMPLETE)
500                                 depth_end(&t, this_depth, depth);
501
502                         if (t_is_write(&t) && read_only) {
503                                 skipped_writes++;
504                                 continue;
505                         }
506                 }
507
508                 handle_trace(td, &t, ios, rw_bs);
509         } while (1);
510
511         for (i = 0; i < td->files_index; i++) {
512                 f = td->files[i];
513                 trace_add_open_close_event(td, f->fileno, FIO_LOG_CLOSE_FILE);
514         }
515
516         fifo_free(fifo);
517         close(fd);
518
519         td_restore_runstate(td, old_state);
520
521         if (!td->files_index) {
522                 log_err("fio: did not find replay device(s)\n");
523                 return 1;
524         }
525
526         /*
527          * For stacked devices, we don't always get a COMPLETE event so
528          * the depth grows to insane values. Limit it to something sane(r).
529          */
530         max_depth = 0;
531         for (i = 0; i < DDIR_RWDIR_CNT; i++) {
532                 if (depth[i] > 1024)
533                         depth[i] = 1024;
534                 else if (!depth[i] && ios[i])
535                         depth[i] = 1;
536                 max_depth = max(depth[i], max_depth);
537         }
538
539         if (skipped_writes)
540                 log_err("fio: %s skips replay of %lu writes due to read-only\n",
541                                                 td->o.name, skipped_writes);
542
543         if (!ios[DDIR_READ] && !ios[DDIR_WRITE]) {
544                 log_err("fio: found no ios in blktrace data\n");
545                 return 1;
546         } else if (ios[DDIR_READ] && !ios[DDIR_WRITE]) {
547                 td->o.td_ddir = TD_DDIR_READ;
548                 td->o.max_bs[DDIR_READ] = rw_bs[DDIR_READ];
549         } else if (!ios[DDIR_READ] && ios[DDIR_WRITE]) {
550                 td->o.td_ddir = TD_DDIR_WRITE;
551                 td->o.max_bs[DDIR_WRITE] = rw_bs[DDIR_WRITE];
552         } else {
553                 td->o.td_ddir = TD_DDIR_RW;
554                 td->o.max_bs[DDIR_READ] = rw_bs[DDIR_READ];
555                 td->o.max_bs[DDIR_WRITE] = rw_bs[DDIR_WRITE];
556                 td->o.max_bs[DDIR_TRIM] = rw_bs[DDIR_TRIM];
557         }
558
559         /*
560          * We need to do direct/raw ios to the device, to avoid getting
561          * read-ahead in our way. But only do so if the minimum block size
562          * is a multiple of 4k, otherwise we don't know if it's safe to do so.
563          */
564         if (!fio_option_is_set(&td->o, odirect) && !(td_min_bs(td) & 4095))
565                 td->o.odirect = 1;
566
567         /*
568          * If depth wasn't manually set, use probed depth
569          */
570         if (!fio_option_is_set(&td->o, iodepth))
571                 td->o.iodepth = td->o.iodepth_low = max_depth;
572
573         return 0;
574 err:
575         close(fd);
576         fifo_free(fifo);
577         return 1;
578 }