Add a system for locally tracking performance on-device.

This commit is contained in:
Greyson Parrelli 2021-08-04 10:01:14 -04:00 committed by GitHub
parent c6c4988583
commit c131754874
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
15 changed files with 535 additions and 5 deletions

View file

@ -50,11 +50,13 @@ public class FlipperSqlCipherAdapter extends DatabaseDriver<FlipperSqlCipherAdap
SignalDatabase keyValueOpenHelper = KeyValueDatabase.getInstance((Application) getContext());
SignalDatabase megaphoneOpenHelper = MegaphoneDatabase.getInstance((Application) getContext());
SignalDatabase jobManagerOpenHelper = JobDatabase.getInstance((Application) getContext());
SignalDatabase metricsOpenHelper = LocalMetricsDatabase.getInstance((Application) getContext());
return Arrays.asList(new Descriptor(mainOpenHelper),
new Descriptor(keyValueOpenHelper),
new Descriptor(megaphoneOpenHelper),
new Descriptor(jobManagerOpenHelper));
new Descriptor(jobManagerOpenHelper),
new Descriptor(metricsOpenHelper));
} catch (Exception e) {
Log.i(TAG, "Unable to use reflection to access raw database.", e);
}

View file

@ -76,6 +76,7 @@ import org.thoughtcrime.securesms.util.AppForegroundObserver;
import org.thoughtcrime.securesms.util.AppStartup;
import org.thoughtcrime.securesms.util.DynamicTheme;
import org.thoughtcrime.securesms.util.FeatureFlags;
import org.thoughtcrime.securesms.util.SignalLocalMetrics;
import org.thoughtcrime.securesms.util.SignalUncaughtExceptionHandler;
import org.thoughtcrime.securesms.util.TextSecurePreferences;
import org.thoughtcrime.securesms.util.Util;
@ -113,6 +114,7 @@ public class ApplicationContext extends MultiDexApplication implements AppForegr
public void onCreate() {
Tracer.getInstance().start("Application#onCreate()");
AppStartup.getInstance().onApplicationCreate();
SignalLocalMetrics.ColdStart.start();
long startTime = System.currentTimeMillis();
@ -178,6 +180,7 @@ public class ApplicationContext extends MultiDexApplication implements AppForegr
.execute();
Log.d(TAG, "onCreate() took " + (System.currentTimeMillis() - startTime) + " ms");
SignalLocalMetrics.ColdStart.onApplicationCreateFinished();
Tracer.getInstance().end("Application#onCreate()");
}

View file

@ -16,6 +16,7 @@ import org.thoughtcrime.securesms.components.settings.DSLSettingsFragment
import org.thoughtcrime.securesms.components.settings.DSLSettingsText
import org.thoughtcrime.securesms.components.settings.configure
import org.thoughtcrime.securesms.database.DatabaseFactory
import org.thoughtcrime.securesms.database.LocalMetricsDatabase
import org.thoughtcrime.securesms.dependencies.ApplicationDependencies
import org.thoughtcrime.securesms.jobs.RefreshAttributesJob
import org.thoughtcrime.securesms.jobs.RefreshOwnProfileJob
@ -255,6 +256,18 @@ class InternalSettingsFragment : DSLSettingsFragment(R.string.preferences__inter
dividerPref()
sectionHeaderPref(R.string.preferences__internal_local_metrics)
clickPref(
title = DSLSettingsText.from(R.string.preferences__internal_clear_local_metrics),
summary = DSLSettingsText.from(R.string.preferences__internal_click_to_clear_all_local_metrics_state),
onClick = {
clearAllLocalMetricsState()
}
)
dividerPref()
sectionHeaderPref(R.string.preferences__internal_calling)
radioPref(
@ -354,4 +367,9 @@ class InternalSettingsFragment : DSLSettingsFragment(R.string.preferences__inter
DatabaseFactory.getSenderKeySharedDatabase(requireContext()).deleteAll()
Toast.makeText(context, "Deleted all sender key shared state.", Toast.LENGTH_SHORT).show()
}
private fun clearAllLocalMetricsState() {
LocalMetricsDatabase.getInstance(ApplicationDependencies.getApplication()).clear()
Toast.makeText(context, "Cleared all local metrics state.", Toast.LENGTH_SHORT).show()
}
}

View file

@ -130,6 +130,7 @@ import org.thoughtcrime.securesms.util.AppStartup;
import org.thoughtcrime.securesms.util.AvatarUtil;
import org.thoughtcrime.securesms.util.PlayStoreUtil;
import org.thoughtcrime.securesms.util.ServiceUtil;
import org.thoughtcrime.securesms.util.SignalLocalMetrics;
import org.thoughtcrime.securesms.util.SignalProxyUtil;
import org.thoughtcrime.securesms.util.SnapToTopDataObserver;
import org.thoughtcrime.securesms.util.StickyHeaderDecoration;
@ -560,6 +561,7 @@ public class ConversationListFragment extends MainFragment implements ActionMode
@Override
public void onItemRangeInserted(int positionStart, int itemCount) {
startupStopwatch.split("data-set");
SignalLocalMetrics.ColdStart.onConversationListDataLoaded();
defaultAdapter.unregisterAdapterDataObserver(this);
list.post(() -> {
AppStartup.getInstance().onCriticalRenderEventEnd();

View file

@ -0,0 +1,257 @@
package org.thoughtcrime.securesms.database
import android.annotation.SuppressLint
import android.app.Application
import android.content.ContentValues
import net.sqlcipher.database.SQLiteDatabase
import net.sqlcipher.database.SQLiteOpenHelper
import org.signal.core.util.logging.Log
import org.thoughtcrime.securesms.crypto.DatabaseSecret
import org.thoughtcrime.securesms.crypto.DatabaseSecretProvider
import org.thoughtcrime.securesms.database.model.LocalMetricsEvent
import org.thoughtcrime.securesms.util.CursorUtil
import org.thoughtcrime.securesms.util.SqlUtil
import java.util.concurrent.TimeUnit
/**
* Stores metrics for user events locally on disk.
*
* These metrics are only ever included in debug logs in an aggregate fashion (i.e. p50, p90, p99) and are never automatically uploaded anywhere.
*
* The performance of insertions is important, but given insertions frequency isn't crazy-high, we can also optimize for retrieval performance.
* SQLite isn't amazing at statistical analysis, so having indices that speeds those operations up is encouraged.
*
* This is it's own separate physical database, so it cannot do joins or queries with any other tables.
*/
class LocalMetricsDatabase private constructor(
application: Application,
private val databaseSecret: DatabaseSecret
) : SQLiteOpenHelper(
application,
DATABASE_NAME,
null,
DATABASE_VERSION,
SqlCipherDatabaseHook(),
SqlCipherErrorHandler(DATABASE_NAME)
),
SignalDatabase {
companion object {
private val TAG = Log.tag(LocalMetricsDatabase::class.java)
private val MAX_AGE = TimeUnit.DAYS.toMillis(7)
private const val DATABASE_VERSION = 1
private const val DATABASE_NAME = "signal-local-metrics.db"
private const val TABLE_NAME = "events"
private const val ID = "_id"
private const val CREATED_AT = "created_at"
private const val EVENT_ID = "event_id"
private const val EVENT_NAME = "event_name"
private const val SPLIT_NAME = "split_name"
private const val DURATION = "duration"
private val CREATE_TABLE = """
CREATE TABLE $TABLE_NAME (
$ID INTEGER PRIMARY KEY,
$CREATED_AT INTEGER NOT NULL,
$EVENT_ID TEXT NOT NULL,
$EVENT_NAME TEXT NOT NULL,
$SPLIT_NAME TEXT NOT NULL,
$DURATION INTEGER NOT NULL
)
""".trimIndent()
private val CREATE_INDEXES = arrayOf(
"CREATE INDEX events_create_at_index ON $TABLE_NAME ($CREATED_AT)",
"CREATE INDEX events_event_name_split_name_index ON $TABLE_NAME ($EVENT_NAME, $SPLIT_NAME)",
"CREATE INDEX events_duration_index ON $TABLE_NAME ($DURATION)"
)
@SuppressLint("StaticFieldLeak") // We hold an Application context, not a view context
@Volatile
private var instance: LocalMetricsDatabase? = null
@JvmStatic
fun getInstance(context: Application): LocalMetricsDatabase {
if (instance == null) {
synchronized(LocalMetricsDatabase::class.java) {
if (instance == null) {
SqlCipherLibraryLoader.load(context)
instance = LocalMetricsDatabase(context, DatabaseSecretProvider.getOrCreateDatabaseSecret(context))
}
}
}
return instance!!
}
}
private object EventTotals {
const val VIEW_NAME = "event_totals"
val CREATE_VIEW = """
CREATE VIEW $VIEW_NAME AS
SELECT $EVENT_ID, $EVENT_NAME, SUM($DURATION) AS $DURATION
FROM $TABLE_NAME
GROUP BY $EVENT_ID
""".trimIndent()
}
override fun onCreate(db: SQLiteDatabase) {
Log.i(TAG, "onCreate()")
db.execSQL(CREATE_TABLE)
CREATE_INDEXES.forEach { db.execSQL(it) }
db.execSQL(EventTotals.CREATE_VIEW)
}
override fun onUpgrade(db: SQLiteDatabase?, oldVersion: Int, newVersion: Int) {
}
override fun getSqlCipherDatabase(): SQLiteDatabase {
return writableDatabase
}
fun insert(currentTime: Long, event: LocalMetricsEvent) {
val db = writableDatabase
db.beginTransaction()
try {
event.splits.forEach { split ->
db.insert(
TABLE_NAME, null,
ContentValues().apply {
put(CREATED_AT, event.createdAt)
put(EVENT_ID, event.eventId)
put(EVENT_NAME, event.eventName)
put(SPLIT_NAME, split.name)
put(DURATION, split.duration)
}
)
}
db.delete(TABLE_NAME, "$CREATED_AT < ?", SqlUtil.buildArgs(currentTime - MAX_AGE))
db.setTransactionSuccessful()
} finally {
db.endTransaction()
}
}
fun clear() {
writableDatabase.delete(TABLE_NAME, null, null)
}
fun getMetrics(): List<EventMetrics> {
val db = readableDatabase
db.beginTransaction()
try {
val events: Map<String, List<String>> = getUniqueEventNames()
val metrics: List<EventMetrics> = events.map { (eventName: String, splits: List<String>) ->
EventMetrics(
name = eventName,
count = getCount(eventName),
p50 = eventPercent(eventName, 50),
p90 = eventPercent(eventName, 90),
p99 = eventPercent(eventName, 99),
splits = splits.map { splitName ->
SplitMetrics(
name = splitName,
p50 = splitPercent(eventName, splitName, 50),
p90 = splitPercent(eventName, splitName, 90),
p99 = splitPercent(eventName, splitName, 99)
)
}
)
}
db.setTransactionSuccessful()
return metrics
} finally {
db.endTransaction()
}
}
private fun getUniqueEventNames(): Map<String, List<String>> {
val events = mutableMapOf<String, MutableList<String>>()
readableDatabase.rawQuery("SELECT DISTINCT $EVENT_NAME, $SPLIT_NAME FROM $TABLE_NAME", null).use { cursor ->
while (cursor.moveToNext()) {
val eventName = CursorUtil.requireString(cursor, EVENT_NAME)
val splitName = CursorUtil.requireString(cursor, SPLIT_NAME)
events.getOrPut(eventName) {
mutableListOf()
}.add(splitName)
}
}
return events
}
private fun getCount(eventName: String): Long {
readableDatabase.rawQuery("SELECT COUNT(DISTINCT $EVENT_ID) FROM $TABLE_NAME WHERE $EVENT_NAME = ?", SqlUtil.buildArgs(eventName)).use { cursor ->
return if (cursor.moveToFirst()) {
cursor.getLong(0)
} else {
0
}
}
}
private fun eventPercent(eventName: String, percent: Int): Long {
return percentile(EventTotals.VIEW_NAME, "$EVENT_NAME = '$eventName'", percent)
}
private fun splitPercent(eventName: String, splitName: String, percent: Int): Long {
return percentile(TABLE_NAME, "$EVENT_NAME = '$eventName' AND $SPLIT_NAME = '$splitName'", percent)
}
private fun percentile(table: String, where: String, percent: Int): Long {
val query: String = """
SELECT $DURATION
FROM $table
WHERE $where
ORDER BY $DURATION ASC
LIMIT 1
OFFSET (SELECT COUNT(*)
FROM $table
WHERE $where) * $percent / 100 - 1
""".trimIndent()
readableDatabase.rawQuery(query, null).use { cursor ->
return if (cursor.moveToFirst()) {
cursor.getLong(0)
} else {
-1
}
}
}
private val readableDatabase: SQLiteDatabase
get() = getReadableDatabase(databaseSecret.asString())
private val writableDatabase: SQLiteDatabase
get() = getWritableDatabase(databaseSecret.asString())
data class EventMetrics(
val name: String,
val count: Long,
val p50: Long,
val p90: Long,
val p99: Long,
val splits: List<SplitMetrics>
)
data class SplitMetrics(
val name: String,
val p50: Long,
val p90: Long,
val p99: Long
)
}

View file

@ -0,0 +1,12 @@
package org.thoughtcrime.securesms.database.model
data class LocalMetricsEvent(
val createdAt: Long,
val eventId: String,
val eventName: String,
val splits: MutableList<LocalMetricsSplit>
) {
override fun toString(): String {
return "[$eventName] total: ${splits.sumOf { it.duration }} | ${splits.map { it.toString() }.joinToString(", ")}"
}
}

View file

@ -0,0 +1,10 @@
package org.thoughtcrime.securesms.database.model
data class LocalMetricsSplit(
val name: String,
val duration: Long
) {
override fun toString(): String {
return "$name: $duration"
}
}

View file

@ -35,7 +35,6 @@ import org.thoughtcrime.securesms.util.EarlyMessageCache;
import org.thoughtcrime.securesms.util.FrameRateTracker;
import org.thoughtcrime.securesms.util.Hex;
import org.thoughtcrime.securesms.util.IasKeyStore;
import org.thoughtcrime.securesms.util.TextSecurePreferences;
import org.whispersystems.signalservice.api.KeyBackupService;
import org.whispersystems.signalservice.api.SignalServiceAccountManager;
import org.whispersystems.signalservice.api.SignalServiceMessageReceiver;

View file

@ -0,0 +1,44 @@
package org.thoughtcrime.securesms.logsubmit;
import android.content.Context;
import androidx.annotation.NonNull;
import org.thoughtcrime.securesms.database.LocalMetricsDatabase;
import org.thoughtcrime.securesms.database.LocalMetricsDatabase.EventMetrics;
import org.thoughtcrime.securesms.database.LocalMetricsDatabase.SplitMetrics;
import org.thoughtcrime.securesms.dependencies.ApplicationDependencies;
import java.util.List;
final class LogSectionLocalMetrics implements LogSection {
@Override
public @NonNull String getTitle() {
return "LOCAL METRICS";
}
@Override
public @NonNull CharSequence getContent(@NonNull Context context) {
List<EventMetrics> metrics = LocalMetricsDatabase.getInstance(ApplicationDependencies.getApplication()).getMetrics();
StringBuilder builder = new StringBuilder();
for (EventMetrics metric : metrics) {
builder.append(metric.getName()).append('\n')
.append(" ").append("count: ").append(metric.getCount()).append('\n')
.append(" ").append("p50: ").append(metric.getP50()).append('\n')
.append(" ").append("p90: ").append(metric.getP90()).append('\n')
.append(" ").append("p99: ").append(metric.getP99()).append('\n');
for (SplitMetrics split : metric.getSplits()) {
builder.append(" ").append(split.getName()).append('\n')
.append(" ").append("p50: ").append(split.getP50()).append('\n')
.append(" ").append("p90: ").append(split.getP90()).append('\n')
.append(" ").append("p99: ").append(split.getP99()).append('\n');
}
builder.append("\n\n");
}
return builder;
}
}

View file

@ -73,12 +73,13 @@ public class SubmitDebugLogRepository {
add(new LogSectionSystemInfo());
add(new LogSectionJobs());
add(new LogSectionConstraints());
add(new LogSectionCapabilities());
add(new LogSectionLocalMetrics());
add(new LogSectionFeatureFlags());
add(new LogSectionPin());
if (Build.VERSION.SDK_INT >= 28) {
add(new LogSectionPower());
}
add(new LogSectionPin());
add(new LogSectionCapabilities());
add(new LogSectionFeatureFlags());
add(new LogSectionNotifications());
add(new LogSectionKeyPreferences());
add(new LogSectionPermissions());

View file

@ -96,6 +96,7 @@ public final class AppStartup {
if (outstandingCriticalRenderEvents == 0 && postRender.size() > 0) {
Log.i(TAG, "Received first critical render event.");
renderStartTime = System.currentTimeMillis();
SignalLocalMetrics.ColdStart.onRenderStart();
postRenderHandler.removeCallbacksAndMessages(null);
postRenderHandler.postDelayed(() -> {
@ -121,6 +122,7 @@ public final class AppStartup {
if (outstandingCriticalRenderEvents == 0 && postRender.size() > 0) {
renderEndTime = System.currentTimeMillis();
SignalLocalMetrics.ColdStart.onRenderFinished();
Log.i(TAG, "First render has finished. " +
"Cold Start: " + (renderEndTime - applicationStartTime) + " ms, " +

View file

@ -0,0 +1,110 @@
package org.thoughtcrime.securesms.util
import org.signal.core.util.concurrent.SignalExecutors
import org.signal.core.util.logging.Log
import org.thoughtcrime.securesms.database.LocalMetricsDatabase
import org.thoughtcrime.securesms.database.model.LocalMetricsEvent
import org.thoughtcrime.securesms.database.model.LocalMetricsSplit
import org.thoughtcrime.securesms.dependencies.ApplicationDependencies
import java.util.concurrent.Executor
/**
* A class for keeping track of local-only metrics.
*
* In particular, this class is geared towards timing events that continue over several code boundaries, e.g. sending a message.
*
* The process of tracking an event looks something like:
* - start("mySpecialId", "send-message")
* - split("mySpecialId", "enqueue-job")
* - split("mySpecialId", "job-prep")
* - split("mySpecialId", "network")
* - split("mySpecialId", "ui-refresh")
* - end("mySpecialId")
*
* These metrics are only ever included in debug logs in an aggregate fashion (i.e. p50, p90, p99) and are never automatically uploaded anywhere.
*/
object LocalMetrics {
private val TAG: String = Log.tag(LocalMetrics::class.java)
private val eventsById: MutableMap<String, LocalMetricsEvent> = mutableMapOf()
private val lastSplitTimeById: MutableMap<String, Long> = mutableMapOf()
private val executor: Executor = SignalExecutors.newCachedSingleThreadExecutor("signal-LocalMetrics")
private val db: LocalMetricsDatabase by lazy { LocalMetricsDatabase.getInstance(ApplicationDependencies.getApplication()) }
@JvmStatic
fun getInstance(): LocalMetrics {
return LocalMetrics
}
/**
* Starts an event with the provided ID and name.
*
* @param id A constant that should be unique to this *specific event*. You'll use this same id when calling [split] and [end]. e.g. "message-send-1234"
* @param name The name of the event. Does not need to be unique. e.g. "message-send"
*/
fun start(id: String, name: String) {
val time = System.currentTimeMillis()
executor.execute {
eventsById[id] = LocalMetricsEvent(
createdAt = System.currentTimeMillis(),
eventId = id,
eventName = name,
splits = mutableListOf()
)
lastSplitTimeById[id] = time
}
}
/**
* Marks a split for an event. The duration of the split will be the difference in time between either the event start or the last split, whichever is
* applicable.
*
* If an event with the provided ID does not exist, this is effectively a no-op.
*/
fun split(id: String, split: String) {
val time = System.currentTimeMillis()
executor.execute {
val lastTime: Long? = lastSplitTimeById[id]
if (lastTime != null) {
eventsById[id]?.splits?.add(LocalMetricsSplit(split, time - lastTime))
lastSplitTimeById[id] = time
}
}
}
/**
* Stop tracking an event you were previously tracking. All future calls to [split] and [end] will do nothing for this id.
*/
fun drop(id: String) {
executor.execute {
eventsById.remove(id)
}
}
/**
* Finishes the event and flushes it to the database.
*/
fun end(id: String) {
executor.execute {
val event: LocalMetricsEvent? = eventsById[id]
if (event != null) {
db.insert(System.currentTimeMillis(), event)
Log.d(TAG, event.toString())
}
}
}
/**
* Clears the entire local metrics store.
*/
fun clear() {
executor.execute {
Log.w(TAG, "Clearing local metrics store.")
db.clear()
}
}
}

View file

@ -0,0 +1,66 @@
package org.thoughtcrime.securesms.util;
import androidx.annotation.MainThread;
/**
* A nice interface for {@link LocalMetrics} that gives us a place to define string constants and nicer method names.
*/
public final class SignalLocalMetrics {
private SignalLocalMetrics() {}
public static final class ColdStart {
private static final String NAME_CONVERSATION_LIST = "cold-start-conversation-list";
private static final String NAME_OTHER = "cold-start-other";
private static final String SPLIT_APPLICATION_CREATE = "application-create";
private static final String SPLIT_ACTIVITY_CREATE = "start-activity";
private static final String SPLIT_DATA_LOADED = "data-loaded";
private static final String SPLIT_RENDER = "render";
private static String conversationListId;
private static String otherId;
private static boolean isConversationList;
@MainThread
public static void start() {
conversationListId = NAME_CONVERSATION_LIST + System.currentTimeMillis();
otherId = NAME_OTHER + System.currentTimeMillis();
LocalMetrics.getInstance().start(conversationListId, NAME_CONVERSATION_LIST);
LocalMetrics.getInstance().start(otherId, NAME_OTHER);
}
@MainThread
public static void onApplicationCreateFinished() {
LocalMetrics.getInstance().split(conversationListId, SPLIT_APPLICATION_CREATE);
LocalMetrics.getInstance().split(otherId, SPLIT_APPLICATION_CREATE);
}
@MainThread
public static void onRenderStart() {
LocalMetrics.getInstance().split(conversationListId, SPLIT_ACTIVITY_CREATE);
LocalMetrics.getInstance().split(otherId, SPLIT_ACTIVITY_CREATE);
}
@MainThread
public static void onConversationListDataLoaded() {
isConversationList = true;
LocalMetrics.getInstance().split(conversationListId, SPLIT_DATA_LOADED);
}
@MainThread
public static void onRenderFinished() {
if (isConversationList) {
LocalMetrics.getInstance().split(conversationListId, SPLIT_RENDER);
LocalMetrics.getInstance().end(conversationListId);
LocalMetrics.getInstance().drop(otherId);
} else {
LocalMetrics.getInstance().split(otherId, SPLIT_RENDER);
LocalMetrics.getInstance().end(otherId);
LocalMetrics.getInstance().drop(conversationListId);
}
}
}
}

View file

@ -31,6 +31,7 @@ public class VersionTracker {
SignalStore.misc().clearClientDeprecated();
TextSecurePreferences.setLastVersionCode(context, currentVersionCode);
ApplicationDependencies.getJobManager().add(new RemoteConfigRefreshJob());
LocalMetrics.getInstance().clear();
}
} catch (IOException ioe) {
throw new AssertionError(ioe);

View file

@ -2482,6 +2482,9 @@
<string name="preferences__internal_remove_the_requirement_that_you_need" translatable="false">Remove the requirement that you need at least 2 recipients to use sender key.</string>
<string name="preferences__internal_delay_resends" translatable="false">Delay resends</string>
<string name="preferences__internal_delay_resending_messages_in_response_to_retry_receipts" translatable="false">Delay resending messages in response to retry receipts by 10 seconds.</string>
<string name="preferences__internal_local_metrics" translatable="false">Local Metrics</string>
<string name="preferences__internal_clear_local_metrics" translatable="false">Clear local metrics</string>
<string name="preferences__internal_click_to_clear_all_local_metrics_state" translatable="false">Click to clear all local metrics state.</string>
<string name="preferences__internal_calling" translatable="false">Group call server</string>
<string name="preferences__internal_calling_default" translatable="false">Default</string>
<string name="preferences__internal_calling_s_server" translatable="false">%1$s server</string>