/* * Measure the time it takes for the logd posting call to make it into * the logs. Expect this to be less than double the process wakeup time (2ms). */ static void BM_log_delay(benchmark::State& state) { pid_t pid = getpid(); struct logger_list* logger_list = android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid); if (!logger_list) { fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); exit(EXIT_FAILURE); } signal(SIGALRM, caught_delay); alarm(alarm_time); while (state.KeepRunning()) { log_time ts(CLOCK_REALTIME); LOG_FAILURE_RETRY(android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); for (;;) { log_msg log_msg; int ret = android_logger_list_read(logger_list, &log_msg); alarm(alarm_time); if (ret <= 0) { state.SkipWithError("android_logger_list_read"); break; } if ((log_msg.entry.len != (4 + 1 + 8)) || (log_msg.id() != LOG_ID_EVENTS)) { continue; } char* eventData = log_msg.msg(); if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) { continue; } log_time tx(eventData + 4 + 1); if (ts != tx) { if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) { state.SkipWithError("signal"); break; } continue; } break; } } state.PauseTiming(); signal(SIGALRM, SIG_DFL); alarm(0); android_logger_list_free(logger_list); }
void dvmLogMadviseStats(size_t madvisedSizes[], size_t arrayLen) { unsigned char eventBuf[1 + (1 + sizeof(int)) * 2]; size_t total, zyg; size_t firstHeap, i; size_t nHeaps = dvmHeapSourceGetNumHeaps(); assert(arrayLen >= nHeaps); firstHeap = nHeaps > 1 ? 1 : 0; total = 0; zyg = 0; for (i = 0; i < nHeaps; i++) { total += madvisedSizes[i]; if (i >= firstHeap) { zyg += madvisedSizes[i]; } } /* Build the event data. * [ 0: 0] item count (2) * [ 1: 1] EVENT_TYPE_INT * [ 2: 5] total madvise byte count * [ 6: 6] EVENT_TYPE_INT * [ 7:10] zygote heap madvise byte count */ unsigned char *c = eventBuf; *c++ = 2; *c++ = EVENT_TYPE_INT; memcpy(c, &total, sizeof(total)); c += sizeof(total); *c++ = EVENT_TYPE_INT; memcpy(c, &zyg, sizeof(zyg)); c += sizeof(zyg); (void) android_btWriteLog(EVENT_LOG_TAG_dvm_gc_madvise_info, EVENT_TYPE_LIST, eventBuf, sizeof(eventBuf)); }
/* * Measure the time it takes for the logd posting call to make it into * the logs. Expect this to be less than double the process wakeup time (2ms). */ static void BM_log_delay(int iters) { pid_t pid = getpid(); struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS, O_RDONLY, 0, pid); if (!logger_list) { fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); exit(EXIT_FAILURE); } signal(SIGALRM, caught_delay); alarm(alarm_time); StartBenchmarkTiming(); for (int i = 0; i < iters; ++i) { log_time ts(CLOCK_REALTIME); LOG_FAILURE_RETRY( android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); for (;;) { log_msg log_msg; int ret = android_logger_list_read(logger_list, &log_msg); alarm(alarm_time); if (ret <= 0) { iters = i; break; } if ((log_msg.entry.len != (4 + 1 + 8)) || (log_msg.id() != LOG_ID_EVENTS)) { continue; } char* eventData = log_msg.msg(); if (eventData[4] != EVENT_TYPE_LONG) { continue; } log_time tx(eventData + 4 + 1); if (ts != tx) { if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) { iters = i; break; } continue; } break; } } signal(SIGALRM, SIG_DFL); alarm(0); StopBenchmarkTiming(); android_logger_list_free(logger_list); }
static void logContentionEvent(Thread *self, u4 waitMs, u4 samplePercent, const char *ownerFileName, u4 ownerLineNumber) { const StackSaveArea *saveArea; const Method *meth; u4 relativePc; char eventBuffer[174]; const char *fileName; char procName[33]; char *cp; size_t len; int fd; /* When a thread is being destroyed it is normal that the frame depth is zero */ if (self->interpSave.curFrame == NULL) { return; } saveArea = SAVEAREA_FROM_FP(self->interpSave.curFrame); meth = saveArea->method; cp = eventBuffer; /* Emit the event list length, 1 byte. */ *cp++ = 9; /* Emit the process name, <= 37 bytes. */ fd = open("/proc/self/cmdline", O_RDONLY); memset(procName, 0, sizeof(procName)); read(fd, procName, sizeof(procName) - 1); close(fd); len = strlen(procName); cp = logWriteString(cp, procName, len); /* Emit the sensitive thread ("main thread") status, 5 bytes. */ bool isSensitive = false; if (gDvm.isSensitiveThreadHook != NULL) { isSensitive = gDvm.isSensitiveThreadHook(); } cp = logWriteInt(cp, isSensitive); /* Emit self thread name string, <= 37 bytes. */ std::string selfName = dvmGetThreadName(self); cp = logWriteString(cp, selfName.c_str(), selfName.size()); /* Emit the wait time, 5 bytes. */ cp = logWriteInt(cp, waitMs); /* Emit the source code file name, <= 37 bytes. */ fileName = dvmGetMethodSourceFile(meth); if (fileName == NULL) fileName = ""; cp = logWriteString(cp, fileName, strlen(fileName)); /* Emit the source code line number, 5 bytes. */ relativePc = saveArea->xtra.currentPc - saveArea->method->insns; cp = logWriteInt(cp, dvmLineNumFromPC(meth, relativePc)); /* Emit the lock owner source code file name, <= 37 bytes. */ if (ownerFileName == NULL) { ownerFileName = ""; } else if (strcmp(fileName, ownerFileName) == 0) { /* Common case, so save on log space. */ ownerFileName = "-"; } cp = logWriteString(cp, ownerFileName, strlen(ownerFileName)); /* Emit the source code line number, 5 bytes. */ cp = logWriteInt(cp, ownerLineNumber); /* Emit the sample percentage, 5 bytes. */ cp = logWriteInt(cp, samplePercent); assert((size_t)(cp - eventBuffer) <= sizeof(eventBuffer)); android_btWriteLog(EVENT_LOG_TAG_dvm_lock_sample, EVENT_TYPE_LIST, eventBuffer, (size_t)(cp - eventBuffer)); }
/* * Measure the time it takes for the logd posting call to acquire the * timestamp to place into the internal record. Expect this to be less than * 4 syscalls (3us). This test uses manual injection of timing because it is * comparing the timestamp at send, and then picking up the corresponding log * end-to-end long path from logd to see what actual timestamp was submitted. */ static void BM_log_latency(benchmark::State& state) { pid_t pid = getpid(); struct logger_list* logger_list = android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid); if (!logger_list) { fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); exit(EXIT_FAILURE); } signal(SIGALRM, caught_latency); alarm(alarm_time); for (size_t j = 0; state.KeepRunning() && j < 10 * state.iterations(); ++j) { retry: // We allow transitory errors (logd overloaded) to be retried. log_time ts; LOG_FAILURE_RETRY((ts = log_time(CLOCK_REALTIME), android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)))); for (;;) { log_msg log_msg; int ret = android_logger_list_read(logger_list, &log_msg); alarm(alarm_time); if (ret <= 0) { state.SkipWithError("android_logger_list_read"); break; } if ((log_msg.entry.len != (4 + 1 + 8)) || (log_msg.id() != LOG_ID_EVENTS)) { continue; } char* eventData = log_msg.msg(); if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) { continue; } log_time tx(eventData + 4 + 1); if (ts != tx) { if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) { state.SkipWithError("signal"); break; } continue; } uint64_t start = ts.nsec(); uint64_t end = log_msg.nsec(); if (end < start) goto retry; state.SetIterationTime((end - start) / (double)NS_PER_SEC); break; } } signal(SIGALRM, SIG_DFL); alarm(0); android_logger_list_free(logger_list); }
/* * In class android.util.EventLog: * static native int writeEvent(long tag, long value) */ static jint android_util_EventLog_writeEvent_Long(JNIEnv* env, jobject clazz, jint tag, jlong value) { return android_btWriteLog(tag, EVENT_TYPE_LONG, &value, sizeof(value)); }
/* * In class android.util.EventLog: * static native int writeEvent(int tag, int value) */ static jint android_util_EventLog_writeEvent_Integer(JNIEnv* env, jobject clazz, jint tag, jint value) { return android_btWriteLog(tag, EVENT_TYPE_INT, &value, sizeof(value)); }
void dvmLogGcStats(size_t numFreed, size_t sizeFreed, size_t gcTimeMs) { size_t perHeapActualSize[HEAP_SOURCE_MAX_HEAP_COUNT], perHeapAllowedSize[HEAP_SOURCE_MAX_HEAP_COUNT], perHeapNumAllocated[HEAP_SOURCE_MAX_HEAP_COUNT], perHeapSizeAllocated[HEAP_SOURCE_MAX_HEAP_COUNT]; unsigned char eventBuf[1 + (1 + sizeof(long long)) * 4]; size_t actualSize, allowedSize, numAllocated, sizeAllocated; size_t softLimit = dvmHeapSourceGetIdealFootprint(); size_t nHeaps = dvmHeapSourceGetNumHeaps(); /* Enough to quiet down gcc for unitialized variable check */ perHeapActualSize[0] = perHeapAllowedSize[0] = perHeapNumAllocated[0] = perHeapSizeAllocated[0] = 0; actualSize = dvmHeapSourceGetValue(HS_FOOTPRINT, perHeapActualSize, HEAP_SOURCE_MAX_HEAP_COUNT); allowedSize = dvmHeapSourceGetValue(HS_ALLOWED_FOOTPRINT, perHeapAllowedSize, HEAP_SOURCE_MAX_HEAP_COUNT); numAllocated = dvmHeapSourceGetValue(HS_OBJECTS_ALLOCATED, perHeapNumAllocated, HEAP_SOURCE_MAX_HEAP_COUNT); sizeAllocated = dvmHeapSourceGetValue(HS_BYTES_ALLOCATED, perHeapSizeAllocated, HEAP_SOURCE_MAX_HEAP_COUNT); /* * Construct the the first 64-bit value to write to the log. * Global information: * * [63 ] Must be zero * [62-24] ASCII process identifier * [23-12] GC time in ms * [11- 0] Bytes freed * */ long long event0; event0 = 0LL << 63 | (long long)intToFloat12(gcTimeMs) << 12 | (long long)intToFloat12(sizeFreed); insertProcessName(&event0); /* * Aggregated heap stats: * * [63-62] 10 * [61-60] Reserved; must be zero * [59-48] Objects freed * [47-36] Actual size (current footprint) * [35-24] Allowed size (current hard max) * [23-12] Objects allocated * [11- 0] Bytes allocated */ long long event1; event1 = 2LL << 62 | (long long)intToFloat12(numFreed) << 48 | (long long)intToFloat12(actualSize) << 36 | (long long)intToFloat12(allowedSize) << 24 | (long long)intToFloat12(numAllocated) << 12 | (long long)intToFloat12(sizeAllocated); /* * Report the current state of the zygote heap(s). * * The active heap is always heap[0]. We can be in one of three states * at present: * * (1) Still in the zygote. Zygote using heap[0]. * (2) In the zygote, when the first child is started. We created a * new heap just before the first fork() call, so the original * "zygote heap" is now heap[1], and we have a small heap[0] for * anything we do from here on. * (3) In an app process. The app gets a new heap[0], and can also * see the two zygote heaps [1] and [2] (probably unwise to * assume any specific ordering). * * So if nHeaps == 1, we want the stats from heap[0]; else we want * the sum of the values from heap[1] to heap[nHeaps-1]. * * * Zygote heap stats (except for the soft limit, which belongs to the * active heap): * * [63-62] 11 * [61-60] Reserved; must be zero * [59-48] Soft Limit (for the active heap) * [47-36] Actual size (current footprint) * [35-24] Allowed size (current hard max) * [23-12] Objects allocated * [11- 0] Bytes allocated */ long long event2; size_t zActualSize, zAllowedSize, zNumAllocated, zSizeAllocated; int firstHeap = (nHeaps == 1) ? 0 : 1; size_t hh; zActualSize = zAllowedSize = zNumAllocated = zSizeAllocated = 0; for (hh = firstHeap; hh < nHeaps; hh++) { zActualSize += perHeapActualSize[hh]; zAllowedSize += perHeapAllowedSize[hh]; zNumAllocated += perHeapNumAllocated[hh]; zSizeAllocated += perHeapSizeAllocated[hh]; } event2 = 3LL << 62 | (long long)intToFloat12(softLimit) << 48 | (long long)intToFloat12(zActualSize) << 36 | (long long)intToFloat12(zAllowedSize) << 24 | (long long)intToFloat12(zNumAllocated) << 12 | (long long)intToFloat12(zSizeAllocated); /* * Report the current external allocation stats and the native heap * summary. * * [63-48] Reserved; must be zero (TODO: put new data in these slots) * [47-36] dlmalloc_footprint * [35-24] mallinfo: total allocated space * [23-12] External byte limit * [11- 0] External bytes allocated */ long long event3; size_t externalLimit, externalBytesAllocated; size_t uordblks, footprint; #if 0 /* * This adds 2-5msec to the GC cost on a DVT, or about 2-3% of the cost * of a GC, so it's not horribly expensive but it's not free either. */ extern size_t dlmalloc_footprint(void); struct mallinfo mi; //u8 start, end; //start = dvmGetRelativeTimeNsec(); mi = mallinfo(); uordblks = mi.uordblks; footprint = dlmalloc_footprint(); //end = dvmGetRelativeTimeNsec(); //LOGD("mallinfo+footprint took %dusec; used=%zd footprint=%zd\n", // (int)((end - start) / 1000), mi.uordblks, footprint); #else uordblks = footprint = 0; #endif externalLimit = dvmHeapSourceGetValue(HS_EXTERNAL_LIMIT, NULL, 0); externalBytesAllocated = dvmHeapSourceGetValue(HS_EXTERNAL_BYTES_ALLOCATED, NULL, 0); event3 = (long long)intToFloat12(footprint) << 36 | (long long)intToFloat12(uordblks) << 24 | (long long)intToFloat12(externalLimit) << 12 | (long long)intToFloat12(externalBytesAllocated); /* Build the event data. * [ 0: 0] item count (4) * [ 1: 1] EVENT_TYPE_LONG * [ 2: 9] event0 * [10:10] EVENT_TYPE_LONG * [11:18] event1 * [19:19] EVENT_TYPE_LONG * [20:27] event2 * [28:28] EVENT_TYPE_LONG * [29:36] event2 */ unsigned char *c = eventBuf; *c++ = 4; *c++ = EVENT_TYPE_LONG; memcpy(c, &event0, sizeof(event0)); c += sizeof(event0); *c++ = EVENT_TYPE_LONG; memcpy(c, &event1, sizeof(event1)); c += sizeof(event1); *c++ = EVENT_TYPE_LONG; memcpy(c, &event2, sizeof(event2)); c += sizeof(event2); *c++ = EVENT_TYPE_LONG; memcpy(c, &event3, sizeof(event3)); (void) android_btWriteLog(EVENT_LOG_TAG_dvm_gc_info, EVENT_TYPE_LIST, eventBuf, sizeof(eventBuf)); }