Skip to content

Commit

Permalink
Periodically print simulator progress. (ServiceWeaver#620)
Browse files Browse the repository at this point in the history
With this PR, a simulator periodically prints out its progress, just
like with Go's fuzz testing. This is important to make sure the user
knows the simulation isn't stuck.

```
$ go test -run=Passing/NoCallsNoGen -v
=== RUN   TestPassingSimulations
=== RUN   TestPassingSimulations/NoCallsNoGen
    simulator.go:390: Simulating *sim.noCallsNoGenWorkload for 10s with 1280 executors...
    simulator.go:405: [1s] 60,520 execs (60,064 execs/s), 4,207,853 ops (4,176,166 ops/s)
    simulator.go:405: [2s] 91,122 execs (45,390 execs/s), 9,494,404 ops (4,729,368 ops/s)
    simulator.go:405: [3s] 116,070 execs (38,594 execs/s), 15,377,846 ops (5,113,218 ops/s)
    simulator.go:405: [4s] 136,944 execs (34,175 execs/s), 21,386,940 ops (5,337,185 ops/s)
    simulator.go:405: [5s] 155,343 execs (31,024 execs/s), 27,506,001 ops (5,493,331 ops/s)
    simulator.go:405: [6s] 172,306 execs (28,681 execs/s), 33,831,171 ops (5,631,418 ops/s)
    simulator.go:405: [7s] 187,752 execs (26,794 execs/s), 40,157,529 ops (5,730,931 ops/s)
    simulator.go:405: [8s] 201,803 execs (25,203 execs/s), 46,384,348 ops (5,792,803 ops/s)
    simulator.go:405: [9s] 215,544 execs (23,930 execs/s), 52,909,102 ops (5,874,082 ops/s)
```
  • Loading branch information
mwhittaker committed Sep 19, 2023
1 parent 3d77487 commit dce9749
Show file tree
Hide file tree
Showing 3 changed files with 34 additions and 4 deletions.
2 changes: 1 addition & 1 deletion go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ require (
golang.org/x/image v0.5.0
golang.org/x/sync v0.3.0
golang.org/x/term v0.10.0
golang.org/x/text v0.9.0
golang.org/x/tools v0.11.0
google.golang.org/genproto/googleapis/api v0.0.0-20230717213848-3f92550aa753
google.golang.org/protobuf v1.31.0
Expand All @@ -48,7 +49,6 @@ require (
go.opentelemetry.io/otel/metric v1.16.0 // indirect
golang.org/x/mod v0.12.0 // indirect
golang.org/x/sys v0.10.0 // indirect
golang.org/x/text v0.9.0 // indirect
google.golang.org/genproto/googleapis/rpc v0.0.0-20230706204954-ccb25ca9f130 // indirect
lukechampine.com/uint128 v1.2.0 // indirect
modernc.org/cc/v3 v3.40.0 // indirect
Expand Down
2 changes: 2 additions & 0 deletions godeps.txt
Original file line number Diff line number Diff line change
Expand Up @@ -283,6 +283,8 @@ github.com/ServiceWeaver/weaver/internal/sim
go.opentelemetry.io/otel/trace
golang.org/x/exp/maps
golang.org/x/sync/errgroup
golang.org/x/text/language
golang.org/x/text/message
log/slog
math/bits
math/rand
Expand Down
34 changes: 31 additions & 3 deletions internal/sim/simulator.go
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,8 @@ import (
"github.com/ServiceWeaver/weaver/runtime/logging"
"github.com/ServiceWeaver/weaver/runtime/protos"
"golang.org/x/exp/maps"
"golang.org/x/text/language"
"golang.org/x/text/message"
)

// FakeComponent is a copy of weavertest.FakeComponent. It's needed to access
Expand Down Expand Up @@ -381,6 +383,30 @@ func (s *Simulator) Run(duration time.Duration) Results {
}
}()

// Spawn a goroutine to periodically print progress.
done.Add(1)
go func() {
defer done.Done()
s.t.Logf("Simulating %v for %v with %d executors...", s.w, duration, n)
printer := message.NewPrinter(language.AmericanEnglish)
ticker := time.NewTicker(time.Second)
for {
select {
case <-ctx.Done():
ticker.Stop()
return
case <-ticker.C:
execs := atomic.LoadInt64(&numExecutions)
ops := atomic.LoadInt64(&numOps)
elapsed := time.Since(start)
truncated := elapsed.Truncate(time.Second)
execRate := printer.Sprintf("%0.0f", float64(execs)/elapsed.Seconds())
opRate := printer.Sprintf("%0.0f", float64(ops)/elapsed.Seconds())
s.t.Logf("[%v] %s execs (%s execs/s), %s ops (%s ops/s)", truncated, printer.Sprint(execs), execRate, printer.Sprint(ops), opRate)
}
}
}()

select {
case err := <-errs:
// An execution failed to execute properly.
Expand Down Expand Up @@ -411,13 +437,15 @@ func (s *Simulator) Run(duration time.Duration) Results {
// Summary returns a human readable summary of the results.
func (r *Results) Summary() string {
duration := r.Duration.Truncate(time.Millisecond)
simRate := float64(r.NumExecutions) / r.Duration.Seconds()
opRate := float64(r.NumOps) / r.Duration.Seconds()
printer := message.NewPrinter(language.AmericanEnglish)
execRate := printer.Sprintf("%0.2f", float64(r.NumExecutions)/r.Duration.Seconds())
opRate := printer.Sprintf("%0.2f", float64(r.NumOps)/r.Duration.Seconds())
prefix := "✅ No errors"
if r.Err != nil {
prefix = "❌ Error"
}
return fmt.Sprintf("%s found after %d ops across %d executions in %v (%0.2f execs/s, %0.2f ops/s).", prefix, r.NumOps, r.NumExecutions, duration, simRate, opRate)
return fmt.Sprintf("%s found after %s ops across %s executions in %v (%s execs/s, %s ops/s).",
prefix, printer.Sprint(r.NumOps), printer.Sprint(r.NumExecutions), duration, execRate, opRate)
}

// Mermaid returns a [mermaid] diagram that illustrates an execution history.
Expand Down

0 comments on commit dce9749

Please sign in to comment.