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

Commit 12311959 authored by Dan Egnor's avatar Dan Egnor
Browse files

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)
parent 44e15c44

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

+40 −17
Original line number Diff line number Diff line
@@ -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);

    }



    /**

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

+3 −6
Original line number Diff line number Diff line
@@ -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

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

+9 −20
Original line number Diff line number Diff line
@@ -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();