Skip to content

Commit cb0f236

Browse files
ZachBrayZachBray
committed
Track time in output.
1 parent c3a654c commit cb0f236

File tree

3 files changed

+69
-31
lines changed

3 files changed

+69
-31
lines changed

‎src/main/kotlin/jstacktrace/Agent.kt

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ import java.lang.instrument.Instrumentation
88
import java.nio.file.Files
99
import java.nio.file.Path
1010
import java.nio.file.StandardOpenOption
11+
import kotlin.concurrent.getOrSet
1112

1213
fun premain(argument: String, instrumentation: Instrumentation) = main(argument, instrumentation)
1314

@@ -33,9 +34,9 @@ private fun main(argument: String, instrumentation: Instrumentation) {
3334

3435
fun attach(filterSpec: String, outputDir: Path, instrumentation: Instrumentation) {
3536
val methodsByType = getSelectedMethods(filterSpec)
36-
val writerCache = mutableMapOf<Thread, BufferedWriter>()
37+
val writerCache = ThreadLocal<BufferedWriter>()
3738
Arguments.writerFactory = { thread ->
38-
writerCache.computeIfAbsent(thread) {
39+
writerCache.getOrSet {
3940
val path = outputDir.resolve("trace-${thread.id}.log")
4041
if (Files.exists(path)) {
4142
Files.delete(path)

‎src/main/kotlin/jstacktrace/MethodInterceptor.kt

Lines changed: 35 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -11,30 +11,41 @@ object Stats {
1111

1212
object Arguments {
1313
var writerFactory: (Thread) -> BufferedWriter? = { null }
14+
var thresholdMillis = 10
15+
var time: () -> Long = { System.currentTimeMillis() }
16+
}
17+
18+
object Utils {
19+
fun writeIndent(depth: ThreadLocal<MutableInt>, writer: BufferedWriter, symbol: Char) {
20+
writer.write("[ms: ")
21+
writer.write(Arguments.time().toString())
22+
writer.write("] ")
23+
for (i in 1..depth.get().value) {
24+
writer.write(" |")
25+
if (i == depth.get().value) {
26+
writer.write("-$symbol ")
27+
} else {
28+
writer.write(" ")
29+
}
30+
}
31+
}
1432
}
1533

1634
object MethodInterceptor {
1735
@Advice.OnMethodEnter
1836
@JvmStatic
1937
fun onEnter(@Advice.Origin("#t::#m") method: String,
20-
@Advice.AllArguments arguments: Array<Any>) {
38+
@Advice.AllArguments arguments: Array<Any>): Long {
2139

22-
val writer = Arguments.writerFactory(Thread.currentThread()) ?: return
40+
val writer = Arguments.writerFactory(Thread.currentThread()) ?: return 0
2341

2442
val depth = Stats.callStackDepth
2543

2644
if (depth.get() == null) {
2745
depth.set(MutableInt())
2846
}
2947

30-
for (i in 1..depth.get().value) {
31-
writer.write(" |")
32-
if (i == depth.get().value) {
33-
writer.write("-> ")
34-
} else {
35-
writer.write(" ")
36-
}
37-
}
48+
Utils.writeIndent(depth, writer, '>')
3849
writer.write(method)
3950
writer.write("(")
4051
arguments.forEachIndexed { index, argument ->
@@ -47,15 +58,26 @@ object MethodInterceptor {
4758
writer.newLine()
4859

4960
++depth.get().value
61+
62+
return Arguments.time()
5063
}
5164

5265
@Advice.OnMethodExit
5366
@JvmStatic
54-
fun onExit() {
67+
fun onExit(@Advice.Enter startTime: Long) {
68+
val writer = Arguments.writerFactory(Thread.currentThread()) ?: return
69+
val endTime = Arguments.time()
70+
5571
val depth = Stats.callStackDepth
56-
--depth.get().value
5772

58-
val writer = Arguments.writerFactory(Thread.currentThread()) ?: return
73+
val durationInMillis = endTime - startTime
74+
if (durationInMillis > Arguments.thresholdMillis) {
75+
Utils.writeIndent(depth, writer, 'o')
76+
writer.write("took: $durationInMillis ms")
77+
writer.newLine()
78+
}
5979
writer.flush()
80+
81+
--depth.get().value
6082
}
6183
}

‎src/test/kotlin/jstacktrace/AgentTest.kt

Lines changed: 31 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@ class AgentTest {
2020
val filterSpec = """
2121
jstacktrace.TestFunctions::fib
2222
""".trimIndent()
23+
Arguments.time = { 100 }
2324
// Act
2425
attach(filterSpec, tempDir, instrumentation)
2526
TestFunctions.fib(5)
@@ -29,21 +30,31 @@ class AgentTest {
2930
assertTrue(expectedOutputFile.exists())
3031
assertEquals("""
3132
Thread name: main
32-
jstacktrace.TestFunctions::fib(5)
33-
|-> jstacktrace.TestFunctions::fib(4)
34-
| |-> jstacktrace.TestFunctions::fib(3)
35-
| | |-> jstacktrace.TestFunctions::fib(2)
36-
| | | |-> jstacktrace.TestFunctions::fib(1)
37-
| | | |-> jstacktrace.TestFunctions::fib(0)
38-
| | |-> jstacktrace.TestFunctions::fib(1)
39-
| |-> jstacktrace.TestFunctions::fib(2)
40-
| | |-> jstacktrace.TestFunctions::fib(1)
41-
| | |-> jstacktrace.TestFunctions::fib(0)
42-
|-> jstacktrace.TestFunctions::fib(3)
43-
| |-> jstacktrace.TestFunctions::fib(2)
44-
| | |-> jstacktrace.TestFunctions::fib(1)
45-
| | |-> jstacktrace.TestFunctions::fib(0)
46-
| |-> jstacktrace.TestFunctions::fib(1)
33+
[ms: 100] jstacktrace.TestFunctions::fib(5)
34+
[ms: 100] |-> jstacktrace.TestFunctions::fib(4)
35+
[ms: 100] | |-> jstacktrace.TestFunctions::fib(3)
36+
[ms: 100] | | |-> jstacktrace.TestFunctions::fib(2)
37+
[ms: 100] | | | |-> jstacktrace.TestFunctions::fib(1)
38+
[ms: 100] | | | |-> jstacktrace.TestFunctions::fib(0)
39+
[ms: 200] | | | | |-o took: 100 ms
40+
[ms: 200] | | | |-o took: 100 ms
41+
[ms: 200] | | |-> jstacktrace.TestFunctions::fib(1)
42+
[ms: 200] | | |-o took: 100 ms
43+
[ms: 200] | |-> jstacktrace.TestFunctions::fib(2)
44+
[ms: 200] | | |-> jstacktrace.TestFunctions::fib(1)
45+
[ms: 200] | | |-> jstacktrace.TestFunctions::fib(0)
46+
[ms: 300] | | | |-o took: 100 ms
47+
[ms: 300] | | |-o took: 100 ms
48+
[ms: 300] | |-o took: 200 ms
49+
[ms: 300] |-> jstacktrace.TestFunctions::fib(3)
50+
[ms: 300] | |-> jstacktrace.TestFunctions::fib(2)
51+
[ms: 300] | | |-> jstacktrace.TestFunctions::fib(1)
52+
[ms: 300] | | |-> jstacktrace.TestFunctions::fib(0)
53+
[ms: 400] | | | |-o took: 100 ms
54+
[ms: 400] | | |-o took: 100 ms
55+
[ms: 400] | |-> jstacktrace.TestFunctions::fib(1)
56+
[ms: 400] | |-o took: 100 ms
57+
[ms: 400] |-o took: 300 ms
4758
4859
""".trimIndent(), expectedOutputFile.readText())
4960
} catch (e: Exception) {
@@ -56,7 +67,11 @@ class AgentTest {
5667

5768
object TestFunctions {
5869
fun fib(n: Int): Int =
59-
if (n == 0) 0
70+
if (n == 0) {
71+
val t = Arguments.time()
72+
Arguments.time = { t + 100 }
73+
0
74+
}
6075
else if (n == 1) 0
6176
else fib(n - 1) + fib(n - 2)
6277
}

0 commit comments

Comments
 (0)