/*
* 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));
}
