Merge change I06fb08c4 into eclair-mr2

* changes:
  Expand db_operation logging to prepare for widespread sample collection: - always enable the log, but subsample for queries faster than 100ms - add information about whether it's blocking a main thread - log the entire sql (have not yet added quoted-string-stripping)

3 files changed, 52 insertions, 43 deletions

diff --git a/core/java/android/database/sqlite/SQLiteDatabase.java b/core/java/android/database/sqlite/SQLiteDatabase.java
index a07176f..ca7cec2 100644
--- a/core/java/android/database/sqlite/SQLiteDatabase.java
+++ b/core/java/android/database/sqlite/SQLiteDatabase.java
@@ -18,6 +18,7 @@ package android.database.sqlite;
 
 import com.google.android.collect.Maps;
 
+import android.app.ActivityThread;
 import android.content.ContentValues;
 import android.database.Cursor;
 import android.database.DatabaseUtils;
@@ -36,6 +37,7 @@ import java.util.HashMap;
 import java.util.Iterator;
 import java.util.Locale;
 import java.util.Map;
+import java.util.Random;
 import java.util.Set;
 import java.util.WeakHashMap;
 import java.util.concurrent.locks.ReentrantLock;
@@ -203,6 +205,11 @@ public class SQLiteDatabase extends SQLiteClosable {
 
     private long mLastLockMessageTime = 0L;
 
+    // always log queries which take 100ms+; shorter queries are sampled accordingly
+    private static final int QUERY_LOG_TIME_IN_NANOS = 100 * 1000000;
+    private static final int QUERY_LOG_SQL_LENGTH = 64;
+    private final Random mRandom = new Random();
+
     /** Used by native code, do not rename */
     /* package */ int mNativeHandle = 0;
 
@@ -250,10 +257,6 @@ public class SQLiteDatabase extends SQLiteClosable {
 
     private final RuntimeException mLeakedException;
 
-    // package visible, since callers will access directly to minimize overhead in the case
-    // that logging is not enabled.
-    /* package */ final boolean mLogStats;
-
     // System property that enables logging of slow queries. Specify the threshold in ms.
     private static final String LOG_SLOW_QUERIES_PROPERTY = "db.log.slow_query_threshold";
     private final int mSlowQueryThreshold;
@@ -1643,8 +1646,7 @@ public class SQLiteDatabase extends SQLiteClosable {
      * @throws SQLException If the SQL string is invalid for some reason
      */
     public void execSQL(String sql) throws SQLException {
-        boolean logStats = mLogStats;
-        long timeStart = logStats ? SystemClock.elapsedRealtime() : 0;
+        long timeStart = Debug.threadCpuTimeNanos();
         lock();
         try {
             native_execSQL(sql);
@@ -1654,9 +1656,7 @@ public class SQLiteDatabase extends SQLiteClosable {
         } finally {
             unlock();
         }
-        if (logStats) {
-            logTimeStat(false /* not a read */, timeStart, SystemClock.elapsedRealtime());
-        }
+        logTimeStat(sql, timeStart);
     }
 
     /**
@@ -1673,8 +1673,7 @@ public class SQLiteDatabase extends SQLiteClosable {
             throw new IllegalArgumentException("Empty bindArgs");
         }
 
-        boolean logStats = mLogStats;
-        long timeStart = logStats ? SystemClock.elapsedRealtime() : 0;
+        long timeStart = Debug.threadCpuTimeNanos();
         lock();
         SQLiteStatement statement = null;
         try {
@@ -1695,9 +1694,7 @@ public class SQLiteDatabase extends SQLiteClosable {
             }
             unlock();
         }
-        if (logStats) {
-            logTimeStat(false /* not a read */, timeStart, SystemClock.elapsedRealtime());
-        }
+        logTimeStat(sql, timeStart);
     }
 
     @Override
@@ -1729,7 +1726,6 @@ public class SQLiteDatabase extends SQLiteClosable {
         }
         mFlags = flags;
         mPath = path;
-        mLogStats = "1".equals(android.os.SystemProperties.get("db.logstats"));
         mSlowQueryThreshold = SystemProperties.getInt(LOG_SLOW_QUERIES_PROPERTY, -1);
 
         mLeakedException = new IllegalStateException(path +
@@ -1890,8 +1886,35 @@ public class SQLiteDatabase extends SQLiteClosable {
         return compiledStatement;
     }
 
-    /* package */ void logTimeStat(boolean read, long begin, long end) {
-        EventLog.writeEvent(EVENT_DB_OPERATION, mPath, read ? 0 : 1, end - begin);
+    /* package */ void logTimeStat(String sql, long beginNanos) {
+        // Sample fast queries in proportion to the time taken.
+        // Quantize the % first, so the logged sampling probability
+        // exactly equals the actual sampling rate for this query.
+
+        int samplePercent;
+        long nanos = Debug.threadCpuTimeNanos() - beginNanos;
+        if (nanos >= QUERY_LOG_TIME_IN_NANOS) {
+            samplePercent = 100;
+        } else {
+            samplePercent = (int) (100 * nanos / QUERY_LOG_TIME_IN_NANOS) + 1;
+            if (mRandom.nextInt(100) < samplePercent) return;
+        }
+
+        if (sql.length() > QUERY_LOG_SQL_LENGTH) sql = sql.substring(0, QUERY_LOG_SQL_LENGTH);
+
+        // 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.
+        //
+        // Sadly, there's no fast way to determine app name if this is *not* a
+        // main thread, or when we are invoked via Binder (e.g. ContentProvider).
+        // Hopefully the full path to the database will be informative enough.
+
+        String blockingPackage = ActivityThread.currentPackageName();
+        if (blockingPackage == null) blockingPackage = "";
+
+        int millis = (int) (nanos / 1000000);
+        EventLog.writeEvent(EVENT_DB_OPERATION, mPath, sql, millis, blockingPackage, samplePercent);
     }
 
     /**
diff --git a/core/java/android/database/sqlite/SQLiteQuery.java b/core/java/android/database/sqlite/SQLiteQuery.java
index 94b950e..c34661d 100644
--- a/core/java/android/database/sqlite/SQLiteQuery.java
+++ b/core/java/android/database/sqlite/SQLiteQuery.java
@@ -17,6 +17,7 @@
 package android.database.sqlite;
 
 import android.database.CursorWindow;
+import android.os.Debug;
 import android.os.SystemClock;
 import android.util.Log;
 
@@ -57,10 +58,9 @@ public class SQLiteQuery extends SQLiteProgram {
      */
     /* package */ int fillWindow(CursorWindow window,  
             int maxRead, int lastPos) {
+        long timeStart = Debug.threadCpuTimeNanos();
         mDatabase.lock();
 
-        boolean logStats = mDatabase.mLogStats;
-        long startTime = logStats ? SystemClock.elapsedRealtime() : 0;
         try {
             acquireReference();
             try {
@@ -75,10 +75,7 @@ public class SQLiteQuery extends SQLiteProgram {
                 if (SQLiteDebug.DEBUG_SQL_STATEMENTS) {
                     Log.d(TAG, "fillWindow(): " + mSql);
                 }
-                if (logStats) {
-                    mDatabase.logTimeStat(true /* read */, startTime,
-                            SystemClock.elapsedRealtime());
-                }
+                mDatabase.logTimeStat(mSql, timeStart);
                 return numRows;
             } catch (IllegalStateException e){
                 // simply ignore it
diff --git a/core/java/android/database/sqlite/SQLiteStatement.java b/core/java/android/database/sqlite/SQLiteStatement.java
index a81c9a6..cc714ee 100644
--- a/core/java/android/database/sqlite/SQLiteStatement.java
+++ b/core/java/android/database/sqlite/SQLiteStatement.java
@@ -16,6 +16,7 @@
 
 package android.database.sqlite;
 
+import android.os.Debug;
 import android.os.SystemClock;
 import android.util.Log;
 
@@ -47,9 +48,8 @@ public class SQLiteStatement extends SQLiteProgram
      *         some reason
      */
     public void execute() {
+        long timeStart = Debug.threadCpuTimeNanos();
         mDatabase.lock();
-        boolean logStats = mDatabase.mLogStats;
-        long startTime = logStats ? SystemClock.elapsedRealtime() : 0;
 
         acquireReference();
         try {
@@ -57,9 +57,7 @@ public class SQLiteStatement extends SQLiteProgram
                 Log.v(TAG, "execute() for [" + mSql + "]");
             }
             native_execute();
-            if (logStats) {
-                mDatabase.logTimeStat(false /* write */, startTime, SystemClock.elapsedRealtime());
-            }
+            mDatabase.logTimeStat(mSql, timeStart);
         } finally {
             releaseReference();
             mDatabase.unlock();
@@ -77,9 +75,8 @@ public class SQLiteStatement extends SQLiteProgram
      *         some reason
      */
     public long executeInsert() {
+        long timeStart = Debug.threadCpuTimeNanos();
         mDatabase.lock();
-        boolean logStats = mDatabase.mLogStats;
-        long startTime = logStats ? SystemClock.elapsedRealtime() : 0;
 
         acquireReference();
         try {
@@ -87,9 +84,7 @@ public class SQLiteStatement extends SQLiteProgram
                 Log.v(TAG, "executeInsert() for [" + mSql + "]");
             }
             native_execute();
-            if (logStats) {
-                mDatabase.logTimeStat(false /* write */, startTime, SystemClock.elapsedRealtime());
-            }
+            mDatabase.logTimeStat(mSql, timeStart);
             return mDatabase.lastInsertRow();
         } finally {
             releaseReference();
@@ -106,9 +101,8 @@ public class SQLiteStatement extends SQLiteProgram
      * @throws android.database.sqlite.SQLiteDoneException if the query returns zero rows
      */
     public long simpleQueryForLong() {
+        long timeStart = Debug.threadCpuTimeNanos();
         mDatabase.lock();
-        boolean logStats = mDatabase.mLogStats;
-        long startTime = logStats ? SystemClock.elapsedRealtime() : 0;
 
         acquireReference();
         try {
@@ -116,9 +110,7 @@ public class SQLiteStatement extends SQLiteProgram
                 Log.v(TAG, "simpleQueryForLong() for [" + mSql + "]");
             }
             long retValue = native_1x1_long();
-            if (logStats) {
-                mDatabase.logTimeStat(false /* write */, startTime, SystemClock.elapsedRealtime());
-            }
+            mDatabase.logTimeStat(mSql, timeStart);
             return retValue;
         } finally {
             releaseReference();
@@ -135,9 +127,8 @@ public class SQLiteStatement extends SQLiteProgram
      * @throws android.database.sqlite.SQLiteDoneException if the query returns zero rows
      */
     public String simpleQueryForString() {
+        long timeStart = Debug.threadCpuTimeNanos();
         mDatabase.lock();
-        boolean logStats = mDatabase.mLogStats;
-        long startTime = logStats ? SystemClock.elapsedRealtime() : 0;
 
         acquireReference();
         try {
@@ -145,9 +136,7 @@ public class SQLiteStatement extends SQLiteProgram
                 Log.v(TAG, "simpleQueryForString() for [" + mSql + "]");
             }
             String retValue = native_1x1_string();
-            if (logStats) {
-                mDatabase.logTimeStat(false /* write */, startTime, SystemClock.elapsedRealtime());
-            }
+            mDatabase.logTimeStat(mSql, timeStart);
             return retValue;
         } finally {
             releaseReference();