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
copyEntryDataAt(size_t offset) const49 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*/
buildEntry(const uint8_t * ptr)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
AbstractEntry(const uint8_t * entry)81 NBLog::AbstractEntry::AbstractEntry(const uint8_t *entry) : mEntry(entry) {
82 }
83
84 // ---------------------------------------------------------------------------
85
begin() const86 NBLog::EntryIterator NBLog::FormatEntry::begin() const {
87 return EntryIterator(mEntry);
88 }
89
formatString() const90 const char *NBLog::FormatEntry::formatString() const {
91 return (const char*) mEntry + offsetof(entry, data);
92 }
93
formatStringLength() const94 size_t NBLog::FormatEntry::formatStringLength() const {
95 return mEntry[offsetof(entry, length)];
96 }
97
args() const98 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
timestamp() const113 int64_t NBLog::FormatEntry::timestamp() const {
114 auto it = begin();
115 // skip start fmt
116 ++it;
117 return it.payload<int64_t>();
118 }
119
hash() const120 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
author() const132 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
copyWithAuthor(std::unique_ptr<audio_utils_fifo_writer> & dst,int author) const147 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
copyTo(std::unique_ptr<audio_utils_fifo_writer> & dst) const173 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
copyData(uint8_t * dst) const178 void NBLog::EntryIterator::copyData(uint8_t *dst) const {
179 memcpy((void*) dst, ptr + offsetof(entry, data), ptr[offsetof(entry, length)]);
180 }
181
EntryIterator()182 NBLog::EntryIterator::EntryIterator()
183 : ptr(nullptr) {}
184
EntryIterator(const uint8_t * entry)185 NBLog::EntryIterator::EntryIterator(const uint8_t *entry)
186 : ptr(entry) {}
187
EntryIterator(const NBLog::EntryIterator & other)188 NBLog::EntryIterator::EntryIterator(const NBLog::EntryIterator &other)
189 : ptr(other.ptr) {}
190
operator *() const191 const NBLog::entry& NBLog::EntryIterator::operator*() const {
192 return *(entry*) ptr;
193 }
194
operator ->() const195 const NBLog::entry* NBLog::EntryIterator::operator->() const {
196 return (entry*) ptr;
197 }
198
operator ++()199 NBLog::EntryIterator& NBLog::EntryIterator::operator++() {
200 ptr += ptr[offsetof(entry, length)] + NBLog::Entry::kOverhead;
201 return *this;
202 }
203
operator --()204 NBLog::EntryIterator& NBLog::EntryIterator::operator--() {
205 ptr -= ptr[NBLog::Entry::kPreviousLengthOffset] + NBLog::Entry::kOverhead;
206 return *this;
207 }
208
next() const209 NBLog::EntryIterator NBLog::EntryIterator::next() const {
210 EntryIterator aux(*this);
211 return ++aux;
212 }
213
prev() const214 NBLog::EntryIterator NBLog::EntryIterator::prev() const {
215 EntryIterator aux(*this);
216 return --aux;
217 }
218
operator -(const NBLog::EntryIterator & other) const219 int NBLog::EntryIterator::operator-(const NBLog::EntryIterator &other) const {
220 return ptr - other.ptr;
221 }
222
operator !=(const EntryIterator & other) const223 bool NBLog::EntryIterator::operator!=(const EntryIterator &other) const {
224 return ptr != other.ptr;
225 }
226
hasConsistentLength() const227 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
timestamp() const234 int64_t NBLog::HistogramEntry::timestamp() const {
235 return EntryIterator(mEntry).payload<HistTsEntry>().ts;
236 }
237
hash() const238 NBLog::log_hash_t NBLog::HistogramEntry::hash() const {
239 return EntryIterator(mEntry).payload<HistTsEntry>().hash;
240 }
241
author() const242 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
copyWithAuthor(std::unique_ptr<audio_utils_fifo_writer> & dst,int author) const251 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*/
sharedSize(size_t size)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
Writer()297 NBLog::Writer::Writer()
298 : mShared(NULL), mFifo(NULL), mFifoWriter(NULL), mEnabled(false), mPidTag(NULL), mPidTagSize(0)
299 {
300 }
301
Writer(void * shared,size_t size)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
Writer(const sp<IMemory> & iMemory,size_t size)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
~Writer()330 NBLog::Writer::~Writer()
331 {
332 delete mFifoWriter;
333 delete mFifo;
334 delete[] mPidTag;
335 }
336
log(const char * string)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
logf(const char * fmt,...)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
logvf(const char * fmt,va_list ap)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
logTimestamp()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
logTimestamp(const int64_t ts)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
logInteger(const int x)399 void NBLog::Writer::logInteger(const int x)
400 {
401 if (!mEnabled) {
402 return;
403 }
404 log(EVENT_INTEGER, &x, sizeof(x));
405 }
406
logFloat(const float x)407 void NBLog::Writer::logFloat(const float x)
408 {
409 if (!mEnabled) {
410 return;
411 }
412 log(EVENT_FLOAT, &x, sizeof(x));
413 }
414
logPID()415 void NBLog::Writer::logPID()
416 {
417 if (!mEnabled) {
418 return;
419 }
420 log(EVENT_PID, mPidTag, mPidTagSize);
421 }
422
logStart(const char * fmt)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
logEnd()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
logHash(log_hash_t hash)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
logEventHistTs(Event event,log_hash_t hash)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
logFormat(const char * fmt,log_hash_t hash,...)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
logVFormat(const char * fmt,log_hash_t hash,va_list argp)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
log(Event event,const void * data,size_t length)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
log(const NBLog::Entry * etr,bool trusted)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
isEnabled() const580 bool NBLog::Writer::isEnabled() const
581 {
582 return mEnabled;
583 }
584
setEnabled(bool enabled)585 bool NBLog::Writer::setEnabled(bool enabled)
586 {
587 bool old = mEnabled;
588 mEnabled = enabled && mShared != NULL;
589 return old;
590 }
591
592 // ---------------------------------------------------------------------------
593
LockedWriter()594 NBLog::LockedWriter::LockedWriter()
595 : Writer()
596 {
597 }
598
LockedWriter(void * shared,size_t size)599 NBLog::LockedWriter::LockedWriter(void *shared, size_t size)
600 : Writer(shared, size)
601 {
602 }
603
log(const char * string)604 void NBLog::LockedWriter::log(const char *string)
605 {
606 Mutex::Autolock _l(mLock);
607 Writer::log(string);
608 }
609
logf(const char * fmt,...)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
logvf(const char * fmt,va_list ap)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
logTimestamp()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
logTimestamp(const int64_t ts)634 void NBLog::LockedWriter::logTimestamp(const int64_t ts)
635 {
636 Mutex::Autolock _l(mLock);
637 Writer::logTimestamp(ts);
638 }
639
logInteger(const int x)640 void NBLog::LockedWriter::logInteger(const int x)
641 {
642 Mutex::Autolock _l(mLock);
643 Writer::logInteger(x);
644 }
645
logFloat(const float x)646 void NBLog::LockedWriter::logFloat(const float x)
647 {
648 Mutex::Autolock _l(mLock);
649 Writer::logFloat(x);
650 }
651
logPID()652 void NBLog::LockedWriter::logPID()
653 {
654 Mutex::Autolock _l(mLock);
655 Writer::logPID();
656 }
657
logStart(const char * fmt)658 void NBLog::LockedWriter::logStart(const char *fmt)
659 {
660 Mutex::Autolock _l(mLock);
661 Writer::logStart(fmt);
662 }
663
664
logEnd()665 void NBLog::LockedWriter::logEnd()
666 {
667 Mutex::Autolock _l(mLock);
668 Writer::logEnd();
669 }
670
logHash(log_hash_t hash)671 void NBLog::LockedWriter::logHash(log_hash_t hash)
672 {
673 Mutex::Autolock _l(mLock);
674 Writer::logHash(hash);
675 }
676
isEnabled() const677 bool NBLog::LockedWriter::isEnabled() const
678 {
679 Mutex::Autolock _l(mLock);
680 return Writer::isEnabled();
681 }
682
setEnabled(bool enabled)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
Reader(const void * shared,size_t size)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
Reader(const sp<IMemory> & iMemory,size_t size)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
~Reader()714 NBLog::Reader::~Reader()
715 {
716 delete mFifoReader;
717 delete mFifo;
718 }
719
findLastEntryOfTypes(const uint8_t * front,const uint8_t * back,const std::set<Event> & types)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.
getSnapshot()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.
getAndProcessSnapshot(NBLog::Reader::Snapshot & snapshot)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
getAndProcessSnapshot()861 void NBLog::MergeReader::getAndProcessSnapshot()
862 {
863 // get a snapshot, process it
864 std::unique_ptr<Snapshot> snap = getSnapshot();
865 getAndProcessSnapshot(*snap);
866 }
867
dump(int fd,int indent)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
dumpLine(const String8 & timestamp,String8 & body)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
isIMemory(const sp<IMemory> & iMemory) const884 bool NBLog::Reader::isIMemory(const sp<IMemory>& iMemory) const
885 {
886 return iMemory != 0 && mIMemory != 0 && iMemory->pointer() == mIMemory->pointer();
887 }
888
889 // ---------------------------------------------------------------------------
890
appendTimestamp(String8 * body,const void * data)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
appendInt(String8 * body,const void * data)898 void NBLog::appendInt(String8 *body, const void *data) {
899 int x = *((int*) data);
900 body->appendFormat("<%d>", x);
901 }
902
appendFloat(String8 * body,const void * data)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
appendPID(String8 * body,const void * data,size_t length)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
bufferDump(const uint8_t * buffer,size_t size)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
bufferDump(const EntryIterator & it)927 String8 NBLog::bufferDump(const EntryIterator &it)
928 {
929 return bufferDump(it, it->length + Entry::kOverhead);
930 }
931
handleFormat(const FormatEntry & fmtEntry,String8 * timestamp,String8 * body)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
Merger(const void * shared,size_t size)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
addReader(const NBLog::NamedReader & reader)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;
MergeItemandroid::MergeItem1044 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
operator >(const struct MergeItem & i1,const struct MergeItem & i2)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
merge()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
getNamedReaders() const1094 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
MergeReader(const void * shared,size_t size,Merger & merger)1101 NBLog::MergeReader::MergeReader(const void *shared, size_t size, Merger &merger)
1102 : Reader(shared, size), mNamedReaders(merger.getNamedReaders()) {}
1103
handleAuthor(const NBLog::AbstractEntry & entry,String8 * body)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
MergeThread(NBLog::Merger & merger,NBLog::MergeReader & mergeReader)1113 NBLog::MergeThread::MergeThread(NBLog::Merger &merger, NBLog::MergeReader &mergeReader)
1114 : mMerger(merger),
1115 mMergeReader(mergeReader),
1116 mTimeoutUs(0) {}
1117
~MergeThread()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
threadLoop()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
wakeup()1147 void NBLog::MergeThread::wakeup() {
1148 setTimeoutUs(kThreadWakeupPeriodUs);
1149 }
1150
setTimeoutUs(int time)1151 void NBLog::MergeThread::setTimeoutUs(int time) {
1152 AutoMutex _l(mMutex);
1153 mTimeoutUs = time;
1154 mCond.signal();
1155 }
1156
1157 } // namespace android
1158