Enhance profiler to report actual time spent at probe locations.

Instead of just reporting the times each probe has been called,
collect and calculate the actual time taken by each probe location from
the whole backtrace pool.
This commit is contained in:
Fedor Isakov 2019-12-08 16:28:31 +01:00
parent 4eb93f20f9
commit 2199905ea2
1 changed files with 41 additions and 21 deletions

View File

@ -55,25 +55,40 @@ class Profiler {
} }
fun formattedData(): Map<String, String> { fun formattedData(): Map<String, String> {
val entries = rawProfilingData().entries.toMutableList() val name2data = rawProfilingData().entries.toMutableList()
val sum = entries.asSequence().fold(0L) { acc, e -> acc + (e.value.dur/1000000) } val sum = name2data.asSequence().fold(0L) { acc, e -> acc + millis(e.value.dur) }
var toReport = (sum * 0.98).toLong() var toReport = (sum * 0.98).toLong()
// sort in-pace descending // sort in-pace descending
Collections.sort(entries) { e1, e2 -> if (e2.value.dur < e1.value.dur) -1 else 1 } Collections.sort(name2data) { e1, e2 -> if (e2.value.dur < e1.value.dur) -1 else 1 }
return entries.asSequence().takeWhile { e -> toReport > 0 && e.value.dur / 1000000 > 0}.map { e -> return name2data
val millis= e.value.dur / 1000000 .asSequence()
toReport -= millis .takeWhile { (_, data) -> toReport > 0 && millis(data.dur) > 0 }
.map { (name, data) ->
toReport -= millis(data.dur)
val parents = e.value.parents.entries.toMutableList() val parentName2Dur = data.parentDurs.entries.toMutableList()
//sort in-place descending val parentsTotal = parentName2Dur.fold(0L) { acc, e -> acc + millis(e.value) }
Collections.sort(parents) { e1, e2 -> e2.value - e1.value } var parentsToReport = (parentsTotal * 0.98).toLong()
val sb = StringBuilder("%1\$Ts.%1\$TLs (%2\$d times)".format(millis, e.value.freq))
parents.forEach { e -> sb.append("\n -- ${e.key} (${e.value} times)") }
e.key.to(sb.toString()) //sort in-place descending
}.toMap() Collections.sort(parentName2Dur) { e1, e2 -> if (e2.value < e1.value) -1 else 1 }
val sb = StringBuilder("time %1\$Ts.%1\$TLs (%2\$d times)".format(millis(data.dur), data.freq))
parentName2Dur
.asSequence()
.takeWhile { (_, dur) -> parentsToReport > 0 && millis(dur) > 0 }
.forEach { (parentName, dur) ->
parentsToReport -= millis(dur)
sb.append("\n -- ${parentName}")
.append(" time %1\$Ts.%1\$TLs".format(millis(dur)))
.append(" (%1\$d times)".format(data.parentFreqs[name] ?: 0)) }
name to sb.toString()
}.toMap()
} }
fun millis(nanos: Long): Long = nanos / 1000000L
fun clear() { fun clear() {
tokenStack.clear() tokenStack.clear()
} }
@ -103,14 +118,18 @@ class Token(val name: String, val id: Int) {
private fun ownDuration(): Long? = duration()?.minus(children.map { ch -> ch.duration() ?: 0 }.sum()) private fun ownDuration(): Long? = duration()?.minus(children.map { ch -> ch.duration() ?: 0 }.sum())
fun mergeDurations(name2durFreq: MutableMap<String, DurFreq>) { fun mergeDurations(name2durFreq: MutableMap<String, DurFreq>) {
children.forEach { ch -> for (ch in children) {
val durFreq = name2durFreq.getOrPut(ch.name) { DurFreq() } ch.mergeDurations(name2durFreq)
ch.ownDuration()?.let { dur -> durFreq.dur += dur }
durFreq.freq += 1
durFreq.parents.set(name, 1 + durFreq.parents.getOrElse(name) {0})
} }
for (c in children) { for (ch in children) {
c.mergeDurations(name2durFreq) val chDurFreq = name2durFreq.getOrPut(ch.name) { DurFreq() }
val chDuration = ch.ownDuration()
chDuration?.let { dur -> chDurFreq.dur += dur }
chDurFreq.freq += 1
chDurFreq.parentFreqs[name] = 1 + chDurFreq.parentFreqs.getOrElse(name) { 0 }
if (chDuration != null) {
chDurFreq.parentDurs[name] = chDuration + chDurFreq.parentDurs.getOrElse(name) { 0L }
}
} }
} }
@ -119,7 +138,8 @@ class Token(val name: String, val id: Int) {
class DurFreq { class DurFreq {
var dur: Long = 0L var dur: Long = 0L
var freq: Int = 0 var freq: Int = 0
val parents: MutableMap<String, Int> = HashMap() val parentFreqs: MutableMap<String, Int> = HashMap()
val parentDurs: MutableMap<String, Long> = HashMap()
} }
inline fun Profiler?.profile(name: String, proc: () -> Unit): Unit { inline fun Profiler?.profile(name: String, proc: () -> Unit): Unit {