1 /* 2 * Copyright 2008-2011, Ingo Weinhold, ingo_weinhold@gmx.de. 3 * Copyright 2008-2009, Axel Dörfler, axeld@pinc-software.de. 4 * Copyright 2012, Rene Gollent, rene@gollent.com. 5 * Distributed under the terms of the MIT License. 6 */ 7 8 9 #include <tracing.h> 10 11 #include <stdlib.h> 12 13 #include <algorithm> 14 15 #include <arch/debug.h> 16 #include <debug.h> 17 #include <debug_heap.h> 18 #include <elf.h> 19 #include <int.h> 20 #include <kernel.h> 21 #include <team.h> 22 #include <thread.h> 23 #include <util/AutoLock.h> 24 #include <vm/vm.h> 25 26 27 #if ENABLE_TRACING 28 29 //#define TRACE_TRACING 30 #ifdef TRACE_TRACING 31 # define TRACE(x) dprintf_no_syslog x 32 #else 33 # define TRACE(x) ; 34 #endif 35 36 37 enum { 38 WRAP_ENTRY = 0x01, 39 ENTRY_INITIALIZED = 0x02, 40 BUFFER_ENTRY = 0x04, 41 FILTER_MATCH = 0x08, 42 INVALID_ENTRY = 0x10, 43 CHECK_ENTRY = 0x20, 44 }; 45 46 47 static const size_t kTraceOutputBufferSize = 10240; 48 static const size_t kBufferSize = MAX_TRACE_SIZE / sizeof(trace_entry); 49 50 static const uint32 kMaxRecoveringErrorCount = 100; 51 static const addr_t kMetaDataBaseAddress = 32 * 1024 * 1024; 52 static const addr_t kMetaDataBaseEndAddress = 128 * 1024 * 1024; 53 static const addr_t kMetaDataAddressIncrement = 8 * 1024 * 1024; 54 static const uint32 kMetaDataMagic1 = 'Vali'; 55 static const uint32 kMetaDataMagic2 = 'dTra'; 56 static const uint32 kMetaDataMagic3 = 'cing'; 57 58 // the maximum we can address with the trace_entry::[previous_]size fields 59 static const size_t kMaxTracingEntryByteSize 60 = ((1 << 13) - 1) * sizeof(trace_entry); 61 62 63 struct TraceOutputPrint { 64 TraceOutputPrint(TraceOutput& output) 65 : 66 fOutput(output) 67 { 68 } 69 70 void operator()(const char* format,...) const 71 { 72 va_list args; 73 va_start(args, format); 74 fOutput.PrintArgs(format, args); 75 va_end(args); 76 } 77 78 private: 79 TraceOutput& fOutput; 80 }; 81 82 83 class TracingMetaData { 84 public: 85 static status_t Create(TracingMetaData*& _metaData); 86 87 inline bool Lock(); 88 inline void Unlock(); 89 90 inline trace_entry* FirstEntry() const; 91 inline trace_entry* AfterLastEntry() const; 92 93 inline uint32 Entries() const; 94 inline uint32 EntriesEver() const; 95 96 inline void IncrementEntriesEver(); 97 98 inline char* TraceOutputBuffer() const; 99 100 trace_entry* NextEntry(trace_entry* entry); 101 trace_entry* PreviousEntry(trace_entry* entry); 102 103 trace_entry* AllocateEntry(size_t size, uint16 flags); 104 105 bool IsInBuffer(void* address, size_t size); 106 107 private: 108 bool _FreeFirstEntry(); 109 bool _MakeSpace(size_t needed); 110 111 static status_t _CreateMetaDataArea(bool findPrevious, 112 area_id& _area, 113 TracingMetaData*& _metaData); 114 bool _InitPreviousTracingData(); 115 116 private: 117 uint32 fMagic1; 118 trace_entry* fBuffer; 119 trace_entry* fFirstEntry; 120 trace_entry* fAfterLastEntry; 121 uint32 fEntries; 122 uint32 fMagic2; 123 uint32 fEntriesEver; 124 spinlock fLock; 125 char* fTraceOutputBuffer; 126 phys_addr_t fPhysicalAddress; 127 uint32 fMagic3; 128 }; 129 130 static TracingMetaData sFallbackTracingMetaData; 131 static TracingMetaData* sTracingMetaData = &sFallbackTracingMetaData; 132 static bool sTracingDataRecovered = false; 133 134 135 // #pragma mark - 136 137 138 template<typename Print> 139 static void 140 print_stack_trace(struct tracing_stack_trace* stackTrace, 141 const Print& print) 142 { 143 if (stackTrace == NULL || stackTrace->depth <= 0) 144 return; 145 146 static const size_t kBufferSize = 256; 147 char* buffer = (char*)debug_malloc(kBufferSize); 148 149 for (int32 i = 0; i < stackTrace->depth; i++) { 150 addr_t address = stackTrace->return_addresses[i]; 151 152 const char* symbol; 153 const char* demangledName = NULL; 154 const char* imageName; 155 bool exactMatch; 156 addr_t baseAddress; 157 158 if (elf_debug_lookup_symbol_address(address, &baseAddress, &symbol, 159 &imageName, &exactMatch) == B_OK) { 160 161 if (buffer != NULL) { 162 bool isObjectMethod; 163 demangledName = debug_demangle_symbol(symbol, buffer, 164 kBufferSize, &isObjectMethod); 165 } 166 167 print(" %p %s + 0x%lx (%s)%s\n", (void*)address, 168 demangledName != NULL ? demangledName : symbol, 169 address - baseAddress, imageName, 170 exactMatch ? "" : " (nearest)"); 171 } else 172 print(" %p\n", (void*)address); 173 } 174 175 if (buffer != NULL) 176 debug_free(buffer); 177 } 178 179 180 // #pragma mark - TracingMetaData 181 182 183 bool 184 TracingMetaData::Lock() 185 { 186 acquire_spinlock(&fLock); 187 return true; 188 } 189 190 191 void 192 TracingMetaData::Unlock() 193 { 194 release_spinlock(&fLock); 195 } 196 197 198 trace_entry* 199 TracingMetaData::FirstEntry() const 200 { 201 return fFirstEntry; 202 } 203 204 205 trace_entry* 206 TracingMetaData::AfterLastEntry() const 207 { 208 return fAfterLastEntry; 209 } 210 211 212 uint32 213 TracingMetaData::Entries() const 214 { 215 return fEntries; 216 } 217 218 219 uint32 220 TracingMetaData::EntriesEver() const 221 { 222 return fEntriesEver; 223 } 224 225 226 void 227 TracingMetaData::IncrementEntriesEver() 228 { 229 fEntriesEver++; 230 // NOTE: Race condition on SMP machines! We should use atomic_add(), 231 // though that costs some performance and the information is for 232 // informational purpose anyway. 233 } 234 235 236 char* 237 TracingMetaData::TraceOutputBuffer() const 238 { 239 return fTraceOutputBuffer; 240 } 241 242 243 trace_entry* 244 TracingMetaData::NextEntry(trace_entry* entry) 245 { 246 entry += entry->size; 247 if ((entry->flags & WRAP_ENTRY) != 0) 248 entry = fBuffer; 249 250 if (entry == fAfterLastEntry) 251 return NULL; 252 253 return entry; 254 } 255 256 257 trace_entry* 258 TracingMetaData::PreviousEntry(trace_entry* entry) 259 { 260 if (entry == fFirstEntry) 261 return NULL; 262 263 if (entry == fBuffer) { 264 // beginning of buffer -- previous entry is a wrap entry 265 entry = fBuffer + kBufferSize - entry->previous_size; 266 } 267 268 return entry - entry->previous_size; 269 } 270 271 272 trace_entry* 273 TracingMetaData::AllocateEntry(size_t size, uint16 flags) 274 { 275 if (fAfterLastEntry == NULL || size == 0 276 || size >= kMaxTracingEntryByteSize) { 277 return NULL; 278 } 279 280 InterruptsSpinLocker _(fLock); 281 282 size = (size + 3) >> 2; 283 // 4 byte aligned, don't store the lower 2 bits 284 285 TRACE(("AllocateEntry(%lu), start %p, end %p, buffer %p\n", size * 4, 286 fFirstEntry, fAfterLastEntry, fBuffer)); 287 288 if (!_MakeSpace(size)) 289 return NULL; 290 291 trace_entry* entry = fAfterLastEntry; 292 entry->size = size; 293 entry->flags = flags; 294 fAfterLastEntry += size; 295 fAfterLastEntry->previous_size = size; 296 297 if (!(flags & BUFFER_ENTRY)) 298 fEntries++; 299 300 TRACE((" entry: %p, end %p, start %p, entries %ld\n", entry, 301 fAfterLastEntry, fFirstEntry, fEntries)); 302 303 return entry; 304 } 305 306 307 bool 308 TracingMetaData::IsInBuffer(void* address, size_t size) 309 { 310 if (fEntries == 0) 311 return false; 312 313 addr_t start = (addr_t)address; 314 addr_t end = start + size; 315 316 if (start < (addr_t)fBuffer || end > (addr_t)(fBuffer + kBufferSize)) 317 return false; 318 319 if (fFirstEntry > fAfterLastEntry) 320 return start >= (addr_t)fFirstEntry || end <= (addr_t)fAfterLastEntry; 321 322 return start >= (addr_t)fFirstEntry && end <= (addr_t)fAfterLastEntry; 323 } 324 325 326 bool 327 TracingMetaData::_FreeFirstEntry() 328 { 329 TRACE((" skip start %p, %lu*4 bytes\n", fFirstEntry, fFirstEntry->size)); 330 331 trace_entry* newFirst = NextEntry(fFirstEntry); 332 333 if (fFirstEntry->flags & BUFFER_ENTRY) { 334 // a buffer entry -- just skip it 335 } else if (fFirstEntry->flags & ENTRY_INITIALIZED) { 336 // Fully initialized TraceEntry: We could destroy it, but don't do so 337 // for sake of robustness. The destructors of tracing entry classes 338 // should be empty anyway. 339 fEntries--; 340 } else { 341 // Not fully initialized TraceEntry. We can't free it, since 342 // then it's constructor might still write into the memory and 343 // overwrite data of the entry we're going to allocate. 344 // We can't do anything until this entry can be discarded. 345 return false; 346 } 347 348 if (newFirst == NULL) { 349 // everything is freed -- practically this can't happen, if 350 // the buffer is large enough to hold three max-sized entries 351 fFirstEntry = fAfterLastEntry = fBuffer; 352 TRACE(("_FreeFirstEntry(): all entries freed!\n")); 353 } else 354 fFirstEntry = newFirst; 355 356 return true; 357 } 358 359 360 /*! Makes sure we have needed * 4 bytes of memory at fAfterLastEntry. 361 Returns \c false, if unable to free that much. 362 */ 363 bool 364 TracingMetaData::_MakeSpace(size_t needed) 365 { 366 // we need space for fAfterLastEntry, too (in case we need to wrap around 367 // later) 368 needed++; 369 370 // If there's not enough space (free or occupied) after fAfterLastEntry, 371 // we free all entries in that region and wrap around. 372 if (fAfterLastEntry + needed > fBuffer + kBufferSize) { 373 TRACE(("_MakeSpace(%lu), wrapping around: after last: %p\n", needed, 374 fAfterLastEntry)); 375 376 // Free all entries after fAfterLastEntry and one more at the beginning 377 // of the buffer. 378 while (fFirstEntry > fAfterLastEntry) { 379 if (!_FreeFirstEntry()) 380 return false; 381 } 382 if (fAfterLastEntry != fBuffer && !_FreeFirstEntry()) 383 return false; 384 385 // just in case _FreeFirstEntry() freed the very last existing entry 386 if (fAfterLastEntry == fBuffer) 387 return true; 388 389 // mark as wrap entry and actually wrap around 390 trace_entry* wrapEntry = fAfterLastEntry; 391 wrapEntry->size = 0; 392 wrapEntry->flags = WRAP_ENTRY; 393 fAfterLastEntry = fBuffer; 394 fAfterLastEntry->previous_size = fBuffer + kBufferSize - wrapEntry; 395 } 396 397 if (fFirstEntry <= fAfterLastEntry) { 398 // buffer is empty or the space after fAfterLastEntry is unoccupied 399 return true; 400 } 401 402 // free the first entries, until there's enough space 403 size_t space = fFirstEntry - fAfterLastEntry; 404 405 if (space < needed) { 406 TRACE(("_MakeSpace(%lu), left %ld\n", needed, space)); 407 } 408 409 while (space < needed) { 410 space += fFirstEntry->size; 411 412 if (!_FreeFirstEntry()) 413 return false; 414 } 415 416 TRACE((" out: start %p, entries %ld\n", fFirstEntry, fEntries)); 417 418 return true; 419 } 420 421 422 /*static*/ status_t 423 TracingMetaData::Create(TracingMetaData*& _metaData) 424 { 425 // search meta data in memory (from previous session) 426 area_id area; 427 TracingMetaData* metaData; 428 status_t error = _CreateMetaDataArea(true, area, metaData); 429 if (error == B_OK) { 430 if (metaData->_InitPreviousTracingData()) { 431 _metaData = metaData; 432 return B_OK; 433 } 434 435 dprintf("Found previous tracing meta data, but failed to init.\n"); 436 437 // invalidate the meta data 438 metaData->fMagic1 = 0; 439 metaData->fMagic2 = 0; 440 metaData->fMagic3 = 0; 441 delete_area(area); 442 } else 443 dprintf("No previous tracing meta data found.\n"); 444 445 // no previous tracing data found -- create new one 446 error = _CreateMetaDataArea(false, area, metaData); 447 if (error != B_OK) 448 return error; 449 450 virtual_address_restrictions virtualRestrictions = {}; 451 virtualRestrictions.address_specification = B_ANY_KERNEL_ADDRESS; 452 physical_address_restrictions physicalRestrictions = {}; 453 area = create_area_etc(B_SYSTEM_TEAM, "tracing log", 454 kTraceOutputBufferSize + MAX_TRACE_SIZE, B_CONTIGUOUS, 455 B_KERNEL_READ_AREA | B_KERNEL_WRITE_AREA, CREATE_AREA_DONT_WAIT, 0, 456 &virtualRestrictions, &physicalRestrictions, 457 (void**)&metaData->fTraceOutputBuffer); 458 if (area < 0) 459 return area; 460 461 // get the physical address 462 physical_entry physicalEntry; 463 if (get_memory_map(metaData->fTraceOutputBuffer, B_PAGE_SIZE, 464 &physicalEntry, 1) == B_OK) { 465 metaData->fPhysicalAddress = physicalEntry.address; 466 } else { 467 dprintf("TracingMetaData::Create(): failed to get physical address " 468 "of tracing buffer\n"); 469 metaData->fPhysicalAddress = 0; 470 } 471 472 metaData->fBuffer = (trace_entry*)(metaData->fTraceOutputBuffer 473 + kTraceOutputBufferSize); 474 metaData->fFirstEntry = metaData->fBuffer; 475 metaData->fAfterLastEntry = metaData->fBuffer; 476 477 metaData->fEntries = 0; 478 metaData->fEntriesEver = 0; 479 B_INITIALIZE_SPINLOCK(&metaData->fLock); 480 481 metaData->fMagic1 = kMetaDataMagic1; 482 metaData->fMagic2 = kMetaDataMagic2; 483 metaData->fMagic3 = kMetaDataMagic3; 484 485 _metaData = metaData; 486 return B_OK; 487 } 488 489 490 /*static*/ status_t 491 TracingMetaData::_CreateMetaDataArea(bool findPrevious, area_id& _area, 492 TracingMetaData*& _metaData) 493 { 494 // search meta data in memory (from previous session) 495 TracingMetaData* metaData; 496 phys_addr_t metaDataAddress = kMetaDataBaseAddress; 497 for (; metaDataAddress <= kMetaDataBaseEndAddress; 498 metaDataAddress += kMetaDataAddressIncrement) { 499 virtual_address_restrictions virtualRestrictions = {}; 500 virtualRestrictions.address_specification = B_ANY_KERNEL_ADDRESS; 501 physical_address_restrictions physicalRestrictions = {}; 502 physicalRestrictions.low_address = metaDataAddress; 503 physicalRestrictions.high_address = metaDataAddress + B_PAGE_SIZE; 504 area_id area = create_area_etc(B_SYSTEM_TEAM, "tracing metadata", 505 B_PAGE_SIZE, B_FULL_LOCK, B_KERNEL_READ_AREA | B_KERNEL_WRITE_AREA, 506 CREATE_AREA_DONT_CLEAR, 0, &virtualRestrictions, 507 &physicalRestrictions, (void**)&metaData); 508 if (area < 0) 509 continue; 510 511 if (!findPrevious) { 512 _area = area; 513 _metaData = metaData; 514 return B_OK; 515 } 516 517 if (metaData->fMagic1 == kMetaDataMagic1 518 && metaData->fMagic2 == kMetaDataMagic2 519 && metaData->fMagic3 == kMetaDataMagic3) { 520 _area = area; 521 _metaData = metaData; 522 return B_OK; 523 } 524 525 delete_area(area); 526 } 527 528 if (findPrevious) 529 return B_ENTRY_NOT_FOUND; 530 531 // We could allocate any of the standard locations. Instead of failing 532 // entirely, we use the static meta data. The tracing buffer won't be 533 // reattachable in the next session, but at least we can use it in this 534 // session. 535 _metaData = &sFallbackTracingMetaData; 536 return B_OK; 537 } 538 539 540 bool 541 TracingMetaData::_InitPreviousTracingData() 542 { 543 // TODO: ATM re-attaching the previous tracing buffer doesn't work very 544 // well. The entries should be checked more thoroughly for validity -- e.g. 545 // the pointers to the entries' vtable pointers could be invalid, which can 546 // make the "traced" command quite unusable. The validity of the entries 547 // could be checked in a safe environment (i.e. with a fault handler) with 548 // typeid() and call of a virtual function. 549 return false; 550 551 addr_t bufferStart 552 = (addr_t)fTraceOutputBuffer + kTraceOutputBufferSize; 553 addr_t bufferEnd = bufferStart + MAX_TRACE_SIZE; 554 555 if (bufferStart > bufferEnd || (addr_t)fBuffer != bufferStart 556 || (addr_t)fFirstEntry % sizeof(trace_entry) != 0 557 || (addr_t)fFirstEntry < bufferStart 558 || (addr_t)fFirstEntry + sizeof(trace_entry) >= bufferEnd 559 || (addr_t)fAfterLastEntry % sizeof(trace_entry) != 0 560 || (addr_t)fAfterLastEntry < bufferStart 561 || (addr_t)fAfterLastEntry > bufferEnd 562 || fPhysicalAddress == 0) { 563 dprintf("Failed to init tracing meta data: Sanity checks " 564 "failed.\n"); 565 return false; 566 } 567 568 // re-map the previous tracing buffer 569 virtual_address_restrictions virtualRestrictions = {}; 570 virtualRestrictions.address = fTraceOutputBuffer; 571 virtualRestrictions.address_specification = B_EXACT_ADDRESS; 572 physical_address_restrictions physicalRestrictions = {}; 573 physicalRestrictions.low_address = fPhysicalAddress; 574 physicalRestrictions.high_address = fPhysicalAddress 575 + ROUNDUP(kTraceOutputBufferSize + MAX_TRACE_SIZE, B_PAGE_SIZE); 576 area_id area = create_area_etc(B_SYSTEM_TEAM, "tracing log", 577 kTraceOutputBufferSize + MAX_TRACE_SIZE, B_CONTIGUOUS, 578 B_KERNEL_READ_AREA | B_KERNEL_WRITE_AREA, CREATE_AREA_DONT_CLEAR, 0, 579 &virtualRestrictions, &physicalRestrictions, NULL); 580 if (area < 0) { 581 dprintf("Failed to init tracing meta data: Mapping tracing log " 582 "buffer failed: %s\n", strerror(area)); 583 return false; 584 } 585 586 dprintf("ktrace: Remapped tracing buffer at %p, size: %" B_PRIuSIZE "\n", 587 fTraceOutputBuffer, kTraceOutputBufferSize + MAX_TRACE_SIZE); 588 589 // verify/repair the tracing entry list 590 uint32 errorCount = 0; 591 uint32 entryCount = 0; 592 uint32 nonBufferEntryCount = 0; 593 uint32 previousEntrySize = 0; 594 trace_entry* entry = fFirstEntry; 595 while (errorCount <= kMaxRecoveringErrorCount) { 596 // check previous entry size 597 if (entry->previous_size != previousEntrySize) { 598 if (entry != fFirstEntry) { 599 dprintf("ktrace recovering: entry %p: fixing previous_size " 600 "size: %" B_PRIu32 " (should be %" B_PRIu32 ")\n", entry, 601 entry->previous_size, previousEntrySize); 602 errorCount++; 603 } 604 entry->previous_size = previousEntrySize; 605 } 606 607 if (entry == fAfterLastEntry) 608 break; 609 610 // check size field 611 if ((entry->flags & WRAP_ENTRY) == 0 && entry->size == 0) { 612 dprintf("ktrace recovering: entry %p: non-wrap entry size is 0\n", 613 entry); 614 errorCount++; 615 fAfterLastEntry = entry; 616 break; 617 } 618 619 if (entry->size > uint32(fBuffer + kBufferSize - entry)) { 620 dprintf("ktrace recovering: entry %p: size too big: %" B_PRIu32 "\n", 621 entry, entry->size); 622 errorCount++; 623 fAfterLastEntry = entry; 624 break; 625 } 626 627 if (entry < fAfterLastEntry && entry + entry->size > fAfterLastEntry) { 628 dprintf("ktrace recovering: entry %p: entry crosses " 629 "fAfterLastEntry (%p)\n", entry, fAfterLastEntry); 630 errorCount++; 631 fAfterLastEntry = entry; 632 break; 633 } 634 635 // check for wrap entry 636 if ((entry->flags & WRAP_ENTRY) != 0) { 637 if ((uint32)(fBuffer + kBufferSize - entry) 638 > kMaxTracingEntryByteSize / sizeof(trace_entry)) { 639 dprintf("ktrace recovering: entry %p: wrap entry at invalid " 640 "buffer location\n", entry); 641 errorCount++; 642 } 643 644 if (entry->size != 0) { 645 dprintf("ktrace recovering: entry %p: invalid wrap entry " 646 "size: %" B_PRIu32 "\n", entry, entry->size); 647 errorCount++; 648 entry->size = 0; 649 } 650 651 previousEntrySize = fBuffer + kBufferSize - entry; 652 entry = fBuffer; 653 continue; 654 } 655 656 if ((entry->flags & BUFFER_ENTRY) == 0) { 657 entry->flags |= CHECK_ENTRY; 658 nonBufferEntryCount++; 659 } 660 661 entryCount++; 662 previousEntrySize = entry->size; 663 664 entry += entry->size; 665 } 666 667 if (errorCount > kMaxRecoveringErrorCount) { 668 dprintf("ktrace recovering: Too many errors.\n"); 669 fAfterLastEntry = entry; 670 fAfterLastEntry->previous_size = previousEntrySize; 671 } 672 673 dprintf("ktrace recovering: Recovered %" B_PRIu32 " entries + %" B_PRIu32 674 " buffer entries from previous session. Expected %" B_PRIu32 675 " entries.\n", nonBufferEntryCount, entryCount - nonBufferEntryCount, 676 fEntries); 677 fEntries = nonBufferEntryCount; 678 679 B_INITIALIZE_SPINLOCK(&fLock); 680 681 // TODO: Actually check the entries! Do that when first accessing the 682 // tracing buffer from the kernel debugger (when sTracingDataRecovered is 683 // true). 684 sTracingDataRecovered = true; 685 return true; 686 } 687 688 689 #endif // ENABLE_TRACING 690 691 692 // #pragma mark - 693 694 695 TraceOutput::TraceOutput(char* buffer, size_t bufferSize, uint32 flags) 696 : fBuffer(buffer), 697 fCapacity(bufferSize), 698 fFlags(flags) 699 { 700 Clear(); 701 } 702 703 704 void 705 TraceOutput::Clear() 706 { 707 if (fCapacity > 0) 708 fBuffer[0] = '\0'; 709 fSize = 0; 710 } 711 712 713 void 714 TraceOutput::PrintArgs(const char* format, va_list args) 715 { 716 #if ENABLE_TRACING 717 if (IsFull()) 718 return; 719 720 size_t length = vsnprintf(fBuffer + fSize, fCapacity - fSize, format, args); 721 fSize += std::min(length, fCapacity - fSize - 1); 722 #endif 723 } 724 725 726 void 727 TraceOutput::PrintStackTrace(tracing_stack_trace* stackTrace) 728 { 729 #if ENABLE_TRACING 730 print_stack_trace(stackTrace, TraceOutputPrint(*this)); 731 #endif 732 } 733 734 735 void 736 TraceOutput::SetLastEntryTime(bigtime_t time) 737 { 738 fLastEntryTime = time; 739 } 740 741 742 bigtime_t 743 TraceOutput::LastEntryTime() const 744 { 745 return fLastEntryTime; 746 } 747 748 749 // #pragma mark - 750 751 752 TraceEntry::TraceEntry() 753 { 754 } 755 756 757 TraceEntry::~TraceEntry() 758 { 759 } 760 761 762 void 763 TraceEntry::Dump(TraceOutput& out) 764 { 765 #if ENABLE_TRACING 766 // to be overridden by subclasses 767 out.Print("ENTRY %p", this); 768 #endif 769 } 770 771 772 void 773 TraceEntry::DumpStackTrace(TraceOutput& out) 774 { 775 } 776 777 778 void 779 TraceEntry::Initialized() 780 { 781 #if ENABLE_TRACING 782 ToTraceEntry()->flags |= ENTRY_INITIALIZED; 783 sTracingMetaData->IncrementEntriesEver(); 784 #endif 785 } 786 787 788 void* 789 TraceEntry::operator new(size_t size, const std::nothrow_t&) throw() 790 { 791 #if ENABLE_TRACING 792 trace_entry* entry = sTracingMetaData->AllocateEntry( 793 size + sizeof(trace_entry), 0); 794 return entry != NULL ? entry + 1 : NULL; 795 #endif 796 return NULL; 797 } 798 799 800 // #pragma mark - 801 802 803 AbstractTraceEntry::~AbstractTraceEntry() 804 { 805 } 806 807 808 void 809 AbstractTraceEntry::Dump(TraceOutput& out) 810 { 811 bigtime_t time = (out.Flags() & TRACE_OUTPUT_DIFF_TIME) 812 ? fTime - out.LastEntryTime() 813 : fTime; 814 815 if (out.Flags() & TRACE_OUTPUT_TEAM_ID) { 816 out.Print("[%6" B_PRId32 ":%6" B_PRId32 "] %10" B_PRId64 ": ", fThread, 817 fTeam, time); 818 } else 819 out.Print("[%6" B_PRId32 "] %10" B_PRId64 ": ", fThread, time); 820 821 AddDump(out); 822 823 out.SetLastEntryTime(fTime); 824 } 825 826 827 void 828 AbstractTraceEntry::AddDump(TraceOutput& out) 829 { 830 } 831 832 833 void 834 AbstractTraceEntry::_Init() 835 { 836 Thread* thread = thread_get_current_thread(); 837 if (thread != NULL) { 838 fThread = thread->id; 839 if (thread->team) 840 fTeam = thread->team->id; 841 } 842 fTime = system_time(); 843 } 844 845 846 // #pragma mark - AbstractTraceEntryWithStackTrace 847 848 849 850 AbstractTraceEntryWithStackTrace::AbstractTraceEntryWithStackTrace( 851 size_t stackTraceDepth, size_t skipFrames, bool kernelOnly) 852 { 853 fStackTrace = capture_tracing_stack_trace(stackTraceDepth, skipFrames + 1, 854 kernelOnly); 855 } 856 857 858 void 859 AbstractTraceEntryWithStackTrace::DumpStackTrace(TraceOutput& out) 860 { 861 out.PrintStackTrace(fStackTrace); 862 } 863 864 865 // #pragma mark - 866 867 868 #if ENABLE_TRACING 869 870 class KernelTraceEntry : public AbstractTraceEntry { 871 public: 872 KernelTraceEntry(const char* message) 873 { 874 fMessage = alloc_tracing_buffer_strcpy(message, 256, false); 875 876 #if KTRACE_PRINTF_STACK_TRACE 877 fStackTrace = capture_tracing_stack_trace( 878 KTRACE_PRINTF_STACK_TRACE, 1, false); 879 #endif 880 Initialized(); 881 } 882 883 virtual void AddDump(TraceOutput& out) 884 { 885 out.Print("kern: %s", fMessage); 886 } 887 888 #if KTRACE_PRINTF_STACK_TRACE 889 virtual void DumpStackTrace(TraceOutput& out) 890 { 891 out.PrintStackTrace(fStackTrace); 892 } 893 #endif 894 895 private: 896 char* fMessage; 897 #if KTRACE_PRINTF_STACK_TRACE 898 tracing_stack_trace* fStackTrace; 899 #endif 900 }; 901 902 903 class UserTraceEntry : public AbstractTraceEntry { 904 public: 905 UserTraceEntry(const char* message) 906 { 907 fMessage = alloc_tracing_buffer_strcpy(message, 256, true); 908 909 #if KTRACE_PRINTF_STACK_TRACE 910 fStackTrace = capture_tracing_stack_trace( 911 KTRACE_PRINTF_STACK_TRACE, 1, false); 912 #endif 913 Initialized(); 914 } 915 916 virtual void AddDump(TraceOutput& out) 917 { 918 out.Print("user: %s", fMessage); 919 } 920 921 #if KTRACE_PRINTF_STACK_TRACE 922 virtual void DumpStackTrace(TraceOutput& out) 923 { 924 out.PrintStackTrace(fStackTrace); 925 } 926 #endif 927 928 private: 929 char* fMessage; 930 #if KTRACE_PRINTF_STACK_TRACE 931 tracing_stack_trace* fStackTrace; 932 #endif 933 }; 934 935 936 class TracingLogStartEntry : public AbstractTraceEntry { 937 public: 938 TracingLogStartEntry() 939 { 940 Initialized(); 941 } 942 943 virtual void AddDump(TraceOutput& out) 944 { 945 out.Print("ktrace start"); 946 } 947 }; 948 949 #endif // ENABLE_TRACING 950 951 952 // #pragma mark - trace filters 953 954 955 TraceFilter::~TraceFilter() 956 { 957 } 958 959 960 bool 961 TraceFilter::Filter(const TraceEntry* entry, LazyTraceOutput& out) 962 { 963 return false; 964 } 965 966 967 968 class ThreadTraceFilter : public TraceFilter { 969 public: 970 virtual bool Filter(const TraceEntry* _entry, LazyTraceOutput& out) 971 { 972 const AbstractTraceEntry* entry 973 = dynamic_cast<const AbstractTraceEntry*>(_entry); 974 return (entry != NULL && entry->ThreadID() == fThread); 975 } 976 }; 977 978 979 class TeamTraceFilter : public TraceFilter { 980 public: 981 virtual bool Filter(const TraceEntry* _entry, LazyTraceOutput& out) 982 { 983 const AbstractTraceEntry* entry 984 = dynamic_cast<const AbstractTraceEntry*>(_entry); 985 return (entry != NULL && entry->TeamID() == fTeam); 986 } 987 }; 988 989 990 class PatternTraceFilter : public TraceFilter { 991 public: 992 virtual bool Filter(const TraceEntry* entry, LazyTraceOutput& out) 993 { 994 return strstr(out.DumpEntry(entry), fString) != NULL; 995 } 996 }; 997 998 999 class DecimalPatternTraceFilter : public TraceFilter { 1000 public: 1001 virtual bool Filter(const TraceEntry* entry, LazyTraceOutput& out) 1002 { 1003 // TODO: this is *very* slow 1004 char buffer[64]; 1005 snprintf(buffer, sizeof(buffer), "%" B_PRId64, fValue); 1006 return strstr(out.DumpEntry(entry), buffer) != NULL; 1007 } 1008 }; 1009 1010 class HexPatternTraceFilter : public TraceFilter { 1011 public: 1012 virtual bool Filter(const TraceEntry* entry, LazyTraceOutput& out) 1013 { 1014 // TODO: this is *very* slow 1015 char buffer[64]; 1016 snprintf(buffer, sizeof(buffer), "%" B_PRIx64, fValue); 1017 return strstr(out.DumpEntry(entry), buffer) != NULL; 1018 } 1019 }; 1020 1021 class StringPatternTraceFilter : public TraceFilter { 1022 public: 1023 virtual bool Filter(const TraceEntry* entry, LazyTraceOutput& out) 1024 { 1025 if (IS_KERNEL_ADDRESS(fValue)) 1026 return strstr(out.DumpEntry(entry), (const char*)fValue) != NULL; 1027 1028 // TODO: this is *very* slow 1029 char buffer[64]; 1030 user_strlcpy(buffer, (const char*)fValue, sizeof(buffer)); 1031 return strstr(out.DumpEntry(entry), buffer) != NULL; 1032 } 1033 }; 1034 1035 class NotTraceFilter : public TraceFilter { 1036 public: 1037 virtual bool Filter(const TraceEntry* entry, LazyTraceOutput& out) 1038 { 1039 return !fSubFilters.first->Filter(entry, out); 1040 } 1041 }; 1042 1043 1044 class AndTraceFilter : public TraceFilter { 1045 public: 1046 virtual bool Filter(const TraceEntry* entry, LazyTraceOutput& out) 1047 { 1048 return fSubFilters.first->Filter(entry, out) 1049 && fSubFilters.second->Filter(entry, out); 1050 } 1051 }; 1052 1053 1054 class OrTraceFilter : public TraceFilter { 1055 public: 1056 virtual bool Filter(const TraceEntry* entry, LazyTraceOutput& out) 1057 { 1058 return fSubFilters.first->Filter(entry, out) 1059 || fSubFilters.second->Filter(entry, out); 1060 } 1061 }; 1062 1063 1064 class TraceFilterParser { 1065 public: 1066 static TraceFilterParser* Default() 1067 { 1068 return &sParser; 1069 } 1070 1071 bool Parse(int argc, const char* const* argv) 1072 { 1073 fTokens = argv; 1074 fTokenCount = argc; 1075 fTokenIndex = 0; 1076 fFilterCount = 0; 1077 1078 TraceFilter* filter = _ParseExpression(); 1079 return fTokenIndex == fTokenCount && filter != NULL; 1080 } 1081 1082 TraceFilter* Filter() 1083 { 1084 return &fFilters[0]; 1085 } 1086 1087 private: 1088 TraceFilter* _ParseExpression() 1089 { 1090 const char* token = _NextToken(); 1091 if (!token) { 1092 // unexpected end of expression 1093 return NULL; 1094 } 1095 1096 if (fFilterCount == MAX_FILTERS) { 1097 // too many filters 1098 return NULL; 1099 } 1100 1101 if (token[0] == '#') { 1102 TraceFilter* filter = new(&fFilters[fFilterCount++]) 1103 PatternTraceFilter; 1104 filter->fString = token + 1; 1105 return filter; 1106 } else if (token[0] == 'd' && token[1] == '#') { 1107 TraceFilter* filter = new(&fFilters[fFilterCount++]) 1108 DecimalPatternTraceFilter; 1109 filter->fValue = parse_expression(token + 2); 1110 return filter; 1111 } else if (token[0] == 'x' && token[1] == '#') { 1112 TraceFilter* filter = new(&fFilters[fFilterCount++]) 1113 HexPatternTraceFilter; 1114 filter->fValue = parse_expression(token + 2); 1115 return filter; 1116 } else if (token[0] == 's' && token[1] == '#') { 1117 TraceFilter* filter = new(&fFilters[fFilterCount++]) 1118 StringPatternTraceFilter; 1119 filter->fValue = parse_expression(token + 2); 1120 return filter; 1121 } else if (strcmp(token, "not") == 0) { 1122 TraceFilter* filter = new(&fFilters[fFilterCount++]) NotTraceFilter; 1123 if ((filter->fSubFilters.first = _ParseExpression()) != NULL) 1124 return filter; 1125 delete(filter); 1126 return NULL; 1127 } else if (strcmp(token, "and") == 0) { 1128 TraceFilter* filter = new(&fFilters[fFilterCount++]) AndTraceFilter; 1129 if ((filter->fSubFilters.first = _ParseExpression()) != NULL 1130 && (filter->fSubFilters.second = _ParseExpression()) != NULL) { 1131 return filter; 1132 } 1133 delete(filter); 1134 return NULL; 1135 } else if (strcmp(token, "or") == 0) { 1136 TraceFilter* filter = new(&fFilters[fFilterCount++]) OrTraceFilter; 1137 if ((filter->fSubFilters.first = _ParseExpression()) != NULL 1138 && (filter->fSubFilters.second = _ParseExpression()) != NULL) { 1139 return filter; 1140 } 1141 delete(filter); 1142 return NULL; 1143 } else if (strcmp(token, "thread") == 0) { 1144 const char* arg = _NextToken(); 1145 if (arg == NULL) { 1146 // unexpected end of expression 1147 return NULL; 1148 } 1149 1150 TraceFilter* filter = new(&fFilters[fFilterCount++]) 1151 ThreadTraceFilter; 1152 filter->fThread = strtol(arg, NULL, 0); 1153 return filter; 1154 } else if (strcmp(token, "team") == 0) { 1155 const char* arg = _NextToken(); 1156 if (arg == NULL) { 1157 // unexpected end of expression 1158 return NULL; 1159 } 1160 1161 TraceFilter* filter = new(&fFilters[fFilterCount++]) 1162 TeamTraceFilter; 1163 filter->fTeam = strtol(arg, NULL, 0); 1164 return filter; 1165 } else { 1166 // invalid token 1167 return NULL; 1168 } 1169 } 1170 1171 const char* _CurrentToken() const 1172 { 1173 if (fTokenIndex >= 1 && fTokenIndex <= fTokenCount) 1174 return fTokens[fTokenIndex - 1]; 1175 return NULL; 1176 } 1177 1178 const char* _NextToken() 1179 { 1180 if (fTokenIndex >= fTokenCount) 1181 return NULL; 1182 return fTokens[fTokenIndex++]; 1183 } 1184 1185 private: 1186 enum { MAX_FILTERS = 32 }; 1187 1188 const char* const* fTokens; 1189 int fTokenCount; 1190 int fTokenIndex; 1191 TraceFilter fFilters[MAX_FILTERS]; 1192 int fFilterCount; 1193 1194 static TraceFilterParser sParser; 1195 }; 1196 1197 1198 TraceFilterParser TraceFilterParser::sParser; 1199 1200 1201 // #pragma mark - 1202 1203 1204 #if ENABLE_TRACING 1205 1206 1207 TraceEntry* 1208 TraceEntryIterator::Next() 1209 { 1210 if (fIndex == 0) { 1211 fEntry = _NextNonBufferEntry(sTracingMetaData->FirstEntry()); 1212 fIndex = 1; 1213 } else if (fEntry != NULL) { 1214 fEntry = _NextNonBufferEntry(sTracingMetaData->NextEntry(fEntry)); 1215 fIndex++; 1216 } 1217 1218 return Current(); 1219 } 1220 1221 1222 TraceEntry* 1223 TraceEntryIterator::Previous() 1224 { 1225 if (fIndex == (int32)sTracingMetaData->Entries() + 1) 1226 fEntry = sTracingMetaData->AfterLastEntry(); 1227 1228 if (fEntry != NULL) { 1229 fEntry = _PreviousNonBufferEntry( 1230 sTracingMetaData->PreviousEntry(fEntry)); 1231 fIndex--; 1232 } 1233 1234 return Current(); 1235 } 1236 1237 1238 TraceEntry* 1239 TraceEntryIterator::MoveTo(int32 index) 1240 { 1241 if (index == fIndex) 1242 return Current(); 1243 1244 if (index <= 0 || index > (int32)sTracingMetaData->Entries()) { 1245 fIndex = (index <= 0 ? 0 : sTracingMetaData->Entries() + 1); 1246 fEntry = NULL; 1247 return NULL; 1248 } 1249 1250 // get the shortest iteration path 1251 int32 distance = index - fIndex; 1252 int32 direction = distance < 0 ? -1 : 1; 1253 distance *= direction; 1254 1255 if (index < distance) { 1256 distance = index; 1257 direction = 1; 1258 fEntry = NULL; 1259 fIndex = 0; 1260 } 1261 if ((int32)sTracingMetaData->Entries() + 1 - fIndex < distance) { 1262 distance = sTracingMetaData->Entries() + 1 - fIndex; 1263 direction = -1; 1264 fEntry = NULL; 1265 fIndex = sTracingMetaData->Entries() + 1; 1266 } 1267 1268 // iterate to the index 1269 if (direction < 0) { 1270 while (fIndex != index) 1271 Previous(); 1272 } else { 1273 while (fIndex != index) 1274 Next(); 1275 } 1276 1277 return Current(); 1278 } 1279 1280 1281 trace_entry* 1282 TraceEntryIterator::_NextNonBufferEntry(trace_entry* entry) 1283 { 1284 while (entry != NULL && (entry->flags & BUFFER_ENTRY) != 0) 1285 entry = sTracingMetaData->NextEntry(entry); 1286 1287 return entry; 1288 } 1289 1290 1291 trace_entry* 1292 TraceEntryIterator::_PreviousNonBufferEntry(trace_entry* entry) 1293 { 1294 while (entry != NULL && (entry->flags & BUFFER_ENTRY) != 0) 1295 entry = sTracingMetaData->PreviousEntry(entry); 1296 1297 return entry; 1298 } 1299 1300 1301 int 1302 dump_tracing_internal(int argc, char** argv, WrapperTraceFilter* wrapperFilter) 1303 { 1304 int argi = 1; 1305 1306 // variables in which we store our state to be continuable 1307 static int32 _previousCount = 0; 1308 static bool _previousHasFilter = false; 1309 static bool _previousPrintStackTrace = false; 1310 static int32 _previousMaxToCheck = 0; 1311 static int32 _previousFirstChecked = 1; 1312 static int32 _previousLastChecked = -1; 1313 static int32 _previousDirection = 1; 1314 static uint32 _previousEntriesEver = 0; 1315 static uint32 _previousEntries = 0; 1316 static uint32 _previousOutputFlags = 0; 1317 static TraceEntryIterator iterator; 1318 1319 uint32 entriesEver = sTracingMetaData->EntriesEver(); 1320 1321 // Note: start and index are Pascal-like indices (i.e. in [1, Entries()]). 1322 int32 start = 0; // special index: print the last count entries 1323 int32 count = 0; 1324 int32 maxToCheck = 0; 1325 int32 cont = 0; 1326 1327 bool hasFilter = false; 1328 bool printStackTrace = false; 1329 1330 uint32 outputFlags = 0; 1331 while (argi < argc) { 1332 if (strcmp(argv[argi], "--difftime") == 0) { 1333 outputFlags |= TRACE_OUTPUT_DIFF_TIME; 1334 argi++; 1335 } else if (strcmp(argv[argi], "--printteam") == 0) { 1336 outputFlags |= TRACE_OUTPUT_TEAM_ID; 1337 argi++; 1338 } else if (strcmp(argv[argi], "--stacktrace") == 0) { 1339 printStackTrace = true; 1340 argi++; 1341 } else 1342 break; 1343 } 1344 1345 if (argi < argc) { 1346 if (strcmp(argv[argi], "forward") == 0) { 1347 cont = 1; 1348 argi++; 1349 } else if (strcmp(argv[argi], "backward") == 0) { 1350 cont = -1; 1351 argi++; 1352 } 1353 } else 1354 cont = _previousDirection; 1355 1356 if (cont != 0) { 1357 if (argi < argc) { 1358 print_debugger_command_usage(argv[0]); 1359 return 0; 1360 } 1361 if (entriesEver == 0 || entriesEver != _previousEntriesEver 1362 || sTracingMetaData->Entries() != _previousEntries) { 1363 kprintf("Can't continue iteration. \"%s\" has not been invoked " 1364 "before, or there were new entries written since the last " 1365 "invocation.\n", argv[0]); 1366 return 0; 1367 } 1368 } 1369 1370 // get start, count, maxToCheck 1371 int32* params[3] = { &start, &count, &maxToCheck }; 1372 for (int i = 0; i < 3 && !hasFilter && argi < argc; i++) { 1373 if (strcmp(argv[argi], "filter") == 0) { 1374 hasFilter = true; 1375 argi++; 1376 } else if (argv[argi][0] == '#') { 1377 hasFilter = true; 1378 } else { 1379 *params[i] = parse_expression(argv[argi]); 1380 argi++; 1381 } 1382 } 1383 1384 // filter specification 1385 if (argi < argc) { 1386 hasFilter = true; 1387 if (strcmp(argv[argi], "filter") == 0) 1388 argi++; 1389 1390 if (!TraceFilterParser::Default()->Parse(argc - argi, argv + argi)) { 1391 print_debugger_command_usage(argv[0]); 1392 return 0; 1393 } 1394 } 1395 1396 int32 direction; 1397 int32 firstToCheck; 1398 int32 lastToCheck; 1399 1400 if (cont != 0) { 1401 // get values from the previous iteration 1402 direction = cont; 1403 count = _previousCount; 1404 maxToCheck = _previousMaxToCheck; 1405 hasFilter = _previousHasFilter; 1406 outputFlags = _previousOutputFlags; 1407 printStackTrace = _previousPrintStackTrace; 1408 1409 if (direction < 0) 1410 start = _previousFirstChecked - 1; 1411 else 1412 start = _previousLastChecked + 1; 1413 } else { 1414 // defaults for count and maxToCheck 1415 if (count == 0) 1416 count = 30; 1417 if (maxToCheck == 0 || !hasFilter) 1418 maxToCheck = count; 1419 else if (maxToCheck < 0) 1420 maxToCheck = sTracingMetaData->Entries(); 1421 1422 // determine iteration direction 1423 direction = (start <= 0 || count < 0 ? -1 : 1); 1424 1425 // validate count and maxToCheck 1426 if (count < 0) 1427 count = -count; 1428 if (maxToCheck < 0) 1429 maxToCheck = -maxToCheck; 1430 if (maxToCheck > (int32)sTracingMetaData->Entries()) 1431 maxToCheck = sTracingMetaData->Entries(); 1432 if (count > maxToCheck) 1433 count = maxToCheck; 1434 1435 // validate start 1436 if (start <= 0 || start > (int32)sTracingMetaData->Entries()) 1437 start = max_c(1, sTracingMetaData->Entries()); 1438 } 1439 1440 if (direction < 0) { 1441 firstToCheck = max_c(1, start - maxToCheck + 1); 1442 lastToCheck = start; 1443 } else { 1444 firstToCheck = start; 1445 lastToCheck = min_c((int32)sTracingMetaData->Entries(), 1446 start + maxToCheck - 1); 1447 } 1448 1449 // reset the iterator, if something changed in the meantime 1450 if (entriesEver == 0 || entriesEver != _previousEntriesEver 1451 || sTracingMetaData->Entries() != _previousEntries) { 1452 iterator.Reset(); 1453 } 1454 1455 LazyTraceOutput out(sTracingMetaData->TraceOutputBuffer(), 1456 kTraceOutputBufferSize, outputFlags); 1457 1458 bool markedMatching = false; 1459 int32 firstToDump = firstToCheck; 1460 int32 lastToDump = lastToCheck; 1461 1462 TraceFilter* filter = NULL; 1463 if (hasFilter) 1464 filter = TraceFilterParser::Default()->Filter(); 1465 1466 if (wrapperFilter != NULL) { 1467 wrapperFilter->Init(filter, direction, cont != 0); 1468 filter = wrapperFilter; 1469 } 1470 1471 if (direction < 0 && filter && lastToCheck - firstToCheck >= count) { 1472 // iteration direction is backwards 1473 markedMatching = true; 1474 1475 // From the last entry to check iterate backwards to check filter 1476 // matches. 1477 int32 matching = 0; 1478 1479 // move to the entry after the last entry to check 1480 iterator.MoveTo(lastToCheck + 1); 1481 1482 // iterate backwards 1483 firstToDump = -1; 1484 lastToDump = -1; 1485 while (iterator.Index() > firstToCheck) { 1486 TraceEntry* entry = iterator.Previous(); 1487 if ((entry->Flags() & ENTRY_INITIALIZED) != 0) { 1488 out.Clear(); 1489 if (filter->Filter(entry, out)) { 1490 entry->ToTraceEntry()->flags |= FILTER_MATCH; 1491 if (lastToDump == -1) 1492 lastToDump = iterator.Index(); 1493 firstToDump = iterator.Index(); 1494 1495 matching++; 1496 if (matching >= count) 1497 break; 1498 } else 1499 entry->ToTraceEntry()->flags &= ~FILTER_MATCH; 1500 } 1501 } 1502 1503 firstToCheck = iterator.Index(); 1504 1505 // iterate to the previous entry, so that the next loop starts at the 1506 // right one 1507 iterator.Previous(); 1508 } 1509 1510 out.SetLastEntryTime(0); 1511 1512 // set the iterator to the entry before the first one to dump 1513 iterator.MoveTo(firstToDump - 1); 1514 1515 // dump the entries matching the filter in the range 1516 // [firstToDump, lastToDump] 1517 int32 dumped = 0; 1518 1519 while (TraceEntry* entry = iterator.Next()) { 1520 int32 index = iterator.Index(); 1521 if (index < firstToDump) 1522 continue; 1523 if (index > lastToDump || dumped >= count) { 1524 if (direction > 0) 1525 lastToCheck = index - 1; 1526 break; 1527 } 1528 1529 if ((entry->Flags() & ENTRY_INITIALIZED) != 0) { 1530 out.Clear(); 1531 if (filter && (markedMatching 1532 ? (entry->Flags() & FILTER_MATCH) == 0 1533 : !filter->Filter(entry, out))) { 1534 continue; 1535 } 1536 1537 // don't print trailing new line 1538 const char* dump = out.DumpEntry(entry); 1539 int len = strlen(dump); 1540 if (len > 0 && dump[len - 1] == '\n') 1541 len--; 1542 1543 kprintf("%5" B_PRId32 ". %.*s\n", index, len, dump); 1544 1545 if (printStackTrace) { 1546 out.Clear(); 1547 entry->DumpStackTrace(out); 1548 if (out.Size() > 0) 1549 kputs(out.Buffer()); 1550 } 1551 } else if (!filter) 1552 kprintf("%5" B_PRId32 ". ** uninitialized entry **\n", index); 1553 1554 dumped++; 1555 } 1556 1557 kprintf("printed %" B_PRId32 " entries within range %" B_PRId32 " to %" 1558 B_PRId32 " (%" B_PRId32 " of %" B_PRId32 " total, %" B_PRId32 " ever)\n", 1559 dumped, firstToCheck, lastToCheck, lastToCheck - firstToCheck + 1, 1560 sTracingMetaData->Entries(), entriesEver); 1561 1562 // store iteration state 1563 _previousCount = count; 1564 _previousMaxToCheck = maxToCheck; 1565 _previousHasFilter = hasFilter; 1566 _previousPrintStackTrace = printStackTrace; 1567 _previousFirstChecked = firstToCheck; 1568 _previousLastChecked = lastToCheck; 1569 _previousDirection = direction; 1570 _previousEntriesEver = entriesEver; 1571 _previousEntries = sTracingMetaData->Entries(); 1572 _previousOutputFlags = outputFlags; 1573 1574 return cont != 0 ? B_KDEBUG_CONT : 0; 1575 } 1576 1577 1578 static int 1579 dump_tracing_command(int argc, char** argv) 1580 { 1581 return dump_tracing_internal(argc, argv, NULL); 1582 } 1583 1584 1585 #endif // ENABLE_TRACING 1586 1587 1588 extern "C" uint8* 1589 alloc_tracing_buffer(size_t size) 1590 { 1591 #if ENABLE_TRACING 1592 trace_entry* entry = sTracingMetaData->AllocateEntry( 1593 size + sizeof(trace_entry), BUFFER_ENTRY); 1594 if (entry == NULL) 1595 return NULL; 1596 1597 return (uint8*)(entry + 1); 1598 #else 1599 return NULL; 1600 #endif 1601 } 1602 1603 1604 uint8* 1605 alloc_tracing_buffer_memcpy(const void* source, size_t size, bool user) 1606 { 1607 if (user && !IS_USER_ADDRESS(source)) 1608 return NULL; 1609 1610 uint8* buffer = alloc_tracing_buffer(size); 1611 if (buffer == NULL) 1612 return NULL; 1613 1614 if (user) { 1615 if (user_memcpy(buffer, source, size) != B_OK) 1616 return NULL; 1617 } else 1618 memcpy(buffer, source, size); 1619 1620 return buffer; 1621 } 1622 1623 1624 char* 1625 alloc_tracing_buffer_strcpy(const char* source, size_t maxSize, bool user) 1626 { 1627 if (source == NULL || maxSize == 0) 1628 return NULL; 1629 1630 if (user && !IS_USER_ADDRESS(source)) 1631 return NULL; 1632 1633 // limit maxSize to the actual source string len 1634 if (user) { 1635 ssize_t size = user_strlcpy(NULL, source, 0); 1636 // there's no user_strnlen() 1637 if (size < 0) 1638 return 0; 1639 maxSize = min_c(maxSize, (size_t)size + 1); 1640 } else 1641 maxSize = strnlen(source, maxSize - 1) + 1; 1642 1643 char* buffer = (char*)alloc_tracing_buffer(maxSize); 1644 if (buffer == NULL) 1645 return NULL; 1646 1647 if (user) { 1648 if (user_strlcpy(buffer, source, maxSize) < B_OK) 1649 return NULL; 1650 } else 1651 strlcpy(buffer, source, maxSize); 1652 1653 return buffer; 1654 } 1655 1656 1657 tracing_stack_trace* 1658 capture_tracing_stack_trace(int32 maxCount, int32 skipFrames, bool kernelOnly) 1659 { 1660 #if ENABLE_TRACING 1661 // page_fault_exception() doesn't allow us to gracefully handle a bad 1662 // address in the stack trace, if interrupts are disabled, so we always 1663 // restrict the stack traces to the kernel only in this case. A bad address 1664 // in the kernel stack trace would still cause a panic(), but this is 1665 // probably even desired. 1666 if (!are_interrupts_enabled()) 1667 kernelOnly = true; 1668 1669 tracing_stack_trace* stackTrace 1670 = (tracing_stack_trace*)alloc_tracing_buffer( 1671 sizeof(tracing_stack_trace) + maxCount * sizeof(addr_t)); 1672 1673 if (stackTrace != NULL) { 1674 stackTrace->depth = arch_debug_get_stack_trace( 1675 stackTrace->return_addresses, maxCount, 0, skipFrames + 1, 1676 STACK_TRACE_KERNEL | (kernelOnly ? 0 : STACK_TRACE_USER)); 1677 } 1678 1679 return stackTrace; 1680 #else 1681 return NULL; 1682 #endif 1683 } 1684 1685 1686 addr_t 1687 tracing_find_caller_in_stack_trace(struct tracing_stack_trace* stackTrace, 1688 const addr_t excludeRanges[], uint32 excludeRangeCount) 1689 { 1690 for (int32 i = 0; i < stackTrace->depth; i++) { 1691 addr_t returnAddress = stackTrace->return_addresses[i]; 1692 1693 bool inRange = false; 1694 for (uint32 j = 0; j < excludeRangeCount; j++) { 1695 if (returnAddress >= excludeRanges[j * 2 + 0] 1696 && returnAddress < excludeRanges[j * 2 + 1]) { 1697 inRange = true; 1698 break; 1699 } 1700 } 1701 1702 if (!inRange) 1703 return returnAddress; 1704 } 1705 1706 return 0; 1707 } 1708 1709 1710 void 1711 tracing_print_stack_trace(struct tracing_stack_trace* stackTrace) 1712 { 1713 #if ENABLE_TRACING 1714 print_stack_trace(stackTrace, kprintf); 1715 #endif 1716 } 1717 1718 1719 int 1720 dump_tracing(int argc, char** argv, WrapperTraceFilter* wrapperFilter) 1721 { 1722 #if ENABLE_TRACING 1723 return dump_tracing_internal(argc, argv, wrapperFilter); 1724 #else 1725 return 0; 1726 #endif 1727 } 1728 1729 1730 bool 1731 tracing_is_entry_valid(AbstractTraceEntry* candidate, bigtime_t entryTime) 1732 { 1733 #if ENABLE_TRACING 1734 if (!sTracingMetaData->IsInBuffer(candidate, sizeof(*candidate))) 1735 return false; 1736 1737 if (entryTime < 0) 1738 return true; 1739 1740 TraceEntryIterator iterator; 1741 while (TraceEntry* entry = iterator.Next()) { 1742 AbstractTraceEntry* abstract = dynamic_cast<AbstractTraceEntry*>(entry); 1743 if (abstract == NULL) 1744 continue; 1745 1746 if (abstract != candidate && abstract->Time() > entryTime) 1747 return false; 1748 1749 return candidate->Time() == entryTime; 1750 } 1751 #endif 1752 1753 return false; 1754 } 1755 1756 1757 void 1758 lock_tracing_buffer() 1759 { 1760 #if ENABLE_TRACING 1761 sTracingMetaData->Lock(); 1762 #endif 1763 } 1764 1765 1766 void 1767 unlock_tracing_buffer() 1768 { 1769 #if ENABLE_TRACING 1770 sTracingMetaData->Unlock(); 1771 #endif 1772 } 1773 1774 1775 extern "C" status_t 1776 tracing_init(void) 1777 { 1778 #if ENABLE_TRACING 1779 status_t result = TracingMetaData::Create(sTracingMetaData); 1780 if (result != B_OK) { 1781 memset(&sFallbackTracingMetaData, 0, sizeof(sFallbackTracingMetaData)); 1782 sTracingMetaData = &sFallbackTracingMetaData; 1783 return result; 1784 } 1785 1786 new(nothrow) TracingLogStartEntry(); 1787 1788 add_debugger_command_etc("traced", &dump_tracing_command, 1789 "Dump recorded trace entries", 1790 "[ --printteam ] [ --difftime ] [ --stacktrace ] " 1791 "(\"forward\" | \"backward\") " 1792 "| ([ <start> [ <count> [ <range> ] ] ] " 1793 "[ #<pattern> | (\"filter\" <filter>) ])\n" 1794 "Prints recorded trace entries. If \"backward\" or \"forward\" is\n" 1795 "specified, the command continues where the previous invocation left\n" 1796 "off, i.e. printing the previous respectively next entries (as many\n" 1797 "as printed before). In this case the command is continuable, that is\n" 1798 "afterwards entering an empty line in the debugger will reinvoke it.\n" 1799 "If no arguments are given, the command continues in the direction\n" 1800 "of the last invocation.\n" 1801 "--printteam - enables printing the entries' team IDs.\n" 1802 "--difftime - print difference times for all but the first entry.\n" 1803 "--stacktrace - print stack traces for entries that captured one.\n" 1804 " <start> - The base index of the entries to print. Depending on\n" 1805 " whether the iteration direction is forward or\n" 1806 " backward this will be the first or last entry printed\n" 1807 " (potentially, if a filter is specified). The index of\n" 1808 " the first entry in the trace buffer is 1. If 0 is\n" 1809 " specified, the last <count> recorded entries are\n" 1810 " printed (iteration direction is backward). Defaults \n" 1811 " to 0.\n" 1812 " <count> - The number of entries to be printed. Defaults to 30.\n" 1813 " If negative, the -<count> entries before and\n" 1814 " including <start> will be printed.\n" 1815 " <range> - Only relevant if a filter is specified. Specifies the\n" 1816 " number of entries to be filtered -- depending on the\n" 1817 " iteration direction the entries before or after\n" 1818 " <start>. If more than <count> entries match the\n" 1819 " filter, only the first (forward) or last (backward)\n" 1820 " <count> matching entries will be printed. If 0 is\n" 1821 " specified <range> will be set to <count>. If -1,\n" 1822 " <range> will be set to the number of recorded\n" 1823 " entries.\n" 1824 " <pattern> - If specified only entries containing this string are\n" 1825 " printed.\n" 1826 " <filter> - If specified only entries matching this filter\n" 1827 " expression are printed. The expression can consist of\n" 1828 " prefix operators \"not\", \"and\", \"or\", and\n" 1829 " filters \"'thread' <thread>\" (matching entries\n" 1830 " with the given thread ID), \"'team' <team>\"\n" 1831 "(matching entries with the given team ID), and\n" 1832 " \"#<pattern>\" (matching entries containing the given\n" 1833 " string).\n", 0); 1834 #endif // ENABLE_TRACING 1835 return B_OK; 1836 } 1837 1838 1839 void 1840 ktrace_printf(const char *format, ...) 1841 { 1842 #if ENABLE_TRACING 1843 va_list list; 1844 va_start(list, format); 1845 1846 char buffer[256]; 1847 vsnprintf(buffer, sizeof(buffer), format, list); 1848 1849 va_end(list); 1850 1851 new(nothrow) KernelTraceEntry(buffer); 1852 #endif // ENABLE_TRACING 1853 } 1854 1855 1856 void 1857 _user_ktrace_output(const char *message) 1858 { 1859 #if ENABLE_TRACING 1860 new(nothrow) UserTraceEntry(message); 1861 #endif // ENABLE_TRACING 1862 } 1863 1864