OSDN Git Service

use sqlite 3.6.22 to print and profile the sql statetements
authorVasu Nori <vnori@google.com>
Fri, 5 Feb 2010 22:49:04 +0000 (14:49 -0800)
committerVasu Nori <vnori@google.com>
Mon, 8 Feb 2010 18:56:48 +0000 (10:56 -0800)
instead of rolling our own trace/profile code in java, lets use
sqlite 3.6.22 features. turns out sqlite does a good job of
printing the sql statements - including the ones from the triggers.

core/java/android/database/sqlite/SQLiteClosable.java
core/java/android/database/sqlite/SQLiteDatabase.java
core/java/android/database/sqlite/SQLiteDebug.java
core/java/android/database/sqlite/SQLiteProgram.java
core/java/android/database/sqlite/SQLiteQuery.java
core/java/android/database/sqlite/SQLiteStatement.java
core/jni/android_database_SQLiteDatabase.cpp
core/tests/coretests/src/android/database/sqlite/SQLiteDebugTest.java [deleted file]

index f64261c..7776520 100644 (file)
@@ -29,7 +29,7 @@ public abstract class SQLiteClosable {
         synchronized(mLock) {
             if (mReferenceCount <= 0) {
                 throw new IllegalStateException(
-                        "attempt to acquire a reference on a close SQLiteClosable");
+                        "attempt to acquire a reference on an already-closed SQLiteClosable obj.");
             }
             mReferenceCount++;     
         }
index 22e2a83..c6548dc 100644 (file)
@@ -290,10 +290,6 @@ public class SQLiteDatabase extends SQLiteClosable {
     @Override
     protected void onAllReferencesReleased() {
         if (isOpen()) {
-            if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-                Log.d(TAG, "captured_sql|" + mPath + "|DETACH DATABASE " +
-                        getDatabaseName(mPath) + ";");
-            }
             if (SQLiteDebug.DEBUG_SQL_CACHE) {
                 mTimeClosed = getTime();
             }
@@ -782,7 +778,14 @@ public class SQLiteDatabase extends SQLiteClosable {
         SQLiteDatabase db = null;
         try {
             // Open the database.
-            return new SQLiteDatabase(path, factory, flags);
+            SQLiteDatabase sqliteDatabase = new SQLiteDatabase(path, factory, flags);
+            if (SQLiteDebug.DEBUG_SQL_STATEMENTS) {
+                sqliteDatabase.enableSqlTracing(path);
+            }
+            if (SQLiteDebug.DEBUG_SQL_TIME) {
+                sqliteDatabase.enableSqlProfiling(path);
+            }
+            return sqliteDatabase;
         } catch (SQLiteDatabaseCorruptException e) {
             // Try to recover from this, if we can.
             // TODO: should we do this for other open failures?
@@ -1652,9 +1655,6 @@ public class SQLiteDatabase extends SQLiteClosable {
      */
     public void execSQL(String sql) throws SQLException {
         long timeStart = Debug.threadCpuTimeNanos();
-        if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-            Log.v(TAG, SQLiteDebug.captureSql(this.getPath(), sql, null));
-        }
         lock();
         try {
             native_execSQL(sql);
@@ -1680,9 +1680,6 @@ public class SQLiteDatabase extends SQLiteClosable {
         if (bindArgs == null) {
             throw new IllegalArgumentException("Empty bindArgs");
         }
-        if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-            Log.v(TAG, SQLiteDebug.captureSql(this.getPath(), sql, bindArgs));
-        }
         long timeStart = Debug.threadCpuTimeNanos();
         lock();
         SQLiteStatement statement = null;
@@ -1741,10 +1738,6 @@ public class SQLiteDatabase extends SQLiteClosable {
         mLeakedException = new IllegalStateException(path +
             " SQLiteDatabase created and never closed");
         mFactory = factory;
-        if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-            Log.d(TAG, "captured_sql|" + mPath + "|ATTACH DATABASE '" + mPath +
-                    "' as " + getDatabaseName(mPath) + ";");
-        }
         dbopen(mPath, mFlags);
         if (SQLiteDebug.DEBUG_SQL_CACHE) {
             mTimeOpened = getTime();
@@ -1754,10 +1747,6 @@ public class SQLiteDatabase extends SQLiteClosable {
             setLocale(Locale.getDefault());
         } catch (RuntimeException e) {
             Log.e(TAG, "Failed to setLocale() when constructing, closing the database", e);
-            if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-                Log.d(TAG, "captured_sql|" + mPath + "|DETACH DATABASE " +
-                        getDatabaseName(mPath) + ";");
-            }
             dbclose();
             if (SQLiteDebug.DEBUG_SQL_CACHE) {
                 mTimeClosed = getTime();
@@ -1770,20 +1759,6 @@ public class SQLiteDatabase extends SQLiteClosable {
         return new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS ").format(System.currentTimeMillis());
     }
 
-    private String getDatabaseName(String path) {
-        if (path == null || path.trim().length() == 0) {
-            return "db not specified?";
-        }
-
-        if (path.equalsIgnoreCase(":memory:")) {
-            return "memorydb";
-        }
-        String[] tokens = path.split("/");
-        String[] lastNodeTokens = tokens[tokens.length - 1].split("\\.", 2);
-        return (lastNodeTokens.length == 1) ? lastNodeTokens[0]
-                : lastNodeTokens[0] + lastNodeTokens[1];
-    }
-
     /**
      * return whether the DB is opened as read only.
      * @return true if DB is opened as read only
@@ -2062,6 +2037,23 @@ public class SQLiteDatabase extends SQLiteClosable {
     private native void dbopen(String path, int flags);
 
     /**
+     * Native call to setup tracing of all sql statements
+     *
+     * @param path the full path to the database
+     */
+    private native void enableSqlTracing(String path);
+
+    /**
+     * Native call to setup profiling of all sql statements.
+     * currently, sqlite's profiling = printing of execution-time
+     * (wall-clock time) of each of the sql statements, as they
+     * are executed.
+     *
+     * @param path the full path to the database
+     */
+    private native void enableSqlProfiling(String path);
+
+    /**
      * Native call to execute a raw SQL statement. {@link #lock} must be held
      * when calling this method.
      *
index b12034a..4ea680e 100644 (file)
@@ -31,17 +31,17 @@ public final class SQLiteDebug {
             Log.isLoggable("SQLiteStatements", Log.VERBOSE);
 
     /**
-     * Controls the printing of compiled-sql-statement cache stats.
+     * Controls the printing of wall-clock time taken to execute SQL statements
+     * as they are executed.
      */
-    public static final boolean DEBUG_SQL_CACHE =
-            Log.isLoggable("SQLiteCompiledSql", Log.VERBOSE);
+    public static final boolean DEBUG_SQL_TIME =
+            Log.isLoggable("SQLiteTime", Log.VERBOSE);
 
     /**
-     * Controls the capturing and printing of complete sql statement including the bind args and
-     * the database name.
+     * Controls the printing of compiled-sql-statement cache stats.
      */
-    public static final boolean DEBUG_CAPTURE_SQL =
-            Log.isLoggable("SQLiteCaptureSql", Log.VERBOSE);
+    public static final boolean DEBUG_SQL_CACHE =
+            Log.isLoggable("SQLiteCompiledSql", Log.VERBOSE);
 
     /**
      * Controls the stack trace reporting of active cursors being
@@ -121,62 +121,4 @@ public final class SQLiteDebug {
     static synchronized void notifyActiveCursorFinalized() {
         sNumActiveCursorsFinalized++;
     }
-
-    /**
-     * returns a  message containing the given database name (path) and the string built by
-     * replacing "?" characters in the given sql string with the corresponding
-     * positional values from the given param bindArgs.
-     *
-     * @param path the database name
-     * @param sql sql string with possibly "?" for bindargs
-     * @param bindArgs args for "?"s in the above string
-     * @return the String to be logged
-     */
-    /* package */ static String captureSql(String path, String sql, Object[] bindArgs) {
-        // how many bindargs in sql
-        sql = sql.trim();
-        String args[] = sql.split("\\?");
-        // how many "?"s in the given sql string?
-        int varArgsInSql = (sql.endsWith("?")) ? args.length : args.length - 1;
-
-        // how many bind args do we have in the given input param bindArgs
-        int bindArgsLen = (bindArgs == null) ? 0 : bindArgs.length;
-        if (varArgsInSql < bindArgsLen) {
-            return "too many bindArgs provided. " +
-                    "# of bindArgs = " + bindArgsLen + ", # of varargs = " + varArgsInSql +
-                    "; sql = " + sql;
-        }
-
-        // if there are no bindArgs, we are done. log the sql as is.
-        if (bindArgsLen == 0 && varArgsInSql == 0) {
-            return logSql(path, sql);
-        }
-
-        StringBuilder buf = new StringBuilder();
-
-        // take the supplied bindArgs and plug them into sql
-        for (int i = 0; i < bindArgsLen; i++) {
-            buf.append(args[i]);
-            buf.append(bindArgs[i]);
-        }
-
-        // does given sql have more varArgs than the supplied bindArgs
-        // if so, assign nulls to the extra varArgs in sql
-        for (int i = bindArgsLen; i < varArgsInSql; i ++) {
-            buf.append(args[i]);
-            buf.append("null");
-        }
-
-        // if there are any characters left in the given sql string AFTER the last "?"
-        // log them also. for example, if the given sql = "select * from test where a=? and b=1
-        // then the following code appends " and b=1" string to buf.
-        if (varArgsInSql < args.length) {
-            buf.append(args[varArgsInSql]);
-        }
-        return logSql(path, buf.toString());
-    }
-
-    private static String logSql(String path, String sql) {
-        return "captured_sql|" + path + "|" + sql + ";";
-    }
 }
index 1159c1d..a0aa019 100644 (file)
 
 package android.database.sqlite;
 
-import java.util.ArrayList;
-import java.util.Collections;
-import java.util.HashMap;
-import java.util.Map;
-import java.util.Set;
-
-import android.util.Log;
-
 /**
  * A base class for compiled SQLite programs.
  */
 public abstract class SQLiteProgram extends SQLiteClosable {
-    private static final String TAG = "SQLiteProgram";
 
     /** The database this program is compiled against. */
     protected SQLiteDatabase mDatabase;
@@ -53,16 +44,7 @@ public abstract class SQLiteProgram extends SQLiteClosable {
      */
     protected int nStatement = 0;
 
-    /**
-     * stores all bindargs for debugging purposes
-     */
-    private Map<Integer, String> mBindArgs = null;
-
     /* package */ SQLiteProgram(SQLiteDatabase db, String sql) {
-        if (SQLiteDebug.DEBUG_SQL_STATEMENTS) {
-            Log.d(TAG, "processing sql: " + sql);
-        }
-
         mDatabase = db;
         mSql = sql;
         db.acquireReference();
@@ -138,9 +120,6 @@ public abstract class SQLiteProgram extends SQLiteClosable {
      * @param index The 1-based index to the parameter to bind null to
      */
     public void bindNull(int index) {
-        if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-            addToBindArgs(index, "null");
-        }
         acquireReference();
         try {
             native_bind_null(index);
@@ -157,9 +136,6 @@ public abstract class SQLiteProgram extends SQLiteClosable {
      * @param value The value to bind
      */
     public void bindLong(int index, long value) {
-        if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-            addToBindArgs(index, value + "");
-        }
         acquireReference();
         try {
             native_bind_long(index, value);
@@ -176,9 +152,6 @@ public abstract class SQLiteProgram extends SQLiteClosable {
      * @param value The value to bind
      */
     public void bindDouble(int index, double value) {
-        if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-            addToBindArgs(index, value + "");
-        }
         acquireReference();
         try {
             native_bind_double(index, value);
@@ -195,9 +168,6 @@ public abstract class SQLiteProgram extends SQLiteClosable {
      * @param value The value to bind
      */
     public void bindString(int index, String value) {
-        if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-            addToBindArgs(index, "'" + value + "'");
-        }
         if (value == null) {
             throw new IllegalArgumentException("the bind value at index " + index + " is null");
         }
@@ -217,9 +187,6 @@ public abstract class SQLiteProgram extends SQLiteClosable {
      * @param value The value to bind
      */
     public void bindBlob(int index, byte[] value) {
-        if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-            addToBindArgs(index, "blob");
-        }
         if (value == null) {
             throw new IllegalArgumentException("the bind value at index " + index + " is null");
         }
@@ -235,9 +202,6 @@ public abstract class SQLiteProgram extends SQLiteClosable {
      * Clears all existing bindings. Unset bindings are treated as NULL.
      */
     public void clearBindings() {
-        if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-            mBindArgs = null;
-        }
         acquireReference();
         try {
             native_clear_bindings();
@@ -259,39 +223,6 @@ public abstract class SQLiteProgram extends SQLiteClosable {
     }
 
     /**
-     * this method is called under the debug flag {@link SQLiteDebug.DEBUG_CAPTURE_SQL} only.
-     * it collects the bindargs as they are called by the callers the bind... methods in this
-     * class.
-     */
-    private void addToBindArgs(int index, String obj) {
-        if (mBindArgs == null) {
-            mBindArgs = new HashMap<Integer, String>();
-        }
-        mBindArgs.put(index, obj);
-    }
-
-    /**
-     * constructs all the bindargs in sequence and returns a String Array of the values.
-     * it uses the HashMap built up by the above method.
-     *
-     * @return the string array of bindArgs with the args arranged in sequence
-     */
-    /* package */ String[] getBindArgs() {
-        if (mBindArgs == null) {
-            return null;
-        }
-        Set<Integer> indexSet = mBindArgs.keySet();
-        ArrayList<Integer> indexList = new ArrayList<Integer>(indexSet);
-        Collections.sort(indexList);
-        int len = indexList.size();
-        String[] bindObjs = new String[len];
-        for (int i = 0; i < len; i++) {
-            bindObjs[i] = mBindArgs.get(indexList.get(i));
-        }
-        return bindObjs;
-    }
-
-    /**
      * Compiles SQL into a SQLite program.
      *
      * <P>The database lock must be held when calling this method.
index c34661d..5bcad4b 100644 (file)
@@ -18,7 +18,6 @@ package android.database.sqlite;
 
 import android.database.CursorWindow;
 import android.os.Debug;
-import android.os.SystemClock;
 import android.util.Log;
 
 /**
index 0cee3c5..f1f5a2a 100644 (file)
@@ -17,7 +17,6 @@
 package android.database.sqlite;
 
 import android.os.Debug;
-import android.util.Log;
 
 /**
  * A pre-compiled statement against a {@link SQLiteDatabase} that can be reused.
@@ -27,8 +26,6 @@ import android.util.Log;
  */
 public class SQLiteStatement extends SQLiteProgram
 {
-    private static final String TAG = "SQLiteStatement";
-
     /**
      * Don't use SQLiteStatement constructor directly, please use
      * {@link SQLiteDatabase#compileStatement(String)}
@@ -52,12 +49,6 @@ public class SQLiteStatement extends SQLiteProgram
 
         acquireReference();
         try {
-            if (SQLiteDebug.DEBUG_SQL_STATEMENTS) {
-                Log.v(TAG, "execute() for [" + mSql + "]");
-            }
-            if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-                Log.v(TAG, SQLiteDebug.captureSql(mDatabase.getPath(), mSql, getBindArgs()));
-            }
             native_execute();
             mDatabase.logTimeStat(mSql, timeStart);
         } finally {
@@ -82,12 +73,6 @@ public class SQLiteStatement extends SQLiteProgram
 
         acquireReference();
         try {
-            if (SQLiteDebug.DEBUG_SQL_STATEMENTS) {
-                Log.v(TAG, "executeInsert() for [" + mSql + "]");
-            }
-            if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-                Log.v(TAG, SQLiteDebug.captureSql(mDatabase.getPath(), mSql, getBindArgs()));
-            }
             native_execute();
             mDatabase.logTimeStat(mSql, timeStart);
             return mDatabase.lastInsertRow();
@@ -111,12 +96,6 @@ public class SQLiteStatement extends SQLiteProgram
 
         acquireReference();
         try {
-            if (SQLiteDebug.DEBUG_SQL_STATEMENTS) {
-                Log.v(TAG, "simpleQueryForLong() for [" + mSql + "]");
-            }
-            if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-                Log.v(TAG, SQLiteDebug.captureSql(mDatabase.getPath(), mSql, getBindArgs()));
-            }
             long retValue = native_1x1_long();
             mDatabase.logTimeStat(mSql, timeStart);
             return retValue;
@@ -140,12 +119,6 @@ public class SQLiteStatement extends SQLiteProgram
 
         acquireReference();
         try {
-            if (SQLiteDebug.DEBUG_SQL_STATEMENTS) {
-                Log.v(TAG, "simpleQueryForString() for [" + mSql + "]");
-            }
-            if (SQLiteDebug.DEBUG_CAPTURE_SQL) {
-                Log.v(TAG, SQLiteDebug.captureSql(mDatabase.getPath(), mSql, getBindArgs()));
-            }
             String retValue = native_1x1_string();
             mDatabase.logTimeStat(mSql, timeStart);
             return retValue;
index 020aff4..c197010 100644 (file)
@@ -143,12 +143,68 @@ done:
     if (handle != NULL) sqlite3_close(handle);
 }
 
+void sqlTrace(void *databaseName, const char *sql) {
+    LOGI("sql_statement|%s|%s\n", (char *)databaseName, sql);
+}
+
+/* public native void enableSqlTracing(); */
+static void enableSqlTracing(JNIEnv* env, jobject object, jstring databaseName)
+{
+    sqlite3 * handle = (sqlite3 *)env->GetIntField(object, offset_db_handle);
+    char const *path = env->GetStringUTFChars(databaseName, NULL);
+    if (path == NULL) {
+        LOGE("Failure in enableSqlTracing(). VM ran out of memory?\n");
+        return; // VM would have thrown OutOfMemoryError
+    }
+    int len = strlen(path);
+    char *traceFuncArg = (char *)malloc(len + 1);
+    strncpy(traceFuncArg, path, len);
+    traceFuncArg[len-1] = NULL;
+    env->ReleaseStringUTFChars(databaseName, path);
+    sqlite3_trace(handle, &sqlTrace, (void *)traceFuncArg);
+    LOGI("will be printing all sql statements executed on database = %s\n", traceFuncArg);
+}
+
+void sqlProfile(void *databaseName, const char *sql, sqlite3_uint64 tm) {
+    double d = tm/1000000.0;
+    LOGI("elapsedTime4Sql|%s|%.3f ms|%s\n", (char *)databaseName, d, sql);
+}
+
+/* public native void enableSqlProfiling(); */
+static void enableSqlProfiling(JNIEnv* env, jobject object, jstring databaseName)
+{
+    sqlite3 * handle = (sqlite3 *)env->GetIntField(object, offset_db_handle);
+    char const *path = env->GetStringUTFChars(databaseName, NULL);
+    if (path == NULL) {
+        LOGE("Failure in enableSqlProfiling(). VM ran out of memory?\n");
+        return; // VM would have thrown OutOfMemoryError
+    }
+    int len = strlen(path);
+    char *traceFuncArg = (char *)malloc(len + 1);
+    strncpy(traceFuncArg, path, len);
+    traceFuncArg[len-1] = NULL;
+    env->ReleaseStringUTFChars(databaseName, path);
+    sqlite3_profile(handle, &sqlProfile, (void *)traceFuncArg);
+    LOGI("will be printing execution time of all sql statements executed on database = %s\n",
+            traceFuncArg);
+}
+
 /* public native void close(); */
 static void dbclose(JNIEnv* env, jobject object)
 {
     sqlite3 * handle = (sqlite3 *)env->GetIntField(object, offset_db_handle);
 
     if (handle != NULL) {
+        // release the memory associated with the traceFuncArg in enableSqlTracing function
+        void *traceFuncArg = sqlite3_trace(handle, &sqlTrace, NULL);
+        if (traceFuncArg != NULL) {
+            free(traceFuncArg);
+        }
+        // release the memory associated with the traceFuncArg in enableSqlProfiling function
+        traceFuncArg = sqlite3_profile(handle, &sqlProfile, NULL);
+        if (traceFuncArg != NULL) {
+            free(traceFuncArg);
+        }
         LOGV("Closing database: handle=%p\n", handle);
         int result = sqlite3_close(handle);
         if (result == SQLITE_OK) {
@@ -357,6 +413,8 @@ static JNINativeMethod sMethods[] =
     /* name, signature, funcPtr */
     {"dbopen", "(Ljava/lang/String;I)V", (void *)dbopen},
     {"dbclose", "()V", (void *)dbclose},
+    {"enableSqlTracing", "(Ljava/lang/String;)V", (void *)enableSqlTracing},
+    {"enableSqlProfiling", "(Ljava/lang/String;)V", (void *)enableSqlProfiling},
     {"native_execSQL", "(Ljava/lang/String;)V", (void *)native_execSQL},
     {"lastInsertRow", "()J", (void *)lastInsertRow},
     {"lastChangeCount", "()I", (void *)lastChangeCount},
diff --git a/core/tests/coretests/src/android/database/sqlite/SQLiteDebugTest.java b/core/tests/coretests/src/android/database/sqlite/SQLiteDebugTest.java
deleted file mode 100644 (file)
index ea807bd..0000000
+++ /dev/null
@@ -1,47 +0,0 @@
-/*
- * Copyright (C) 2008 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.database.sqlite;
-
-import junit.framework.TestCase;
-
-/**
- * Tests for the SQLiteDebug
- */
-public class SQLiteDebugTest extends TestCase {
-    private static final String TEST_DB = "test.db";
-
-    public void testCaptureSql() {
-        String rslt = SQLiteDebug.captureSql(TEST_DB, "select * from t1 where a=? and b=1",
-                new Object[] {"blah"});
-        String expectedVal = "select * from t1 where a='blah' and b=1";
-        assertTrue(rslt.equals("captured_sql|" + TEST_DB + "|" + expectedVal));
-
-        rslt = SQLiteDebug.captureSql(TEST_DB, "select * from t1 where a=?",
-                new Object[] {"blah"});
-        expectedVal = "select * from t1 where a='blah'";
-        assertTrue(rslt.equals("captured_sql|" + TEST_DB + "|" + expectedVal));
-
-        rslt = SQLiteDebug.captureSql(TEST_DB, "select * from t1 where a=1",
-                new Object[] {"blah"});
-        assertTrue(rslt.startsWith("too many bindArgs provided."));
-
-        rslt = SQLiteDebug.captureSql(TEST_DB, "update t1 set a=? where b=?",
-                new Object[] {"blah", "foo"});
-        expectedVal = "update t1 set a='blah' where b='foo'";
-        assertTrue(rslt.equals("captured_sql|" + TEST_DB + "|" + expectedVal));
-    }
-}