1 /* 2 * Copyright (C) 2013 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 * 16 * 17 */ 18 19 #define LOG_TAG "NBLog" 20 21 #include <algorithm> 22 #include <climits> 23 #include <deque> 24 #include <fstream> 25 #include <iostream> 26 #include <math.h> 27 #include <numeric> 28 #include <vector> 29 #include <stdarg.h> 30 #include <stdint.h> 31 #include <stdio.h> 32 #include <string.h> 33 #include <sys/prctl.h> 34 #include <time.h> 35 #include <new> 36 #include <audio_utils/roundup.h> 37 #include <media/nblog/NBLog.h> 38 #include <media/nblog/PerformanceAnalysis.h> 39 #include <media/nblog/ReportPerformance.h> 40 #include <utils/CallStack.h> 41 #include <utils/Log.h> 42 #include <utils/String8.h> 43 44 #include <queue> 45 #include <utility> 46 47 namespace android { 48 49 int NBLog::Entry::copyEntryDataAt(size_t offset) const 50 { 51 // FIXME This is too slow 52 if (offset == 0) 53 return mEvent; 54 else if (offset == 1) 55 return mLength; 56 else if (offset < (size_t) (mLength + 2)) 57 return ((char *) mData)[offset - 2]; 58 else if (offset == (size_t) (mLength + 2)) 59 return mLength; 60 else 61 return 0; 62 } 63 64 // --------------------------------------------------------------------------- 65 66 /*static*/ 67 std::unique_ptr<NBLog::AbstractEntry> NBLog::AbstractEntry::buildEntry(const uint8_t *ptr) { 68 const uint8_t type = EntryIterator(ptr)->type; 69 switch (type) { 70 case EVENT_START_FMT: 71 return std::make_unique<FormatEntry>(FormatEntry(ptr)); 72 case EVENT_AUDIO_STATE: 73 case EVENT_HISTOGRAM_ENTRY_TS: 74 return std::make_unique<HistogramEntry>(HistogramEntry(ptr)); 75 default: 76 ALOGW("Tried to create AbstractEntry of type %d", type); 77 return nullptr; 78 } 79 } 80 81 NBLog::AbstractEntry::AbstractEntry(const uint8_t *entry) : mEntry(entry) { 82 } 83 84 // --------------------------------------------------------------------------- 85 86 NBLog::EntryIterator NBLog::FormatEntry::begin() const { 87 return EntryIterator(mEntry); 88 } 89 90 const char *NBLog::FormatEntry::formatString() const { 91 return (const char*) mEntry + offsetof(entry, data); 92 } 93 94 size_t NBLog::FormatEntry::formatStringLength() const { 95 return mEntry[offsetof(entry, length)]; 96 } 97 98 NBLog::EntryIterator NBLog::FormatEntry::args() const { 99 auto it = begin(); 100 // skip start fmt 101 ++it; 102 // skip timestamp 103 ++it; 104 // skip hash 105 ++it; 106 // Skip author if present 107 if (it->type == EVENT_AUTHOR) { 108 ++it; 109 } 110 return it; 111 } 112 113 int64_t NBLog::FormatEntry::timestamp() const { 114 auto it = begin(); 115 // skip start fmt 116 ++it; 117 return it.payload<int64_t>(); 118 } 119 120 NBLog::log_hash_t NBLog::FormatEntry::hash() const { 121 auto it = begin(); 122 // skip start fmt 123 ++it; 124 // skip timestamp 125 ++it; 126 // unaligned 64-bit read not supported 127 log_hash_t hash; 128 memcpy(&hash, it->data, sizeof(hash)); 129 return hash; 130 } 131 132 int NBLog::FormatEntry::author() const { 133 auto it = begin(); 134 // skip start fmt 135 ++it; 136 // skip timestamp 137 ++it; 138 // skip hash 139 ++it; 140 // if there is an author entry, return it, return -1 otherwise 141 if (it->type == EVENT_AUTHOR) { 142 return it.payload<int>(); 143 } 144 return -1; 145 } 146 147 NBLog::EntryIterator NBLog::FormatEntry::copyWithAuthor( 148 std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const { 149 auto it = begin(); 150 // copy fmt start entry 151 it.copyTo(dst); 152 // copy timestamp 153 (++it).copyTo(dst); // copy hash 154 (++it).copyTo(dst); 155 // insert author entry 156 size_t authorEntrySize = NBLog::Entry::kOverhead + sizeof(author); 157 uint8_t authorEntry[authorEntrySize]; 158 authorEntry[offsetof(entry, type)] = EVENT_AUTHOR; 159 authorEntry[offsetof(entry, length)] = 160 authorEntry[authorEntrySize + NBLog::Entry::kPreviousLengthOffset] = 161 sizeof(author); 162 *(int*) (&authorEntry[offsetof(entry, data)]) = author; 163 dst->write(authorEntry, authorEntrySize); 164 // copy rest of entries 165 while ((++it)->type != EVENT_END_FMT) { 166 it.copyTo(dst); 167 } 168 it.copyTo(dst); 169 ++it; 170 return it; 171 } 172 173 void NBLog::EntryIterator::copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst) const { 174 size_t length = ptr[offsetof(entry, length)] + NBLog::Entry::kOverhead; 175 dst->write(ptr, length); 176 } 177 178 void NBLog::EntryIterator::copyData(uint8_t *dst) const { 179 memcpy((void*) dst, ptr + offsetof(entry, data), ptr[offsetof(entry, length)]); 180 } 181 182 NBLog::EntryIterator::EntryIterator() 183 : ptr(nullptr) {} 184 185 NBLog::EntryIterator::EntryIterator(const uint8_t *entry) 186 : ptr(entry) {} 187 188 NBLog::EntryIterator::EntryIterator(const NBLog::EntryIterator &other) 189 : ptr(other.ptr) {} 190 191 const NBLog::entry& NBLog::EntryIterator::operator*() const { 192 return *(entry*) ptr; 193 } 194 195 const NBLog::entry* NBLog::EntryIterator::operator->() const { 196 return (entry*) ptr; 197 } 198 199 NBLog::EntryIterator& NBLog::EntryIterator::operator++() { 200 ptr += ptr[offsetof(entry, length)] + NBLog::Entry::kOverhead; 201 return *this; 202 } 203 204 NBLog::EntryIterator& NBLog::EntryIterator::operator--() { 205 ptr -= ptr[NBLog::Entry::kPreviousLengthOffset] + NBLog::Entry::kOverhead; 206 return *this; 207 } 208 209 NBLog::EntryIterator NBLog::EntryIterator::next() const { 210 EntryIterator aux(*this); 211 return ++aux; 212 } 213 214 NBLog::EntryIterator NBLog::EntryIterator::prev() const { 215 EntryIterator aux(*this); 216 return --aux; 217 } 218 219 int NBLog::EntryIterator::operator-(const NBLog::EntryIterator &other) const { 220 return ptr - other.ptr; 221 } 222 223 bool NBLog::EntryIterator::operator!=(const EntryIterator &other) const { 224 return ptr != other.ptr; 225 } 226 227 bool NBLog::EntryIterator::hasConsistentLength() const { 228 return ptr[offsetof(entry, length)] == ptr[ptr[offsetof(entry, length)] + 229 NBLog::Entry::kOverhead + NBLog::Entry::kPreviousLengthOffset]; 230 } 231 232 // --------------------------------------------------------------------------- 233 234 int64_t NBLog::HistogramEntry::timestamp() const { 235 return EntryIterator(mEntry).payload<HistTsEntry>().ts; 236 } 237 238 NBLog::log_hash_t NBLog::HistogramEntry::hash() const { 239 return EntryIterator(mEntry).payload<HistTsEntry>().hash; 240 } 241 242 int NBLog::HistogramEntry::author() const { 243 EntryIterator it(mEntry); 244 if (it->length == sizeof(HistTsEntryWithAuthor)) { 245 return it.payload<HistTsEntryWithAuthor>().author; 246 } else { 247 return -1; 248 } 249 } 250 251 NBLog::EntryIterator NBLog::HistogramEntry::copyWithAuthor( 252 std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const { 253 // Current histogram entry has {type, length, struct HistTsEntry, length}. 254 // We now want {type, length, struct HistTsEntryWithAuthor, length} 255 uint8_t buffer[Entry::kOverhead + sizeof(HistTsEntryWithAuthor)]; 256 // Copy content until the point we want to add the author 257 memcpy(buffer, mEntry, sizeof(entry) + sizeof(HistTsEntry)); 258 // Copy the author 259 *(int*) (buffer + sizeof(entry) + sizeof(HistTsEntry)) = author; 260 // Update lengths 261 buffer[offsetof(entry, length)] = sizeof(HistTsEntryWithAuthor); 262 buffer[offsetof(entry, data) + sizeof(HistTsEntryWithAuthor) + offsetof(ending, length)] 263 = sizeof(HistTsEntryWithAuthor); 264 // Write new buffer into FIFO 265 dst->write(buffer, sizeof(buffer)); 266 return EntryIterator(mEntry).next(); 267 } 268 269 // --------------------------------------------------------------------------- 270 271 #if 0 // FIXME see note in NBLog.h 272 NBLog::Timeline::Timeline(size_t size, void *shared) 273 : mSize(roundup(size)), mOwn(shared == NULL), 274 mShared((Shared *) (mOwn ? new char[sharedSize(size)] : shared)) 275 { 276 new (mShared) Shared; 277 } 278 279 NBLog::Timeline::~Timeline() 280 { 281 mShared->~Shared(); 282 if (mOwn) { 283 delete[] (char *) mShared; 284 } 285 } 286 #endif 287 288 /*static*/ 289 size_t NBLog::Timeline::sharedSize(size_t size) 290 { 291 // TODO fifo now supports non-power-of-2 buffer sizes, so could remove the roundup 292 return sizeof(Shared) + roundup(size); 293 } 294 295 // --------------------------------------------------------------------------- 296 297 NBLog::Writer::Writer() 298 : mShared(NULL), mFifo(NULL), mFifoWriter(NULL), mEnabled(false), mPidTag(NULL), mPidTagSize(0) 299 { 300 } 301 302 NBLog::Writer::Writer(void *shared, size_t size) 303 : mShared((Shared *) shared), 304 mFifo(mShared != NULL ? 305 new audio_utils_fifo(size, sizeof(uint8_t), 306 mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL), 307 mFifoWriter(mFifo != NULL ? new audio_utils_fifo_writer(*mFifo) : NULL), 308 mEnabled(mFifoWriter != NULL) 309 { 310 // caching pid and process name 311 pid_t id = ::getpid(); 312 char procName[16]; 313 int status = prctl(PR_GET_NAME, procName); 314 if (status) { // error getting process name 315 procName[0] = '\0'; 316 } 317 size_t length = strlen(procName); 318 mPidTagSize = length + sizeof(pid_t); 319 mPidTag = new char[mPidTagSize]; 320 memcpy(mPidTag, &id, sizeof(pid_t)); 321 memcpy(mPidTag + sizeof(pid_t), procName, length); 322 } 323 324 NBLog::Writer::Writer(const sp<IMemory>& iMemory, size_t size) 325 : Writer(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL, size) 326 { 327 mIMemory = iMemory; 328 } 329 330 NBLog::Writer::~Writer() 331 { 332 delete mFifoWriter; 333 delete mFifo; 334 delete[] mPidTag; 335 } 336 337 void NBLog::Writer::log(const char *string) 338 { 339 if (!mEnabled) { 340 return; 341 } 342 LOG_ALWAYS_FATAL_IF(string == NULL, "Attempted to log NULL string"); 343 size_t length = strlen(string); 344 if (length > Entry::kMaxLength) { 345 length = Entry::kMaxLength; 346 } 347 log(EVENT_STRING, string, length); 348 } 349 350 void NBLog::Writer::logf(const char *fmt, ...) 351 { 352 if (!mEnabled) { 353 return; 354 } 355 va_list ap; 356 va_start(ap, fmt); 357 Writer::logvf(fmt, ap); // the Writer:: is needed to avoid virtual dispatch for LockedWriter 358 va_end(ap); 359 } 360 361 void NBLog::Writer::logvf(const char *fmt, va_list ap) 362 { 363 if (!mEnabled) { 364 return; 365 } 366 char buffer[Entry::kMaxLength + 1 /*NUL*/]; 367 int length = vsnprintf(buffer, sizeof(buffer), fmt, ap); 368 if (length >= (int) sizeof(buffer)) { 369 length = sizeof(buffer) - 1; 370 // NUL termination is not required 371 // buffer[length] = '\0'; 372 } 373 if (length >= 0) { 374 log(EVENT_STRING, buffer, length); 375 } 376 } 377 378 void NBLog::Writer::logTimestamp() 379 { 380 if (!mEnabled) { 381 return; 382 } 383 int64_t ts = get_monotonic_ns(); 384 if (ts > 0) { 385 log(EVENT_TIMESTAMP, &ts, sizeof(ts)); 386 } else { 387 ALOGE("Failed to get timestamp"); 388 } 389 } 390 391 void NBLog::Writer::logTimestamp(const int64_t ts) 392 { 393 if (!mEnabled) { 394 return; 395 } 396 log(EVENT_TIMESTAMP, &ts, sizeof(ts)); 397 } 398 399 void NBLog::Writer::logInteger(const int x) 400 { 401 if (!mEnabled) { 402 return; 403 } 404 log(EVENT_INTEGER, &x, sizeof(x)); 405 } 406 407 void NBLog::Writer::logFloat(const float x) 408 { 409 if (!mEnabled) { 410 return; 411 } 412 log(EVENT_FLOAT, &x, sizeof(x)); 413 } 414 415 void NBLog::Writer::logPID() 416 { 417 if (!mEnabled) { 418 return; 419 } 420 log(EVENT_PID, mPidTag, mPidTagSize); 421 } 422 423 void NBLog::Writer::logStart(const char *fmt) 424 { 425 if (!mEnabled) { 426 return; 427 } 428 size_t length = strlen(fmt); 429 if (length > Entry::kMaxLength) { 430 length = Entry::kMaxLength; 431 } 432 log(EVENT_START_FMT, fmt, length); 433 } 434 435 void NBLog::Writer::logEnd() 436 { 437 if (!mEnabled) { 438 return; 439 } 440 Entry entry = Entry(EVENT_END_FMT, NULL, 0); 441 log(&entry, true); 442 } 443 444 void NBLog::Writer::logHash(log_hash_t hash) 445 { 446 if (!mEnabled) { 447 return; 448 } 449 log(EVENT_HASH, &hash, sizeof(hash)); 450 } 451 452 void NBLog::Writer::logEventHistTs(Event event, log_hash_t hash) 453 { 454 if (!mEnabled) { 455 return; 456 } 457 HistTsEntry data; 458 data.hash = hash; 459 data.ts = get_monotonic_ns(); 460 if (data.ts > 0) { 461 log(event, &data, sizeof(data)); 462 } else { 463 ALOGE("Failed to get timestamp"); 464 } 465 } 466 467 void NBLog::Writer::logFormat(const char *fmt, log_hash_t hash, ...) 468 { 469 if (!mEnabled) { 470 return; 471 } 472 473 va_list ap; 474 va_start(ap, hash); 475 Writer::logVFormat(fmt, hash, ap); 476 va_end(ap); 477 } 478 479 void NBLog::Writer::logVFormat(const char *fmt, log_hash_t hash, va_list argp) 480 { 481 if (!mEnabled) { 482 return; 483 } 484 Writer::logStart(fmt); 485 int i; 486 double f; 487 char* s; 488 int64_t t; 489 Writer::logTimestamp(); 490 Writer::logHash(hash); 491 for (const char *p = fmt; *p != '\0'; p++) { 492 // TODO: implement more complex formatting such as %.3f 493 if (*p != '%') { 494 continue; 495 } 496 switch(*++p) { 497 case 's': // string 498 s = va_arg(argp, char *); 499 Writer::log(s); 500 break; 501 502 case 't': // timestamp 503 t = va_arg(argp, int64_t); 504 Writer::logTimestamp(t); 505 break; 506 507 case 'd': // integer 508 i = va_arg(argp, int); 509 Writer::logInteger(i); 510 break; 511 512 case 'f': // float 513 f = va_arg(argp, double); // float arguments are promoted to double in vararg lists 514 Writer::logFloat((float)f); 515 break; 516 517 case 'p': // pid 518 Writer::logPID(); 519 break; 520 521 // the "%\0" case finishes parsing 522 case '\0': 523 --p; 524 break; 525 526 case '%': 527 break; 528 529 default: 530 ALOGW("NBLog Writer parsed invalid format specifier: %c", *p); 531 break; 532 } 533 } 534 Writer::logEnd(); 535 } 536 537 void NBLog::Writer::log(Event event, const void *data, size_t length) 538 { 539 if (!mEnabled) { 540 return; 541 } 542 if (data == NULL || length > Entry::kMaxLength) { 543 // TODO Perhaps it makes sense to display truncated data or at least a 544 // message that the data is too long? The current behavior can create 545 // a confusion for a programmer debugging their code. 546 return; 547 } 548 // Ignore if invalid event 549 if (event == EVENT_RESERVED || event >= EVENT_UPPER_BOUND) { 550 return; 551 } 552 Entry etr(event, data, length); 553 log(&etr, true /*trusted*/); 554 } 555 556 void NBLog::Writer::log(const NBLog::Entry *etr, bool trusted) 557 { 558 if (!mEnabled) { 559 return; 560 } 561 if (!trusted) { 562 log(etr->mEvent, etr->mData, etr->mLength); 563 return; 564 } 565 size_t need = etr->mLength + Entry::kOverhead; // mEvent, mLength, data[mLength], mLength 566 // need = number of bytes written to FIFO 567 568 // FIXME optimize this using memcpy for the data part of the Entry. 569 // The Entry could have a method copyTo(ptr, offset, size) to optimize the copy. 570 // checks size of a single log Entry: type, length, data pointer and ending 571 uint8_t temp[Entry::kMaxLength + Entry::kOverhead]; 572 // write this data to temp array 573 for (size_t i = 0; i < need; i++) { 574 temp[i] = etr->copyEntryDataAt(i); 575 } 576 // write to circular buffer 577 mFifoWriter->write(temp, need); 578 } 579 580 bool NBLog::Writer::isEnabled() const 581 { 582 return mEnabled; 583 } 584 585 bool NBLog::Writer::setEnabled(bool enabled) 586 { 587 bool old = mEnabled; 588 mEnabled = enabled && mShared != NULL; 589 return old; 590 } 591 592 // --------------------------------------------------------------------------- 593 594 NBLog::LockedWriter::LockedWriter() 595 : Writer() 596 { 597 } 598 599 NBLog::LockedWriter::LockedWriter(void *shared, size_t size) 600 : Writer(shared, size) 601 { 602 } 603 604 void NBLog::LockedWriter::log(const char *string) 605 { 606 Mutex::Autolock _l(mLock); 607 Writer::log(string); 608 } 609 610 void NBLog::LockedWriter::logf(const char *fmt, ...) 611 { 612 // FIXME should not take the lock until after formatting is done 613 Mutex::Autolock _l(mLock); 614 va_list ap; 615 va_start(ap, fmt); 616 Writer::logvf(fmt, ap); 617 va_end(ap); 618 } 619 620 void NBLog::LockedWriter::logvf(const char *fmt, va_list ap) 621 { 622 // FIXME should not take the lock until after formatting is done 623 Mutex::Autolock _l(mLock); 624 Writer::logvf(fmt, ap); 625 } 626 627 void NBLog::LockedWriter::logTimestamp() 628 { 629 // FIXME should not take the lock until after the clock_gettime() syscall 630 Mutex::Autolock _l(mLock); 631 Writer::logTimestamp(); 632 } 633 634 void NBLog::LockedWriter::logTimestamp(const int64_t ts) 635 { 636 Mutex::Autolock _l(mLock); 637 Writer::logTimestamp(ts); 638 } 639 640 void NBLog::LockedWriter::logInteger(const int x) 641 { 642 Mutex::Autolock _l(mLock); 643 Writer::logInteger(x); 644 } 645 646 void NBLog::LockedWriter::logFloat(const float x) 647 { 648 Mutex::Autolock _l(mLock); 649 Writer::logFloat(x); 650 } 651 652 void NBLog::LockedWriter::logPID() 653 { 654 Mutex::Autolock _l(mLock); 655 Writer::logPID(); 656 } 657 658 void NBLog::LockedWriter::logStart(const char *fmt) 659 { 660 Mutex::Autolock _l(mLock); 661 Writer::logStart(fmt); 662 } 663 664 665 void NBLog::LockedWriter::logEnd() 666 { 667 Mutex::Autolock _l(mLock); 668 Writer::logEnd(); 669 } 670 671 void NBLog::LockedWriter::logHash(log_hash_t hash) 672 { 673 Mutex::Autolock _l(mLock); 674 Writer::logHash(hash); 675 } 676 677 bool NBLog::LockedWriter::isEnabled() const 678 { 679 Mutex::Autolock _l(mLock); 680 return Writer::isEnabled(); 681 } 682 683 bool NBLog::LockedWriter::setEnabled(bool enabled) 684 { 685 Mutex::Autolock _l(mLock); 686 return Writer::setEnabled(enabled); 687 } 688 689 // --------------------------------------------------------------------------- 690 691 const std::set<NBLog::Event> NBLog::Reader::startingTypes {NBLog::Event::EVENT_START_FMT, 692 NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS, 693 NBLog::Event::EVENT_AUDIO_STATE}; 694 const std::set<NBLog::Event> NBLog::Reader::endingTypes {NBLog::Event::EVENT_END_FMT, 695 NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS, 696 NBLog::Event::EVENT_AUDIO_STATE}; 697 698 NBLog::Reader::Reader(const void *shared, size_t size) 699 : mFd(-1), mIndent(0), mLost(0), 700 mShared((/*const*/ Shared *) shared), /*mIMemory*/ 701 mFifo(mShared != NULL ? 702 new audio_utils_fifo(size, sizeof(uint8_t), 703 mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL), 704 mFifoReader(mFifo != NULL ? new audio_utils_fifo_reader(*mFifo) : NULL) 705 { 706 } 707 708 NBLog::Reader::Reader(const sp<IMemory>& iMemory, size_t size) 709 : Reader(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL, size) 710 { 711 mIMemory = iMemory; 712 } 713 714 NBLog::Reader::~Reader() 715 { 716 delete mFifoReader; 717 delete mFifo; 718 } 719 720 const uint8_t *NBLog::Reader::findLastEntryOfTypes(const uint8_t *front, const uint8_t *back, 721 const std::set<Event> &types) { 722 while (back + Entry::kPreviousLengthOffset >= front) { 723 const uint8_t *prev = back - back[Entry::kPreviousLengthOffset] - Entry::kOverhead; 724 if (prev < front || prev + prev[offsetof(entry, length)] + 725 Entry::kOverhead != back) { 726 727 // prev points to an out of limits or inconsistent entry 728 return nullptr; 729 } 730 if (types.find((const Event) prev[offsetof(entry, type)]) != types.end()) { 731 return prev; 732 } 733 back = prev; 734 } 735 return nullptr; // no entry found 736 } 737 738 // Copies content of a Reader FIFO into its Snapshot 739 // The Snapshot has the same raw data, but represented as a sequence of entries 740 // and an EntryIterator making it possible to process the data. 741 std::unique_ptr<NBLog::Reader::Snapshot> NBLog::Reader::getSnapshot() 742 { 743 if (mFifoReader == NULL) { 744 return std::unique_ptr<NBLog::Reader::Snapshot>(new Snapshot()); 745 } 746 // make a copy to avoid race condition with writer 747 size_t capacity = mFifo->capacity(); 748 749 // This emulates the behaviour of audio_utils_fifo_reader::read, but without incrementing the 750 // reader index. The index is incremented after handling corruption, to after the last complete 751 // entry of the buffer 752 size_t lost; 753 audio_utils_iovec iovec[2]; 754 ssize_t availToRead = mFifoReader->obtain(iovec, capacity, NULL /*timeout*/, &lost); 755 if (availToRead <= 0) { 756 return std::unique_ptr<NBLog::Reader::Snapshot>(new Snapshot()); 757 } 758 759 std::unique_ptr<Snapshot> snapshot(new Snapshot(availToRead)); 760 memcpy(snapshot->mData, (const char *) mFifo->buffer() + iovec[0].mOffset, iovec[0].mLength); 761 if (iovec[1].mLength > 0) { 762 memcpy(snapshot->mData + (iovec[0].mLength), 763 (const char *) mFifo->buffer() + iovec[1].mOffset, iovec[1].mLength); 764 } 765 766 // Handle corrupted buffer 767 // Potentially, a buffer has corrupted data on both beginning (due to overflow) and end 768 // (due to incomplete format entry). But even if the end format entry is incomplete, 769 // it ends in a complete entry (which is not an END_FMT). So is safe to traverse backwards. 770 // TODO: handle client corruption (in the middle of a buffer) 771 772 const uint8_t *back = snapshot->mData + availToRead; 773 const uint8_t *front = snapshot->mData; 774 775 // Find last END_FMT. <back> is sitting on an entry which might be the middle of a FormatEntry. 776 // We go backwards until we find an EVENT_END_FMT. 777 const uint8_t *lastEnd = findLastEntryOfTypes(front, back, endingTypes); 778 if (lastEnd == nullptr) { 779 snapshot->mEnd = snapshot->mBegin = EntryIterator(front); 780 } else { 781 // end of snapshot points to after last END_FMT entry 782 snapshot->mEnd = EntryIterator(lastEnd).next(); 783 // find first START_FMT 784 const uint8_t *firstStart = nullptr; 785 const uint8_t *firstStartTmp = snapshot->mEnd; 786 while ((firstStartTmp = findLastEntryOfTypes(front, firstStartTmp, startingTypes)) 787 != nullptr) { 788 firstStart = firstStartTmp; 789 } 790 // firstStart is null if no START_FMT entry was found before lastEnd 791 if (firstStart == nullptr) { 792 snapshot->mBegin = snapshot->mEnd; 793 } else { 794 snapshot->mBegin = EntryIterator(firstStart); 795 } 796 } 797 798 // advance fifo reader index to after last entry read. 799 mFifoReader->release(snapshot->mEnd - front); 800 801 snapshot->mLost = lost; 802 return snapshot; 803 804 } 805 806 // Takes raw content of the local merger FIFO, processes log entries, and 807 // writes the data to a map of class PerformanceAnalysis, based on their thread ID. 808 void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Reader::Snapshot &snapshot) 809 { 810 String8 timestamp, body; 811 812 for (auto entry = snapshot.begin(); entry != snapshot.end();) { 813 switch (entry->type) { 814 case EVENT_START_FMT: 815 entry = handleFormat(FormatEntry(entry), ×tamp, &body); 816 break; 817 case EVENT_HISTOGRAM_ENTRY_TS: { 818 HistTsEntryWithAuthor *data = (HistTsEntryWithAuthor *) (entry->data); 819 // TODO This memcpies are here to avoid unaligned memory access crash. 820 // There's probably a more efficient way to do it 821 log_hash_t hash; 822 memcpy(&hash, &(data->hash), sizeof(hash)); 823 int64_t ts; 824 memcpy(&ts, &data->ts, sizeof(ts)); 825 // TODO: hash for histogram ts and audio state need to match 826 // and correspond to audio production source file location 827 mThreadPerformanceAnalysis[data->author][0 /*hash*/].logTsEntry(ts); 828 ++entry; 829 break; 830 } 831 case EVENT_AUDIO_STATE: { 832 HistTsEntryWithAuthor *data = (HistTsEntryWithAuthor *) (entry->data); 833 // TODO This memcpies are here to avoid unaligned memory access crash. 834 // There's probably a more efficient way to do it 835 log_hash_t hash; 836 memcpy(&hash, &(data->hash), sizeof(hash)); 837 // TODO: remove ts if unused 838 int64_t ts; 839 memcpy(&ts, &data->ts, sizeof(ts)); 840 mThreadPerformanceAnalysis[data->author][0 /*hash*/].handleStateChange(); 841 ++entry; 842 break; 843 } 844 case EVENT_END_FMT: 845 body.appendFormat("warning: got to end format event"); 846 ++entry; 847 break; 848 case EVENT_RESERVED: 849 default: 850 body.appendFormat("warning: unexpected event %d", entry->type); 851 ++entry; 852 break; 853 } 854 } 855 // FIXME: decide whether to print the warnings here or elsewhere 856 if (!body.isEmpty()) { 857 dumpLine(timestamp, body); 858 } 859 } 860 861 void NBLog::MergeReader::getAndProcessSnapshot() 862 { 863 // get a snapshot, process it 864 std::unique_ptr<Snapshot> snap = getSnapshot(); 865 getAndProcessSnapshot(*snap); 866 } 867 868 void NBLog::MergeReader::dump(int fd, int indent) { 869 // TODO: add a mutex around media.log dump 870 ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis); 871 } 872 873 // Writes a string to the console 874 void NBLog::Reader::dumpLine(const String8 ×tamp, String8 &body) 875 { 876 if (mFd >= 0) { 877 dprintf(mFd, "%.*s%s %s\n", mIndent, "", timestamp.string(), body.string()); 878 } else { 879 ALOGI("%.*s%s %s", mIndent, "", timestamp.string(), body.string()); 880 } 881 body.clear(); 882 } 883 884 bool NBLog::Reader::isIMemory(const sp<IMemory>& iMemory) const 885 { 886 return iMemory != 0 && mIMemory != 0 && iMemory->pointer() == mIMemory->pointer(); 887 } 888 889 // --------------------------------------------------------------------------- 890 891 void NBLog::appendTimestamp(String8 *body, const void *data) { 892 int64_t ts; 893 memcpy(&ts, data, sizeof(ts)); 894 body->appendFormat("[%d.%03d]", (int) (ts / (1000 * 1000 * 1000)), 895 (int) ((ts / (1000 * 1000)) % 1000)); 896 } 897 898 void NBLog::appendInt(String8 *body, const void *data) { 899 int x = *((int*) data); 900 body->appendFormat("<%d>", x); 901 } 902 903 void NBLog::appendFloat(String8 *body, const void *data) { 904 float f; 905 memcpy(&f, data, sizeof(float)); 906 body->appendFormat("<%f>", f); 907 } 908 909 void NBLog::appendPID(String8 *body, const void* data, size_t length) { 910 pid_t id = *((pid_t*) data); 911 char * name = &((char*) data)[sizeof(pid_t)]; 912 body->appendFormat("<PID: %d, name: %.*s>", id, (int) (length - sizeof(pid_t)), name); 913 } 914 915 String8 NBLog::bufferDump(const uint8_t *buffer, size_t size) 916 { 917 String8 str; 918 str.append("[ "); 919 for(size_t i = 0; i < size; i++) 920 { 921 str.appendFormat("%d ", buffer[i]); 922 } 923 str.append("]"); 924 return str; 925 } 926 927 String8 NBLog::bufferDump(const EntryIterator &it) 928 { 929 return bufferDump(it, it->length + Entry::kOverhead); 930 } 931 932 NBLog::EntryIterator NBLog::Reader::handleFormat(const FormatEntry &fmtEntry, 933 String8 *timestamp, 934 String8 *body) { 935 // log timestamp 936 int64_t ts = fmtEntry.timestamp(); 937 timestamp->clear(); 938 timestamp->appendFormat("[%d.%03d]", (int) (ts / (1000 * 1000 * 1000)), 939 (int) ((ts / (1000 * 1000)) % 1000)); 940 941 // log unique hash 942 log_hash_t hash = fmtEntry.hash(); 943 // print only lower 16bit of hash as hex and line as int to reduce spam in the log 944 body->appendFormat("%.4X-%d ", (int)(hash >> 16) & 0xFFFF, (int) hash & 0xFFFF); 945 946 // log author (if present) 947 handleAuthor(fmtEntry, body); 948 949 // log string 950 NBLog::EntryIterator arg = fmtEntry.args(); 951 952 const char* fmt = fmtEntry.formatString(); 953 size_t fmt_length = fmtEntry.formatStringLength(); 954 955 for (size_t fmt_offset = 0; fmt_offset < fmt_length; ++fmt_offset) { 956 if (fmt[fmt_offset] != '%') { 957 body->append(&fmt[fmt_offset], 1); // TODO optimize to write consecutive strings at once 958 continue; 959 } 960 // case "%%"" 961 if (fmt[++fmt_offset] == '%') { 962 body->append("%"); 963 continue; 964 } 965 // case "%\0" 966 if (fmt_offset == fmt_length) { 967 continue; 968 } 969 970 NBLog::Event event = (NBLog::Event) arg->type; 971 size_t length = arg->length; 972 973 // TODO check length for event type is correct 974 975 if (event == EVENT_END_FMT) { 976 break; 977 } 978 979 // TODO: implement more complex formatting such as %.3f 980 const uint8_t *datum = arg->data; // pointer to the current event args 981 switch(fmt[fmt_offset]) 982 { 983 case 's': // string 984 ALOGW_IF(event != EVENT_STRING, 985 "NBLog Reader incompatible event for string specifier: %d", event); 986 body->append((const char*) datum, length); 987 break; 988 989 case 't': // timestamp 990 ALOGW_IF(event != EVENT_TIMESTAMP, 991 "NBLog Reader incompatible event for timestamp specifier: %d", event); 992 appendTimestamp(body, datum); 993 break; 994 995 case 'd': // integer 996 ALOGW_IF(event != EVENT_INTEGER, 997 "NBLog Reader incompatible event for integer specifier: %d", event); 998 appendInt(body, datum); 999 break; 1000 1001 case 'f': // float 1002 ALOGW_IF(event != EVENT_FLOAT, 1003 "NBLog Reader incompatible event for float specifier: %d", event); 1004 appendFloat(body, datum); 1005 break; 1006 1007 case 'p': // pid 1008 ALOGW_IF(event != EVENT_PID, 1009 "NBLog Reader incompatible event for pid specifier: %d", event); 1010 appendPID(body, datum, length); 1011 break; 1012 1013 default: 1014 ALOGW("NBLog Reader encountered unknown character %c", fmt[fmt_offset]); 1015 } 1016 ++arg; 1017 } 1018 ALOGW_IF(arg->type != EVENT_END_FMT, "Expected end of format, got %d", arg->type); 1019 ++arg; 1020 return arg; 1021 } 1022 1023 NBLog::Merger::Merger(const void *shared, size_t size): 1024 mShared((Shared *) shared), 1025 mFifo(mShared != NULL ? 1026 new audio_utils_fifo(size, sizeof(uint8_t), 1027 mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL), 1028 mFifoWriter(mFifo != NULL ? new audio_utils_fifo_writer(*mFifo) : NULL) 1029 {} 1030 1031 void NBLog::Merger::addReader(const NBLog::NamedReader &reader) { 1032 1033 // FIXME This is called by binder thread in MediaLogService::registerWriter 1034 // but the access to shared variable mNamedReaders is not yet protected by a lock. 1035 mNamedReaders.push_back(reader); 1036 } 1037 1038 // items placed in priority queue during merge 1039 // composed by a timestamp and the index of the snapshot where the timestamp came from 1040 struct MergeItem 1041 { 1042 int64_t ts; 1043 int index; 1044 MergeItem(int64_t ts, int index): ts(ts), index(index) {} 1045 }; 1046 1047 // operators needed for priority queue in merge 1048 // bool operator>(const int64_t &t1, const int64_t &t2) { 1049 // return t1.tv_sec > t2.tv_sec || (t1.tv_sec == t2.tv_sec && t1.tv_nsec > t2.tv_nsec); 1050 // } 1051 1052 bool operator>(const struct MergeItem &i1, const struct MergeItem &i2) { 1053 return i1.ts > i2.ts || (i1.ts == i2.ts && i1.index > i2.index); 1054 } 1055 1056 // Merge registered readers, sorted by timestamp, and write data to a single FIFO in local memory 1057 void NBLog::Merger::merge() { 1058 // FIXME This is called by merge thread 1059 // but the access to shared variable mNamedReaders is not yet protected by a lock. 1060 int nLogs = mNamedReaders.size(); 1061 std::vector<std::unique_ptr<NBLog::Reader::Snapshot>> snapshots(nLogs); 1062 std::vector<NBLog::EntryIterator> offsets(nLogs); 1063 for (int i = 0; i < nLogs; ++i) { 1064 snapshots[i] = mNamedReaders[i].reader()->getSnapshot(); 1065 offsets[i] = snapshots[i]->begin(); 1066 } 1067 // initialize offsets 1068 // TODO custom heap implementation could allow to update top, improving performance 1069 // for bursty buffers 1070 std::priority_queue<MergeItem, std::vector<MergeItem>, std::greater<MergeItem>> timestamps; 1071 for (int i = 0; i < nLogs; ++i) 1072 { 1073 if (offsets[i] != snapshots[i]->end()) { 1074 int64_t ts = AbstractEntry::buildEntry(offsets[i])->timestamp(); 1075 timestamps.emplace(ts, i); 1076 } 1077 } 1078 1079 while (!timestamps.empty()) { 1080 // find minimum timestamp 1081 int index = timestamps.top().index; 1082 // copy it to the log, increasing offset 1083 offsets[index] = AbstractEntry::buildEntry(offsets[index])->copyWithAuthor(mFifoWriter, 1084 index); 1085 // update data structures 1086 timestamps.pop(); 1087 if (offsets[index] != snapshots[index]->end()) { 1088 int64_t ts = AbstractEntry::buildEntry(offsets[index])->timestamp(); 1089 timestamps.emplace(ts, index); 1090 } 1091 } 1092 } 1093 1094 const std::vector<NBLog::NamedReader>& NBLog::Merger::getNamedReaders() const { 1095 // FIXME This is returning a reference to a shared variable that needs a lock 1096 return mNamedReaders; 1097 } 1098 1099 // --------------------------------------------------------------------------- 1100 1101 NBLog::MergeReader::MergeReader(const void *shared, size_t size, Merger &merger) 1102 : Reader(shared, size), mNamedReaders(merger.getNamedReaders()) {} 1103 1104 void NBLog::MergeReader::handleAuthor(const NBLog::AbstractEntry &entry, String8 *body) { 1105 int author = entry.author(); 1106 // FIXME Needs a lock 1107 const char* name = mNamedReaders[author].name(); 1108 body->appendFormat("%s: ", name); 1109 } 1110 1111 // --------------------------------------------------------------------------- 1112 1113 NBLog::MergeThread::MergeThread(NBLog::Merger &merger, NBLog::MergeReader &mergeReader) 1114 : mMerger(merger), 1115 mMergeReader(mergeReader), 1116 mTimeoutUs(0) {} 1117 1118 NBLog::MergeThread::~MergeThread() { 1119 // set exit flag, set timeout to 0 to force threadLoop to exit and wait for the thread to join 1120 requestExit(); 1121 setTimeoutUs(0); 1122 join(); 1123 } 1124 1125 bool NBLog::MergeThread::threadLoop() { 1126 bool doMerge; 1127 { 1128 AutoMutex _l(mMutex); 1129 // If mTimeoutUs is negative, wait on the condition variable until it's positive. 1130 // If it's positive, wait kThreadSleepPeriodUs and then merge 1131 nsecs_t waitTime = mTimeoutUs > 0 ? kThreadSleepPeriodUs * 1000 : LLONG_MAX; 1132 mCond.waitRelative(mMutex, waitTime); 1133 doMerge = mTimeoutUs > 0; 1134 mTimeoutUs -= kThreadSleepPeriodUs; 1135 } 1136 if (doMerge) { 1137 // Merge data from all the readers 1138 mMerger.merge(); 1139 // Process the data collected by mMerger and write it to PerformanceAnalysis 1140 // FIXME: decide whether to call getAndProcessSnapshot every time 1141 // or whether to have a separate thread that calls it with a lower frequency 1142 mMergeReader.getAndProcessSnapshot(); 1143 } 1144 return true; 1145 } 1146 1147 void NBLog::MergeThread::wakeup() { 1148 setTimeoutUs(kThreadWakeupPeriodUs); 1149 } 1150 1151 void NBLog::MergeThread::setTimeoutUs(int time) { 1152 AutoMutex _l(mMutex); 1153 mTimeoutUs = time; 1154 mCond.signal(); 1155 } 1156 1157 } // namespace android 1158