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#define LOG_TAG "NBLog" 18//#define LOG_NDEBUG 0 19 20#include <stdarg.h> 21#include <stdint.h> 22#include <stdio.h> 23#include <string.h> 24#include <time.h> 25#include <new> 26#include <cutils/atomic.h> 27#include <media/nbaio/NBLog.h> 28#include <utils/Log.h> 29 30namespace android { 31 32int NBLog::Entry::readAt(size_t offset) const 33{ 34 // FIXME This is too slow, despite the name it is used during writing 35 if (offset == 0) 36 return mEvent; 37 else if (offset == 1) 38 return mLength; 39 else if (offset < (size_t) (mLength + 2)) 40 return ((char *) mData)[offset - 2]; 41 else if (offset == (size_t) (mLength + 2)) 42 return mLength; 43 else 44 return 0; 45} 46 47// --------------------------------------------------------------------------- 48 49#if 0 // FIXME see note in NBLog.h 50NBLog::Timeline::Timeline(size_t size, void *shared) 51 : mSize(roundup(size)), mOwn(shared == NULL), 52 mShared((Shared *) (mOwn ? new char[sharedSize(size)] : shared)) 53{ 54 new (mShared) Shared; 55} 56 57NBLog::Timeline::~Timeline() 58{ 59 mShared->~Shared(); 60 if (mOwn) { 61 delete[] (char *) mShared; 62 } 63} 64#endif 65 66/*static*/ 67size_t NBLog::Timeline::sharedSize(size_t size) 68{ 69 return sizeof(Shared) + roundup(size); 70} 71 72// --------------------------------------------------------------------------- 73 74NBLog::Writer::Writer() 75 : mSize(0), mShared(NULL), mRear(0), mEnabled(false) 76{ 77} 78 79NBLog::Writer::Writer(size_t size, void *shared) 80 : mSize(roundup(size)), mShared((Shared *) shared), mRear(0), mEnabled(mShared != NULL) 81{ 82} 83 84NBLog::Writer::Writer(size_t size, const sp<IMemory>& iMemory) 85 : mSize(roundup(size)), mShared(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL), 86 mIMemory(iMemory), mRear(0), mEnabled(mShared != NULL) 87{ 88} 89 90void NBLog::Writer::log(const char *string) 91{ 92 if (!mEnabled) { 93 return; 94 } 95 size_t length = strlen(string); 96 if (length > 255) { 97 length = 255; 98 } 99 log(EVENT_STRING, string, length); 100} 101 102void NBLog::Writer::logf(const char *fmt, ...) 103{ 104 if (!mEnabled) { 105 return; 106 } 107 va_list ap; 108 va_start(ap, fmt); 109 Writer::logvf(fmt, ap); // the Writer:: is needed to avoid virtual dispatch for LockedWriter 110 va_end(ap); 111} 112 113void NBLog::Writer::logvf(const char *fmt, va_list ap) 114{ 115 if (!mEnabled) { 116 return; 117 } 118 char buffer[256]; 119 int length = vsnprintf(buffer, sizeof(buffer), fmt, ap); 120 if (length >= (int) sizeof(buffer)) { 121 length = sizeof(buffer) - 1; 122 // NUL termination is not required 123 // buffer[length] = '\0'; 124 } 125 if (length >= 0) { 126 log(EVENT_STRING, buffer, length); 127 } 128} 129 130void NBLog::Writer::logTimestamp() 131{ 132 if (!mEnabled) { 133 return; 134 } 135 struct timespec ts; 136 if (!clock_gettime(CLOCK_MONOTONIC, &ts)) { 137 log(EVENT_TIMESTAMP, &ts, sizeof(struct timespec)); 138 } 139} 140 141void NBLog::Writer::logTimestamp(const struct timespec& ts) 142{ 143 if (!mEnabled) { 144 return; 145 } 146 log(EVENT_TIMESTAMP, &ts, sizeof(struct timespec)); 147} 148 149void NBLog::Writer::log(Event event, const void *data, size_t length) 150{ 151 if (!mEnabled) { 152 return; 153 } 154 if (data == NULL || length > 255) { 155 return; 156 } 157 switch (event) { 158 case EVENT_STRING: 159 case EVENT_TIMESTAMP: 160 break; 161 case EVENT_RESERVED: 162 default: 163 return; 164 } 165 Entry entry(event, data, length); 166 log(&entry, true /*trusted*/); 167} 168 169void NBLog::Writer::log(const NBLog::Entry *entry, bool trusted) 170{ 171 if (!mEnabled) { 172 return; 173 } 174 if (!trusted) { 175 log(entry->mEvent, entry->mData, entry->mLength); 176 return; 177 } 178 size_t rear = mRear & (mSize - 1); 179 size_t written = mSize - rear; // written = number of bytes that have been written so far 180 size_t need = entry->mLength + 3; // mEvent, mLength, data[length], mLength 181 // need = number of bytes remaining to write 182 if (written > need) { 183 written = need; 184 } 185 size_t i; 186 // FIXME optimize this using memcpy for the data part of the Entry. 187 // The Entry could have a method copyTo(ptr, offset, size) to optimize the copy. 188 for (i = 0; i < written; ++i) { 189 mShared->mBuffer[rear + i] = entry->readAt(i); 190 } 191 if (rear + written == mSize && (need -= written) > 0) { 192 for (i = 0; i < need; ++i) { 193 mShared->mBuffer[i] = entry->readAt(written + i); 194 } 195 written += need; 196 } 197 android_atomic_release_store(mRear += written, &mShared->mRear); 198} 199 200bool NBLog::Writer::isEnabled() const 201{ 202 return mEnabled; 203} 204 205bool NBLog::Writer::setEnabled(bool enabled) 206{ 207 bool old = mEnabled; 208 mEnabled = enabled && mShared != NULL; 209 return old; 210} 211 212// --------------------------------------------------------------------------- 213 214NBLog::LockedWriter::LockedWriter() 215 : Writer() 216{ 217} 218 219NBLog::LockedWriter::LockedWriter(size_t size, void *shared) 220 : Writer(size, shared) 221{ 222} 223 224void NBLog::LockedWriter::log(const char *string) 225{ 226 Mutex::Autolock _l(mLock); 227 Writer::log(string); 228} 229 230void NBLog::LockedWriter::logf(const char *fmt, ...) 231{ 232 // FIXME should not take the lock until after formatting is done 233 Mutex::Autolock _l(mLock); 234 va_list ap; 235 va_start(ap, fmt); 236 Writer::logvf(fmt, ap); 237 va_end(ap); 238} 239 240void NBLog::LockedWriter::logvf(const char *fmt, va_list ap) 241{ 242 // FIXME should not take the lock until after formatting is done 243 Mutex::Autolock _l(mLock); 244 Writer::logvf(fmt, ap); 245} 246 247void NBLog::LockedWriter::logTimestamp() 248{ 249 // FIXME should not take the lock until after the clock_gettime() syscall 250 Mutex::Autolock _l(mLock); 251 Writer::logTimestamp(); 252} 253 254void NBLog::LockedWriter::logTimestamp(const struct timespec& ts) 255{ 256 Mutex::Autolock _l(mLock); 257 Writer::logTimestamp(ts); 258} 259 260bool NBLog::LockedWriter::isEnabled() const 261{ 262 Mutex::Autolock _l(mLock); 263 return Writer::isEnabled(); 264} 265 266bool NBLog::LockedWriter::setEnabled(bool enabled) 267{ 268 Mutex::Autolock _l(mLock); 269 return Writer::setEnabled(enabled); 270} 271 272// --------------------------------------------------------------------------- 273 274NBLog::Reader::Reader(size_t size, const void *shared) 275 : mSize(roundup(size)), mShared((const Shared *) shared), mFront(0) 276{ 277} 278 279NBLog::Reader::Reader(size_t size, const sp<IMemory>& iMemory) 280 : mSize(roundup(size)), mShared(iMemory != 0 ? (const Shared *) iMemory->pointer() : NULL), 281 mIMemory(iMemory), mFront(0) 282{ 283} 284 285void NBLog::Reader::dump(int fd, size_t indent) 286{ 287 int32_t rear = android_atomic_acquire_load(&mShared->mRear); 288 size_t avail = rear - mFront; 289 if (avail == 0) { 290 return; 291 } 292 size_t lost = 0; 293 if (avail > mSize) { 294 lost = avail - mSize; 295 mFront += lost; 296 avail = mSize; 297 } 298 size_t remaining = avail; // remaining = number of bytes left to read 299 size_t front = mFront & (mSize - 1); 300 size_t read = mSize - front; // read = number of bytes that have been read so far 301 if (read > remaining) { 302 read = remaining; 303 } 304 // make a copy to avoid race condition with writer 305 uint8_t *copy = new uint8_t[avail]; 306 // copy first part of circular buffer up until the wraparound point 307 memcpy(copy, &mShared->mBuffer[front], read); 308 if (front + read == mSize) { 309 if ((remaining -= read) > 0) { 310 // copy second part of circular buffer starting at beginning 311 memcpy(©[read], mShared->mBuffer, remaining); 312 read += remaining; 313 // remaining = 0 but not necessary 314 } 315 } 316 mFront += read; 317 size_t i = avail; 318 Event event; 319 size_t length; 320 struct timespec ts; 321 time_t maxSec = -1; 322 while (i >= 3) { 323 length = copy[i - 1]; 324 if (length + 3 > i || copy[i - length - 2] != length) { 325 break; 326 } 327 event = (Event) copy[i - length - 3]; 328 if (event == EVENT_TIMESTAMP) { 329 if (length != sizeof(struct timespec)) { 330 // corrupt 331 break; 332 } 333 memcpy(&ts, ©[i - length - 1], sizeof(struct timespec)); 334 if (ts.tv_sec > maxSec) { 335 maxSec = ts.tv_sec; 336 } 337 } 338 i -= length + 3; 339 } 340 if (i > 0) { 341 lost += i; 342 if (fd >= 0) { 343 fdprintf(fd, "%*swarning: lost %u bytes worth of events\n", indent, "", lost); 344 } else { 345 ALOGI("%*swarning: lost %u bytes worth of events\n", indent, "", lost); 346 } 347 } 348 size_t width = 1; 349 while (maxSec >= 10) { 350 ++width; 351 maxSec /= 10; 352 } 353 char prefix[32]; 354 if (maxSec >= 0) { 355 snprintf(prefix, sizeof(prefix), "[%*s] ", width + 4, ""); 356 } else { 357 prefix[0] = '\0'; 358 } 359 while (i < avail) { 360 event = (Event) copy[i]; 361 length = copy[i + 1]; 362 const void *data = ©[i + 2]; 363 size_t advance = length + 3; 364 switch (event) { 365 case EVENT_STRING: 366 if (fd >= 0) { 367 fdprintf(fd, "%*s%s%.*s\n", indent, "", prefix, length, (const char *) data); 368 } else { 369 ALOGI("%*s%s%.*s", indent, "", prefix, length, (const char *) data); 370 } break; 371 case EVENT_TIMESTAMP: { 372 // already checked that length == sizeof(struct timespec); 373 memcpy(&ts, data, sizeof(struct timespec)); 374 long prevNsec = ts.tv_nsec; 375 long deltaMin = LONG_MAX; 376 long deltaMax = -1; 377 long deltaTotal = 0; 378 size_t j = i; 379 for (;;) { 380 j += sizeof(struct timespec) + 3; 381 if (j >= avail || (Event) copy[j] != EVENT_TIMESTAMP) { 382 break; 383 } 384 struct timespec tsNext; 385 memcpy(&tsNext, ©[j + 2], sizeof(struct timespec)); 386 if (tsNext.tv_sec != ts.tv_sec) { 387 break; 388 } 389 long delta = tsNext.tv_nsec - prevNsec; 390 if (delta < 0) { 391 break; 392 } 393 if (delta < deltaMin) { 394 deltaMin = delta; 395 } 396 if (delta > deltaMax) { 397 deltaMax = delta; 398 } 399 deltaTotal += delta; 400 prevNsec = tsNext.tv_nsec; 401 } 402 size_t n = (j - i) / (sizeof(struct timespec) + 3); 403 if (n >= kSquashTimestamp) { 404 if (fd >= 0) { 405 fdprintf(fd, "%*s[%d.%03d to .%.03d by .%.03d to .%.03d]\n", indent, "", 406 (int) ts.tv_sec, (int) (ts.tv_nsec / 1000000), 407 (int) ((ts.tv_nsec + deltaTotal) / 1000000), 408 (int) (deltaMin / 1000000), (int) (deltaMax / 1000000)); 409 } else { 410 ALOGI("%*s[%d.%03d to .%.03d by .%.03d to .%.03d]\n", indent, "", 411 (int) ts.tv_sec, (int) (ts.tv_nsec / 1000000), 412 (int) ((ts.tv_nsec + deltaTotal) / 1000000), 413 (int) (deltaMin / 1000000), (int) (deltaMax / 1000000)); 414 } 415 i = j; 416 advance = 0; 417 break; 418 } 419 if (fd >= 0) { 420 fdprintf(fd, "%*s[%d.%03d]\n", indent, "", (int) ts.tv_sec, 421 (int) (ts.tv_nsec / 1000000)); 422 } else { 423 ALOGI("%*s[%d.%03d]", indent, "", (int) ts.tv_sec, 424 (int) (ts.tv_nsec / 1000000)); 425 } 426 } break; 427 case EVENT_RESERVED: 428 default: 429 if (fd >= 0) { 430 fdprintf(fd, "%*s%swarning: unknown event %d\n", indent, "", prefix, event); 431 } else { 432 ALOGI("%*s%swarning: unknown event %d", indent, "", prefix, event); 433 } 434 break; 435 } 436 i += advance; 437 } 438 // FIXME it would be more efficient to put a char mCopy[256] as a member variable of the dumper 439 delete[] copy; 440} 441 442bool NBLog::Reader::isIMemory(const sp<IMemory>& iMemory) const 443{ 444 return iMemory.get() == mIMemory.get(); 445} 446 447} // namespace android 448