<https://medium.com/@vishna/watcha-doin-inspecting-kotlin-coroutines-with-timing-graphs-1676132d940f...

# feed

[vishna]

https://medium.com/@vishna/watcha-doin-inspecting-kotlin-coroutines-with-timing-graphs-1676132d940f

[Nikky]

next break i have from work i will instrument my code using this,
this seems like it should be able to help me visualize so much better

[vishna]

nice. if you have any problems using it just create an issue on the repo - the whole project is just 2 files so it should also be relatively simple to contribute to it.

[Nikky]

how does a String.watch spawned watch know when the function it was passed in completes ?
does it just wait for any next watch from the same scope to appear ?

[vishna]

you just pass the watch as an argument to the function you want to measure and then you wrap function scope with the stopwatch… and I just realized I’m not doing that in the snippet in the article 🤦‍♂️ gonna fix it quickly

[vishna]

fixed: https://gist.github.com/vishna/7ca6c0b08292201ae549afdab64b268e/revisions

you can just check out the whole project and run ./gradlew build - unit tests should generate those timings for you:

https://github.com/eyeem/watch-a-doin/blob/master/src/test/kotlin/com/eyeem/watchadoin/WatchadoinTest.kt

[Nikky]

what i ended up doing is adding a extension function

fun Stopwatch.child(name: String): Stopwatch {
    val childStopwatch = Stopwatch(name)
    children.add(childStopwatch)
    return childStopwatch
}

inline fun <T> Stopwatch.child(name: String, block: Stopwatch.() -> T) : T {
    val childStopwatch = Stopwatch(name)
    children.add(childStopwatch)
    with(childStopwatch) {
        start()
        val t = childStopwatch.block()
        end()
        return t
    }
}

and then wrapping single calls or the body of loops or such with watch.child("childname") { }
and then pass through this as the Stopwatch param to any functions in there

[Nikky]

how do you otherwise use "expensiveOperation".watch when Stopwatch is not this ?

[vishna]

if you need to create child watches outside of the parent’s scope then that makes sense - I’d love to hear your use case.

I had child method just like yours, then changed it to get operator but finally decided to removed it to “force” creating children within the parent’s context by design - otherwise at some point it was getting confusing who is the owner of the children.

String.watch returns Stopwatch instance, so in theory you can use that to create watch within parent’s context but you can keep reference around if you need to do something non-standard, e.g.:

https://gist.github.com/vishna/691020e9db807efd0a0933a4e3d6c01e#file-loopwatch_5-kt

[Nikky]

i did not know kotlin resolves multiple scopes so good now

[Nikky]

i did not think that would work so flawlessly, i remembered having issues with this before

[Nikky]

but i have something weird happen with the output.. some watches seem to never stop

[Nikky]

for some reason my flepicker and uploading to slack does not work so here it is: https://cdn.discordapp.com/attachments/460158280812068864/603888386822111232/report.svg

[Nikky]

initTome and initCHangelogBuilder are finished and then the rest of the code runs, but they seem to never call end()

[Nikky]

single statement function like fun doExpensiveWork(stopwatch: Stopwatch) = stopwatch {....}

[Nikky]

with a few more arguments but that should not matter

[Nikky]

could having multiple watches with the same name be a problem ?

[vishna]

no, you can have multiple watches with the same name

[vishna]

the parent watch will cancel all the children watches and make those appear red

[vishna]

if they did not finish on time

[Nikky]

well this block works ..

val tomeWatch = "initTome".watch
            val tomeEnv = initTome(
                stopwatch = tomeWatch, libs = libs, host = host, tomeDir = tomeDir, docDir = docDir
            )
            tomeWatch.end()

[Nikky]

note that initTome just is = stopwatch {} and afaik invoke calls end() already

[Nikky]

it could be something related to evaluating kotlin scripts.. thats the thing i do in all of those cases

[vishna]

is the watch started?

[Nikky]

i call invoke with a block. .that would do start, block and end
i think i might now the issue.. some child watch might not end properly

[Nikky]

also.. what do red bars singify in the svg output ?

[vishna]

parent.end was called before child.end

[Nikky]

i see.. that seems to be the case ...

[vishna]

also you can call timeout explicitly on the watch (might be useful if an exception is thrown or something) - this will make it red as well

[Nikky]

seems like measuring time of BasicScriptingHost#eval somehow runs into issues

[Nikky]

isn't there some sort of format for the output of flamegraphs that would make it easier to navigate and zoom ?
currently i have the issue that i cannot easily read the time a watch took, and the name is cut off

[Nikky]

svg is pretty nice for a start though

[vishna]

you can print the output as text - println(stopwatch.toStringPretty())

[vishna]

I tried to make it work with Trace Event Format but it looked terrible

[Nikky]

is that the flamegraph format this one uses for eaxmple ? https://plugins.jetbrains.com/plugin/10305-flameviewer

[Nikky]

i am fine with "looking" terrible as long as i still see the relative time between watches and hovering or clicking gives the info i need

[vishna]

hmm… maybe - it’s the one used in chrome://tracing/ …could be the same thing

[vishna]

by terrible I meant blocks would overlap as they had the same tid which is kinda a thing with coroutines

[vishna]

it probably is the same format

[Nikky]

yeah that would be unreadable, but you can get the coroutine specific info too right ?

[Nikky]

you could add suspend and CoroutineScope overloads for watches and then get the necessary info from them

[Nikky]

and thread + coroutine executor/id should give enough info to organize it

[Nikky]

i think i found the culprits:
return@stopwatch vs return
😠

[vishna]

sorry about that

[vishna]

I haven’t thought of combining yet Stopwatch with CoroutineScope - wondering how hard that would be to get all of this more automatic

[vishna]

I’ll try to push what I have for supporting Trace Event Format (https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit) maybe it will look better in FlameViewer

[Nikky]

another pitfall i ran stright into was putting the outer watch so that the inner watches fire off with launch and it completels before the inner ones, not obvious on first glance but very obvious on second one, luckily it was easy to find since the library tells me which watch acts up

[Nikky]

all in all i got the main paths of my tool covered in watches and i can add more finegrained monitoring later,
great tool

[vishna]

in the meantime I pushed this

[vishna]

so some timing tests look ok in this

[vishna]

some, like test7 is just horrible

[vishna]

FlameViewer appears to be using some other format

[Nikky]

do you have to use gson? i feel like using kotlinx.serialization would be better to convserve multiplatform compatibilty? or is gson just temporary ?

[vishna]

great suggestion, I’ll give it a try - I used gson just as test dependency

[Nikky]

seems like they use the jfr format from the java flight recorder

[Nikky]

and other formats: https://github.com/kornilova-l/FlameViewer/blob/master/README.md#uploading-file-to-flameviewer

[Nikky]

i think of those the csv format might be the easiest to generate

[Nikky]

i googled around a bit but its hard to find a library for parsing/generating that flamegraph format o even to find a spec for it

[vishna]

so many tracing formats 🤯

[Nikky]

pick whicherever
1. keeps it readable
2. is multiplatform compatible

[Nikky]

but i guess on kotlinJs you can just use the chrome thing, since you are most likely using a browser anyways

[vishna]

flameviewer is kinda in browser too

[Nikky]

but there exist a idea plugin

[Nikky]

and i guess you can view jfr flight logs as flameviews too, but those are not crossplatorm compatible really

[Nikky]

is it just me or is jitpack just refusing to give me a updates jar whenever i only use master-SNAPSHOT as a version ?

[vishna]

./gradlew clean build --refresh-dependencies should usually do it

[Nikky]

hmm i thought i could not find .asTestReport because the jar was outdated.. but...
https://github.com/eyeem/watch-a-doin/blob/1d8e116c684e5468e5b68d10174af743652d5d7d/src/test/kotlin/com/eyeem/watchadoin/WatchadoinTest.kt#L203-L214

[Nikky]

you put it in the test sources

[vishna]

ha but stopwatch.asTraceEventsReport should be there tho
https://github.com/eyeem/watch-a-doin/blob/1d8e116c684e5468e5b68d10174af743652d5d7d/src/main/kotlin/com/eyeem/watchadoin/TraceEventFormat.kt#L17

[vishna]

didn’t want to add gson as library dependency, people use various things

[Nikky]

i see.. i am currently adding kotlinx-serialization to my fork

[Nikky]

and i notice you use the maven plugin..that is afaik rather outdated and maven-publish offers better features

[Nikky]

like a publishToMavenLocal out of the box, valuable for testing

[vishna]

sure, feel free to make a PR

[vishna]

I think I found build.kts template somewhere with maven plugin and didn’t give it much thought since it just worked with jitpack

[vishna]

can’t be really bothered with signing and all that

[Nikky]

i hope i can make the serialization dependency compileOnly or so

[Nikky]

but i guess that will probably not work

[Nikky]

another small thing; chrome://tracing was blocked for me until i accessed about:tracing

[Nikky]

indeed does not look to pretty, bu this is good progress for me today

[Nikky]

https://cdn.discordapp.com/attachments/460158280812068864/603973806855553062/unknown.png▾

[vishna]

noice 👏