ceph/src/spdk/app/trace/trace.cpp

   1 /*-
   2  *   BSD LICENSE
   3  *
   4  *   Copyright (c) Intel Corporation.
   5  *   All rights reserved.
   6  *
   7  *   Redistribution and use in source and binary forms, with or without
   8  *   modification, are permitted provided that the following conditions
   9  *   are met:
  10  *
  11  *     * Redistributions of source code must retain the above copyright
  12  *       notice, this list of conditions and the following disclaimer.
  13  *     * Redistributions in binary form must reproduce the above copyright
  14  *       notice, this list of conditions and the following disclaimer in
  15  *       the documentation and/or other materials provided with the
  16  *       distribution.
  17  *     * Neither the name of Intel Corporation nor the names of its
  18  *       contributors may be used to endorse or promote products derived
  19  *       from this software without specific prior written permission.
  20  *
  21  *   THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
  22  *   "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
  23  *   LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
  24  *   A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
  25  *   OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
  26  *   SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
  27  *   LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
  28  *   DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
  29  *   THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
  30  *   (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
  31  *   OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
  32  */
  33
  34 #include "spdk/stdinc.h"
  35
  36 #include <map>
  37
  38 extern "C" {
  39 #include "spdk/trace.h"
  40 #include "spdk/util.h"
  41 }
  42
  43 static struct spdk_trace_histories *g_histories;
  44 static bool g_print_tsc = false;
  45
  46 static void usage(void);
  47
  48 struct entry_key {
  49         entry_key(uint16_t _lcore, uint64_t _tsc) : lcore(_lcore), tsc(_tsc) {}
  50         uint16_t lcore;
  51         uint64_t tsc;
  52 };
  53
  54 class compare_entry_key
  55 {
  56 public:
  57         bool operator()(const entry_key &first, const entry_key &second) const
  58         {
  59                 if (first.tsc == second.tsc) {
  60                         return first.lcore < second.lcore;
  61                 } else {
  62                         return first.tsc < second.tsc;
  63                 }
  64         }
  65 };
  66
  67 typedef std::map<entry_key, spdk_trace_entry *, compare_entry_key> entry_map;
  68
  69 entry_map g_entry_map;
  70
  71 struct object_stats {
  72
  73         std::map<uint64_t, uint64_t> start;
  74         std::map<uint64_t, uint64_t> index;
  75         std::map<uint64_t, uint64_t> size;
  76         std::map<uint64_t, uint64_t> tpoint_id;
  77         uint64_t counter;
  78
  79         object_stats() : start(), index(), size(), tpoint_id(), counter(0) {}
  80 };
  81
  82 struct object_stats g_stats[SPDK_TRACE_MAX_OBJECT];
  83
  84 static char *g_exe_name;
  85 static int g_verbose = 1;
  86
  87 static uint64_t g_tsc_rate;
  88 static uint64_t g_first_tsc = 0x0;
  89
  90 static float
  91 get_us_from_tsc(uint64_t tsc, uint64_t tsc_rate)
  92 {
  93         return ((float)tsc) * 1000 * 1000 / tsc_rate;
  94 }
  95
  96 static void
  97 print_ptr(const char *arg_string, uint64_t arg)
  98 {
  99         printf("%-7.7s0x%-14jx ", arg_string, arg);
 100 }
 101
 102 static void
 103 print_uint64(const char *arg_string, uint64_t arg)
 104 {
 105         /*
 106          * Print arg as signed, since -1 is a common value especially
 107          *  for FLUSH WRITEBUF when writev() returns -1 due to full
 108          *  socket buffer.
 109          */
 110         printf("%-7.7s%-16jd ", arg_string, arg);
 111 }
 112
 113 static void
 114 print_string(const char *arg_string, uint64_t arg)
 115 {
 116         char *str = (char *)&arg;
 117         printf("%-7.7s%.8s ", arg_string, str);
 118 }
 119
 120 static void
 121 print_size(uint32_t size)
 122 {
 123         if (size > 0) {
 124                 printf("size: %6u ", size);
 125         } else {
 126                 printf("%13s", " ");
 127         }
 128 }
 129
 130 static void
 131 print_object_id(uint8_t type, uint64_t id)
 132 {
 133         printf("id:    %c%-15jd ", g_histories->flags.object[type].id_prefix, id);
 134 }
 135
 136 static void
 137 print_float(const char *arg_string, float arg)
 138 {
 139         printf("%-7s%-16.3f ", arg_string, arg);
 140 }
 141
 142 static void
 143 print_arg(uint8_t arg_type, const char *arg_string, uint64_t arg)
 144 {
 145         if (arg_string[0] == 0) {
 146                 printf("%24s", "");
 147                 return;
 148         }
 149
 150         switch (arg_type) {
 151         case SPDK_TRACE_ARG_TYPE_PTR:
 152                 print_ptr(arg_string, arg);
 153                 break;
 154         case SPDK_TRACE_ARG_TYPE_INT:
 155                 print_uint64(arg_string, arg);
 156                 break;
 157         case SPDK_TRACE_ARG_TYPE_STR:
 158                 print_string(arg_string, arg);
 159                 break;
 160         }
 161 }
 162
 163 static void
 164 print_event(struct spdk_trace_entry *e, uint64_t tsc_rate,
 165             uint64_t tsc_offset, uint16_t lcore)
 166 {
 167         struct spdk_trace_tpoint        *d;
 168         struct object_stats             *stats;
 169         float                           us;
 170
 171         d = &g_histories->flags.tpoint[e->tpoint_id];
 172         stats = &g_stats[d->object_type];
 173
 174         if (d->new_object) {
 175                 stats->index[e->object_id] = stats->counter++;
 176                 stats->tpoint_id[e->object_id] = e->tpoint_id;
 177                 stats->start[e->object_id] = e->tsc;
 178                 stats->size[e->object_id] = e->size;
 179         }
 180
 181         us = get_us_from_tsc(e->tsc - tsc_offset, tsc_rate);
 182
 183         printf("%2d: %10.3f ", lcore, us);
 184         if (g_print_tsc) {
 185                 printf("(%9ju) ", e->tsc - tsc_offset);
 186         }
 187         if (g_histories->flags.owner[d->owner_type].id_prefix) {
 188                 printf("%c%02d ", g_histories->flags.owner[d->owner_type].id_prefix, e->poller_id);
 189         } else {
 190                 printf("%4s", " ");
 191         }
 192
 193         printf("%-*s ", (int)sizeof(d->name), d->name);
 194         print_size(e->size);
 195
 196         print_arg(d->arg1_type, d->arg1_name, e->arg1);
 197         if (d->new_object) {
 198                 print_object_id(d->object_type, stats->index[e->object_id]);
 199         } else if (d->object_type != OBJECT_NONE) {
 200                 if (stats->start.find(e->object_id) != stats->start.end()) {
 201                         us = get_us_from_tsc(e->tsc - stats->start[e->object_id],
 202                                              tsc_rate);
 203                         print_object_id(d->object_type, stats->index[e->object_id]);
 204                         print_float("time:", us);
 205                 } else {
 206                         printf("id:    N/A");
 207                 }
 208         } else if (e->object_id != 0) {
 209                 print_arg(SPDK_TRACE_ARG_TYPE_PTR, "object: ", e->object_id);
 210         }
 211         printf("\n");
 212 }
 213
 214 static void
 215 process_event(struct spdk_trace_entry *e, uint64_t tsc_rate,
 216               uint64_t tsc_offset, uint16_t lcore)
 217 {
 218         if (g_verbose) {
 219                 print_event(e, tsc_rate, tsc_offset, lcore);
 220         }
 221 }
 222
 223 static int
 224 populate_events(struct spdk_trace_history *history, int num_entries)
 225 {
 226         int i, num_entries_filled;
 227         struct spdk_trace_entry *e;
 228         int first, last, lcore;
 229
 230         lcore = history->lcore;
 231
 232         e = history->entries;
 233
 234         num_entries_filled = num_entries;
 235         while (e[num_entries_filled - 1].tsc == 0) {
 236                 num_entries_filled--;
 237         }
 238
 239         if (num_entries == num_entries_filled) {
 240                 first = last = 0;
 241                 for (i = 1; i < num_entries; i++) {
 242                         if (e[i].tsc < e[first].tsc) {
 243                                 first = i;
 244                         }
 245                         if (e[i].tsc > e[last].tsc) {
 246                                 last = i;
 247                         }
 248                 }
 249         } else {
 250                 first = 0;
 251                 last = num_entries_filled - 1;
 252         }
 253
 254         /*
 255          * We keep track of the highest first TSC out of all reactors.
 256          *  We will ignore any events that occured before this TSC on any
 257          *  other reactors.  This will ensure we only print data for the
 258          *  subset of time where we have data across all reactors.
 259          */
 260         if (e[first].tsc > g_first_tsc) {
 261                 g_first_tsc = e[first].tsc;
 262         }
 263
 264         i = first;
 265         while (1) {
 266                 g_entry_map[entry_key(lcore, e[i].tsc)] = &e[i];
 267                 if (i == last) {
 268                         break;
 269                 }
 270                 i++;
 271                 if (i == num_entries_filled) {
 272                         i = 0;
 273                 }
 274         }
 275
 276         return (0);
 277 }
 278
 279 static void usage(void)
 280 {
 281         fprintf(stderr, "usage:\n");
 282         fprintf(stderr, "   %s <option> <lcore#>\n", g_exe_name);
 283         fprintf(stderr, "        option = '-q' to disable verbose mode\n");
 284         fprintf(stderr, "                 '-c' to display single lcore history\n");
 285         fprintf(stderr, "                 '-t' to display TSC offset for each event\n");
 286         fprintf(stderr, "                 '-s' to specify spdk_trace shm name for a\n");
 287         fprintf(stderr, "                      currently running process\n");
 288         fprintf(stderr, "                 '-i' to specify the shared memory ID\n");
 289         fprintf(stderr, "                 '-p' to specify the trace PID\n");
 290         fprintf(stderr, "                      (If -s is specified, then one of\n");
 291         fprintf(stderr, "                       -i or -p must be specified)\n");
 292         fprintf(stderr, "                 '-f' to specify a tracepoint file name\n");
 293         fprintf(stderr, "                      (-s and -f are mutually exclusive)\n");
 294 }
 295
 296 int main(int argc, char **argv)
 297 {
 298         void                    *history_ptr;
 299         struct spdk_trace_history *history;
 300         int                     fd, i, rc;
 301         int                     lcore = SPDK_TRACE_MAX_LCORE;
 302         uint64_t                tsc_offset;
 303         const char              *app_name = NULL;
 304         const char              *file_name = NULL;
 305         int                     op;
 306         char                    shm_name[64];
 307         int                     shm_id = -1, shm_pid = -1;
 308         uint64_t                trace_histories_size;
 309         struct stat             _stat;
 310
 311         g_exe_name = argv[0];
 312         while ((op = getopt(argc, argv, "c:f:i:p:qs:t")) != -1) {
 313                 switch (op) {
 314                 case 'c':
 315                         lcore = atoi(optarg);
 316                         if (lcore > SPDK_TRACE_MAX_LCORE) {
 317                                 fprintf(stderr, "Selected lcore: %d "
 318                                         "exceeds maximum %d\n", lcore,
 319                                         SPDK_TRACE_MAX_LCORE);
 320                                 exit(1);
 321                         }
 322                         break;
 323                 case 'i':
 324                         shm_id = atoi(optarg);
 325                         break;
 326                 case 'p':
 327                         shm_pid = atoi(optarg);
 328                         break;
 329                 case 'q':
 330                         g_verbose = 0;
 331                         break;
 332                 case 's':
 333                         app_name = optarg;
 334                         break;
 335                 case 'f':
 336                         file_name = optarg;
 337                         break;
 338                 case 't':
 339                         g_print_tsc = true;
 340                         break;
 341                 default:
 342                         usage();
 343                         exit(1);
 344                 }
 345         }
 346
 347         if (file_name != NULL && app_name != NULL) {
 348                 fprintf(stderr, "-f and -s are mutually exclusive\n");
 349                 usage();
 350                 exit(1);
 351         }
 352
 353         if (file_name == NULL && app_name == NULL) {
 354                 fprintf(stderr, "One of -f and -s must be specified\n");
 355                 usage();
 356                 exit(1);
 357         }
 358
 359         if (file_name) {
 360                 fd = open(file_name, O_RDONLY);
 361         } else {
 362                 if (shm_id >= 0) {
 363                         snprintf(shm_name, sizeof(shm_name), "/%s_trace.%d", app_name, shm_id);
 364                 } else {
 365                         snprintf(shm_name, sizeof(shm_name), "/%s_trace.pid%d", app_name, shm_pid);
 366                 }
 367                 fd = shm_open(shm_name, O_RDONLY, 0600);
 368                 file_name = shm_name;
 369         }
 370         if (fd < 0) {
 371                 fprintf(stderr, "Could not open %s.\n", file_name);
 372                 usage();
 373                 exit(-1);
 374         }
 375
 376         rc = fstat(fd, &_stat);
 377         if (rc < 0) {
 378                 fprintf(stderr, "Could not get size of %s.\n", file_name);
 379                 usage();
 380                 exit(-1);
 381         }
 382         if ((size_t)_stat.st_size < sizeof(*g_histories)) {
 383                 fprintf(stderr, "%s is not a valid trace file\n", file_name);
 384                 usage();
 385                 exit(-1);
 386         }
 387
 388         /* Map the header of trace file */
 389         history_ptr = mmap(NULL, sizeof(*g_histories), PROT_READ, MAP_SHARED, fd, 0);
 390         if (history_ptr == MAP_FAILED) {
 391                 fprintf(stderr, "Could not mmap %s.\n", file_name);
 392                 usage();
 393                 exit(-1);
 394         }
 395
 396         g_histories = (struct spdk_trace_histories *)history_ptr;
 397
 398         g_tsc_rate = g_histories->flags.tsc_rate;
 399         if (g_tsc_rate == 0) {
 400                 fprintf(stderr, "Invalid tsc_rate %ju\n", g_tsc_rate);
 401                 usage();
 402                 exit(-1);
 403         }
 404
 405         if (g_verbose) {
 406                 printf("TSC Rate: %ju\n", g_tsc_rate);
 407         }
 408
 409         /* Remap the entire trace file */
 410         trace_histories_size = spdk_get_trace_histories_size(g_histories);
 411         munmap(history_ptr, sizeof(*g_histories));
 412         if ((size_t)_stat.st_size < trace_histories_size) {
 413                 fprintf(stderr, "%s is not a valid trace file\n", file_name);
 414                 usage();
 415                 exit(-1);
 416         }
 417         history_ptr = mmap(NULL, trace_histories_size, PROT_READ, MAP_SHARED, fd, 0);
 418         if (history_ptr == MAP_FAILED) {
 419                 fprintf(stderr, "Could not mmap %s.\n", file_name);
 420                 usage();
 421                 exit(-1);
 422         }
 423
 424         g_histories = (struct spdk_trace_histories *)history_ptr;
 425
 426         if (lcore == SPDK_TRACE_MAX_LCORE) {
 427                 for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
 428                         history = spdk_get_per_lcore_history(g_histories, i);
 429                         if (history->num_entries == 0 || history->entries[0].tsc == 0) {
 430                                 continue;
 431                         }
 432
 433                         if (g_verbose && history->num_entries) {
 434                                 printf("Trace Size of lcore (%d): %ju\n", i, history->num_entries);
 435                         }
 436
 437                         populate_events(history, history->num_entries);
 438                 }
 439         } else {
 440                 history = spdk_get_per_lcore_history(g_histories, lcore);
 441                 if (history->num_entries > 0 && history->entries[0].tsc != 0) {
 442                         if (g_verbose && history->num_entries) {
 443                                 printf("Trace Size of lcore (%d): %ju\n", lcore, history->num_entries);
 444                         }
 445
 446                         populate_events(history, history->num_entries);
 447                 }
 448         }
 449
 450         tsc_offset = g_first_tsc;
 451         for (entry_map::iterator it = g_entry_map.begin(); it != g_entry_map.end(); it++) {
 452                 if (it->first.tsc < g_first_tsc) {
 453                         continue;
 454                 }
 455                 process_event(it->second, g_tsc_rate, tsc_offset, it->first.lcore);
 456         }
 457
 458         munmap(history_ptr, trace_histories_size);
 459         close(fd);
 460
 461         return (0);
 462 }