This repository has been archived by the owner on Feb 17, 2024. It is now read-only.
Trace function calls #150
Labels
enhancement
New feature or request
Comments
gernest
added a commit
to gernest/timecraft
that referenced
this issue
Oct 8, 2023
Closes dispatchrun#150 **NOTE** There is no actionable insight provided on the issue. I believe I have no business implementing this (Probably someone is already working on this internally). I got too excited when I came across this project and had a lot of idle time so I decided to take this challenge. There is a lot of shortcomings on this PR ( again, sorry to bother you guys), however I think I figured out the fundamentals of having the feature introduced. I will go into more details on this. What is missing ? ---- - Tests : there are no unit tests included because I wasn't sure which direction you had in mind regarding this feature. I however made sure to make minimal changes to ensure someone can review the changes in one sitting. - `JSON` and `YAML` output: Only table output is implemented showing function duration and function name - Top down rendering like in https://justine.lol/ftrace/ : Reading segments logs returns them in an opposite order from `ftrace`. Sorting can fix this, in order to minimize changes this commit doesn't sort the call stack Output looks like ``` ... # omitted text for brevity 936ns .sync_atomic.CompareAndSwapUint64 3.415µs .internal_poll.__fdMutex_.rwunlock 4.344µs .internal_poll.__FD_.writeUnlock 5.166µs .internal_poll.__FD_.Write.func1 23.386µs .internal_poll.__FD_.Write 24.455µs .os.__File_.Write 25.934µs .bufio.__Writer_.Flush 27.46µs .main.main.func1 48.527µs .main.main 199ns .runtime_internal_atomic.Load 160ns .runtime_internal_atomic.Load 901ns .runtime.runExitHooks ``` - Limiting: Generated trace can be long, there is no way to limit rendered output - Sampling : No way to sample the traced functions - Fine tune which functions to trace: Currently we trace everything including system calls which may be redundant considering we already have api for tracing system calls Adding support for this is straightforward so I had to de prioritize. How it works ? --- wazero has experimental api for hooking function calls https://pkg.go.dev/github.com/tetratelabs/[email protected]/experimental#FunctionListenerFactory We take advantage of this to provide custom implementation of this api and store the collected data in our segment registry. For now same segment (0) is used for system calls and function calls , Initially I had separate segment for function calls segment(1) but I had to make a lot of changes to glue things together. I settled with the same segment but it should be possible to switch to separate segments. I am more than happy to own the issue if I get feedback on which direction you had in mind . But also I won't mind if this PR is closed. Usage --- ``` $ timecraft run testdata/go/get.wasm https://eo3qh2ncelpc9q0.m.pipedream.net 79642983-87b9-492c-b24e-b78397d28362 Hello, World! ``` ``` $ timecraft trace f 79642983-87b9-492c-b24e-b78397d28362 ... # truncated for brevity 3.303µs .internal_poll.__FD_.writeUnlock 3.896µs .internal_poll.__FD_.Write.func1 17.796µs .internal_poll.__FD_.Write 18.578µs .os.__File_.Write 20.593µs .bufio.__Writer_.Flush 21.898µs .main.main.func1 38.941µs .main.main 164ns .runtime_internal_atomic.Load 144ns .runtime_internal_atomic.Load 734ns .runtime.runExitHooks ``` This project has the highest quality go code base on github (apart from the go standard library). I came across this on saturday and found my way to implement this feature on sunday. Thanks for the project.
gernest
added a commit
to gernest/timecraft
that referenced
this issue
Oct 9, 2023
Closes dispatchrun#150 **NOTE** There is no actionable insight provided on the issue. I believe I have no business implementing this (Probably someone is already working on this internally). I got too excited when I came across this project and had a lot of idle time so I decided to take this challenge. There is a lot of shortcomings on this PR ( again, sorry to bother you guys), however I think I figured out the fundamentals of having the feature introduced. I will go into more details on this. What is missing ? ---- - Tests : there are no unit tests included because I wasn't sure which direction you had in mind regarding this feature. I however made sure to make minimal changes to ensure someone can review the changes in one sitting. - `JSON` and `YAML` output: Only table output is implemented showing function duration and function name - Top down rendering like in https://justine.lol/ftrace/ : Reading segments logs returns them in an opposite order from `ftrace`. Sorting can fix this, in order to minimize changes this commit doesn't sort the call stack Output looks like ``` ... # omitted text for brevity 936ns .sync_atomic.CompareAndSwapUint64 3.415µs .internal_poll.__fdMutex_.rwunlock 4.344µs .internal_poll.__FD_.writeUnlock 5.166µs .internal_poll.__FD_.Write.func1 23.386µs .internal_poll.__FD_.Write 24.455µs .os.__File_.Write 25.934µs .bufio.__Writer_.Flush 27.46µs .main.main.func1 48.527µs .main.main 199ns .runtime_internal_atomic.Load 160ns .runtime_internal_atomic.Load 901ns .runtime.runExitHooks ``` - Limiting: Generated trace can be long, there is no way to limit rendered output - Sampling : No way to sample the traced functions - Fine tune which functions to trace: Currently we trace everything including system calls which may be redundant considering we already have api for tracing system calls Adding support for this is straightforward so I had to de prioritize. How it works ? --- wazero has experimental api for hooking function calls https://pkg.go.dev/github.com/tetratelabs/[email protected]/experimental#FunctionListenerFactory We take advantage of this to provide custom implementation of this api and store the collected data in our segment registry. For now same segment (0) is used for system calls and function calls , Initially I had separate segment for function calls segment(1) but I had to make a lot of changes to glue things together. I settled with the same segment but it should be possible to switch to separate segments. I am more than happy to own the issue if I get feedback on which direction you had in mind . But also I won't mind if this PR is closed. Usage --- ``` $ timecraft run testdata/go/get.wasm https://eo3qh2ncelpc9q0.m.pipedream.net 79642983-87b9-492c-b24e-b78397d28362 Hello, World! ``` ``` $ timecraft trace f 79642983-87b9-492c-b24e-b78397d28362 ... # truncated for brevity 3.303µs .internal_poll.__FD_.writeUnlock 3.896µs .internal_poll.__FD_.Write.func1 17.796µs .internal_poll.__FD_.Write 18.578µs .os.__File_.Write 20.593µs .bufio.__Writer_.Flush 21.898µs .main.main.func1 38.941µs .main.main 164ns .runtime_internal_atomic.Load 144ns .runtime_internal_atomic.Load 734ns .runtime.runExitHooks ``` This project has the highest quality go code base on github (apart from the go standard library). I came across this on saturday and found my way to implement this feature on sunday. Thanks for the project. Signed-off-by: gernest <[email protected]>
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
Timecraft has the ability to trace system calls. Tracing function calls would also be a useful feature (e.g. https://justine.lol/ftrace/).
The text was updated successfully, but these errors were encountered: