Skip to content
This repository has been archived by the owner on Feb 17, 2024. It is now read-only.

Add support for tracing function calls #232

Open
wants to merge 1 commit into
base: main
Choose a base branch
from

Conversation

gernest
Copy link

@gernest gernest commented Oct 8, 2023

Closes #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/wazero@v1.5.0/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.

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/wazero@v1.5.0/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 <geofreyernest@live.com>
@gernest gernest force-pushed the add-function-call-trace-support branch from 655f9fc to 5c9e6a8 Compare October 9, 2023 19:01
@gernest gernest mentioned this pull request Oct 10, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Trace function calls
1 participant