Skip to content

Commit eed1eeb

Browse files
committed
Adds some example
1 parent eeb6fde commit eed1eeb

File tree

16 files changed

+634
-0
lines changed

16 files changed

+634
-0
lines changed
Lines changed: 57 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,57 @@
1+
package main
2+
3+
import (
4+
"context"
5+
"fmt"
6+
"github.com/openshift-online/async-routine/opid"
7+
"log/slog"
8+
"os"
9+
"runtime/pprof"
10+
"time"
11+
)
12+
13+
func main() {
14+
slog.Info("Program started")
15+
16+
for i := 0; i < 10; i++ {
17+
foo(opid.NewContext())
18+
}
19+
20+
// Wait enough time to have some routine started
21+
time.Sleep(4 * time.Second)
22+
23+
pprof.Lookup("goroutine").WriteTo(os.Stdout, 1)
24+
fmt.Scanln()
25+
}
26+
27+
func foo(ctx context.Context) {
28+
slog.Info("foo() started",
29+
"opid", opid.FromContext(ctx))
30+
bar(ctx)
31+
slog.Info("foo() ended",
32+
"opid", opid.FromContext(ctx))
33+
}
34+
35+
func bar(ctx context.Context) {
36+
slog.Info("bar() started",
37+
"opid", opid.FromContext(ctx))
38+
go parentGoroutine(ctx)
39+
slog.Info("bar() ended",
40+
"opid", opid.FromContext(ctx))
41+
}
42+
43+
func parentGoroutine(ctx context.Context) {
44+
slog.Info("parentGoroutine() started",
45+
"opid", opid.FromContext(ctx))
46+
47+
go stuckInSelect()
48+
time.Sleep(500 * time.Millisecond)
49+
slog.Info("parentGoroutine() ended",
50+
"opid", opid.FromContext(ctx))
51+
}
52+
53+
func stuckInSelect() {
54+
slog.Info("stuckInSelect() started")
55+
select {}
56+
slog.Info("stuckInSelect() ended")
57+
}
Lines changed: 107 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,107 @@
1+
package main
2+
3+
import (
4+
"context"
5+
"github.com/openshift-online/async-routine"
6+
"github.com/openshift-online/async-routine/opid"
7+
"log/slog"
8+
"time"
9+
)
10+
11+
var _ async.RoutinesObserver = (*exampleRoutineObserver)(nil)
12+
13+
func main() {
14+
slog.Info("Program started")
15+
16+
// Setup the AsyncRoutineManager
17+
async.Manager(
18+
// Take a snapshot every 2 seconds
19+
async.WithSnapshottingInterval(2 * time.Second)).
20+
// Start the routine monitor
21+
Monitor().Start()
22+
23+
// Add our custom observer to the list of routine observers
24+
_ = async.Manager().AddObserver(&exampleRoutineObserver{})
25+
26+
for i := 0; i < 10; i++ {
27+
foo(opid.NewContext())
28+
}
29+
30+
// Wait enough time to have some routine started
31+
time.Sleep(4 * time.Second)
32+
}
33+
34+
func foo(ctx context.Context) {
35+
slog.Info("foo() started",
36+
"opid", opid.FromContext(ctx))
37+
bar(ctx)
38+
slog.Info("foo() ended",
39+
"opid", opid.FromContext(ctx))
40+
}
41+
42+
func bar(ctx context.Context) {
43+
slog.Info("bar() started",
44+
"opid", opid.FromContext(ctx))
45+
async.NewAsyncRoutine("parent go routine", ctx,
46+
func() {
47+
parentGoroutine(ctx)
48+
}).
49+
Timebox(2 * time.Second).
50+
Run()
51+
slog.Info("bar() ended",
52+
"opid", opid.FromContext(ctx))
53+
}
54+
55+
func parentGoroutine(ctx context.Context) {
56+
slog.Info("parentGoroutine() started",
57+
"opid", opid.FromContext(ctx))
58+
59+
async.NewAsyncRoutine("stuck in select", ctx, stuckInSelect).
60+
Timebox(2 * time.Second).
61+
Run()
62+
time.Sleep(500 * time.Millisecond)
63+
64+
slog.Info("parentGoroutine() ended",
65+
"opid", opid.FromContext(ctx))
66+
}
67+
68+
func stuckInSelect() {
69+
slog.Info("parentGoroutine() started")
70+
select {}
71+
slog.Info("parentGoroutine() ended")
72+
}
73+
74+
type exampleRoutineObserver struct{}
75+
76+
func (e exampleRoutineObserver) RoutineStarted(routine async.AsyncRoutine) {
77+
slog.Info("Routine started",
78+
"name", routine.Name(),
79+
"opid", routine.OpId(),
80+
"parent-opid", routine.OriginatorOpId(),
81+
)
82+
}
83+
84+
func (e exampleRoutineObserver) RoutineFinished(routine async.AsyncRoutine) {
85+
slog.Info("Routine finished",
86+
"name", routine.Name(),
87+
"opid", routine.OpId(),
88+
"parent-opid", routine.OriginatorOpId(),
89+
)
90+
}
91+
92+
func (e exampleRoutineObserver) RoutineExceededTimebox(routine async.AsyncRoutine) {
93+
slog.Warn("Routine exceeded timebox",
94+
"name", routine.Name(),
95+
"opid", routine.OpId(),
96+
"parent-opid", routine.OriginatorOpId(),
97+
"startedAt", routine.StartedAt(),
98+
)
99+
}
100+
101+
func (e exampleRoutineObserver) RunningRoutineCount(count int) {
102+
// nothing to do in this example
103+
}
104+
105+
func (e exampleRoutineObserver) RunningRoutineByNameCount(name string, count int) {
106+
// nothing to do in this example
107+
}
Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,13 @@
1+
# Routine Leak Detection with AsyncRoutineManager
2+
This demonstration illustrates how the `AsyncRoutineManager` help identifying routine leaks and pinpoint their source.
3+
4+
Each folder, named step1 to stepN, adds a progressive integration of the `AsyncRoutineManager`, starting from the
5+
naked code of `step1` to the full integration in the last step.
6+
7+
The application we are going to use for this demonstration is very simple:
8+
9+
1. The `main` function starts the `doJob` go routine and then, every 4 seconds, prints the `pproof` goroutine dump
10+
2. `doJob` runs indefinitely and every 50 milliseconds invokes the `foo` function
11+
3. `foo` just invokes `bar` wich in turn starts the `parentGoRoutine` routine
12+
4. `parentGoRoutine` starts the `doInterestingStuff` routine passing a random number between 0 and 99
13+
5. `doInterestingStuff` hangs indefinitely if the received value is a multiple of 4, otherwise exits
Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,24 @@
1+
# STEP1 - the leaking code
2+
3+
In this step, we will use the native `go` keyword to start go routines.
4+
The code is very simple:
5+
6+
1. The `main` function starts the `doJob` go routine and then, every 4 seconds, prints the `pproof` goroutine dump
7+
2. `doJob` runs indefinitely and every 50 milliseconds invokes the `foo` function
8+
3. `foo` just invokes `bar` wich in turn starts the `parentGoRoutine` routine
9+
4. `parentGoRoutine` starts the `doInterestingStuff` routine passing a random number between 0 and 99
10+
5. `doInterestingStuff` hangs indefinitely if the received value is a multiple of 4, otherwise exits
11+
12+
Running the application we can see how the total number of goroutine keeps increasing:
13+
```
14+
goroutine profile: total 32
15+
20 @ 0x100e9caa8 0x100e7d520 0x100ef588c 0x100ea42b4
16+
# 0x100ef588b main.doInterestingStuff+0x3b
17+
...
18+
...
19+
goroutine profile: total 50
20+
38 @ 0x100e9caa8 0x100e7d520 0x100ef588c 0x100ea42b4
21+
# 0x100ef588b main.doInterestingStuff+0x3b
22+
```
23+
24+
We can see that the leaked routine os the `doInterestingStuff` but we have no idea of the context of execution.
Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
package main
2+
3+
import (
4+
"math/rand"
5+
"os"
6+
"runtime/pprof"
7+
"time"
8+
)
9+
10+
func main() {
11+
go doJob()
12+
13+
for {
14+
time.Sleep(4 * time.Second)
15+
_ = pprof.Lookup("goroutine").WriteTo(os.Stdout, 1)
16+
}
17+
18+
}
19+
20+
func doJob() {
21+
for {
22+
foo()
23+
time.Sleep(50 * time.Millisecond)
24+
}
25+
}
26+
27+
func foo() {
28+
bar()
29+
}
30+
31+
func bar() {
32+
go parentGoroutine()
33+
}
34+
35+
func parentGoroutine() {
36+
go doInterestingStuff(rand.Intn(100))
37+
time.Sleep(500 * time.Millisecond)
38+
}
39+
40+
func doInterestingStuff(value int) {
41+
if value%4 == 0 {
42+
select {}
43+
}
44+
}
Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,7 @@
1+
# STEP2 - integrating the AsyncRoutineManager
2+
3+
In this step, we integrate the `AsyncRoutineManager` to handle routine management.
4+
In fact, incorporating the `AsyncRoutineManager` is almost as simple as replacing the `go` keyword with a call
5+
to the `NewAsyncRoutine` function.
6+
Running this code produces the same behavior as in STEP 1, but now we have established the foundation to
7+
fully leverage the capabilities of the `AsyncRoutineManager`.
Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,52 @@
1+
package main
2+
3+
import (
4+
"context"
5+
"github.com/openshift-online/async-routine"
6+
"math/rand"
7+
"os"
8+
"runtime/pprof"
9+
"time"
10+
)
11+
12+
func main() {
13+
async.
14+
NewAsyncRoutine("main-job", context.Background(), doJob).
15+
Run()
16+
17+
for {
18+
time.Sleep(4 * time.Second)
19+
_ = pprof.Lookup("goroutine").WriteTo(os.Stdout, 1)
20+
}
21+
22+
}
23+
24+
func doJob() {
25+
for {
26+
foo()
27+
time.Sleep(50 * time.Millisecond)
28+
}
29+
}
30+
31+
func foo() {
32+
bar()
33+
}
34+
35+
func bar() {
36+
async.
37+
NewAsyncRoutine("parent-go-routine", context.Background(), parentGoroutine).
38+
Run()
39+
}
40+
41+
func parentGoroutine() {
42+
async.
43+
NewAsyncRoutine("run-command", context.Background(), func() { doInterestingStuff(rand.Intn(100)) }).
44+
Run()
45+
time.Sleep(500 * time.Millisecond)
46+
}
47+
48+
func doInterestingStuff(value int) {
49+
if value%4 == 0 {
50+
select {}
51+
}
52+
}
Lines changed: 40 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,40 @@
1+
# STEP3 - Replacing the pproof dump with a Routine Observer
2+
3+
In this example, we implement an observer that prints the number of running routine:
4+
```go
5+
6+
type leakingRoutineObserver struct{}
7+
8+
func (l leakingRoutineObserver) RunningRoutineCount(count int) {
9+
fmt.Println("running routine count:", count)
10+
}
11+
...
12+
...
13+
```
14+
15+
Next, to ensure the observer is automatically notified of all running routines, we need to register the
16+
observer and start the monitor.
17+
18+
```go
19+
func main() {
20+
async.Manager(async.WithSnapshottingInterval(500 * time.Millisecond)).Monitor().Start()
21+
async.Manager().AddObserver(&leakingRoutineObserver{})
22+
...
23+
...
24+
}
25+
```
26+
27+
The output will be something like this:
28+
```
29+
running routine count: 14
30+
running routine count: 17
31+
running routine count: 19
32+
running routine count: 21
33+
running routine count: 23
34+
running routine count: 28
35+
running routine count: 30
36+
running routine count: 31
37+
...
38+
```
39+
40+
We can see we have a routine leak, but we still have no idea of what is the routine leak.

0 commit comments

Comments
 (0)