tests/vm-trace/vm-trace.c

   1 #define _LARGEFILE64_SOURCE
   2 #define _GNU_SOURCE
   3 #include <stdio.h>
   4 #include <stdlib.h>
   5 #include <unistd.h>
   6 #include <string.h>
   7 #include <stdint.h>
   8 #include <fcntl.h>
   9 #include <limits.h>
  10 #include <time.h>
  11 #include <pthread.h>
  12 #include <sched.h>
  13 #include <errno.h>
  14 #include <sys/types.h>
  15 #include <sys/stat.h>
  16
  17 struct file_header
  18 {
  19   uint32_t signature;
  20   uint16_t vmentry_id;
  21   uint16_t vmexit_id;
  22 };
  23
  24 struct thread_param
  25 {
  26   int raw_fd;
  27   int out_fd;
  28   int pipefd[2];
  29   int cpu;
  30 };
  31
  32 struct event
  33 {
  34   uint64_t timestamp;
  35   uint16_t type;
  36 };
  37
  38 enum rb_type
  39 {
  40   RINGBUF_TYPE_DATA_TYPE_LEN_MAX = 28,
  41   RINGBUF_TYPE_PADDING,
  42   RINGBUF_TYPE_TIME_EXTEND,
  43   RINGBUF_TYPE_TIME_STAMP
  44 };
  45
  46 struct vmexit_data
  47 {
  48   uint32_t exit_reason;
  49   uint64_t guest_rip;
  50   uint32_t isa;
  51   uint64_t info1;
  52   uint64_t info2;
  53 };
  54
  55 struct vmentry_data
  56 {
  57   uint32_t vcpu_id;
  58 };
  59
  60 #pragma pack(1)
  61
  62 struct trace_data
  63 {
  64   uint16_t type;
  65   uint8_t flags;
  66   uint8_t preempt_count;
  67   int32_t pid;
  68   uint16_t migrate_disable;
  69   uint16_t padding1;
  70   uint32_t padding2;
  71   union
  72   {
  73     struct vmexit_data vmexit;
  74     struct vmentry_data vmentry;
  75   };
  76 };
  77
  78 struct event_entry
  79 {
  80   uint32_t type_len: 5, time_delta: 27;
  81   union
  82   {
  83     uint32_t array[1];
  84     struct trace_data trace;
  85   };
  86 };
  87
  88 #define DATA_SIZE 4080
  89
  90 struct event_page
  91 {
  92   uint64_t timestamp;
  93   uint64_t commit;
  94   union
  95   {
  96     uint8_t data[DATA_SIZE];
  97     struct event_entry event;
  98   };
  99 };
 100
 101 #define PAGE_SIZE sizeof(struct event_page)
 102
 103 #define TRACE_PATH "/sys/kernel/debug/tracing"
 104 #define TRACE_FILE "trace.bin"
 105 #define TRACE_SIG 0xcce96d01
 106
 107 #define VM_ENTRY "kvm/kvm_entry"
 108 #define VM_EXIT "kvm/kvm_exit"
 109
 110 #ifdef DEBUG
 111 #define dbg_printf(_f_,...) {printf(_f_,##__VA_ARGS__);}
 112 #else
 113 #define dbg_printf(_f_,...)
 114 #endif
 115
 116 static uint16_t vmentry_id;
 117 static uint16_t vmexit_id;
 118
 119 static int stop_tracing;
 120 static int verbose;
 121
 122
 123 static struct event* read_events(int fd, size_t *n)
 124 {
 125   int i, j;
 126   ssize_t rd;
 127   uint32_t len, offset;
 128   uint64_t event_time, pre_event_time, pre_page_time = 0;
 129   struct event_page page;
 130   struct event_entry *e;
 131   struct event *events = NULL;
 132
 133   *n = 0;
 134   for (i = 0; 1; i++)
 135   {
 136     if ((rd = read(fd, &page, PAGE_SIZE)) == 0)
 137     {
 138       if (*n == 0)
 139         fprintf(stderr, "No events found\nMake sure a VM is running and the CPU to trace is bound to a QEMU vCPU thread\n");
 140
 141       return events;
 142     }
 143     else if (rd < 0)
 144     {
 145       fprintf(stderr, "Failed to read trace file\n");
 146       free(events);
 147       return NULL;
 148     }
 149     else if (rd < PAGE_SIZE)
 150     {
 151       fprintf(stderr, "Trace file does not have enough data\n");
 152       free(events);
 153       return NULL;
 154     }
 155
 156     dbg_printf("Page %d:\n", i);
 157     dbg_printf("  timestamp = %ld\n", page.timestamp);
 158     dbg_printf("  commit = %ld\n", page.commit);
 159
 160     if (page.timestamp < pre_page_time)
 161       fprintf(stderr, "Warning: page time going backwards\n");
 162
 163     pre_page_time = page.timestamp;
 164
 165     offset = 0;
 166     pre_event_time = 0;
 167     for (j = 0; 1; j++)
 168     {
 169       e = (struct event_entry *)(page.data+offset);
 170
 171       if (e->type_len == 0)
 172         e = (struct event_entry *)&e->array[1];
 173
 174       if (pre_event_time)
 175         event_time = pre_event_time + e->time_delta;
 176       else
 177         event_time = page.timestamp;
 178
 179       if (e->type_len < RINGBUF_TYPE_DATA_TYPE_LEN_MAX)
 180       {
 181         len = (e->type_len+1) * sizeof(uint32_t);
 182
 183         if (e->trace.type == vmexit_id || e->trace.type == vmentry_id)
 184         {
 185           if ((events = realloc(events, (*n+1) * sizeof(struct event))) == NULL)
 186           {
 187             fprintf(stderr, "Failed to allocate memory\n");
 188             return NULL;
 189           }
 190
 191           events[*n].timestamp = event_time;
 192           events[*n].type = e->trace.type;
 193
 194           if (verbose)
 195           {
 196             if (e->trace.type == vmexit_id)
 197             {
 198               printf("  %ld: VM_EXIT reason: %08x, ", event_time, e->trace.vmexit.exit_reason);
 199               printf("info1: %016lx, info2: %08lx\n", e->trace.vmexit.info1, e->trace.vmexit.info2);
 200             }
 201             else
 202             {
 203               printf("  %ld: VM_ENTRY dt: %d, vcpu: %d\n", event_time, e->time_delta, e->trace.vmentry.vcpu_id);
 204             }
 205           }
 206
 207           *n += 1;
 208         }
 209         else if (e->trace.type == 0)
 210           break;
 211         else
 212           fprintf(stderr, "UNKNOWN event %d\n", e->trace.type);
 213       }
 214       else if (e->type_len == RINGBUF_TYPE_TIME_EXTEND)
 215       {
 216         len = 8;
 217         event_time = pre_event_time + (e->time_delta | (e->array[0]<<28));
 218         dbg_printf("  entry %d: TIME_EXTEND %ld\n", j, event_time);
 219       }
 220       else if (e->type_len == RINGBUF_TYPE_PADDING)
 221       {
 222         if (e->time_delta == 0)
 223           break;
 224
 225         len = e->array[0] + sizeof(uint32_t);
 226         dbg_printf("  entry %d: PADDING, len %d @ %ld\n", j, len, event_time);
 227       }
 228       else if (e->type_len == RINGBUF_TYPE_TIME_STAMP)
 229       {
 230         len = 16;
 231         dbg_printf("  entry %d: TIME_STAMP @ %ld\n", j, event_time);
 232       }
 233
 234       pre_event_time = event_time;
 235
 236       offset += len;
 237       if (offset >= DATA_SIZE)
 238         break;
 239     }
 240
 241     dbg_printf("  events in page %d = %d\n", i, j);
 242   }
 243
 244   return events;
 245 }
 246
 247 static int parse_trace_file(char *file)
 248 {
 249   int fd;
 250   uint16_t pre_event = 0;
 251   struct event *events;
 252   size_t num_events, i, j = 0;
 253   uint64_t d, exit_time = 0, total = 0, max_lat = 0;
 254   uint64_t pre_time = 0, acc_1ms = 0, max_acc = 0;
 255   struct file_header header;
 256
 257   if ((fd = open(file, O_RDONLY|O_LARGEFILE)) < 0)
 258   {
 259     perror(file);
 260     return -1;
 261   }
 262
 263   if (read(fd, &header, sizeof(struct file_header)) < 0)
 264   {
 265     perror(file);
 266     return -1;
 267   }
 268
 269   if (header.signature != TRACE_SIG)
 270   {
 271     fprintf(stderr, "File %s is not a vm-trace file\n", file);
 272     return -1;
 273   }
 274
 275   vmentry_id = header.vmentry_id;
 276   vmexit_id = header.vmexit_id;
 277
 278   if ((events = read_events(fd, &num_events)) == NULL)
 279     return -1;
 280
 281   printf("Number of VM events = %ld\n", num_events);
 282
 283   for (i = 0; i < num_events; i++)
 284   {
 285     if (events[i].type == vmexit_id)
 286     {
 287       exit_time = events[i].timestamp;
 288     }
 289     else if (events[i].type == vmentry_id)
 290     {
 291       if (exit_time)
 292       {
 293         d = events[i].timestamp - exit_time;
 294         if (d > max_lat)
 295           max_lat = d;
 296
 297         total += d;
 298         acc_1ms += d;
 299         j++;
 300       }
 301     }
 302
 303     if (events[i].type == pre_event)
 304       fprintf(stderr, "Warning: repeated events\n");
 305     pre_event = events[i].type;
 306
 307     if (pre_time)
 308     {
 309       if (events[i].timestamp - pre_time >= 1000000)
 310       {
 311         if (acc_1ms > max_acc)
 312           max_acc = acc_1ms;
 313
 314         acc_1ms = 0;
 315         pre_time = events[i].timestamp;
 316       }
 317     }
 318     else
 319       pre_time = events[i].timestamp;
 320   }
 321
 322   free(events);
 323
 324   printf("Average VM Exit-Entry latency = %ldus\n", total/j/1000);
 325   printf("Maximum VM Exit-Entry latency = %ldus\n", max_lat/1000);
 326   printf("Maximum cumulative latency within 1ms = %ldus\n", max_acc/1000);
 327
 328   close(fd);
 329   return 0;
 330 }
 331
 332 static int get_event_id(char *event)
 333 {
 334   char path[PATH_MAX+1];
 335   int fd;
 336   ssize_t r;
 337
 338   sprintf(path, "%s/events/%s/id", TRACE_PATH, event);
 339   if ((fd = open(path, O_RDONLY)) < 0)
 340   {
 341     perror(path);
 342     return -1;
 343   }
 344
 345   if ((r = read(fd, path, PATH_MAX)) < 0)
 346   {
 347     close(fd);
 348     perror(path);
 349     return -1;
 350   }
 351
 352   close(fd);
 353
 354   path[r+1] = '\0';
 355   return atoi(path);
 356 }
 357
 358 static int enable_event(char *event, int en)
 359 {
 360   char path[PATH_MAX+1], *s;
 361   int fd;
 362
 363   if (en)
 364     s = "1";
 365   else
 366     s = "0";
 367
 368   sprintf(path, "%s/events/%s/enable", TRACE_PATH, event);
 369   if ((fd = open(path, O_WRONLY | O_TRUNC)) < 0)
 370   {
 371     perror(path);
 372     return -1;
 373   }
 374
 375   if (write(fd, s, 2) < 0)
 376   {
 377     close(fd);
 378     perror(path);
 379     return -1;
 380   }
 381
 382   close(fd);
 383
 384   return 0;
 385 }
 386
 387 static int enable_events(int en)
 388 {
 389   if (enable_event(VM_ENTRY, en) < 0)
 390     return -1;
 391
 392   if (enable_event(VM_EXIT, en) < 0)
 393     return -1;
 394
 395   return 0;
 396 }
 397
 398 static int setup_tracing(int cpu)
 399 {
 400   char path[PATH_MAX+1], mask[20];
 401   int fd, h, l;
 402
 403   if (cpu > 31)
 404   {
 405     l = 0;
 406     h = 1 << (cpu-32);
 407   }
 408   else
 409   {
 410     l = 1 << cpu;
 411     h = 0;
 412   }
 413
 414   sprintf(mask, "%X,%X", h, l);
 415
 416   sprintf(path, "%s/tracing_cpumask", TRACE_PATH);
 417   if ((fd = open(path, O_WRONLY | O_TRUNC)) < 0)
 418   {
 419     perror(path);
 420     return -1;
 421   }
 422
 423   if (write(fd, mask, strlen(mask)) < 0)
 424   {
 425     close(fd);
 426     perror(path);
 427     return -1;
 428   }
 429
 430   close(fd);
 431
 432   sprintf(path, "%s/trace", TRACE_PATH);
 433   if ((fd = open(path, O_WRONLY | O_TRUNC)) < 0)
 434   {
 435     perror(path);
 436     return -1;
 437   }
 438
 439   if (write(fd, "", 1) < 0)
 440   {
 441     close(fd);
 442     perror(path);
 443     return -1;
 444   }
 445
 446   close(fd);
 447
 448   if ((vmentry_id = get_event_id(VM_ENTRY)) < 0)
 449     return -1;
 450
 451   if ((vmexit_id = get_event_id(VM_EXIT)) < 0)
 452     return -1;
 453
 454   if (enable_events(1) < 0)
 455     return -1;
 456
 457   return 0;
 458 }
 459
 460 static void disable_tracing(int fd, pthread_t thread)
 461 {
 462   if (write(fd, "0", 2) < 0)
 463     perror("disable_tracing");
 464   close(fd);
 465
 466   enable_events(0);
 467
 468   stop_tracing = 1;
 469   pthread_join(thread, NULL);
 470 }
 471
 472 static void *tracing_thread(void *param)
 473 {
 474   cpu_set_t mask;
 475   struct thread_param *p = param;
 476   ssize_t r;
 477
 478   CPU_ZERO(&mask);
 479   CPU_SET(p->cpu, &mask);
 480   if(pthread_setaffinity_np(pthread_self(), sizeof(cpu_set_t), &mask) != 0)
 481     fprintf(stderr, "Could not set CPU affinity to CPU #%d\n", p->cpu);
 482
 483   while (!stop_tracing)
 484   {
 485     if ((r = splice(p->raw_fd, NULL, p->pipefd[1], NULL, PAGE_SIZE, SPLICE_F_MOVE|SPLICE_F_NONBLOCK)) < 0)
 486     {
 487       if (errno == EAGAIN)
 488         continue;
 489
 490       perror("splice1");
 491       break;
 492     }
 493     else if (r == 0)
 494       continue;
 495
 496     if (splice(p->pipefd[0], NULL, p->out_fd, NULL, PAGE_SIZE, SPLICE_F_MOVE|SPLICE_F_NONBLOCK) < 0)
 497     {
 498       perror("splice2");
 499       break;
 500     }
 501   }
 502
 503   close(p->raw_fd);
 504   close(p->pipefd[1]);
 505   close(p->pipefd[0]);
 506   close(p->out_fd);
 507
 508   return NULL;
 509 }
 510
 511 static void usage(char *argv[])
 512 {
 513   fprintf(stderr, "Usage: %s -p cpu_to_trace -c cpu_to_collect_trace -s duration_in_seconds\n", argv[0]);
 514   fprintf(stderr, "       %s -f trace_file [-v]\n", argv[0]);
 515   exit(-1);
 516 }
 517
 518 int main(int argc, char *argv[])
 519 {
 520   char path[PATH_MAX+1], *file = NULL;
 521   int cpu = -1, ttime = 0;
 522   int opt, fd;
 523   pthread_t thread;
 524   struct file_header header;
 525   struct thread_param param;
 526   struct timespec interval;
 527
 528   param.cpu = -1;
 529
 530   while ((opt = getopt(argc, argv, "p:c:s:f:v")) != -1)
 531   {
 532     switch (opt)
 533     {
 534       case 'p':
 535         cpu = atoi(optarg);
 536         break;
 537       case 'c':
 538         param.cpu = atoi(optarg);
 539         break;
 540       case 's':
 541         ttime = atoi(optarg);
 542         break;
 543       case 'f':
 544         file = optarg;
 545         break;
 546       case 'v':
 547         verbose = 1;
 548         break;
 549       default:
 550         usage(argv);
 551     }
 552   }
 553
 554   if ((cpu < 0 || param.cpu < 0 || ttime <= 0) && file == NULL)
 555     usage(argv);
 556
 557   if (file != NULL)
 558     return parse_trace_file(file);
 559
 560   verbose = 0;
 561
 562   if (setup_tracing(cpu) < 0)
 563     return -1;
 564
 565   if ((param.out_fd = open(TRACE_FILE, O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0644)) < 0)
 566   {
 567     perror(TRACE_FILE);
 568     return -1;
 569   }
 570
 571   header.signature = TRACE_SIG;
 572   header.vmentry_id = vmentry_id;
 573   header.vmexit_id = vmexit_id;
 574
 575   if (write(param.out_fd, &header, sizeof(struct file_header)) < 0)
 576   {
 577     perror(TRACE_FILE);
 578     return -1;
 579   }
 580
 581   sprintf(path, "%s/per_cpu/cpu%d/trace_pipe_raw", TRACE_PATH, cpu);
 582   if ((param.raw_fd = open(path, O_RDONLY)) < 0)
 583   {
 584     perror(path);
 585     return -1;
 586   }
 587
 588   if (pipe(param.pipefd) < 0)
 589   {
 590     perror("pipe");
 591     return -1;
 592   }
 593
 594   sprintf(path, "%s/tracing_on", TRACE_PATH);
 595   if ((fd = open(path, O_WRONLY)) < 0)
 596   {
 597     perror(path);
 598     return -1;
 599   }
 600
 601   if (pthread_create(&thread, NULL, tracing_thread, &param))
 602   {
 603     perror("pthread_create");
 604     return -1;
 605   }
 606
 607   if (write(fd, "1", 2) < 0)
 608   {
 609     perror(path);
 610     disable_tracing(fd, thread);
 611     return -1;
 612   }
 613
 614   printf("CPU to trace: %d\n", cpu);
 615   printf("CPU to collect trace: %d\n", param.cpu);
 616   printf("Duration: %d seconds\n", ttime);
 617
 618   interval.tv_sec = ttime;
 619   interval.tv_nsec = 0;
 620   if (clock_nanosleep(CLOCK_MONOTONIC, 0, &interval, NULL))
 621   {
 622     perror("clock_nanosleep");
 623     disable_tracing(fd, thread);
 624     return -1;
 625   }
 626
 627   disable_tracing(fd, thread);
 628
 629   printf("Processing event file ...\n");
 630
 631   return parse_trace_file(TRACE_FILE);
 632 }