1 /* 2 * qsp.c - QEMU Synchronization Profiler 3 * 4 * Copyright (C) 2018, Emilio G. Cota <cota@braap.org> 5 * 6 * License: GNU GPL, version 2 or later. 7 * See the COPYING file in the top-level directory. 8 * 9 * QSP profiles the time spent in synchronization primitives, which can 10 * help diagnose performance problems, e.g. scalability issues when 11 * contention is high. 12 * 13 * The primitives currently supported are mutexes, recursive mutexes and 14 * condition variables. Note that not all related functions are intercepted; 15 * instead we profile only those functions that can have a performance impact, 16 * either due to blocking (e.g. cond_wait, mutex_lock) or cache line 17 * contention (e.g. mutex_lock, mutex_trylock). 18 * 19 * QSP's design focuses on speed and scalability. This is achieved 20 * by having threads do their profiling entirely on thread-local data. 21 * The appropriate thread-local data is found via a QHT, i.e. a concurrent hash 22 * table. To aggregate data in order to generate a report, we iterate over 23 * all entries in the hash table. Depending on the number of threads and 24 * synchronization objects this might be expensive, but note that it is 25 * very rarely called -- reports are generated only when requested by users. 26 * 27 * Reports are generated as a table where each row represents a call site. A 28 * call site is the triplet formed by the __file__ and __LINE__ of the caller 29 * as well as the address of the "object" (i.e. mutex, rec. mutex or condvar) 30 * being operated on. Optionally, call sites that operate on different objects 31 * of the same type can be coalesced, which can be particularly useful when 32 * profiling dynamically-allocated objects. 33 * 34 * Alternative designs considered: 35 * 36 * - Use an off-the-shelf profiler such as mutrace. This is not a viable option 37 * for us because QEMU has __malloc_hook set (by one of the libraries it 38 * uses); leaving this hook unset is required to avoid deadlock in mutrace. 39 * 40 * - Use a glib HT for each thread, protecting each HT with its own lock. 41 * This isn't simpler than the current design, and is 10% slower in the 42 * atomic_add-bench microbenchmark (-m option). 43 * 44 * - For reports, just use a binary tree as we aggregate data, instead of having 45 * an intermediate hash table. This would simplify the code only slightly, but 46 * would perform badly if there were many threads and objects to track. 47 * 48 * - Wrap operations on qsp entries with RCU read-side critical sections, so 49 * that qsp_reset() can delete entries. Unfortunately, the overhead of calling 50 * rcu_read_lock/unlock slows down atomic_add-bench -m by 24%. Having 51 * a snapshot that is updated on qsp_reset() avoids this overhead. 52 * 53 * Related Work: 54 * - Lennart Poettering's mutrace: http://0pointer.de/blog/projects/mutrace.html 55 * - Lozi, David, Thomas, Lawall and Muller. "Remote Core Locking: Migrating 56 * Critical-Section Execution to Improve the Performance of Multithreaded 57 * Applications", USENIX ATC'12. 58 */ 59 60 #include "qemu/osdep.h" 61 #include "qemu/qemu-print.h" 62 #include "qemu/thread.h" 63 #include "qemu/timer.h" 64 #include "qemu/qht.h" 65 #include "qemu/rcu.h" 66 #include "qemu/xxhash.h" 67 68 enum QSPType { 69 QSP_MUTEX, 70 QSP_BQL_MUTEX, 71 QSP_REC_MUTEX, 72 QSP_CONDVAR, 73 }; 74 75 struct QSPCallSite { 76 const void *obj; 77 const char *file; /* i.e. __FILE__; shortened later */ 78 int line; 79 enum QSPType type; 80 }; 81 typedef struct QSPCallSite QSPCallSite; 82 83 struct QSPEntry { 84 void *thread_ptr; 85 const QSPCallSite *callsite; 86 uint64_t n_acqs; 87 uint64_t ns; 88 unsigned int n_objs; /* count of coalesced objs; only used for reporting */ 89 }; 90 typedef struct QSPEntry QSPEntry; 91 92 struct QSPSnapshot { 93 struct rcu_head rcu; 94 struct qht ht; 95 }; 96 typedef struct QSPSnapshot QSPSnapshot; 97 98 /* initial sizing for hash tables */ 99 #define QSP_INITIAL_SIZE 64 100 101 /* If this file is moved, QSP_REL_PATH should be updated accordingly */ 102 #define QSP_REL_PATH "util/qsp.c" 103 104 /* this file's full path. Used to present all call sites with relative paths */ 105 static size_t qsp_qemu_path_len; 106 107 /* the address of qsp_thread gives us a unique 'thread ID' */ 108 static __thread int qsp_thread; 109 110 /* 111 * Call sites are the same for all threads, so we track them in a separate hash 112 * table to save memory. 113 */ 114 static struct qht qsp_callsite_ht; 115 116 static struct qht qsp_ht; 117 static QSPSnapshot *qsp_snapshot; 118 static bool qsp_initialized, qsp_initializing; 119 120 static const char * const qsp_typenames[] = { 121 [QSP_MUTEX] = "mutex", 122 [QSP_BQL_MUTEX] = "BQL mutex", 123 [QSP_REC_MUTEX] = "rec_mutex", 124 [QSP_CONDVAR] = "condvar", 125 }; 126 127 QemuMutexLockFunc qemu_bql_mutex_lock_func = qemu_mutex_lock_impl; 128 QemuMutexLockFunc qemu_mutex_lock_func = qemu_mutex_lock_impl; 129 QemuMutexTrylockFunc qemu_mutex_trylock_func = qemu_mutex_trylock_impl; 130 QemuRecMutexLockFunc qemu_rec_mutex_lock_func = qemu_rec_mutex_lock_impl; 131 QemuRecMutexTrylockFunc qemu_rec_mutex_trylock_func = 132 qemu_rec_mutex_trylock_impl; 133 QemuCondWaitFunc qemu_cond_wait_func = qemu_cond_wait_impl; 134 QemuCondTimedWaitFunc qemu_cond_timedwait_func = qemu_cond_timedwait_impl; 135 136 /* 137 * It pays off to _not_ hash callsite->file; hashing a string is slow, and 138 * without it we still get a pretty unique hash. 139 */ 140 static inline 141 uint32_t do_qsp_callsite_hash(const QSPCallSite *callsite, uint64_t ab) 142 { 143 uint64_t cd = (uint64_t)(uintptr_t)callsite->obj; 144 uint32_t e = callsite->line; 145 uint32_t f = callsite->type; 146 147 return qemu_xxhash6(ab, cd, e, f); 148 } 149 150 static inline 151 uint32_t qsp_callsite_hash(const QSPCallSite *callsite) 152 { 153 return do_qsp_callsite_hash(callsite, 0); 154 } 155 156 static inline uint32_t do_qsp_entry_hash(const QSPEntry *entry, uint64_t a) 157 { 158 return do_qsp_callsite_hash(entry->callsite, a); 159 } 160 161 static uint32_t qsp_entry_hash(const QSPEntry *entry) 162 { 163 return do_qsp_entry_hash(entry, (uint64_t)(uintptr_t)entry->thread_ptr); 164 } 165 166 static uint32_t qsp_entry_no_thread_hash(const QSPEntry *entry) 167 { 168 return do_qsp_entry_hash(entry, 0); 169 } 170 171 /* without the objects we need to hash the file name to get a decent hash */ 172 static uint32_t qsp_entry_no_thread_obj_hash(const QSPEntry *entry) 173 { 174 const QSPCallSite *callsite = entry->callsite; 175 uint64_t ab = g_str_hash(callsite->file); 176 uint64_t cd = callsite->line; 177 uint32_t e = callsite->type; 178 179 return qemu_xxhash5(ab, cd, e); 180 } 181 182 static bool qsp_callsite_cmp(const void *ap, const void *bp) 183 { 184 const QSPCallSite *a = ap; 185 const QSPCallSite *b = bp; 186 187 return a == b || 188 (a->obj == b->obj && 189 a->line == b->line && 190 a->type == b->type && 191 (a->file == b->file || !strcmp(a->file, b->file))); 192 } 193 194 static bool qsp_callsite_no_obj_cmp(const void *ap, const void *bp) 195 { 196 const QSPCallSite *a = ap; 197 const QSPCallSite *b = bp; 198 199 return a == b || 200 (a->line == b->line && 201 a->type == b->type && 202 (a->file == b->file || !strcmp(a->file, b->file))); 203 } 204 205 static bool qsp_entry_no_thread_cmp(const void *ap, const void *bp) 206 { 207 const QSPEntry *a = ap; 208 const QSPEntry *b = bp; 209 210 return qsp_callsite_cmp(a->callsite, b->callsite); 211 } 212 213 static bool qsp_entry_no_thread_obj_cmp(const void *ap, const void *bp) 214 { 215 const QSPEntry *a = ap; 216 const QSPEntry *b = bp; 217 218 return qsp_callsite_no_obj_cmp(a->callsite, b->callsite); 219 } 220 221 static bool qsp_entry_cmp(const void *ap, const void *bp) 222 { 223 const QSPEntry *a = ap; 224 const QSPEntry *b = bp; 225 226 return a->thread_ptr == b->thread_ptr && 227 qsp_callsite_cmp(a->callsite, b->callsite); 228 } 229 230 /* 231 * Normally we'd call this from a constructor function, but we want it to work 232 * via libutil as well. 233 */ 234 static void qsp_do_init(void) 235 { 236 /* make sure this file's path in the tree is up to date with QSP_REL_PATH */ 237 g_assert(strstr(__FILE__, QSP_REL_PATH)); 238 qsp_qemu_path_len = strlen(__FILE__) - strlen(QSP_REL_PATH); 239 240 qht_init(&qsp_ht, qsp_entry_cmp, QSP_INITIAL_SIZE, 241 QHT_MODE_AUTO_RESIZE | QHT_MODE_RAW_MUTEXES); 242 qht_init(&qsp_callsite_ht, qsp_callsite_cmp, QSP_INITIAL_SIZE, 243 QHT_MODE_AUTO_RESIZE | QHT_MODE_RAW_MUTEXES); 244 } 245 246 static __attribute__((noinline)) void qsp_init__slowpath(void) 247 { 248 if (qatomic_cmpxchg(&qsp_initializing, false, true) == false) { 249 qsp_do_init(); 250 qatomic_set(&qsp_initialized, true); 251 } else { 252 while (!qatomic_read(&qsp_initialized)) { 253 cpu_relax(); 254 } 255 } 256 } 257 258 /* qsp_init() must be called from _all_ exported functions */ 259 static inline void qsp_init(void) 260 { 261 if (likely(qatomic_read(&qsp_initialized))) { 262 return; 263 } 264 qsp_init__slowpath(); 265 } 266 267 static QSPCallSite *qsp_callsite_find(const QSPCallSite *orig) 268 { 269 QSPCallSite *callsite; 270 uint32_t hash; 271 272 hash = qsp_callsite_hash(orig); 273 callsite = qht_lookup(&qsp_callsite_ht, orig, hash); 274 if (callsite == NULL) { 275 void *existing = NULL; 276 277 callsite = g_new(QSPCallSite, 1); 278 memcpy(callsite, orig, sizeof(*callsite)); 279 qht_insert(&qsp_callsite_ht, callsite, hash, &existing); 280 if (unlikely(existing)) { 281 g_free(callsite); 282 callsite = existing; 283 } 284 } 285 return callsite; 286 } 287 288 static QSPEntry * 289 qsp_entry_create(struct qht *ht, const QSPEntry *entry, uint32_t hash) 290 { 291 QSPEntry *e; 292 void *existing = NULL; 293 294 e = g_new0(QSPEntry, 1); 295 e->thread_ptr = entry->thread_ptr; 296 e->callsite = qsp_callsite_find(entry->callsite); 297 298 qht_insert(ht, e, hash, &existing); 299 if (unlikely(existing)) { 300 g_free(e); 301 e = existing; 302 } 303 return e; 304 } 305 306 static QSPEntry * 307 qsp_entry_find(struct qht *ht, const QSPEntry *entry, uint32_t hash) 308 { 309 QSPEntry *e; 310 311 e = qht_lookup(ht, entry, hash); 312 if (e == NULL) { 313 e = qsp_entry_create(ht, entry, hash); 314 } 315 return e; 316 } 317 318 /* 319 * Note: Entries are never removed, so callers do not have to be in an RCU 320 * read-side critical section. 321 */ 322 static QSPEntry *qsp_entry_get(const void *obj, const char *file, int line, 323 enum QSPType type) 324 { 325 QSPCallSite callsite = { 326 .obj = obj, 327 .file = file, 328 .line = line, 329 .type = type, 330 }; 331 QSPEntry orig; 332 uint32_t hash; 333 334 qsp_init(); 335 336 orig.thread_ptr = &qsp_thread; 337 orig.callsite = &callsite; 338 339 hash = qsp_entry_hash(&orig); 340 return qsp_entry_find(&qsp_ht, &orig, hash); 341 } 342 343 /* 344 * @e is in the global hash table; it is only written to by the current thread, 345 * so we write to it atomically (as in "write once") to prevent torn reads. 346 */ 347 static inline void do_qsp_entry_record(QSPEntry *e, int64_t delta, bool acq) 348 { 349 qatomic_set_u64(&e->ns, e->ns + delta); 350 if (acq) { 351 qatomic_set_u64(&e->n_acqs, e->n_acqs + 1); 352 } 353 } 354 355 static inline void qsp_entry_record(QSPEntry *e, int64_t delta) 356 { 357 do_qsp_entry_record(e, delta, true); 358 } 359 360 #define QSP_GEN_VOID(type_, qsp_t_, func_, impl_) \ 361 static void func_(type_ *obj, const char *file, int line) \ 362 { \ 363 QSPEntry *e; \ 364 int64_t t0, t1; \ 365 \ 366 t0 = get_clock(); \ 367 impl_(obj, file, line); \ 368 t1 = get_clock(); \ 369 \ 370 e = qsp_entry_get(obj, file, line, qsp_t_); \ 371 qsp_entry_record(e, t1 - t0); \ 372 } 373 374 #define QSP_GEN_RET1(type_, qsp_t_, func_, impl_) \ 375 static int func_(type_ *obj, const char *file, int line) \ 376 { \ 377 QSPEntry *e; \ 378 int64_t t0, t1; \ 379 int err; \ 380 \ 381 t0 = get_clock(); \ 382 err = impl_(obj, file, line); \ 383 t1 = get_clock(); \ 384 \ 385 e = qsp_entry_get(obj, file, line, qsp_t_); \ 386 do_qsp_entry_record(e, t1 - t0, !err); \ 387 return err; \ 388 } 389 390 QSP_GEN_VOID(QemuMutex, QSP_BQL_MUTEX, qsp_bql_mutex_lock, qemu_mutex_lock_impl) 391 QSP_GEN_VOID(QemuMutex, QSP_MUTEX, qsp_mutex_lock, qemu_mutex_lock_impl) 392 QSP_GEN_RET1(QemuMutex, QSP_MUTEX, qsp_mutex_trylock, qemu_mutex_trylock_impl) 393 394 QSP_GEN_VOID(QemuRecMutex, QSP_REC_MUTEX, qsp_rec_mutex_lock, 395 qemu_rec_mutex_lock_impl) 396 QSP_GEN_RET1(QemuRecMutex, QSP_REC_MUTEX, qsp_rec_mutex_trylock, 397 qemu_rec_mutex_trylock_impl) 398 399 #undef QSP_GEN_RET1 400 #undef QSP_GEN_VOID 401 402 static void 403 qsp_cond_wait(QemuCond *cond, QemuMutex *mutex, const char *file, int line) 404 { 405 QSPEntry *e; 406 int64_t t0, t1; 407 408 t0 = get_clock(); 409 qemu_cond_wait_impl(cond, mutex, file, line); 410 t1 = get_clock(); 411 412 e = qsp_entry_get(cond, file, line, QSP_CONDVAR); 413 qsp_entry_record(e, t1 - t0); 414 } 415 416 static bool 417 qsp_cond_timedwait(QemuCond *cond, QemuMutex *mutex, int ms, 418 const char *file, int line) 419 { 420 QSPEntry *e; 421 int64_t t0, t1; 422 bool ret; 423 424 t0 = get_clock(); 425 ret = qemu_cond_timedwait_impl(cond, mutex, ms, file, line); 426 t1 = get_clock(); 427 428 e = qsp_entry_get(cond, file, line, QSP_CONDVAR); 429 qsp_entry_record(e, t1 - t0); 430 return ret; 431 } 432 433 bool qsp_is_enabled(void) 434 { 435 return qatomic_read(&qemu_mutex_lock_func) == qsp_mutex_lock; 436 } 437 438 void qsp_enable(void) 439 { 440 qatomic_set(&qemu_mutex_lock_func, qsp_mutex_lock); 441 qatomic_set(&qemu_mutex_trylock_func, qsp_mutex_trylock); 442 qatomic_set(&qemu_bql_mutex_lock_func, qsp_bql_mutex_lock); 443 qatomic_set(&qemu_rec_mutex_lock_func, qsp_rec_mutex_lock); 444 qatomic_set(&qemu_rec_mutex_trylock_func, qsp_rec_mutex_trylock); 445 qatomic_set(&qemu_cond_wait_func, qsp_cond_wait); 446 qatomic_set(&qemu_cond_timedwait_func, qsp_cond_timedwait); 447 } 448 449 void qsp_disable(void) 450 { 451 qatomic_set(&qemu_mutex_lock_func, qemu_mutex_lock_impl); 452 qatomic_set(&qemu_mutex_trylock_func, qemu_mutex_trylock_impl); 453 qatomic_set(&qemu_bql_mutex_lock_func, qemu_mutex_lock_impl); 454 qatomic_set(&qemu_rec_mutex_lock_func, qemu_rec_mutex_lock_impl); 455 qatomic_set(&qemu_rec_mutex_trylock_func, qemu_rec_mutex_trylock_impl); 456 qatomic_set(&qemu_cond_wait_func, qemu_cond_wait_impl); 457 qatomic_set(&qemu_cond_timedwait_func, qemu_cond_timedwait_impl); 458 } 459 460 static gint qsp_tree_cmp(gconstpointer ap, gconstpointer bp, gpointer up) 461 { 462 const QSPEntry *a = ap; 463 const QSPEntry *b = bp; 464 enum QSPSortBy sort_by = *(enum QSPSortBy *)up; 465 const QSPCallSite *ca; 466 const QSPCallSite *cb; 467 468 switch (sort_by) { 469 case QSP_SORT_BY_TOTAL_WAIT_TIME: 470 if (a->ns > b->ns) { 471 return -1; 472 } else if (a->ns < b->ns) { 473 return 1; 474 } 475 break; 476 case QSP_SORT_BY_AVG_WAIT_TIME: 477 { 478 double avg_a = a->n_acqs ? a->ns / a->n_acqs : 0; 479 double avg_b = b->n_acqs ? b->ns / b->n_acqs : 0; 480 481 if (avg_a > avg_b) { 482 return -1; 483 } else if (avg_a < avg_b) { 484 return 1; 485 } 486 break; 487 } 488 default: 489 g_assert_not_reached(); 490 } 491 492 ca = a->callsite; 493 cb = b->callsite; 494 /* Break the tie with the object's address */ 495 if (ca->obj < cb->obj) { 496 return -1; 497 } else if (ca->obj > cb->obj) { 498 return 1; 499 } else { 500 int cmp; 501 502 /* same obj. Break the tie with the callsite's file */ 503 cmp = strcmp(ca->file, cb->file); 504 if (cmp) { 505 return cmp; 506 } 507 /* same callsite file. Break the tie with the callsite's line */ 508 g_assert(ca->line != cb->line); 509 if (ca->line < cb->line) { 510 return -1; 511 } else if (ca->line > cb->line) { 512 return 1; 513 } else { 514 /* break the tie with the callsite's type */ 515 return cb->type - ca->type; 516 } 517 } 518 } 519 520 static void qsp_sort(void *p, uint32_t h, void *userp) 521 { 522 QSPEntry *e = p; 523 GTree *tree = userp; 524 525 g_tree_insert(tree, e, NULL); 526 } 527 528 static void qsp_aggregate(void *p, uint32_t h, void *up) 529 { 530 struct qht *ht = up; 531 const QSPEntry *e = p; 532 QSPEntry *agg; 533 uint32_t hash; 534 535 hash = qsp_entry_no_thread_hash(e); 536 agg = qsp_entry_find(ht, e, hash); 537 /* 538 * The entry is in the global hash table; read from it atomically (as in 539 * "read once"). 540 */ 541 agg->ns += qatomic_read_u64(&e->ns); 542 agg->n_acqs += qatomic_read_u64(&e->n_acqs); 543 } 544 545 static void qsp_iter_diff(void *p, uint32_t hash, void *htp) 546 { 547 struct qht *ht = htp; 548 QSPEntry *old = p; 549 QSPEntry *new; 550 551 new = qht_lookup(ht, old, hash); 552 /* entries are never deleted, so we must have this one */ 553 g_assert(new != NULL); 554 /* our reading of the stats happened after the snapshot was taken */ 555 g_assert(new->n_acqs >= old->n_acqs); 556 g_assert(new->ns >= old->ns); 557 558 new->n_acqs -= old->n_acqs; 559 new->ns -= old->ns; 560 561 /* No point in reporting an empty entry */ 562 if (new->n_acqs == 0 && new->ns == 0) { 563 bool removed = qht_remove(ht, new, hash); 564 565 g_assert(removed); 566 g_free(new); 567 } 568 } 569 570 static void qsp_diff(struct qht *orig, struct qht *new) 571 { 572 qht_iter(orig, qsp_iter_diff, new); 573 } 574 575 static void qsp_iter_callsite_coalesce(void *p, uint32_t h, void *htp) 576 { 577 struct qht *ht = htp; 578 QSPEntry *old = p; 579 QSPEntry *e; 580 uint32_t hash; 581 582 hash = qsp_entry_no_thread_obj_hash(old); 583 e = qht_lookup(ht, old, hash); 584 if (e == NULL) { 585 e = qsp_entry_create(ht, old, hash); 586 e->n_objs = 1; 587 } else if (e->callsite->obj != old->callsite->obj) { 588 e->n_objs++; 589 } 590 e->ns += old->ns; 591 e->n_acqs += old->n_acqs; 592 } 593 594 static void qsp_ht_delete(void *p, uint32_t h, void *htp) 595 { 596 g_free(p); 597 } 598 599 static void qsp_mktree(GTree *tree, bool callsite_coalesce) 600 { 601 struct qht ht, coalesce_ht; 602 struct qht *htp; 603 604 /* 605 * First, see if there's a prior snapshot, so that we read the global hash 606 * table _after_ the snapshot has been created, which guarantees that 607 * the entries we'll read will be a superset of the snapshot's entries. 608 * 609 * We must remain in an RCU read-side critical section until we're done 610 * with the snapshot. 611 */ 612 WITH_RCU_READ_LOCK_GUARD() { 613 QSPSnapshot *snap = qatomic_rcu_read(&qsp_snapshot); 614 615 /* Aggregate all results from the global hash table into a local one */ 616 qht_init(&ht, qsp_entry_no_thread_cmp, QSP_INITIAL_SIZE, 617 QHT_MODE_AUTO_RESIZE | QHT_MODE_RAW_MUTEXES); 618 qht_iter(&qsp_ht, qsp_aggregate, &ht); 619 620 /* compute the difference wrt the snapshot, if any */ 621 if (snap) { 622 qsp_diff(&snap->ht, &ht); 623 } 624 } 625 626 htp = &ht; 627 if (callsite_coalesce) { 628 qht_init(&coalesce_ht, qsp_entry_no_thread_obj_cmp, QSP_INITIAL_SIZE, 629 QHT_MODE_AUTO_RESIZE | QHT_MODE_RAW_MUTEXES); 630 qht_iter(&ht, qsp_iter_callsite_coalesce, &coalesce_ht); 631 632 /* free the previous hash table, and point htp to coalesce_ht */ 633 qht_iter(&ht, qsp_ht_delete, NULL); 634 qht_destroy(&ht); 635 htp = &coalesce_ht; 636 } 637 638 /* sort the hash table elements by using a tree */ 639 qht_iter(htp, qsp_sort, tree); 640 641 /* free the hash table, but keep the elements (those are in the tree now) */ 642 qht_destroy(htp); 643 } 644 645 /* free string with g_free */ 646 static char *qsp_at(const QSPCallSite *callsite) 647 { 648 GString *s = g_string_new(NULL); 649 const char *shortened; 650 651 /* remove the absolute path to qemu */ 652 if (unlikely(strlen(callsite->file) < qsp_qemu_path_len)) { 653 shortened = callsite->file; 654 } else { 655 shortened = callsite->file + qsp_qemu_path_len; 656 } 657 g_string_append_printf(s, "%s:%u", shortened, callsite->line); 658 return g_string_free(s, FALSE); 659 } 660 661 struct QSPReportEntry { 662 const void *obj; 663 char *callsite_at; 664 const char *typename; 665 double time_s; 666 double ns_avg; 667 uint64_t n_acqs; 668 unsigned int n_objs; 669 }; 670 typedef struct QSPReportEntry QSPReportEntry; 671 672 struct QSPReport { 673 QSPReportEntry *entries; 674 size_t n_entries; 675 size_t max_n_entries; 676 }; 677 typedef struct QSPReport QSPReport; 678 679 static gboolean qsp_tree_report(gpointer key, gpointer value, gpointer udata) 680 { 681 const QSPEntry *e = key; 682 QSPReport *report = udata; 683 QSPReportEntry *entry; 684 685 if (report->n_entries == report->max_n_entries) { 686 return TRUE; 687 } 688 entry = &report->entries[report->n_entries]; 689 report->n_entries++; 690 691 entry->obj = e->callsite->obj; 692 entry->n_objs = e->n_objs; 693 entry->callsite_at = qsp_at(e->callsite); 694 entry->typename = qsp_typenames[e->callsite->type]; 695 entry->time_s = e->ns * 1e-9; 696 entry->n_acqs = e->n_acqs; 697 entry->ns_avg = e->n_acqs ? e->ns / e->n_acqs : 0; 698 return FALSE; 699 } 700 701 static void pr_report(const QSPReport *rep) 702 { 703 char *dashes; 704 size_t max_len = 0; 705 int callsite_len = 0; 706 int callsite_rspace; 707 int n_dashes; 708 size_t i; 709 710 /* find out the maximum length of all 'callsite' fields */ 711 for (i = 0; i < rep->n_entries; i++) { 712 const QSPReportEntry *e = &rep->entries[i]; 713 size_t len = strlen(e->callsite_at); 714 715 if (len > max_len) { 716 max_len = len; 717 } 718 } 719 720 callsite_len = MAX(max_len, strlen("Call site")); 721 /* white space to leave to the right of "Call site" */ 722 callsite_rspace = callsite_len - strlen("Call site"); 723 724 qemu_printf("Type Object Call site%*s Wait Time (s) " 725 " Count Average (us)\n", callsite_rspace, ""); 726 727 /* build a horizontal rule with dashes */ 728 n_dashes = 79 + callsite_rspace; 729 dashes = g_malloc(n_dashes + 1); 730 memset(dashes, '-', n_dashes); 731 dashes[n_dashes] = '\0'; 732 qemu_printf("%s\n", dashes); 733 734 for (i = 0; i < rep->n_entries; i++) { 735 const QSPReportEntry *e = &rep->entries[i]; 736 GString *s = g_string_new(NULL); 737 738 g_string_append_printf(s, "%-9s ", e->typename); 739 if (e->n_objs > 1) { 740 g_string_append_printf(s, "[%12u]", e->n_objs); 741 } else { 742 g_string_append_printf(s, "%14p", e->obj); 743 } 744 g_string_append_printf(s, " %s%*s %13.5f %12" PRIu64 " %12.2f\n", 745 e->callsite_at, 746 callsite_len - (int)strlen(e->callsite_at), "", 747 e->time_s, e->n_acqs, e->ns_avg * 1e-3); 748 qemu_printf("%s", s->str); 749 g_string_free(s, TRUE); 750 } 751 752 qemu_printf("%s\n", dashes); 753 g_free(dashes); 754 } 755 756 static void report_destroy(QSPReport *rep) 757 { 758 size_t i; 759 760 for (i = 0; i < rep->n_entries; i++) { 761 QSPReportEntry *e = &rep->entries[i]; 762 763 g_free(e->callsite_at); 764 } 765 g_free(rep->entries); 766 } 767 768 void qsp_report(size_t max, enum QSPSortBy sort_by, 769 bool callsite_coalesce) 770 { 771 GTree *tree = g_tree_new_full(qsp_tree_cmp, &sort_by, g_free, NULL); 772 QSPReport rep; 773 774 qsp_init(); 775 776 rep.entries = g_new0(QSPReportEntry, max); 777 rep.n_entries = 0; 778 rep.max_n_entries = max; 779 780 qsp_mktree(tree, callsite_coalesce); 781 g_tree_foreach(tree, qsp_tree_report, &rep); 782 g_tree_destroy(tree); 783 784 pr_report(&rep); 785 report_destroy(&rep); 786 } 787 788 static void qsp_snapshot_destroy(QSPSnapshot *snap) 789 { 790 qht_iter(&snap->ht, qsp_ht_delete, NULL); 791 qht_destroy(&snap->ht); 792 g_free(snap); 793 } 794 795 void qsp_reset(void) 796 { 797 QSPSnapshot *new = g_new(QSPSnapshot, 1); 798 QSPSnapshot *old; 799 800 qsp_init(); 801 802 qht_init(&new->ht, qsp_entry_cmp, QSP_INITIAL_SIZE, 803 QHT_MODE_AUTO_RESIZE | QHT_MODE_RAW_MUTEXES); 804 805 /* take a snapshot of the current state */ 806 qht_iter(&qsp_ht, qsp_aggregate, &new->ht); 807 808 /* replace the previous snapshot, if any */ 809 old = qatomic_xchg(&qsp_snapshot, new); 810 if (old) { 811 call_rcu(old, qsp_snapshot_destroy, rcu); 812 } 813 } 814