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