am b59573cf: Merge change I06fb08c4 into eclair-mr2

Merge commit 'b59573cf53c8f09ac25fe0bfaf1d7067604ee983' into eclair-mr2-plus-aosp

* commit 'b59573cf53c8f09ac25fe0bfaf1d7067604ee983':
  Expand db_operation logging to prepare for widespread sample collection:
This commit is contained in:
Dan Egnor
2009-11-23 19:14:23 -08:00
committed by Android Git Automerger
3 changed files with 52 additions and 43 deletions

View File

@ -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);
}
/**

View File

@ -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

View File

@ -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();