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 <sys/types.h>
  35 #include <sys/uio.h>
  36 #include <sys/mman.h>
  37 #include <sys/stat.h>
  38 #include <fcntl.h>
  39 #include <inttypes.h>
  40 #include <stdio.h>
  41 #include <stdlib.h>
  42 #include <stdint.h>
  43 #include <string.h>
  44 #include <errno.h>
  45 #include <unistd.h>
  46 #include <signal.h>
  47 #include <fcntl.h>
  48
  49 #include <map>
  50
  51 extern "C" {
  52 #include "spdk/trace.h"
  53 }
  54
  55 static struct spdk_trace_histories *g_histories;
  56
  57 static void usage(void);
  58
  59 struct entry_key {
  60         entry_key(uint16_t _lcore, uint64_t _tsc) : lcore(_lcore), tsc(_tsc) {}
  61         uint16_t lcore;
  62         uint64_t tsc;
  63 };
  64
  65 class compare_entry_key
  66 {
  67 public:
  68         bool operator()(const entry_key &first, const entry_key &second) const
  69         {
  70                 if (first.tsc == second.tsc) {
  71                         return first.lcore < second.lcore;
  72                 } else {
  73                         return first.tsc < second.tsc;
  74                 }
  75         }
  76 };
  77
  78 typedef std::map<entry_key, spdk_trace_entry *, compare_entry_key> entry_map;
  79
  80 entry_map g_entry_map;
  81
  82 struct object_stats {
  83
  84         std::map<uint64_t, uint64_t> start;
  85         std::map<uint64_t, uint64_t> index;
  86         std::map<uint64_t, uint64_t> size;
  87         std::map<uint64_t, uint64_t> tpoint_id;
  88         uint64_t counter;
  89
  90         object_stats() : start(), index(), size(), tpoint_id(), counter(0) {}
  91 };
  92
  93 struct object_stats g_stats[SPDK_TRACE_MAX_OBJECT];
  94
  95 static char *exe_name;
  96 static int verbose = 1;
  97 static int g_fudge_factor = 20;
  98
  99 static uint64_t tsc_rate;
 100 static uint64_t first_tsc = 0x0;
 101 static uint64_t last_tsc = -1ULL;
 102
 103 static float
 104 get_us_from_tsc(uint64_t tsc, uint64_t tsc_rate)
 105 {
 106         return ((float)tsc) * 1000 * 1000 / tsc_rate;
 107 }
 108
 109 static void
 110 print_ptr(const char *arg_string, uint64_t arg)
 111 {
 112         printf("%-7.7s0x%-14jx ", arg_string, arg);
 113 }
 114
 115 static void
 116 print_uint64(const char *arg_string, uint64_t arg)
 117 {
 118         /*
 119          * Print arg as signed, since -1 is a common value especially
 120          *  for FLUSH WRITEBUF when writev() returns -1 due to full
 121          *  socket buffer.
 122          */
 123         printf("%-7.7s%-16jd ", arg_string, arg);
 124 }
 125
 126 static void
 127 print_size(uint32_t size)
 128 {
 129         if (size > 0) {
 130                 printf("size: %6u ", size);
 131         } else {
 132                 printf("%13s", " ");
 133         }
 134 }
 135
 136 static void
 137 print_object_id(uint8_t type, uint64_t id)
 138 {
 139         printf("id:    %c%-15jd ", g_histories->object[type].id_prefix, id);
 140 }
 141
 142 static void
 143 print_float(const char *arg_string, float arg)
 144 {
 145         printf("%-7s%-16.3f ", arg_string, arg);
 146 }
 147
 148 static void
 149 print_arg(bool arg_is_ptr, const char *arg_string, uint64_t arg)
 150 {
 151         if (arg_string[0] == 0)
 152                 return;
 153
 154         if (arg_is_ptr)
 155                 print_ptr(arg_string, arg);
 156         else
 157                 print_uint64(arg_string, arg);
 158 }
 159
 160 static void
 161 print_event(struct spdk_trace_entry *e, uint64_t tsc_rate,
 162             uint64_t tsc_offset, uint16_t lcore)
 163 {
 164         struct spdk_trace_tpoint        *d;
 165         struct object_stats             *stats;
 166         float                           us;
 167
 168         d = &g_histories->tpoint[e->tpoint_id];
 169         stats = &g_stats[d->object_type];
 170
 171         if (d->new_object) {
 172                 stats->index[e->object_id] = stats->counter++;
 173                 stats->tpoint_id[e->object_id] = e->tpoint_id;
 174                 stats->start[e->object_id] = e->tsc;
 175                 stats->size[e->object_id] = e->size;
 176         }
 177
 178         if (d->arg1_is_alias) {
 179                 stats->index[e->arg1] = stats->index[e->object_id];
 180                 stats->start[e->arg1] = stats->start[e->object_id];
 181                 stats->size[e->arg1] = stats->size[e->object_id];
 182         }
 183
 184         us = get_us_from_tsc(e->tsc - tsc_offset, tsc_rate);
 185
 186         printf("%2d: %10.3f (%9ju) ", lcore, us, e->tsc - tsc_offset);
 187         if (g_histories->owner[d->owner_type].id_prefix) {
 188                 printf("%c%02d ", g_histories->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         if (d->new_object) {
 197                 print_arg(d->arg1_is_ptr, d->arg1_name, e->arg1);
 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                         struct spdk_trace_tpoint *start_description;
 202
 203                         us = get_us_from_tsc(e->tsc - stats->start[e->object_id],
 204                                              tsc_rate);
 205                         print_object_id(d->object_type, stats->index[e->object_id]);
 206                         print_float("time:", us);
 207                         start_description = &g_histories->tpoint[stats->tpoint_id[e->object_id]];
 208                         if (start_description->short_name[0] != 0) {
 209                                 printf(" (%.4s)", start_description->short_name);
 210                         }
 211                 } else {
 212                         printf("id:    N/A");
 213                 }
 214         } else {
 215                 print_arg(d->arg1_is_ptr, d->arg1_name, e->arg1);
 216         }
 217         printf("\n");
 218 }
 219
 220 static void
 221 process_event(struct spdk_trace_entry *e, uint64_t tsc_rate,
 222               uint64_t tsc_offset, uint16_t lcore)
 223 {
 224         if (verbose) {
 225                 print_event(e, tsc_rate, tsc_offset, lcore);
 226         }
 227 }
 228
 229 static int
 230 populate_events(struct spdk_trace_history *history)
 231 {
 232         int i, entry_size, history_size, num_entries, num_entries_filled;
 233         struct spdk_trace_entry *e;
 234         int first, last, lcore;
 235
 236         lcore = history->lcore;
 237
 238         entry_size = sizeof(history->entries[0]);
 239         history_size = sizeof(history->entries);
 240         num_entries = history_size / entry_size;
 241
 242         e = history->entries;
 243
 244         num_entries_filled = num_entries;
 245         while (e[num_entries_filled - 1].tsc == 0) {
 246                 num_entries_filled--;
 247         }
 248
 249         if (num_entries == num_entries_filled) {
 250                 first = last = 0;
 251                 for (i = 1; i < num_entries; i++) {
 252                         if (e[i].tsc < e[first].tsc)
 253                                 first = i;
 254                         if (e[i].tsc > e[last].tsc)
 255                                 last = i;
 256                 }
 257
 258                 first += g_fudge_factor;
 259                 if (first >= num_entries)
 260                         first -= num_entries;
 261
 262                 last -= g_fudge_factor;
 263                 if (last < 0)
 264                         last += num_entries;
 265         } else {
 266                 first = 0;
 267                 last = num_entries_filled - 1;
 268         }
 269
 270         /*
 271          * We keep track of the highest first TSC out of all reactors and
 272          *  the lowest last TSC out of all reactors.  We will ignore any
 273          *  events outside the range of these two TSC values.  This will
 274          *  ensure we only print data for the subset of time where we have
 275          *  data across all reactors.
 276          */
 277         if (e[first].tsc > first_tsc) {
 278                 first_tsc = e[first].tsc;
 279         }
 280         if (e[last].tsc < last_tsc) {
 281                 last_tsc = e[last].tsc;
 282         }
 283
 284         i = first;
 285         while (1) {
 286                 g_entry_map[entry_key(lcore, e[i].tsc)] = &e[i];
 287                 if (i == last) {
 288                         break;
 289                 }
 290                 i++;
 291                 if (i == num_entries_filled) {
 292                         i = 0;
 293                 }
 294         }
 295
 296         return (0);
 297 }
 298
 299 static void usage(void)
 300 {
 301         fprintf(stderr, "usage:\n");
 302         fprintf(stderr, "   %s <option> <lcore#>\n", exe_name);
 303         fprintf(stderr, "        option = '-q' to disable verbose mode\n");
 304         fprintf(stderr, "                 '-s' to specify spdk_trace shm name\n");
 305         fprintf(stderr, "                 '-c' to display single lcore history\n");
 306         fprintf(stderr, "                 '-f' to specify number of events to ignore at\n");
 307         fprintf(stderr, "                      beginning and end of trace (default: 20)\n");
 308         fprintf(stderr, "                 '-i' to specify the shared memory ID\n");
 309         fprintf(stderr, "                 '-p' to specify the trace PID\n");
 310         fprintf(stderr, "                 (One of -i or -p must be specified)\n");
 311 }
 312
 313 int main(int argc, char **argv)
 314 {
 315         void                    *history_ptr;
 316         struct spdk_trace_history *history_entries, *history;
 317         int                     fd, i;
 318         int                     lcore = SPDK_TRACE_MAX_LCORE;
 319         uint64_t                tsc_offset;
 320         const char              *app_name = "ids";
 321         int                     op;
 322         char                    shm_name[64];
 323         int                     shm_id = -1, shm_pid = -1;
 324
 325         exe_name = argv[0];
 326         while ((op = getopt(argc, argv, "c:f:i:p:qs:")) != -1) {
 327                 switch (op) {
 328                 case 'c':
 329                         lcore = atoi(optarg);
 330                         if (lcore > SPDK_TRACE_MAX_LCORE) {
 331                                 fprintf(stderr, "Selected lcore: %d "
 332                                         "exceeds maximum %d\n", lcore,
 333                                         SPDK_TRACE_MAX_LCORE);
 334                                 exit(1);
 335                         }
 336                         break;
 337                 case 'f':
 338                         g_fudge_factor = atoi(optarg);
 339                         break;
 340                 case 'i':
 341                         shm_id = atoi(optarg);
 342                         break;
 343                 case 'p':
 344                         shm_pid = atoi(optarg);
 345                         break;
 346                 case 'q':
 347                         verbose = 0;
 348                         break;
 349                 case 's':
 350                         app_name = optarg;
 351                         break;
 352                 default:
 353                         usage();
 354                         exit(1);
 355                 }
 356         }
 357
 358         if (shm_id >= 0) {
 359                 snprintf(shm_name, sizeof(shm_name), "/%s_trace.%d", app_name, shm_id);
 360         } else {
 361                 snprintf(shm_name, sizeof(shm_name), "/%s_trace.pid%d", app_name, shm_pid);
 362         }
 363
 364         fd = shm_open(shm_name, O_RDONLY, 0600);
 365         if (fd < 0) {
 366                 fprintf(stderr, "Could not open shm %s.\n", shm_name);
 367                 usage();
 368                 exit(-1);
 369         }
 370
 371         history_ptr = mmap(NULL, sizeof(*g_histories), PROT_READ, MAP_SHARED, fd, 0);
 372         if (history_ptr == MAP_FAILED) {
 373                 fprintf(stderr, "Could not mmap shm %s.\n", shm_name);
 374                 usage();
 375                 exit(-1);
 376         }
 377
 378         g_histories = (struct spdk_trace_histories *)history_ptr;
 379
 380         tsc_rate = g_histories->tsc_rate;
 381         if (tsc_rate == 0) {
 382                 fprintf(stderr, "Invalid tsc_rate %ju\n", tsc_rate);
 383                 usage();
 384                 exit(-1);
 385         }
 386
 387         if (verbose) {
 388                 printf("TSC Rate: %ju\n", tsc_rate);
 389         }
 390
 391         history_entries = (struct spdk_trace_history *)malloc(sizeof(g_histories->per_lcore_history));
 392         if (history_entries == NULL) {
 393                 goto cleanup;
 394         }
 395         memcpy(history_entries, g_histories->per_lcore_history,
 396                sizeof(g_histories->per_lcore_history));
 397
 398         if (lcore == SPDK_TRACE_MAX_LCORE) {
 399                 for (i = 0; i < SPDK_TRACE_MAX_LCORE; i++) {
 400                         history = &history_entries[i];
 401                         if (history->entries[0].tsc == 0) {
 402                                 continue;
 403                         }
 404                         populate_events(history);
 405                 }
 406         } else {
 407                 history = &history_entries[lcore];
 408                 if (history->entries[0].tsc != 0) {
 409                         populate_events(history);
 410                 }
 411         }
 412
 413         tsc_offset = first_tsc;
 414         for (entry_map::iterator it = g_entry_map.begin(); it != g_entry_map.end(); it++) {
 415                 if (it->first.tsc < first_tsc || it->first.tsc > last_tsc) {
 416                         continue;
 417                 }
 418                 process_event(it->second, tsc_rate, tsc_offset, it->first.lcore);
 419         }
 420
 421         free(history_entries);
 422
 423 cleanup:
 424         munmap(history_ptr, sizeof(*g_histories));
 425         close(fd);
 426
 427         return (0);
 428 }