trace_begin分析

This commit is contained in:
foxleezh
2019-02-19 22:51:25 +08:00
parent ae6c66c96e
commit c4a3210f58
7 changed files with 1399 additions and 4 deletions

View File

@@ -0,0 +1,310 @@
/*
* Copyright (C) 2012 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package android.os;
import dalvik.annotation.optimization.FastNative;
/**
* Writes trace events to the system trace buffer. These trace events can be
* collected and visualized using the Systrace tool.
*
* <p>This tracing mechanism is independent of the method tracing mechanism
* offered by {@link Debug#startMethodTracing}. In particular, it enables
* tracing of events that occur across multiple processes.
* <p>For information about using the Systrace tool, read <a
* href="{@docRoot}tools/debugging/systrace.html">Analyzing Display and Performance
* with Systrace</a>.
*/
public final class Trace {
/*
* Writes trace events to the kernel trace buffer. These trace events can be
* collected using the "atrace" program for offline analysis.
*/
private static final String TAG = "Trace";
// These tags must be kept in sync with system/core/include/cutils/trace.h.
// They should also be added to frameworks/native/cmds/atrace/atrace.cpp.
/** @hide */
public static final long TRACE_TAG_NEVER = 0;
/** @hide */
public static final long TRACE_TAG_ALWAYS = 1L << 0;
/** @hide */
public static final long TRACE_TAG_GRAPHICS = 1L << 1;
/** @hide */
public static final long TRACE_TAG_INPUT = 1L << 2;
/** @hide */
public static final long TRACE_TAG_VIEW = 1L << 3;
/** @hide */
public static final long TRACE_TAG_WEBVIEW = 1L << 4;
/** @hide */
public static final long TRACE_TAG_WINDOW_MANAGER = 1L << 5;
/** @hide */
public static final long TRACE_TAG_ACTIVITY_MANAGER = 1L << 6;
/** @hide */
public static final long TRACE_TAG_SYNC_MANAGER = 1L << 7;
/** @hide */
public static final long TRACE_TAG_AUDIO = 1L << 8;
/** @hide */
public static final long TRACE_TAG_VIDEO = 1L << 9;
/** @hide */
public static final long TRACE_TAG_CAMERA = 1L << 10;
/** @hide */
public static final long TRACE_TAG_HAL = 1L << 11;
/** @hide */
public static final long TRACE_TAG_APP = 1L << 12;
/** @hide */
public static final long TRACE_TAG_RESOURCES = 1L << 13;
/** @hide */
public static final long TRACE_TAG_DALVIK = 1L << 14;
/** @hide */
public static final long TRACE_TAG_RS = 1L << 15;
/** @hide */
public static final long TRACE_TAG_BIONIC = 1L << 16;
/** @hide */
public static final long TRACE_TAG_POWER = 1L << 17;
/** @hide */
public static final long TRACE_TAG_PACKAGE_MANAGER = 1L << 18;
/** @hide */
public static final long TRACE_TAG_SYSTEM_SERVER = 1L << 19;
/** @hide */
public static final long TRACE_TAG_DATABASE = 1L << 20;
/** @hide */
public static final long TRACE_TAG_NETWORK = 1L << 21;
/** @hide */
public static final long TRACE_TAG_ADB = 1L << 22;
private static final long TRACE_TAG_NOT_READY = 1L << 63;
private static final int MAX_SECTION_NAME_LEN = 127;
// Must be volatile to avoid word tearing.
private static volatile long sEnabledTags = TRACE_TAG_NOT_READY;
private static native long nativeGetEnabledTags();
private static native void nativeSetAppTracingAllowed(boolean allowed);
private static native void nativeSetTracingEnabled(boolean allowed);
@FastNative
private static native void nativeTraceCounter(long tag, String name, int value);
@FastNative
private static native void nativeTraceBegin(long tag, String name);
@FastNative
private static native void nativeTraceEnd(long tag);
@FastNative
private static native void nativeAsyncTraceBegin(long tag, String name, int cookie);
@FastNative
private static native void nativeAsyncTraceEnd(long tag, String name, int cookie);
static {
// We configure two separate change callbacks, one in Trace.cpp and one here. The
// native callback reads the tags from the system property, and this callback
// reads the value that the native code retrieved. It's essential that the native
// callback executes first.
//
// The system provides ordering through a priority level. Callbacks made through
// SystemProperties.addChangeCallback currently have a negative priority, while
// our native code is using a priority of zero.
SystemProperties.addChangeCallback(new Runnable() {
@Override public void run() {
cacheEnabledTags();
}
});
}
private Trace() {
}
/**
* Caches a copy of the enabled-tag bits. The "master" copy is held by the native code,
* and comes from the PROPERTY_TRACE_TAG_ENABLEFLAGS property.
* <p>
* If the native code hasn't yet read the property, we will cause it to do one-time
* initialization. We don't want to do this during class init, because this class is
* preloaded, so all apps would be stuck with whatever the zygote saw. (The zygote
* doesn't see the system-property update broadcasts.)
* <p>
* We want to defer initialization until the first use by an app, post-zygote.
* <p>
* We're okay if multiple threads call here simultaneously -- the native state is
* synchronized, and sEnabledTags is volatile (prevents word tearing).
*/
private static long cacheEnabledTags() {
long tags = nativeGetEnabledTags();
sEnabledTags = tags;
return tags;
}
/**
* Returns true if a trace tag is enabled.
*
* @param traceTag The trace tag to check.
* @return True if the trace tag is valid.
*
* @hide
*/
public static boolean isTagEnabled(long traceTag) {
long tags = sEnabledTags;
if (tags == TRACE_TAG_NOT_READY) {
tags = cacheEnabledTags();
}
return (tags & traceTag) != 0;
}
/**
* Writes trace message to indicate the value of a given counter.
*
* @param traceTag The trace tag.
* @param counterName The counter name to appear in the trace.
* @param counterValue The counter value.
*
* @hide
*/
public static void traceCounter(long traceTag, String counterName, int counterValue) {
if (isTagEnabled(traceTag)) {
nativeTraceCounter(traceTag, counterName, counterValue);
}
}
/**
* Set whether application tracing is allowed for this process. This is intended to be set
* once at application start-up time based on whether the application is debuggable.
*
* @hide
*/
public static void setAppTracingAllowed(boolean allowed) {
nativeSetAppTracingAllowed(allowed);
// Setting whether app tracing is allowed may change the tags, so we update the cached
// tags here.
cacheEnabledTags();
}
/**
* Set whether tracing is enabled in this process. Tracing is disabled shortly after Zygote
* initializes and re-enabled after processes fork from Zygote. This is done because Zygote
* has no way to be notified about changes to the tracing tags, and if Zygote ever reads and
* caches the tracing tags, forked processes will inherit those stale tags.
*
* @hide
*/
public static void setTracingEnabled(boolean enabled) {
nativeSetTracingEnabled(enabled);
// Setting whether tracing is enabled may change the tags, so we update the cached tags
// here.
cacheEnabledTags();
}
/**
* Writes a trace message to indicate that a given section of code has
* begun. Must be followed by a call to {@link #traceEnd} using the same
* tag.
*
* @param traceTag The trace tag.
* @param methodName The method name to appear in the trace.
*
* @hide
*/
public static void traceBegin(long traceTag, String methodName) {
if (isTagEnabled(traceTag)) {
nativeTraceBegin(traceTag, methodName);
}
}
/**
* Writes a trace message to indicate that the current method has ended.
* Must be called exactly once for each call to {@link #traceBegin} using the same tag.
*
* @param traceTag The trace tag.
*
* @hide
*/
public static void traceEnd(long traceTag) {
if (isTagEnabled(traceTag)) {
nativeTraceEnd(traceTag);
}
}
/**
* Writes a trace message to indicate that a given section of code has
* begun. Must be followed by a call to {@link #asyncTraceEnd} using the same
* tag. Unlike {@link #traceBegin(long, String)} and {@link #traceEnd(long)},
* asynchronous events do not need to be nested. The name and cookie used to
* begin an event must be used to end it.
*
* @param traceTag The trace tag.
* @param methodName The method name to appear in the trace.
* @param cookie Unique identifier for distinguishing simultaneous events
*
* @hide
*/
public static void asyncTraceBegin(long traceTag, String methodName, int cookie) {
if (isTagEnabled(traceTag)) {
nativeAsyncTraceBegin(traceTag, methodName, cookie);
}
}
/**
* Writes a trace message to indicate that the current method has ended.
* Must be called exactly once for each call to {@link #asyncTraceBegin(long, String, int)}
* using the same tag, name and cookie.
*
* @param traceTag The trace tag.
* @param methodName The method name to appear in the trace.
* @param cookie Unique identifier for distinguishing simultaneous events
*
* @hide
*/
public static void asyncTraceEnd(long traceTag, String methodName, int cookie) {
if (isTagEnabled(traceTag)) {
nativeAsyncTraceEnd(traceTag, methodName, cookie);
}
}
/**
* Writes a trace message to indicate that a given section of code has begun. This call must
* be followed by a corresponding call to {@link #endSection()} on the same thread.
*
* <p class="note"> At this time the vertical bar character '|', newline character '\n', and
* null character '\0' are used internally by the tracing mechanism. If sectionName contains
* these characters they will be replaced with a space character in the trace.
*
* @param sectionName The name of the code section to appear in the trace. This may be at
* most 127 Unicode code units long.
*/
public static void beginSection(String sectionName) {
if (isTagEnabled(TRACE_TAG_APP)) {
if (sectionName.length() > MAX_SECTION_NAME_LEN) {
throw new IllegalArgumentException("sectionName is too long");
}
nativeTraceBegin(TRACE_TAG_APP, sectionName);
}
}
/**
* Writes a trace message to indicate that a given section of code has ended. This call must
* be preceeded by a corresponding call to {@link #beginSection(String)}. Calling this method
* will mark the end of the most recently begun section of code, so care must be taken to
* ensure that beginSection / endSection pairs are properly nested and called from the same
* thread.
*/
public static void endSection() {
if (isTagEnabled(TRACE_TAG_APP)) {
nativeTraceEnd(TRACE_TAG_APP);
}
}
}

View File

@@ -0,0 +1,10 @@
# See system/core/logcat/event.logtags for a description of the format of this file.
option java_package com.android.internal.logging;
# interaction logs
524287 sysui_view_visibility (category|1|5),(visible|1|6)
524288 sysui_action (category|1|5),(pkg|3)
524292 sysui_multi_action (content|4)
524290 sysui_count (name|3),(increment|1)
524291 sysui_histogram (name|3),(bucket|1)

View File

@@ -0,0 +1,218 @@
/*
* Copyright (C) 2015 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package com.android.internal.logging;
import android.content.Context;
import android.metrics.LogMaker;
import android.os.Build;
import android.view.View;
import com.android.internal.logging.nano.MetricsProto.MetricsEvent;
/**
* Log all the things.
*
* @hide
*/
public class MetricsLogger {
// define metric categories in frameworks/base/proto/src/metrics_constants.proto.
// mirror changes in native version at system/core/libmetricslogger/metrics_logger.cpp
private static MetricsLogger sMetricsLogger;
private static MetricsLogger getLogger() {
if (sMetricsLogger == null) {
sMetricsLogger = new MetricsLogger();
}
return sMetricsLogger;
}
protected void saveLog(Object[] rep) {
EventLogTags.writeSysuiMultiAction(rep);
}
public static final int VIEW_UNKNOWN = MetricsEvent.VIEW_UNKNOWN;
public static final int LOGTAG = EventLogTags.SYSUI_MULTI_ACTION;
public void write(LogMaker content) {
if (content.getType() == MetricsEvent.TYPE_UNKNOWN) {
content.setType(MetricsEvent.TYPE_ACTION);
}
saveLog(content.serialize());
}
public void visible(int category) throws IllegalArgumentException {
if (Build.IS_DEBUGGABLE && category == VIEW_UNKNOWN) {
throw new IllegalArgumentException("Must define metric category");
}
EventLogTags.writeSysuiViewVisibility(category, 100);
saveLog(new LogMaker(category)
.setType(MetricsEvent.TYPE_OPEN)
.serialize());
}
public void hidden(int category) throws IllegalArgumentException {
if (Build.IS_DEBUGGABLE && category == VIEW_UNKNOWN) {
throw new IllegalArgumentException("Must define metric category");
}
EventLogTags.writeSysuiViewVisibility(category, 0);
saveLog(new LogMaker(category)
.setType(MetricsEvent.TYPE_CLOSE)
.serialize());
}
public void visibility(int category, boolean visibile)
throws IllegalArgumentException {
if (visibile) {
visible(category);
} else {
hidden(category);
}
}
public void visibility(int category, int vis)
throws IllegalArgumentException {
visibility(category, vis == View.VISIBLE);
}
public void action(int category) {
EventLogTags.writeSysuiAction(category, "");
saveLog(new LogMaker(category)
.setType(MetricsEvent.TYPE_ACTION)
.serialize());
}
public void action(int category, int value) {
EventLogTags.writeSysuiAction(category, Integer.toString(value));
saveLog(new LogMaker(category)
.setType(MetricsEvent.TYPE_ACTION)
.setSubtype(value)
.serialize());
}
public void action(int category, boolean value) {
EventLogTags.writeSysuiAction(category, Boolean.toString(value));
saveLog(new LogMaker(category)
.setType(MetricsEvent.TYPE_ACTION)
.setSubtype(value ? 1 : 0)
.serialize());
}
public void action(int category, String pkg) {
if (Build.IS_DEBUGGABLE && category == VIEW_UNKNOWN) {
throw new IllegalArgumentException("Must define metric category");
}
EventLogTags.writeSysuiAction(category, pkg);
saveLog(new LogMaker(category)
.setType(MetricsEvent.TYPE_ACTION)
.setPackageName(pkg)
.serialize());
}
/** Add an integer value to the monotonically increasing counter with the given name. */
public void count(String name, int value) {
EventLogTags.writeSysuiCount(name, value);
saveLog(new LogMaker(MetricsEvent.RESERVED_FOR_LOGBUILDER_COUNTER)
.setCounterName(name)
.setCounterValue(value)
.serialize());
}
/** Increment the bucket with the integer label on the histogram with the given name. */
public void histogram(String name, int bucket) {
// see LogHistogram in system/core/libmetricslogger/metrics_logger.cpp
EventLogTags.writeSysuiHistogram(name, bucket);
saveLog(new LogMaker(MetricsEvent.RESERVED_FOR_LOGBUILDER_HISTOGRAM)
.setCounterName(name)
.setCounterBucket(bucket)
.setCounterValue(1)
.serialize());
}
/** @deprecated use {@link #visible(int)} */
@Deprecated
public static void visible(Context context, int category) throws IllegalArgumentException {
getLogger().visible(category);
}
/** @deprecated use {@link #hidden(int)} */
@Deprecated
public static void hidden(Context context, int category) throws IllegalArgumentException {
getLogger().hidden(category);
}
/** @deprecated use {@link #visibility(int, boolean)} */
@Deprecated
public static void visibility(Context context, int category, boolean visibile)
throws IllegalArgumentException {
getLogger().visibility(category, visibile);
}
/** @deprecated use {@link #visibility(int, int)} */
@Deprecated
public static void visibility(Context context, int category, int vis)
throws IllegalArgumentException {
visibility(context, category, vis == View.VISIBLE);
}
/** @deprecated use {@link #action(int)} */
@Deprecated
public static void action(Context context, int category) {
getLogger().action(category);
}
/** @deprecated use {@link #action(int, int)} */
@Deprecated
public static void action(Context context, int category, int value) {
getLogger().action(category, value);
}
/** @deprecated use {@link #action(int, boolean)} */
@Deprecated
public static void action(Context context, int category, boolean value) {
getLogger().action(category, value);
}
/** @deprecated use {@link #write(LogMaker)} */
@Deprecated
public static void action(LogMaker content) {
getLogger().write(content);
}
/** @deprecated use {@link #action(int, String)} */
@Deprecated
public static void action(Context context, int category, String pkg) {
getLogger().action(category, pkg);
}
/**
* Add an integer value to the monotonically increasing counter with the given name.
* @deprecated use {@link #count(String, int)}
*/
@Deprecated
public static void count(Context context, String name, int value) {
getLogger().count(name, value);
}
/**
* Increment the bucket with the integer label on the histogram with the given name.
* @deprecated use {@link #histogram(String, int)}
*/
@Deprecated
public static void histogram(Context context, String name, int bucket) {
getLogger().histogram(name, bucket);
}
}

View File

@@ -0,0 +1,329 @@
/*
* Copyright (C) 2007-2014 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#include <fcntl.h>
#include <log/log_event_list.h>
#include <log/log.h>
#include "JNIHelp.h"
#include "core_jni_helpers.h"
#include "jni.h"
#define UNUSED __attribute__((__unused__))
namespace android {
static jclass gCollectionClass;
static jmethodID gCollectionAddID;
static jclass gEventClass;
static jmethodID gEventInitID;
static jclass gIntegerClass;
static jfieldID gIntegerValueID;
static jclass gLongClass;
static jfieldID gLongValueID;
static jclass gFloatClass;
static jfieldID gFloatValueID;
static jclass gStringClass;
/*
* In class android.util.EventLog:
* static native int writeEvent(int tag, int value)
*/
static jint android_util_EventLog_writeEvent_Integer(JNIEnv* env UNUSED,
jobject clazz UNUSED,
jint tag, jint value)
{
android_log_event_list ctx(tag);
ctx << (int32_t)value;
return ctx.write();
}
/*
* In class android.util.EventLog:
* static native int writeEvent(long tag, long value)
*/
static jint android_util_EventLog_writeEvent_Long(JNIEnv* env UNUSED,
jobject clazz UNUSED,
jint tag, jlong value)
{
android_log_event_list ctx(tag);
ctx << (int64_t)value;
return ctx.write();
}
/*
* In class android.util.EventLog:
* static native int writeEvent(long tag, float value)
*/
static jint android_util_EventLog_writeEvent_Float(JNIEnv* env UNUSED,
jobject clazz UNUSED,
jint tag, jfloat value)
{
android_log_event_list ctx(tag);
ctx << (float)value;
return ctx.write();
}
/*
* In class android.util.EventLog:
* static native int writeEvent(int tag, String value)
*/
static jint android_util_EventLog_writeEvent_String(JNIEnv* env,
jobject clazz UNUSED,
jint tag, jstring value) {
android_log_event_list ctx(tag);
// Don't throw NPE -- I feel like it's sort of mean for a logging function
// to be all crashy if you pass in NULL -- but make the NULL value explicit.
if (value != NULL) {
const char *str = env->GetStringUTFChars(value, NULL);
ctx << str;
env->ReleaseStringUTFChars(value, str);
} else {
ctx << "NULL";
}
return ctx.write();
}
/*
* In class android.util.EventLog:
* static native int writeEvent(long tag, Object... value)
*/
static jint android_util_EventLog_writeEvent_Array(JNIEnv* env, jobject clazz,
jint tag, jobjectArray value) {
android_log_event_list ctx(tag);
if (value == NULL) {
ctx << "[NULL]";
return ctx.write();
}
jsize copied = 0, num = env->GetArrayLength(value);
for (; copied < num && copied < 255; ++copied) {
if (ctx.status()) break;
jobject item = env->GetObjectArrayElement(value, copied);
if (item == NULL) {
ctx << "NULL";
} else if (env->IsInstanceOf(item, gStringClass)) {
const char *str = env->GetStringUTFChars((jstring) item, NULL);
ctx << str;
env->ReleaseStringUTFChars((jstring) item, str);
} else if (env->IsInstanceOf(item, gIntegerClass)) {
ctx << (int32_t)env->GetIntField(item, gIntegerValueID);
} else if (env->IsInstanceOf(item, gLongClass)) {
ctx << (int64_t)env->GetLongField(item, gLongValueID);
} else if (env->IsInstanceOf(item, gFloatClass)) {
ctx << (float)env->GetFloatField(item, gFloatValueID);
} else {
jniThrowException(env,
"java/lang/IllegalArgumentException",
"Invalid payload item type");
return -1;
}
env->DeleteLocalRef(item);
}
return ctx.write();
}
static void readEvents(JNIEnv* env, int loggerMode, jintArray tags, jlong startTime, jobject out) {
struct logger_list *logger_list;
if (startTime) {
logger_list = android_logger_list_alloc_time(loggerMode,
log_time(startTime / NS_PER_SEC, startTime % NS_PER_SEC), 0);
} else {
logger_list = android_logger_list_alloc(loggerMode, 0, 0);
}
if (!logger_list) {
jniThrowIOException(env, errno);
return;
}
if (!android_logger_open(logger_list, LOG_ID_EVENTS)) {
jniThrowIOException(env, errno);
android_logger_list_free(logger_list);
return;
}
jsize tagLength = env->GetArrayLength(tags);
jint *tagValues = env->GetIntArrayElements(tags, NULL);
while (1) {
log_msg log_msg;
int ret = android_logger_list_read(logger_list, &log_msg);
if (ret == 0) {
break;
}
if (ret < 0) {
if (ret == -EINTR) {
continue;
}
if (ret == -EINVAL) {
jniThrowException(env, "java/io/IOException", "Event too short");
} else if (ret != -EAGAIN) {
jniThrowIOException(env, -ret); // Will throw on return
}
break;
}
if (log_msg.id() != LOG_ID_EVENTS) {
continue;
}
int32_t tag = * (int32_t *) log_msg.msg();
int found = 0;
for (int i = 0; !found && i < tagLength; ++i) {
found = (tag == tagValues[i]);
}
if (found) {
jsize len = ret;
jbyteArray array = env->NewByteArray(len);
if (array == NULL) {
break;
}
jbyte *bytes = env->GetByteArrayElements(array, NULL);
memcpy(bytes, log_msg.buf, len);
env->ReleaseByteArrayElements(array, bytes, 0);
jobject event = env->NewObject(gEventClass, gEventInitID, array);
if (event == NULL) {
break;
}
env->CallBooleanMethod(out, gCollectionAddID, event);
env->DeleteLocalRef(event);
env->DeleteLocalRef(array);
}
}
android_logger_list_close(logger_list);
env->ReleaseIntArrayElements(tags, tagValues, 0);
}
/*
* In class android.util.EventLog:
* static native void readEvents(int[] tags, Collection<Event> output)
*
* Reads events from the event log
*/
static void android_util_EventLog_readEvents(JNIEnv* env, jobject clazz UNUSED,
jintArray tags,
jobject out) {
if (tags == NULL || out == NULL) {
jniThrowNullPointerException(env, NULL);
return;
}
readEvents(env, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, tags, 0, out);
}
/*
* In class android.util.EventLog:
* static native void readEventsOnWrapping(int[] tags, long timestamp, Collection<Event> output)
*
* Reads events from the event log, blocking until events after timestamp are to be overwritten.
*/
static void android_util_EventLog_readEventsOnWrapping(JNIEnv* env, jobject clazz UNUSED,
jintArray tags,
jlong timestamp,
jobject out) {
if (tags == NULL || out == NULL) {
jniThrowNullPointerException(env, NULL);
return;
}
readEvents(env, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK | ANDROID_LOG_WRAP,
tags, timestamp, out);
}
/*
* JNI registration.
*/
static const JNINativeMethod gRegisterMethods[] = {
/* name, signature, funcPtr */
{ "writeEvent", "(II)I", (void*) android_util_EventLog_writeEvent_Integer },
{ "writeEvent", "(IJ)I", (void*) android_util_EventLog_writeEvent_Long },
{ "writeEvent", "(IF)I", (void*) android_util_EventLog_writeEvent_Float },
{ "writeEvent",
"(ILjava/lang/String;)I",
(void*) android_util_EventLog_writeEvent_String
},
{ "writeEvent",
"(I[Ljava/lang/Object;)I",
(void*) android_util_EventLog_writeEvent_Array
},
{ "readEvents",
"([ILjava/util/Collection;)V",
(void*) android_util_EventLog_readEvents
},
{ "readEventsOnWrapping",
"([IJLjava/util/Collection;)V",
(void*) android_util_EventLog_readEventsOnWrapping
},
};
static struct { const char *name; jclass *clazz; } gClasses[] = {
{ "android/util/EventLog$Event", &gEventClass },
{ "java/lang/Integer", &gIntegerClass },
{ "java/lang/Long", &gLongClass },
{ "java/lang/Float", &gFloatClass },
{ "java/lang/String", &gStringClass },
{ "java/util/Collection", &gCollectionClass },
};
static struct { jclass *c; const char *name, *ft; jfieldID *id; } gFields[] = {
{ &gIntegerClass, "value", "I", &gIntegerValueID },
{ &gLongClass, "value", "J", &gLongValueID },
{ &gFloatClass, "value", "F", &gFloatValueID },
};
static struct { jclass *c; const char *name, *mt; jmethodID *id; } gMethods[] = {
{ &gEventClass, "<init>", "([B)V", &gEventInitID },
{ &gCollectionClass, "add", "(Ljava/lang/Object;)Z", &gCollectionAddID },
};
int register_android_util_EventLog(JNIEnv* env) {
for (int i = 0; i < NELEM(gClasses); ++i) {
jclass clazz = FindClassOrDie(env, gClasses[i].name);
*gClasses[i].clazz = MakeGlobalRefOrDie(env, clazz);
}
for (int i = 0; i < NELEM(gFields); ++i) {
*gFields[i].id = GetFieldIDOrDie(env,
*gFields[i].c, gFields[i].name, gFields[i].ft);
}
for (int i = 0; i < NELEM(gMethods); ++i) {
*gMethods[i].id = GetMethodIDOrDie(env,
*gMethods[i].c, gMethods[i].name, gMethods[i].mt);
}
return RegisterMethodsOrDie(
env,
"android/util/EventLog",
gRegisterMethods, NELEM(gRegisterMethods));
}
}; // namespace android

View File

@@ -0,0 +1,234 @@
/*
* Copyright (C) 2012 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#define LOG_TAG "cutils-trace"
#include <errno.h>
#include <fcntl.h>
#include <limits.h>
#include <pthread.h>
#include <stdatomic.h>
#include <stdbool.h>
#include <stdlib.h>
#include <string.h>
#include <sys/types.h>
#include <cutils/compiler.h>
#include <cutils/properties.h>
#include <cutils/trace.h>
#include <log/log.h>
#include <log/log_properties.h>
/**
* Maximum size of a message that can be logged to the trace buffer.
* Note this message includes a tag, the pid, and the string given as the name.
* Names should be kept short to get the most use of the trace buffer.
*/
#define ATRACE_MESSAGE_LENGTH 1024
atomic_bool atrace_is_ready = ATOMIC_VAR_INIT(false);
int atrace_marker_fd = -1;
uint64_t atrace_enabled_tags = ATRACE_TAG_NOT_READY;
static bool atrace_is_debuggable = false;
static atomic_bool atrace_is_enabled = ATOMIC_VAR_INIT(true);
static pthread_once_t atrace_once_control = PTHREAD_ONCE_INIT;
static pthread_mutex_t atrace_tags_mutex = PTHREAD_MUTEX_INITIALIZER;
// Set whether this process is debuggable, which determines whether
// application-level tracing is allowed when the ro.debuggable system property
// is not set to '1'.
void atrace_set_debuggable(bool debuggable)
{
atrace_is_debuggable = debuggable;
atrace_update_tags();
}
// Set whether tracing is enabled in this process. This is used to prevent
// the Zygote process from tracing.
void atrace_set_tracing_enabled(bool enabled)
{
atomic_store_explicit(&atrace_is_enabled, enabled, memory_order_release);
atrace_update_tags();
}
// Check whether the given command line matches one of the comma-separated
// values listed in the app_cmdlines property.
static bool atrace_is_cmdline_match(const char* cmdline)
{
int count = property_get_int32("debug.atrace.app_number", 0);
char buf[PROPERTY_KEY_MAX];
char value[PROPERTY_VALUE_MAX];
for (int i = 0; i < count; i++) {
snprintf(buf, sizeof(buf), "debug.atrace.app_%d", i);
property_get(buf, value, "");
if (strcmp(value, cmdline) == 0) {
return true;
}
}
return false;
}
// Determine whether application-level tracing is enabled for this process.
static bool atrace_is_app_tracing_enabled()
{
bool sys_debuggable = __android_log_is_debuggable();
bool result = false;
if (sys_debuggable || atrace_is_debuggable) {
// Check whether tracing is enabled for this process.
FILE * file = fopen("/proc/self/cmdline", "re");
if (file) {
char cmdline[4096];
if (fgets(cmdline, sizeof(cmdline), file)) {
result = atrace_is_cmdline_match(cmdline);
} else {
ALOGE("Error reading cmdline: %s (%d)", strerror(errno), errno);
}
fclose(file);
} else {
ALOGE("Error opening /proc/self/cmdline: %s (%d)", strerror(errno),
errno);
}
}
return result;
}
// Read the sysprop and return the value tags should be set to
static uint64_t atrace_get_property()
{
char value[PROPERTY_VALUE_MAX];
char *endptr;
uint64_t tags;
property_get("debug.atrace.tags.enableflags", value, "0");
errno = 0;
tags = strtoull(value, &endptr, 0);
if (value[0] == '\0' || *endptr != '\0') {
ALOGE("Error parsing trace property: Not a number: %s", value);
return 0;
} else if (errno == ERANGE || tags == ULLONG_MAX) {
ALOGE("Error parsing trace property: Number too large: %s", value);
return 0;
}
// Only set the "app" tag if this process was selected for app-level debug
// tracing.
if (atrace_is_app_tracing_enabled()) {
tags |= ATRACE_TAG_APP;
} else {
tags &= ~ATRACE_TAG_APP;
}
return (tags | ATRACE_TAG_ALWAYS) & ATRACE_TAG_VALID_MASK;
}
// Update tags if tracing is ready. Useful as a sysprop change callback.
void atrace_update_tags()
{
uint64_t tags;
if (CC_UNLIKELY(atomic_load_explicit(&atrace_is_ready, memory_order_acquire))) {
if (atomic_load_explicit(&atrace_is_enabled, memory_order_acquire)) {
tags = atrace_get_property();
pthread_mutex_lock(&atrace_tags_mutex);
atrace_enabled_tags = tags;
pthread_mutex_unlock(&atrace_tags_mutex);
} else {
// Tracing is disabled for this process, so we simply don't
// initialize the tags.
pthread_mutex_lock(&atrace_tags_mutex);
atrace_enabled_tags = ATRACE_TAG_NOT_READY;
pthread_mutex_unlock(&atrace_tags_mutex);
}
}
}
static void atrace_init_once()
{
atrace_marker_fd = open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY | O_CLOEXEC);
if (atrace_marker_fd == -1) {
ALOGE("Error opening trace file: %s (%d)", strerror(errno), errno);
atrace_enabled_tags = 0;
goto done;
}
atrace_enabled_tags = atrace_get_property();
done:
atomic_store_explicit(&atrace_is_ready, true, memory_order_release);
}
void atrace_setup()
{
pthread_once(&atrace_once_control, atrace_init_once);
}
void atrace_begin_body(const char* name)
{
char buf[ATRACE_MESSAGE_LENGTH];
int len = snprintf(buf, sizeof(buf), "B|%d|%s", getpid(), name);
if (len >= (int) sizeof(buf)) {
ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name);
len = sizeof(buf) - 1;
}
write(atrace_marker_fd, buf, len);
}
void atrace_end_body()
{
char c = 'E';
write(atrace_marker_fd, &c, 1);
}
#define WRITE_MSG(format_begin, format_end, pid, name, value) { \
char buf[ATRACE_MESSAGE_LENGTH]; \
int len = snprintf(buf, sizeof(buf), format_begin "%s" format_end, pid, \
name, value); \
if (len >= (int) sizeof(buf)) { \
/* Given the sizeof(buf), and all of the current format buffers, \
* it is impossible for name_len to be < 0 if len >= sizeof(buf). */ \
int name_len = strlen(name) - (len - sizeof(buf)) - 1; \
/* Truncate the name to make the message fit. */ \
ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name); \
len = snprintf(buf, sizeof(buf), format_begin "%.*s" format_end, pid, \
name_len, name, value); \
} \
write(atrace_marker_fd, buf, len); \
}
void atrace_async_begin_body(const char* name, int32_t cookie)
{
WRITE_MSG("S|%d|", "|%" PRId32, getpid(), name, cookie);
}
void atrace_async_end_body(const char* name, int32_t cookie)
{
WRITE_MSG("F|%d|", "|%" PRId32, getpid(), name, cookie);
}
void atrace_int_body(const char* name, int32_t value)
{
WRITE_MSG("C|%d|", "|%" PRId32, getpid(), name, value);
}
void atrace_int64_body(const char* name, int64_t value)
{
WRITE_MSG("C|%d|", "|%" PRId64, getpid(), name, value);
}

View File

@@ -0,0 +1,141 @@
# The entries in this file map a sparse set of log tag numbers to tag names.
# This is installed on the device, in /system/etc, and parsed by logcat.
#
# Tag numbers are decimal integers, from 0 to 2^31. (Let's leave the
# negative values alone for now.)
#
# Tag names are one or more ASCII letters and numbers or underscores, i.e.
# "[A-Z][a-z][0-9]_". Do not include spaces or punctuation (the former
# impacts log readability, the latter makes regex searches more annoying).
#
# Tag numbers and names are separated by whitespace. Blank lines and lines
# starting with '#' are ignored.
#
# Optionally, after the tag names can be put a description for the value(s)
# of the tag. Description are in the format
# (<name>|data type[|data unit])
# Multiple values are separated by commas.
#
# The data type is a number from the following values:
# 1: int
# 2: long
# 3: string
# 4: list
# 5: float
#
# The data unit is a number taken from the following list:
# 1: Number of objects
# 2: Number of bytes
# 3: Number of milliseconds
# 4: Number of allocations
# 5: Id
# 6: Percent
# Default value for data of type int/long is 2 (bytes).
#
# TODO: generate ".java" and ".h" files with integer constants from this file.
# These are used for testing, do not modify without updating
# tests/framework-tests/src/android/util/EventLogFunctionalTest.java.
42 answer (to life the universe etc|3)
314 pi
2718 e
# "account" is the java hash of the account name
2720 sync (id|3),(event|1|5),(source|1|5),(account|1|5)
# This event is logged when the location service uploads location data.
2740 location_controller
# This event is logged when someone is deciding to force a garbage collection
2741 force_gc (reason|3)
# This event is logged on each tickle
2742 tickle (authority|3)
# contacts aggregation: time and number of contacts.
# count is negative for query phase, positive for merge phase
2747 contacts_aggregation (aggregation time|2|3), (count|1|1)
# Device boot timings. We include monotonic clock values because the
# intrinsic event log times are wall-clock.
#
# Runtime starts:
3000 boot_progress_start (time|2|3)
# ZygoteInit class preloading starts:
3020 boot_progress_preload_start (time|2|3)
# ZygoteInit class preloading ends:
3030 boot_progress_preload_end (time|2|3)
# Dalvik VM
20003 dvm_lock_sample (process|3),(main|1|5),(thread|3),(time|1|3),(file|3),(line|1|5),(ownerfile|3),(ownerline|1|5),(sample_percent|1|6)
75000 sqlite_mem_alarm_current (current|1|2)
75001 sqlite_mem_alarm_max (max|1|2)
75002 sqlite_mem_alarm_alloc_attempt (attempts|1|4)
75003 sqlite_mem_released (Memory released|1|2)
75004 sqlite_db_corrupt (Database file corrupt|3)
50000 menu_item_selected (Menu type where 0 is options and 1 is context|1|5),(Menu item title|3)
50001 menu_opened (Menu type where 0 is options and 1 is context|1|5)
# HSM wifi state change
# Hierarchical state class name (as defined in WifiStateTracker.java)
# Logged on every state change in the hierarchical state machine
50021 wifi_state_changed (wifi_state|3)
# HSM wifi event
# [31-16] Reserved for future use
# [15 - 0] HSM event (as defined in WifiStateTracker.java)
# Logged when an event is handled in a hierarchical state
50022 wifi_event_handled (wifi_event|1|5)
# Supplicant state change
# [31-13] Reserved for future use
# [8 - 0] Supplicant state (as defined in SupplicantState.java)
# Logged when the supplicant switches to a new state
50023 wifi_supplicant_state_changed (supplicant_state|1|5)
# Database operation samples.
# db: the filename of the database
# sql: the executed query (without query args)
# time: cpu time millis (not wall time), including lock acquisition
# blocking_package: if this is on a main thread, the package name, otherwise ""
# sample_percent: the percent likelihood this query was logged
52000 db_sample (db|3),(sql|3),(time|1|3),(blocking_package|3),(sample_percent|1|6)
# http request/response stats
52001 http_stats (useragent|3),(response|2|3),(processing|2|3),(tx|1|2),(rx|1|2)
60000 viewroot_draw (Draw time|1|3)
60001 viewroot_layout (Layout time|1|3)
60002 view_build_drawing_cache (View created drawing cache|1|5)
60003 view_use_drawing_cache (View drawn using bitmap cache|1|5)
# graphics timestamp
# 60100 - 60199 reserved for surfaceflinger
# 0 for screen off, 1 for screen on, 2 for key-guard done
70000 screen_toggled (screen_state|1|5)
# aggregation service
70200 aggregation (aggregation time|2|3)
70201 aggregation_test (field1|1|2),(field2|1|2),(field3|1|2),(field4|1|2),(field5|1|2)
# libc failure logging
80100 bionic_event_memcpy_buffer_overflow (uid|1)
80105 bionic_event_strcat_buffer_overflow (uid|1)
80110 bionic_event_memmov_buffer_overflow (uid|1)
80115 bionic_event_strncat_buffer_overflow (uid|1)
80120 bionic_event_strncpy_buffer_overflow (uid|1)
80125 bionic_event_memset_buffer_overflow (uid|1)
80130 bionic_event_strcpy_buffer_overflow (uid|1)
80200 bionic_event_strcat_integer_overflow (uid|1)
80205 bionic_event_strncat_integer_overflow (uid|1)
80300 bionic_event_resolver_old_response (uid|1)
80305 bionic_event_resolver_wrong_server (uid|1)
80310 bionic_event_resolver_wrong_query (uid|1)
# libcore failure logging
90100 exp_det_cert_pin_failure (certs|4)
1397638484 snet_event_log (subtag|3) (uid|1) (message|3)
# NOTE - the range 1000000-2000000 is reserved for partners and others who
# want to define their own log tags without conflicting with the core platform.

View File

@@ -14,6 +14,14 @@
本文涉及到的文件
```
platform/frameworks/base/core/java/com/android/internal/os/ZygoteInit.java
platform/frameworks/base/core/java/com/android/internal/logging/MetricsLogger.java
platform/frameworks/base/core/java/com/android/internal/logging/EventLogTags.logtags
platform/system/core/logcat/event.logtags
platform/build/tools/java-event-log-tags.py
platform/frameworks/base/core/jni/android_util_EventLog.cpp
platform/frameworks/base/core/java/android/os/Trace.java
platform/frameworks/base/core/jni/android_os_Trace.cpp
platform/system/core/libcutils/trace-dev.c
```
## 一、性能统计
@@ -106,7 +114,7 @@ option java_package com.android.internal.logging;
```
他说对于这个脚本的描述在system/core/logcat/event.logtags
我们找下platform/frameworks/system/core/logcat/event.logtags
我们找下platform/system/core/logcat/event.logtags
```text
@@ -248,7 +256,7 @@ public class EventLogTags{
```
所以EventLogTags.writeSysuiHistogram最终是调用了EventLog.writeEvent函数这个函数是一个native函数它的实现在
platform/base/core/jni/android_util_EventLog.cpp
platform/frameworks/base/core/jni/android_util_EventLog.cpp
#### 1.1.3 android_util_EventLog
@@ -321,9 +329,154 @@ writeEvent有许多函数但是基本都是向ctx里面拼接字符然后
}
```
android_log_write_list函数就是去输出日志了,里面写得比较复杂,不过主要作用就是输出到logcat
android_log_write_list里面写得比较复杂因为这涉及到日志系统的处理流程,后续再专门拿一篇文章来讲,
android_log_write_list函数并不会直接输出日志只是把要输出的日志内容加入到一个链表中而日志系统会循环这个链表最终输出
到这里,我们就理清了事件日志记录的全过程,主要是有一个脚本转化的过程,以后所有以.logtags结尾的文件都可以这样理解了
#### 1.2.1 traceBegin
定义在platform/frameworks/base/core/java/android/os/Trace.java
```java
public static void traceBegin(long traceTag, String methodName) {
if (isTagEnabled(traceTag)) {
nativeTraceBegin(traceTag, methodName);
}
}
public static boolean isTagEnabled(long traceTag) {
long tags = sEnabledTags;
if (tags == TRACE_TAG_NOT_READY) {
tags = cacheEnabledTags();
}
return (tags & traceTag) != 0;
}
@FastNative
private static native void nativeTraceBegin(long tag, String name);
```
traceBegin先判断了下一个状态值sEnabledTags如果满足条件就调用nativeTraceBegin
#### 1.2.2 nativeTraceBegin
定义在platform/frameworks/base/core/jni/android_os_Trace.cpp
```C++
static const JNINativeMethod gTraceMethods[] = {
// ----------- @FastNative ----------------
{ "nativeTraceBegin",
"(JLjava/lang/String;)V",
(void*)android_os_Trace_nativeTraceBegin },
{ "nativeTraceEnd",
"(J)V",
(void*)android_os_Trace_nativeTraceEnd },
};
```
这里提一下@FastNative这个注解这是ART 8.0增加的可以提升JNI调用速度参考https://blog.csdn.net/zhangbijun1230/article/details/80562747
nativeTraceBegin对应的函数是android_os_Trace_nativeTraceBegin
```C++
static void android_os_Trace_nativeTraceBegin(JNIEnv* env, jclass clazz,
jlong tag, jstring nameStr) {
ScopedStringChars jchars(env, nameStr); //对String的封装
String8 utf8Chars(reinterpret_cast<const char16_t*>(jchars.get()), jchars.size());//也是对String的封装
sanitizeString(utf8Chars);//将 /0, 回车,| 转为空格
ALOGV("%s: %" PRId64 " %s", __FUNCTION__, tag, utf8Chars.string());
atrace_begin(tag, utf8Chars.string());
}
```
这里是将传进来和参数转为C里面封装的String然后将 /0, 回车,| 转为空格输出一段日志后就调用atrace_begin
这里稍微讲一下C中如何寻找一些函数的定义比如这里的atrace_begin函数并不在该源文件中怎样快速找到对应的实现
首先Souce Insight导入文件时尽量把一个文件夹一起导入因为相关的源码都基本放在同一个文件夹下这样就可以迅速找到
但是有时源码之间相差很远这时我们就要观察include看哪个比较像
```C++
#include <inttypes.h>
#include <cutils/trace.h>
#include <utils/String8.h>
#include <log/log.h>
#include <JNIHelp.h>
#include <ScopedUtfChars.h>
#include <ScopedStringChars.h>
```
该源文件中就这几个头文件一看就知道应该是cutils/trace.h所以就去对应目录platform/system/core/xxx找基本就可以找到
另外再推荐一个Windows的搜索工具Everything比如你找不到trace.h,直接搜索就能找到
```C
static inline void atrace_begin(uint64_t tag, const char* name)
{
if (CC_UNLIKELY(atrace_is_tag_enabled(tag))) {
void atrace_begin_body(const char*);
atrace_begin_body(name);
}
}
```
一般来讲头文件只做函数声明不做代码实现这里似乎实现了代码其实并没有这个函数是inline函数本身会被消除掉
也就是说在编译后会把调用这个函数的地方替换为方法体中的代码CC_UNLIKELY主要是做代码优化的本身没有什么逻辑
我们主要看下atrace_begin_body这里就涉及到寻找.h的实现类
头文件的实现类xx.cxx.cpp基本也就在对应的目录下名字也不会差太远
另外可以观察目录下的Android.mk或者Android.bp这些编译文件里面会写包含了哪些源文件
```text
android: {
srcs: libcutils_nonwindows_sources + [
"android_reboot.c",
"ashmem-dev.c",
"klog.cpp",
"partition_utils.c",
"properties.cpp",
"qtaguid.c",
"trace-dev.c",
"uevent.c",
],
sanitize: {
misc_undefined: ["integer"],
},
},
```
trace.h的实现类叫trace-dev.c,定义在platform/system/core/libcutils/trace-dev.c
#### 1.2.3 atrace_begin_body
定义在platform/system/core/libcutils/trace-dev.c
```C++
void atrace_begin_body(const char* name)
{
char buf[ATRACE_MESSAGE_LENGTH];
int len = snprintf(buf, sizeof(buf), "B|%d|%s", getpid(), name); //拼接pid
if (len >= (int) sizeof(buf)) {
ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name);
len = sizeof(buf) - 1;
}
write(atrace_marker_fd, buf, len);//写入trace_marker文件
}
atrace_marker_fd = open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY | O_CLOEXEC);
```
这就是最终干活的地方了将pid拼接一下将拼接的结果写入文件/sys/kernel/debug/tracing/trace_marker
到这里,我们就理清了事件日志记录的全过程,主要是有一个脚本转化的过程,以后所以以.logtags结尾的文件都可以这样理解了
#### 1.1 参数解析