Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit b28c7972 authored by Brad Fitzpatrick's avatar Brad Fitzpatrick
Browse files

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.
parent 70251b17

core/java/android/database/sqlite/SQLiteDatabase.java

+23 −3
Original line number Diff line number Diff line
@@ -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,8 +1667,16 @@ public class SQLiteDatabase extends SQLiteClosable { 
        } finally {

            unlock();

        }



        // 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);

        }

    }



    /**

     * Execute a single SQL statement that is not a query. For example, CREATE
@@ -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.