| 1 | /* |
| 2 | * This file contains format parsing code for blkparse, allowing you to |
| 3 | * customize the individual action format and generel output format. |
| 4 | */ |
| 5 | #include <stdio.h> |
| 6 | #include <string.h> |
| 7 | #include <stdlib.h> |
| 8 | #include <unistd.h> |
| 9 | #include <ctype.h> |
| 10 | #include <time.h> |
| 11 | |
| 12 | #include "blktrace.h" |
| 13 | |
| 14 | #define VALID_SPECS "ABCDFGIMPQRSTUWX" |
| 15 | |
| 16 | #define HEADER "%D %2c %8s %5T.%9t %5p %2a %3d " |
| 17 | |
| 18 | static char *override_format[256]; |
| 19 | |
| 20 | static inline int valid_spec(int spec) |
| 21 | { |
| 22 | return strchr(VALID_SPECS, spec) != NULL; |
| 23 | } |
| 24 | |
| 25 | void set_all_format_specs(char *option) |
| 26 | { |
| 27 | char *p; |
| 28 | |
| 29 | for (p = VALID_SPECS; *p; p++) |
| 30 | if (override_format[(int)(*p)] == NULL) |
| 31 | override_format[(int)(*p)] = strdup(option); |
| 32 | } |
| 33 | |
| 34 | int add_format_spec(char *option) |
| 35 | { |
| 36 | int spec = optarg[0]; |
| 37 | |
| 38 | if (!valid_spec(spec)) { |
| 39 | fprintf(stderr,"Bad format specifier %c\n", spec); |
| 40 | return 1; |
| 41 | } |
| 42 | if (optarg[1] != ',') { |
| 43 | fprintf(stderr,"Bad format specifier - need ',' %s\n", option); |
| 44 | return 1; |
| 45 | } |
| 46 | option += 2; |
| 47 | |
| 48 | override_format[spec] = strdup(option); |
| 49 | |
| 50 | return 0; |
| 51 | } |
| 52 | |
| 53 | static inline void fill_rwbs(char *rwbs, struct blk_io_trace *t) |
| 54 | { |
| 55 | int w = t->action & BLK_TC_ACT(BLK_TC_WRITE); |
| 56 | int a = t->action & BLK_TC_ACT(BLK_TC_AHEAD); |
| 57 | int s = t->action & BLK_TC_ACT(BLK_TC_SYNC); |
| 58 | int m = t->action & BLK_TC_ACT(BLK_TC_META); |
| 59 | int d = t->action & BLK_TC_ACT(BLK_TC_DISCARD); |
| 60 | int f = t->action & BLK_TC_ACT(BLK_TC_FLUSH); |
| 61 | int u = t->action & BLK_TC_ACT(BLK_TC_FUA); |
| 62 | int i = 0; |
| 63 | |
| 64 | if (f) |
| 65 | rwbs[i++] = 'F'; /* flush */ |
| 66 | |
| 67 | if (d) |
| 68 | rwbs[i++] = 'D'; |
| 69 | else if (w) |
| 70 | rwbs[i++] = 'W'; |
| 71 | else if (t->bytes) |
| 72 | rwbs[i++] = 'R'; |
| 73 | else |
| 74 | rwbs[i++] = 'N'; |
| 75 | |
| 76 | if (u) |
| 77 | rwbs[i++] = 'F'; /* fua */ |
| 78 | if (a) |
| 79 | rwbs[i++] = 'A'; |
| 80 | if (s) |
| 81 | rwbs[i++] = 'S'; |
| 82 | if (m) |
| 83 | rwbs[i++] = 'M'; |
| 84 | |
| 85 | rwbs[i] = '\0'; |
| 86 | } |
| 87 | |
| 88 | static const char * |
| 89 | print_time(unsigned long long timestamp) |
| 90 | { |
| 91 | static char timebuf[128]; |
| 92 | struct tm *tm; |
| 93 | time_t sec; |
| 94 | unsigned long nsec; |
| 95 | |
| 96 | sec = abs_start_time.tv_sec + SECONDS(timestamp); |
| 97 | nsec = abs_start_time.tv_nsec + NANO_SECONDS(timestamp); |
| 98 | if (nsec >= 1000000000) { |
| 99 | nsec -= 1000000000; |
| 100 | sec += 1; |
| 101 | } |
| 102 | |
| 103 | tm = localtime(&sec); |
| 104 | snprintf(timebuf, sizeof(timebuf), |
| 105 | "%02u:%02u:%02u.%06lu", |
| 106 | tm->tm_hour, |
| 107 | tm->tm_min, |
| 108 | tm->tm_sec, |
| 109 | nsec / 1000); |
| 110 | return timebuf; |
| 111 | } |
| 112 | |
| 113 | static inline int pdu_rest_is_zero(unsigned char *pdu, int len) |
| 114 | { |
| 115 | static char zero[4096]; |
| 116 | |
| 117 | return !memcmp(pdu, zero, len); |
| 118 | } |
| 119 | |
| 120 | static char *dump_pdu(unsigned char *pdu_buf, int pdu_len) |
| 121 | { |
| 122 | static char p[4096]; |
| 123 | int i, len; |
| 124 | |
| 125 | if (!pdu_buf || !pdu_len) |
| 126 | return NULL; |
| 127 | |
| 128 | for (len = 0, i = 0; i < pdu_len; i++) { |
| 129 | if (i) |
| 130 | len += sprintf(p + len, " "); |
| 131 | |
| 132 | len += sprintf(p + len, "%02x", pdu_buf[i]); |
| 133 | |
| 134 | /* |
| 135 | * usually dump for cdb dumps where we can see lots of |
| 136 | * zeroes, stop when the rest is just zeroes and indicate |
| 137 | * so with a .. appended |
| 138 | */ |
| 139 | if (!pdu_buf[i] && pdu_rest_is_zero(pdu_buf + i, pdu_len - i)) { |
| 140 | sprintf(p + len, " .."); |
| 141 | break; |
| 142 | } |
| 143 | } |
| 144 | |
| 145 | return p; |
| 146 | } |
| 147 | |
| 148 | #define pdu_start(t) (((void *) (t) + sizeof(struct blk_io_trace))) |
| 149 | |
| 150 | static unsigned int get_pdu_int(struct blk_io_trace *t) |
| 151 | { |
| 152 | __u64 *val = pdu_start(t); |
| 153 | |
| 154 | return be64_to_cpu(*val); |
| 155 | } |
| 156 | |
| 157 | static void get_pdu_remap(struct blk_io_trace *t, struct blk_io_trace_remap *r) |
| 158 | { |
| 159 | struct blk_io_trace_remap *__r = pdu_start(t); |
| 160 | __u64 sector_from = __r->sector_from; |
| 161 | |
| 162 | r->device_from = be32_to_cpu(__r->device_from); |
| 163 | r->device_to = be32_to_cpu(__r->device_to); |
| 164 | r->sector_from = be64_to_cpu(sector_from); |
| 165 | } |
| 166 | |
| 167 | static void print_field(char *act, struct per_cpu_info *pci, |
| 168 | struct blk_io_trace *t, unsigned long long elapsed, |
| 169 | int pdu_len, unsigned char *pdu_buf, char field, |
| 170 | int minus, int has_w, int width) |
| 171 | { |
| 172 | char format[64]; |
| 173 | |
| 174 | if (has_w) { |
| 175 | if (minus) |
| 176 | sprintf(format, "%%-%d", width); |
| 177 | else |
| 178 | sprintf(format, "%%%d", width); |
| 179 | } else |
| 180 | sprintf(format, "%%"); |
| 181 | |
| 182 | switch (field) { |
| 183 | case 'a': |
| 184 | fprintf(ofp, strcat(format, "s"), act); |
| 185 | break; |
| 186 | case 'c': |
| 187 | fprintf(ofp, strcat(format, "d"), pci->cpu); |
| 188 | break; |
| 189 | case 'C': { |
| 190 | char *name = find_process_name(t->pid); |
| 191 | |
| 192 | fprintf(ofp, strcat(format, "s"), name); |
| 193 | break; |
| 194 | } |
| 195 | case 'd': { |
| 196 | char rwbs[8]; |
| 197 | |
| 198 | fill_rwbs(rwbs, t); |
| 199 | fprintf(ofp, strcat(format, "s"), rwbs); |
| 200 | break; |
| 201 | } |
| 202 | case 'D': /* format width ignored */ |
| 203 | fprintf(ofp,"%3d,%-3d", MAJOR(t->device), MINOR(t->device)); |
| 204 | break; |
| 205 | case 'e': |
| 206 | fprintf(ofp, strcat(format, "d"), t->error); |
| 207 | break; |
| 208 | case 'M': |
| 209 | fprintf(ofp, strcat(format, "d"), MAJOR(t->device)); |
| 210 | break; |
| 211 | case 'm': |
| 212 | fprintf(ofp, strcat(format, "d"), MINOR(t->device)); |
| 213 | break; |
| 214 | case 'n': |
| 215 | fprintf(ofp, strcat(format, "u"), t_sec(t)); |
| 216 | break; |
| 217 | case 'N': |
| 218 | fprintf(ofp, strcat(format, "u"), t->bytes); |
| 219 | break; |
| 220 | case 'p': |
| 221 | fprintf(ofp, strcat(format, "u"), t->pid); |
| 222 | break; |
| 223 | case 'P': { /* format width ignored */ |
| 224 | char *p = dump_pdu(pdu_buf, pdu_len); |
| 225 | if (p) |
| 226 | fprintf(ofp, "%s", p); |
| 227 | break; |
| 228 | } |
| 229 | case 's': |
| 230 | fprintf(ofp, strcat(format, "ld"), t->sequence); |
| 231 | break; |
| 232 | case 'S': |
| 233 | fprintf(ofp, strcat(format, "lu"), t->sector); |
| 234 | break; |
| 235 | case 't': |
| 236 | sprintf(format, "%%0%dlu", has_w ? width : 9); |
| 237 | fprintf(ofp, format, NANO_SECONDS(t->time)); |
| 238 | break; |
| 239 | case 'T': |
| 240 | fprintf(ofp, strcat(format, "d"), SECONDS(t->time)); |
| 241 | break; |
| 242 | case 'u': |
| 243 | if (elapsed == -1ULL) { |
| 244 | fprintf(stderr, "Expecting elapsed value\n"); |
| 245 | exit(1); |
| 246 | } |
| 247 | fprintf(ofp, strcat(format, "llu"), elapsed / 1000); |
| 248 | break; |
| 249 | case 'U': |
| 250 | fprintf(ofp, strcat(format, "u"), get_pdu_int(t)); |
| 251 | break; |
| 252 | case 'z': |
| 253 | fprintf(ofp, strcat(format, "s"), print_time(t->time)); |
| 254 | break; |
| 255 | default: |
| 256 | fprintf(ofp,strcat(format, "c"), field); |
| 257 | break; |
| 258 | } |
| 259 | } |
| 260 | |
| 261 | static char *parse_field(char *act, struct per_cpu_info *pci, |
| 262 | struct blk_io_trace *t, unsigned long long elapsed, |
| 263 | int pdu_len, unsigned char *pdu_buf, |
| 264 | char *master_format) |
| 265 | { |
| 266 | int minus = 0; |
| 267 | int has_w = 0; |
| 268 | int width = 0; |
| 269 | char *p = master_format; |
| 270 | |
| 271 | if (*p == '-') { |
| 272 | minus = 1; |
| 273 | p++; |
| 274 | } |
| 275 | if (isdigit(*p)) { |
| 276 | has_w = 1; |
| 277 | do { |
| 278 | width = (width * 10) + (*p++ - '0'); |
| 279 | } while ((*p) && (isdigit(*p))); |
| 280 | } |
| 281 | if (*p) { |
| 282 | print_field(act, pci, t, elapsed, pdu_len, pdu_buf, *p++, |
| 283 | minus, has_w, width); |
| 284 | } |
| 285 | return p; |
| 286 | } |
| 287 | |
| 288 | static void process_default(char *act, struct per_cpu_info *pci, |
| 289 | struct blk_io_trace *t, unsigned long long elapsed, |
| 290 | int pdu_len, unsigned char *pdu_buf) |
| 291 | { |
| 292 | struct blk_io_trace_remap r = { .device_from = 0, }; |
| 293 | char rwbs[8]; |
| 294 | char *name; |
| 295 | |
| 296 | fill_rwbs(rwbs, t); |
| 297 | |
| 298 | /* |
| 299 | * For remaps we have to modify the device using the remap structure |
| 300 | * passed up. |
| 301 | */ |
| 302 | if (act[0] == 'A') { |
| 303 | get_pdu_remap(t, &r); |
| 304 | t->device = r.device_to; |
| 305 | } |
| 306 | |
| 307 | /* |
| 308 | * The header is always the same |
| 309 | */ |
| 310 | fprintf(ofp, "%3d,%-3d %2d %8d %5d.%09lu %5u %2s %3s ", |
| 311 | MAJOR(t->device), MINOR(t->device), pci->cpu, t->sequence, |
| 312 | (int) SECONDS(t->time), (unsigned long) NANO_SECONDS(t->time), |
| 313 | t->pid, act, rwbs); |
| 314 | |
| 315 | name = find_process_name(t->pid); |
| 316 | |
| 317 | switch (act[0]) { |
| 318 | case 'R': /* Requeue */ |
| 319 | case 'C': /* Complete */ |
| 320 | if (t->action & BLK_TC_ACT(BLK_TC_PC)) { |
| 321 | char *p = dump_pdu(pdu_buf, pdu_len); |
| 322 | if (p) |
| 323 | fprintf(ofp, "(%s) ", p); |
| 324 | fprintf(ofp, "[%d]\n", t->error); |
| 325 | } else { |
| 326 | if (elapsed != -1ULL) { |
| 327 | if (t_sec(t)) |
| 328 | fprintf(ofp, "%llu + %u (%8llu) [%d]\n", |
| 329 | (unsigned long long) t->sector, |
| 330 | t_sec(t), elapsed, t->error); |
| 331 | else |
| 332 | fprintf(ofp, "%llu (%8llu) [%d]\n", |
| 333 | (unsigned long long) t->sector, |
| 334 | elapsed, t->error); |
| 335 | } else { |
| 336 | if (t_sec(t)) |
| 337 | fprintf(ofp, "%llu + %u [%d]\n", |
| 338 | (unsigned long long) t->sector, |
| 339 | t_sec(t), t->error); |
| 340 | else |
| 341 | fprintf(ofp, "%llu [%d]\n", |
| 342 | (unsigned long long) t->sector, |
| 343 | t->error); |
| 344 | } |
| 345 | } |
| 346 | break; |
| 347 | |
| 348 | case 'D': /* Issue */ |
| 349 | case 'I': /* Insert */ |
| 350 | case 'Q': /* Queue */ |
| 351 | case 'B': /* Bounce */ |
| 352 | if (t->action & BLK_TC_ACT(BLK_TC_PC)) { |
| 353 | char *p; |
| 354 | fprintf(ofp, "%u ", t->bytes); |
| 355 | p = dump_pdu(pdu_buf, pdu_len); |
| 356 | if (p) |
| 357 | fprintf(ofp, "(%s) ", p); |
| 358 | fprintf(ofp, "[%s]\n", name); |
| 359 | } else { |
| 360 | if (elapsed != -1ULL) { |
| 361 | if (t_sec(t)) |
| 362 | fprintf(ofp, "%llu + %u (%8llu) [%s]\n", |
| 363 | (unsigned long long) t->sector, |
| 364 | t_sec(t), elapsed, name); |
| 365 | else |
| 366 | fprintf(ofp, "(%8llu) [%s]\n", elapsed, |
| 367 | name); |
| 368 | } else { |
| 369 | if (t_sec(t)) |
| 370 | fprintf(ofp, "%llu + %u [%s]\n", |
| 371 | (unsigned long long) t->sector, |
| 372 | t_sec(t), name); |
| 373 | else |
| 374 | fprintf(ofp, "[%s]\n", name); |
| 375 | } |
| 376 | } |
| 377 | break; |
| 378 | |
| 379 | case 'M': /* Back merge */ |
| 380 | case 'F': /* Front merge */ |
| 381 | case 'G': /* Get request */ |
| 382 | case 'S': /* Sleep request */ |
| 383 | if (t_sec(t)) |
| 384 | fprintf(ofp, "%llu + %u [%s]\n", |
| 385 | (unsigned long long) t->sector, t_sec(t), name); |
| 386 | else |
| 387 | fprintf(ofp, "[%s]\n", name); |
| 388 | break; |
| 389 | |
| 390 | case 'P': /* Plug */ |
| 391 | fprintf(ofp, "[%s]\n", name); |
| 392 | break; |
| 393 | |
| 394 | case 'U': /* Unplug IO */ |
| 395 | case 'T': /* Unplug timer */ |
| 396 | fprintf(ofp, "[%s] %u\n", name, get_pdu_int(t)); |
| 397 | break; |
| 398 | |
| 399 | case 'A': /* remap */ |
| 400 | get_pdu_remap(t, &r); |
| 401 | fprintf(ofp, "%llu + %u <- (%d,%d) %llu\n", |
| 402 | (unsigned long long) t->sector, t_sec(t), |
| 403 | MAJOR(r.device_from), MINOR(r.device_from), |
| 404 | (unsigned long long) r.sector_from); |
| 405 | break; |
| 406 | |
| 407 | case 'X': /* Split */ |
| 408 | fprintf(ofp, "%llu / %u [%s]\n", (unsigned long long) t->sector, |
| 409 | get_pdu_int(t), name); |
| 410 | break; |
| 411 | |
| 412 | case 'm': /* Message */ |
| 413 | fprintf(ofp, "%*s\n", pdu_len, pdu_buf); |
| 414 | break; |
| 415 | |
| 416 | default: |
| 417 | fprintf(stderr, "Unknown action %c\n", act[0]); |
| 418 | break; |
| 419 | } |
| 420 | |
| 421 | } |
| 422 | |
| 423 | void process_fmt(char *act, struct per_cpu_info *pci, struct blk_io_trace *t, |
| 424 | unsigned long long elapsed, int pdu_len, |
| 425 | unsigned char *pdu_buf) |
| 426 | { |
| 427 | char *p = override_format[(int) *act]; |
| 428 | |
| 429 | if (!p) { |
| 430 | process_default(act, pci, t, elapsed, pdu_len, pdu_buf); |
| 431 | return; |
| 432 | } |
| 433 | |
| 434 | while (*p) { |
| 435 | switch (*p) { |
| 436 | case '%': /* Field specifier */ |
| 437 | p++; |
| 438 | if (*p == '%') |
| 439 | fprintf(ofp, "%c", *p++); |
| 440 | else if (!*p) |
| 441 | fprintf(ofp, "%c", '%'); |
| 442 | else |
| 443 | p = parse_field(act, pci, t, elapsed, |
| 444 | pdu_len, pdu_buf, p); |
| 445 | break; |
| 446 | case '\\': { /* escape */ |
| 447 | switch (p[1]) { |
| 448 | case 'b': fprintf(ofp, "\b"); break; |
| 449 | case 'n': fprintf(ofp, "\n"); break; |
| 450 | case 'r': fprintf(ofp, "\r"); break; |
| 451 | case 't': fprintf(ofp, "\t"); break; |
| 452 | default: |
| 453 | fprintf(stderr, |
| 454 | "Invalid escape char in format %c\n", |
| 455 | p[1]); |
| 456 | exit(1); |
| 457 | /*NOTREACHED*/ |
| 458 | } |
| 459 | p += 2; |
| 460 | break; |
| 461 | } |
| 462 | default: |
| 463 | fprintf(ofp, "%c", *p++); |
| 464 | break; |
| 465 | } |
| 466 | } |
| 467 | } |
| 468 | |
| 469 | |