diff --git a/app/src/main/java/org/thoughtcrime/securesms/conversation/v2/data/ConversationDataSource.kt b/app/src/main/java/org/thoughtcrime/securesms/conversation/v2/data/ConversationDataSource.kt index 64b0e478d1..92dbf76b40 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/conversation/v2/data/ConversationDataSource.kt +++ b/app/src/main/java/org/thoughtcrime/securesms/conversation/v2/data/ConversationDataSource.kt @@ -94,7 +94,7 @@ class ConversationDataSource( } override fun load(start: Int, length: Int, totalSize: Int, cancellationSignal: PagedDataSource.CancellationSignal): List { - val stopwatch = Stopwatch("load($start, $length), thread $threadId") + val stopwatch = Stopwatch(title = "load($start, $length), thread $threadId", decimalPlaces = 2) var records: MutableList = ArrayList(length) MessageTable.mmsReaderFor(SignalDatabase.messages.getConversation(threadId, start.toLong(), length.toLong())) @@ -150,7 +150,7 @@ class ConversationDataSource( } stopwatch.split("header") - val log = stopwatch.stopAndGetLogString(TAG) + val log = stopwatch.stopAndGetLogString() Log.d(TAG, "$log || ${extraData.timeLog}") return if (threadHeaders.isNotEmpty()) messages + threadHeaders else messages @@ -166,7 +166,7 @@ class ConversationDataSource( return null } - val stopwatch = Stopwatch("load($key), thread $threadId") + val stopwatch = Stopwatch(title = "load($key), thread $threadId", decimalPlaces = 2) var record = SignalDatabase.messages.getMessageRecordOrNull(key.id) if ((record as? MediaMmsMessageRecord)?.parentStoryId?.isGroupReply() == true) { @@ -201,7 +201,7 @@ class ConversationDataSource( ).toMappingModel() } } finally { - val log = stopwatch.stopAndGetLogString(TAG) + val log = stopwatch.stopAndGetLogString() Log.d(TAG, "$log || ${extraData?.timeLog}") } } diff --git a/app/src/main/java/org/thoughtcrime/securesms/conversation/v2/data/MessageDataFetcher.kt b/app/src/main/java/org/thoughtcrime/securesms/conversation/v2/data/MessageDataFetcher.kt index 7abc74848b..9a0efc0084 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/conversation/v2/data/MessageDataFetcher.kt +++ b/app/src/main/java/org/thoughtcrime/securesms/conversation/v2/data/MessageDataFetcher.kt @@ -119,7 +119,7 @@ object MessageDataFetcher { attachments = attachmentsResult.result, payments = paymentsResult.result, calls = callsResult.result, - timeLog = "mentions: ${mentionsResult.duration} is-quoted: ${hasBeenQuotedResult.duration} reactions: ${reactionsResult.duration} attachments: ${attachmentsResult.duration} payments: ${paymentsResult.duration} calls: ${callsResult.duration} >> cpuTime: ${cpuTimeMs.roundedString(2)} wallTime: ${wallTimeMs.roundedString(2)}" + timeLog = "mentions: ${mentionsResult.duration}, is-quoted: ${hasBeenQuotedResult.duration}, reactions: ${reactionsResult.duration}, attachments: ${attachmentsResult.duration}, payments: ${paymentsResult.duration}, calls: ${callsResult.duration} >> cpuTime: ${cpuTimeMs.roundedString(2)}, wallTime: ${wallTimeMs.roundedString(2)}" ) } diff --git a/app/src/main/java/org/thoughtcrime/securesms/conversationlist/ConversationListDataSource.java b/app/src/main/java/org/thoughtcrime/securesms/conversationlist/ConversationListDataSource.java index 0be2b9bbf0..beffad736e 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/conversationlist/ConversationListDataSource.java +++ b/app/src/main/java/org/thoughtcrime/securesms/conversationlist/ConversationListDataSource.java @@ -68,7 +68,7 @@ abstract class ConversationListDataSource implements PagedDataSource load(int start, int length, int totalSize, @NonNull CancellationSignal cancellationSignal) { SignalTrace.beginSection("ConversationListDataSource#load"); - Stopwatch stopwatch = new Stopwatch("load(" + start + ", " + length + "), " + getClass().getSimpleName() + ", " + conversationFilter); + Stopwatch stopwatch = new Stopwatch("load(" + start + ", " + length + "), " + getClass().getSimpleName() + ", " + conversationFilter, 2); List conversations = new ArrayList<>(length); List recipients = new LinkedList<>(); diff --git a/core-util/src/main/java/org/signal/core/util/DoubleExtensions.kt b/core-util/src/main/java/org/signal/core/util/DoubleExtensions.kt index 55bf504cd1..21823a500e 100644 --- a/core-util/src/main/java/org/signal/core/util/DoubleExtensions.kt +++ b/core-util/src/main/java/org/signal/core/util/DoubleExtensions.kt @@ -5,9 +5,6 @@ package org.signal.core.util -import kotlin.math.pow -import kotlin.math.round - /** * Rounds a number to the specified number of places. e.g. * @@ -15,6 +12,5 @@ import kotlin.math.round * 1.123456f.roundedString(5) = 1.12346 */ fun Double.roundedString(places: Int): String { - val powerMultiplier = 10f.pow(places) - return (round(this * powerMultiplier) / powerMultiplier).toString() + return String.format("%.${places}f", this) } diff --git a/core-util/src/main/java/org/signal/core/util/FloatExtensions.kt b/core-util/src/main/java/org/signal/core/util/FloatExtensions.kt index 6b03435afa..28f46ad25e 100644 --- a/core-util/src/main/java/org/signal/core/util/FloatExtensions.kt +++ b/core-util/src/main/java/org/signal/core/util/FloatExtensions.kt @@ -5,9 +5,6 @@ package org.signal.core.util -import kotlin.math.pow -import kotlin.math.round - /** * Rounds a number to the specified number of places. e.g. * @@ -15,6 +12,5 @@ import kotlin.math.round * 1.123456f.roundedString(5) = 1.12346 */ fun Float.roundedString(places: Int): String { - val powerMultiplier = 10f.pow(places) - return (round(this * powerMultiplier) / powerMultiplier).toString() + return String.format("%.${places}f", this) } diff --git a/core-util/src/main/java/org/signal/core/util/Stopwatch.java b/core-util/src/main/java/org/signal/core/util/Stopwatch.java deleted file mode 100644 index da232ea7aa..0000000000 --- a/core-util/src/main/java/org/signal/core/util/Stopwatch.java +++ /dev/null @@ -1,63 +0,0 @@ -package org.signal.core.util; - -import androidx.annotation.NonNull; - -import org.signal.core.util.logging.Log; - -import java.util.LinkedList; -import java.util.List; - -public class Stopwatch { - - private final long startTime; - private final String title; - private final List splits; - - public Stopwatch(@NonNull String title) { - this.startTime = System.currentTimeMillis(); - this.title = title; - this.splits = new LinkedList<>(); - } - - public void split(@NonNull String label) { - splits.add(new Split(System.currentTimeMillis(), label)); - } - - public void stop(@NonNull String tag) { - Log.d(tag, stopAndGetLogString(tag)); - } - - public String stopAndGetLogString(String tag) { - StringBuilder out = new StringBuilder(); - out.append("[").append(title).append("] "); - - if (splits.size() > 0) { - out.append(splits.get(0).label).append(": "); - out.append(splits.get(0).time - startTime); - out.append(" "); - } - - if (splits.size() > 1) { - for (int i = 1; i < splits.size(); i++) { - out.append(splits.get(i).label).append(": "); - out.append(splits.get(i).time - splits.get(i - 1).time); - out.append(" "); - } - - out.append("total: ").append(splits.get(splits.size() - 1).time - startTime); - } - - return out.toString(); - } - - - private static class Split { - final long time; - final String label; - - Split(long time, String label) { - this.time = time; - this.label = label; - } - } -} diff --git a/core-util/src/main/java/org/signal/core/util/Stopwatch.kt b/core-util/src/main/java/org/signal/core/util/Stopwatch.kt new file mode 100644 index 0000000000..0f4d2b3f8c --- /dev/null +++ b/core-util/src/main/java/org/signal/core/util/Stopwatch.kt @@ -0,0 +1,74 @@ +package org.signal.core.util + +import org.signal.core.util.logging.Log +import kotlin.time.Duration.Companion.nanoseconds +import kotlin.time.DurationUnit + +/** + * Simple utility to easily track the time a multi-step operation takes via splits. + * + * e.g. + * + * ```kotlin + * val stopwatch = Stopwatch("my-event") + * stopwatch.split("split-1") + * stopwatch.split("split-2") + * stopwatch.split("split-3") + * stopwatch.stop(TAG) + * ``` + */ +class Stopwatch @JvmOverloads constructor(private val title: String, private val decimalPlaces: Int = 0) { + private val startTimeNanos: Long = System.nanoTime() + private val splits: MutableList = mutableListOf() + + /** + * Create a new split between now and the last event. + */ + fun split(label: String) { + val now = System.nanoTime() + + val previousTime = if (splits.isEmpty()) { + startTimeNanos + } else { + splits.last().nanoTime + } + + splits += Split( + nanoTime = now, + durationNanos = now - previousTime, + label = label + ) + } + + /** + * Stops the stopwatch and logs the results with the provided tag. + */ + fun stop(tag: String) { + Log.d(tag, stopAndGetLogString()) + } + + /** + * Similar to [stop], but instead of logging directly, this will return the log string. + */ + fun stopAndGetLogString(): String { + val now = System.nanoTime() + + splits += Split( + nanoTime = now, + durationNanos = now - startTimeNanos, + label = "total" + ) + + val splitString = splits + .joinToString(separator = ", ", transform = { it.displayString(decimalPlaces) }) + + return "[$title] $splitString" + } + + private data class Split(val nanoTime: Long, val durationNanos: Long, val label: String) { + fun displayString(decimalPlaces: Int): String { + val timeMs: String = durationNanos.nanoseconds.toDouble(DurationUnit.MILLISECONDS).roundedString(decimalPlaces) + return "$label: $timeMs" + } + } +}