From b28c7972bd3e5e34138e2fd7a2e1433d65205bdf Mon Sep 17 00:00:00 2001
From: Brad Fitzpatrick <bradfitz@android.com>
Date: Fri, 12 Feb 2010 12:49:41 -0800
Subject: [PATCH] Log previous SQL statement also when logging "COMMIT;"
 operations.

Previously, as somewhat expected, the top SQL statements showing up in
the SQL analysis dashboards from developer phones was just "COMMIT;"
statements, which is pretty uselessly ambiguous.

Now the logs for commit operations look like:

I/db_operation( 1249): [/data/data/com.google.android.gsf/databases/subscribedfeeds.db,COMMIT;DELETE FROM _deleted_feeds WHERE _sync_account=? AND _syn,461,com.google.process.gapps,100]
I/db_operation( 1290): [/data/data/com.android.providers.contacts/databases/contacts2.db,COMMIT;SELECT account_name, account_type FROM _sync_state,126,android.process.acore,100]
I/db_operation( 1249): [/data/data/com.google.android.gsf/databases/talk.db,COMMIT;INSERT OR REPLACE  INTO providerSettings(value, name) VAL,252,com.google.process.gapps,100]
I/db_operation( 1377): [/data/data/com.android.providers.calendar/databases/calendar.db,COMMIT;SELECT localTimezone, minInstance, maxInstance FROM Calen,948,,100]
I/db_operation( 1377): [/data/data/com.android.providers.calendar/databases/calendar.db,COMMIT;SELECT begin-(minutes*60000) AS myAlarmTime, Instances.ev,82,,83]

It doesn't totally pin-point the offending code, but it should get us
most of the way there.  We may enhance this logging again in the
future.
---
 .../database/sqlite/SQLiteDatabase.java       | 26 ++++++++++++++++---
 1 file changed, 23 insertions(+), 3 deletions(-)

diff --git a/core/java/android/database/sqlite/SQLiteDatabase.java b/core/java/android/database/sqlite/SQLiteDatabase.java
index a7e6ca0c3f023..9ac8a4dab5e73 100644
--- a/core/java/android/database/sqlite/SQLiteDatabase.java
+++ b/core/java/android/database/sqlite/SQLiteDatabase.java
@@ -201,10 +201,17 @@ public class SQLiteDatabase extends SQLiteClosable {
 
     private long mLastLockMessageTime = 0L;
 
-    // always log queries which take 100ms+; shorter queries are sampled accordingly
+    // Things related to query logging/sampling for debugging
+    // slow/frequent queries during development.  Always log queries
+    // which take 100ms+; shorter queries are sampled accordingly.
+    // Commit statements, which are typically slow, are logged
+    // together with the most recently executed SQL statement, for
+    // disambiguation.
     private static final int QUERY_LOG_TIME_IN_MILLIS = 100;
     private static final int QUERY_LOG_SQL_LENGTH = 64;
+    private static final String COMMIT_SQL = "COMMIT;";
     private final Random mRandom = new Random();
+    private String mLastSqlStatement = null;
 
     /** Used by native code, do not rename */
     /* package */ int mNativeHandle = 0;
@@ -540,7 +547,7 @@ public class SQLiteDatabase extends SQLiteClosable {
                 }
             }
             if (mTransactionIsSuccessful) {
-                execSQL("COMMIT;");
+                execSQL(COMMIT_SQL);
             } else {
                 try {
                     execSQL("ROLLBACK;");
@@ -1660,7 +1667,15 @@ public class SQLiteDatabase extends SQLiteClosable {
         } finally {
             unlock();
         }
-        logTimeStat(sql, timeStart);
+
+        // Log commit statements along with the most recently executed
+        // SQL statement for disambiguation.  Note that instance
+        // equality to COMMIT_SQL is safe here.
+        if (sql == COMMIT_SQL) {
+            logTimeStat(sql + mLastSqlStatement, timeStart);
+        } else {
+            logTimeStat(sql, timeStart);
+        }
     }
 
     /**
@@ -1786,6 +1801,11 @@ public class SQLiteDatabase extends SQLiteClosable {
 
 
     /* package */ void logTimeStat(String sql, long beginMillis) {
+        // Keep track of the last statement executed here, as this is
+        // the common funnel through which all methods of hitting
+        // libsqlite eventually flow.
+        mLastSqlStatement = sql;
+
         // 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.