Log ContentProvider operations to the EventLog.
Just like with db_operation, operations over 100ms are always logged,
while operations under that are subsampled.
This will help with performance analysis, getting real-world
performance numbers from dogfooders.
diff --git a/Android.mk b/Android.mk
index ec6f96b..eb84785 100644
--- a/Android.mk
+++ b/Android.mk
@@ -33,6 +33,9 @@
# FRAMEWORKS_BASE_SUBDIRS comes from build/core/pathmap.mk
LOCAL_SRC_FILES := $(call find-other-java-files,$(FRAMEWORKS_BASE_SUBDIRS))
+# EventLogTags files.
+LOCAL_SRC_FILES += core/java/android/content/EventLogTags.logtags
+
# The following filters out code we are temporarily not including at all.
# TODO: Move AWT and beans (and associated harmony code) back into libcore.
# TODO: Maybe remove javax.microedition entirely?
diff --git a/core/java/android/content/ContentResolver.java b/core/java/android/content/ContentResolver.java
index b33be23..bdbe341 100644
--- a/core/java/android/content/ContentResolver.java
+++ b/core/java/android/content/ContentResolver.java
@@ -16,6 +16,8 @@
package android.content;
+import android.accounts.Account;
+import android.app.ActivityThread;
import android.content.pm.PackageManager.NameNotFoundException;
import android.content.res.AssetFileDescriptor;
import android.content.res.Resources;
@@ -30,8 +32,8 @@
import android.os.RemoteException;
import android.os.ServiceManager;
import android.text.TextUtils;
-import android.accounts.Account;
import android.util.Config;
+import android.util.EventLog;
import android.util.Log;
import java.io.File;
@@ -41,6 +43,7 @@
import java.io.InputStream;
import java.io.OutputStream;
import java.util.List;
+import java.util.Random;
import java.util.ArrayList;
@@ -163,6 +166,11 @@
/** @hide */
public static final int SYNC_OBSERVER_TYPE_ALL = 0x7fffffff;
+ // Always log queries which take 100ms+; shorter queries are
+ // sampled accordingly.
+ private static final int SLOW_THRESHOLD_MILLIS = 100;
+ private final Random mRandom = new Random(); // guarded by itself
+
public ContentResolver(Context context) {
mContext = context;
}
@@ -235,12 +243,15 @@
return null;
}
try {
+ long startTime = System.currentTimeMillis();
Cursor qCursor = provider.query(uri, projection, selection, selectionArgs, sortOrder);
- if(qCursor == null) {
+ if (qCursor == null) {
releaseProvider(provider);
return null;
}
- //Wrap the cursor object into CursorWrapperInner object
+ long durationMillis = System.currentTimeMillis() - startTime;
+ maybeLogQueryToEventLog(durationMillis, uri, projection, selection, sortOrder);
+ // Wrap the cursor object into CursorWrapperInner object
return new CursorWrapperInner(qCursor, provider);
} catch (RemoteException e) {
releaseProvider(provider);
@@ -572,7 +583,11 @@
throw new IllegalArgumentException("Unknown URL " + url);
}
try {
- return provider.insert(url, values);
+ long startTime = System.currentTimeMillis();
+ Uri createdRow = provider.insert(url, values);
+ long durationMillis = System.currentTimeMillis() - startTime;
+ maybeLogUpdateToEventLog(durationMillis, url, "insert", null /* where */);
+ return createdRow;
} catch (RemoteException e) {
return null;
} finally {
@@ -627,7 +642,11 @@
throw new IllegalArgumentException("Unknown URL " + url);
}
try {
- return provider.bulkInsert(url, values);
+ long startTime = System.currentTimeMillis();
+ int rowsCreated = provider.bulkInsert(url, values);
+ long durationMillis = System.currentTimeMillis() - startTime;
+ maybeLogUpdateToEventLog(durationMillis, url, "bulkinsert", null /* where */);
+ return rowsCreated;
} catch (RemoteException e) {
return 0;
} finally {
@@ -652,7 +671,11 @@
throw new IllegalArgumentException("Unknown URL " + url);
}
try {
- return provider.delete(url, where, selectionArgs);
+ long startTime = System.currentTimeMillis();
+ int rowsDeleted = provider.delete(url, where, selectionArgs);
+ long durationMillis = System.currentTimeMillis() - startTime;
+ maybeLogUpdateToEventLog(durationMillis, url, "delete", where);
+ return rowsDeleted;
} catch (RemoteException e) {
return -1;
} finally {
@@ -680,7 +703,11 @@
throw new IllegalArgumentException("Unknown URI " + uri);
}
try {
- return provider.update(uri, values, where, selectionArgs);
+ long startTime = System.currentTimeMillis();
+ int rowsUpdated = provider.update(uri, values, where, selectionArgs);
+ long durationMillis = System.currentTimeMillis() - startTime;
+ maybeLogUpdateToEventLog(durationMillis, uri, "update", where);
+ return rowsUpdated;
} catch (RemoteException e) {
return -1;
} finally {
@@ -1217,6 +1244,78 @@
}
}
+ /**
+ * Returns sampling percentage for a given duration.
+ *
+ * Always returns at least 1%.
+ */
+ private int samplePercentForDuration(long durationMillis) {
+ if (durationMillis >= SLOW_THRESHOLD_MILLIS) {
+ return 100;
+ }
+ return (int) (100 * durationMillis / SLOW_THRESHOLD_MILLIS) + 1;
+ }
+
+ private void maybeLogQueryToEventLog(long durationMillis,
+ Uri uri, String[] projection,
+ String selection, String sortOrder) {
+ int samplePercent = samplePercentForDuration(durationMillis);
+ if (samplePercent < 100) {
+ synchronized (mRandom) {
+ if (mRandom.nextInt(100) >= samplePercent) {
+ return;
+ }
+ }
+ }
+
+ StringBuilder projectionBuffer = new StringBuilder(100);
+ if (projection != null) {
+ for (int i = 0; i < projection.length; ++i) {
+ // Note: not using a comma delimiter here, as the
+ // multiple arguments to EventLog.writeEvent later
+ // stringify with a comma delimiter, which would make
+ // parsing uglier later.
+ if (i != 0) projectionBuffer.append('/');
+ projectionBuffer.append(projection[i]);
+ }
+ }
+
+ // ActivityThread.currentPackageName() only returns non-null if the
+ // current thread is an application main thread. This parameter tells
+ // us whether an event loop is blocked, and if so, which app it is.
+ String blockingPackage = ActivityThread.currentPackageName();
+
+ EventLog.writeEvent(
+ EventLogTags.CONTENT_QUERY_OPERATION,
+ uri.toString(),
+ projectionBuffer.toString(),
+ selection != null ? selection : "",
+ sortOrder != null ? sortOrder : "",
+ durationMillis,
+ blockingPackage != null ? blockingPackage : "",
+ samplePercent);
+ }
+
+ private void maybeLogUpdateToEventLog(
+ long durationMillis, Uri uri, String operation, String selection) {
+ int samplePercent = samplePercentForDuration(durationMillis);
+ if (samplePercent < 100) {
+ synchronized (mRandom) {
+ if (mRandom.nextInt(100) >= samplePercent) {
+ return;
+ }
+ }
+ }
+ String blockingPackage = ActivityThread.currentPackageName();
+ EventLog.writeEvent(
+ EventLogTags.CONTENT_UPDATE_OPERATION,
+ uri.toString(),
+ operation,
+ selection != null ? selection : "",
+ durationMillis,
+ blockingPackage != null ? blockingPackage : "",
+ samplePercent);
+ }
private final class CursorWrapperInner extends CursorWrapper {
private IContentProvider mContentProvider;
diff --git a/core/java/android/content/EventLogTags.logtags b/core/java/android/content/EventLogTags.logtags
new file mode 100644
index 0000000..a815b95
--- /dev/null
+++ b/core/java/android/content/EventLogTags.logtags
@@ -0,0 +1,6 @@
+# See system/core/logcat/event.logtags for a description of the format of this file.
+
+option java_package android.content;
+
+52002 content_query_operation (uri|3),(projection|3),(selection|3),(sortorder|3),(time|1|3),(blocking_package|3),(sample_percent|1|6)
+52003 content_update_operation (uri|3),(operation|3),(selection|3),(time|1|3),(blocking_package|3),(sample_percent|1|6)