Update Stopwatch to log fractional milliseconds.

This commit is contained in:
Greyson Parrelli 2023-08-30 16:14:03 -04:00 committed by Nicholas Tinsley
parent 95c6f569d6
commit e08e02ae80
7 changed files with 82 additions and 79 deletions

View file

@ -94,7 +94,7 @@ class ConversationDataSource(
}
override fun load(start: Int, length: Int, totalSize: Int, cancellationSignal: PagedDataSource.CancellationSignal): List<ConversationElement> {
val stopwatch = Stopwatch("load($start, $length), thread $threadId")
val stopwatch = Stopwatch(title = "load($start, $length), thread $threadId", decimalPlaces = 2)
var records: MutableList<MessageRecord> = 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}")
}
}

View file

@ -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)}"
)
}

View file

@ -68,7 +68,7 @@ abstract class ConversationListDataSource implements PagedDataSource<Long, Conve
@Override
public @NonNull List<Conversation> 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<Conversation> conversations = new ArrayList<>(length);
List<Recipient> recipients = new LinkedList<>();

View file

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

View file

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

View file

@ -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<Split> 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;
}
}
}

View file

@ -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<Split> = 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"
}
}
}