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

Commit 16057fad authored by Vasu Nori's avatar Vasu Nori
Browse files

fix broken logTimeStat stuff 

log time in the following 2 situations
1. all transactions. time measured = wall time between begin-commit
2. queries (which are not in tranactions)

Change-Id: I67be9487a96072695aff3529ba4a257f4c8ec596
parent 5579bb75

core/java/android/database/sqlite/SQLiteCursor.java

+2 −2
Original line number Diff line number Diff line
@@ -241,7 +241,7 @@ public class SQLiteCursor extends AbstractWindowedCursor { 
        mColumnNameMap = null;

        mQuery = query;



        query.mDatabase.lock();

        query.mDatabase.lock(query.mSql);

        try {

            // Setup the list of columns

            int columnCount = mQuery.columnCountLocked();
@@ -419,7 +419,7 @@ public class SQLiteCursor extends AbstractWindowedCursor { 
                // since we need to use a different database connection handle,

                // re-compile the query

                try {

                    db.lock();

                    db.lock(mQuery.mSql);

                } catch (IllegalStateException e) {

                    // for backwards compatibility, just return false

                    Log.w(TAG, "requery() failed " + e.getMessage(), e);

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

+39 −32
Original line number Diff line number Diff line
@@ -230,9 +230,23 @@ public class SQLiteDatabase extends SQLiteClosable { 
    private static int sQueryLogTimeInMillis = 0;  // lazily initialized

    private static final int QUERY_LOG_SQL_LENGTH = 64;

    private static final String COMMIT_SQL = "COMMIT;";

    private static final String BEGIN_SQL = "BEGIN;";

    private final Random mRandom = new Random();

    /** the last non-commit/rollback sql statement in a transaction */

    // guarded by 'this'

    private String mLastSqlStatement = null;



    synchronized String getLastSqlStatement() {

        return mLastSqlStatement;

    }



    synchronized void setLastSqlStatement(String sql) {

        mLastSqlStatement = sql;

    }



    /** guarded by {@link #mLock} */

    private long mTransStartTime;



    // String prefix for slow database query EventLog records that show

    // lock acquistions of the database.

    /* package */ static final String GET_LOCK_LOG_PREFIX = "GETLOCK:";
@@ -386,11 +400,16 @@ public class SQLiteDatabase extends SQLiteClosable { 
     *

     * @see #unlock()

     */

    /* package */ void lock() {

        lock(false);

    /* package */ void lock(String sql) {

        lock(sql, false);

    }



    /* pachage */ void lock() {

        lock(null, false);

    }



    private static final long LOCK_WAIT_PERIOD = 30L;

    private void lock(boolean forced) {

    private void lock(String sql, boolean forced) {

        // make sure this method is NOT being called from a 'synchronized' method

        if (Thread.holdsLock(this)) {

            Log.w(TAG, "don't lock() while in a synchronized method");
@@ -398,6 +417,7 @@ public class SQLiteDatabase extends SQLiteClosable { 
        verifyDbIsOpen();

        if (!forced && !mLockingEnabled) return;

        boolean done = false;

        long timeStart = SystemClock.uptimeMillis();

        while (!done) {

            try {

                // wait for 30sec to acquire the lock
@@ -420,6 +440,9 @@ public class SQLiteDatabase extends SQLiteClosable { 
                mLockAcquiredThreadTime = Debug.threadCpuTimeNanos();

            }

        }

        if (sql != null) {

            logTimeStat(sql, timeStart, GET_LOCK_LOG_PREFIX);

        }

    }

    private static class DatabaseReentrantLock extends ReentrantLock {

        DatabaseReentrantLock(boolean fair) {
@@ -444,7 +467,11 @@ public class SQLiteDatabase extends SQLiteClosable { 
     * @see #unlockForced()

     */

    private void lockForced() {

        lock(true);

        lock(null, true);

    }



    private void lockForced(String sql) {

        lock(sql, true);

    }



    /**
@@ -612,7 +639,7 @@ public class SQLiteDatabase extends SQLiteClosable { 
    private void beginTransaction(SQLiteTransactionListener transactionListener,

            boolean exclusive) {

        verifyDbIsOpen();

        lockForced();

        lockForced(BEGIN_SQL);

        boolean ok = false;

        try {

            // If this thread already had the lock then get out
@@ -635,6 +662,7 @@ public class SQLiteDatabase extends SQLiteClosable { 
            } else {

                execSQL("BEGIN IMMEDIATE;");

            }

            mTransStartTime = SystemClock.uptimeMillis();

            mTransactionListener = transactionListener;

            mTransactionIsSuccessful = true;

            mInnerTransactionIsSuccessful = false;
@@ -698,6 +726,8 @@ public class SQLiteDatabase extends SQLiteClosable { 
                        Log.i(TAG, "PRAGMA wal_Checkpoint done");

                    }

                }

                // log the transaction time to the Eventlog.

                logTimeStat(getLastSqlStatement(), mTransStartTime, COMMIT_SQL);

            } else {

                try {

                    execSQL("ROLLBACK;");
@@ -1855,24 +1885,11 @@ public class SQLiteDatabase extends SQLiteClosable { 
     * @throws SQLException if the SQL string is invalid

     */

    public void execSQL(String sql) throws SQLException {

        int stmtType = DatabaseUtils.getSqlStatementType(sql);

        if (stmtType == DatabaseUtils.STATEMENT_ATTACH) {

        if (DatabaseUtils.getSqlStatementType(sql) == DatabaseUtils.STATEMENT_ATTACH) {

            disableWriteAheadLogging();

        }

        long timeStart = SystemClock.uptimeMillis();

        logTimeStat(mLastSqlStatement, timeStart, GET_LOCK_LOG_PREFIX);

        executeSql(sql, null);



        if (stmtType == DatabaseUtils.STATEMENT_ATTACH) {

            mHasAttachedDbs = true;

        }

        // Log commit statements along with the most recently executed

        // SQL statement for disambiguation.

        if (stmtType == DatabaseUtils.STATEMENT_COMMIT) {

            logTimeStat(mLastSqlStatement, timeStart, COMMIT_SQL);

        } else {

            logTimeStat(sql, timeStart, null);

        }

        executeSql(sql, null);

    }



    /**
@@ -1926,19 +1943,15 @@ public class SQLiteDatabase extends SQLiteClosable { 
    }



    private int executeSql(String sql, Object[] bindArgs) throws SQLException {

        long timeStart = SystemClock.uptimeMillis();

        int n;

        SQLiteStatement statement = new SQLiteStatement(this, sql, bindArgs);

        try {

            n = statement.executeUpdateDelete();

            return statement.executeUpdateDelete();

        } catch (SQLiteDatabaseCorruptException e) {

            onCorruption();

            throw e;

        } finally {

            statement.close();

        }

        logTimeStat(sql, timeStart);

        return n;

    }



    @Override
@@ -2027,12 +2040,7 @@ public class SQLiteDatabase extends SQLiteClosable { 
        logTimeStat(sql, beginMillis, null);

    }



    /* package */ void logTimeStat(String sql, long beginMillis, String prefix) {

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



    private void logTimeStat(String sql, long beginMillis, String prefix) {

        // 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.
@@ -2059,7 +2067,6 @@ public class SQLiteDatabase extends SQLiteClosable { 
        if (prefix != null) {

            sql = prefix + sql;

        }



        if (sql.length() > QUERY_LOG_SQL_LENGTH) sql = sql.substring(0, QUERY_LOG_SQL_LENGTH);



        // ActivityThread.currentPackageName() only returns non-null if the

core/java/android/database/sqlite/SQLiteDirectCursorDriver.java

+1 −1
Original line number Diff line number Diff line
@@ -42,7 +42,7 @@ public class SQLiteDirectCursorDriver implements SQLiteCursorDriver { 
        SQLiteQuery query = null;



        try {

            mDatabase.lock();

            mDatabase.lock(mSql);

            mDatabase.closePendingStatements();

            query = new SQLiteQuery(mDatabase, mSql, 0, selectionArgs);

core/java/android/database/sqlite/SQLiteQuery.java

+1 −2
Original line number Diff line number Diff line
@@ -70,9 +70,8 @@ public class SQLiteQuery extends SQLiteProgram { 
     */

    /* package */ int fillWindow(CursorWindow window,

            int maxRead, int lastPos) {

        mDatabase.lock(mSql);

        long timeStart = SystemClock.uptimeMillis();

        mDatabase.lock();

        mDatabase.logTimeStat(mSql, timeStart, SQLiteDatabase.GET_LOCK_LOG_PREFIX);

        try {

            acquireReference();

            try {

core/java/android/database/sqlite/SQLiteStatement.java

+15 −8
Original line number Diff line number Diff line
@@ -80,7 +80,8 @@ public class SQLiteStatement extends SQLiteProgram 
     */

    public int executeUpdateDelete() {

        try {

            long timeStart = acquireAndLock(WRITE);

            saveSqlAsLastSqlStatement();

            acquireAndLock(WRITE);

            int numChanges = 0;

            if ((mStatementType & STATEMENT_DONT_PREPARE) > 0) {

                // since the statement doesn't have to be prepared,
@@ -90,7 +91,6 @@ public class SQLiteStatement extends SQLiteProgram 
            } else {

                numChanges = native_execute();

            }

            mDatabase.logTimeStat(mSql, timeStart);

            return numChanges;

        } finally {

            releaseAndUnlock();
@@ -108,15 +108,22 @@ public class SQLiteStatement extends SQLiteProgram 
     */

    public long executeInsert() {

        try {

            long timeStart = acquireAndLock(WRITE);

            long lastInsertedRowId = native_executeInsert();

            mDatabase.logTimeStat(mSql, timeStart);

            return lastInsertedRowId;

            saveSqlAsLastSqlStatement();

            acquireAndLock(WRITE);

            return native_executeInsert();

        } finally {

            releaseAndUnlock();

        }

    }



    private void saveSqlAsLastSqlStatement() {

        if (((mStatementType & SQLiteProgram.STATEMENT_TYPE_MASK) ==

                DatabaseUtils.STATEMENT_UPDATE) ||

                (mStatementType & SQLiteProgram.STATEMENT_TYPE_MASK) ==

                DatabaseUtils.STATEMENT_BEGIN) {

            mDatabase.setLastSqlStatement(mSql);

        }

    }

    /**

     * Execute a statement that returns a 1 by 1 table with a numeric value.

     * For example, SELECT COUNT(*) FROM table;
@@ -199,7 +206,7 @@ public class SQLiteStatement extends SQLiteProgram 
     *   <li>if the SQL statement is an update, start transaction if not already in one.

     *   otherwise, get lock on the database</li>

     *   <li>acquire reference on this object</li>

     *   <li>and then return the current time _before_ the database lock was acquired</li>

     *   <li>and then return the current time _after_ the database lock was acquired</li>

     * </ul>

     * <p>

     * This method removes the duplicate code from the other public
@@ -243,7 +250,7 @@ public class SQLiteStatement extends SQLiteProgram 
        }

        // do I have database lock? if not, grab it.

        if (!mDatabase.isDbLockedByCurrentThread()) {

            mDatabase.lock();

            mDatabase.lock(mSql);

            mState = LOCK_ACQUIRED;

        }