Skip to content

Commit

Permalink
starlark/profile: use real time (not monotonic) clock for Profile.time (
Browse files Browse the repository at this point in the history
google#187)

Also, add integration test of profiler and 'go tool pprof'.

Fixes google#186
  • Loading branch information
adonovan authored Apr 5, 2019
1 parent 2494ae9 commit 61fc542
Show file tree
Hide file tree
Showing 2 changed files with 98 additions and 11 deletions.
26 changes: 15 additions & 11 deletions starlark/profile.go
Original file line number Diff line number Diff line change
Expand Up @@ -327,11 +327,12 @@ func profile(w io.Writer) {
wnenc.int(ValueType_unit, str("nanoseconds"))

// informational fields of Profile
enc.bytes(Profile_sample_type, wallNanos.Bytes()) // type of samples
enc.int(Profile_period, quantum.Nanoseconds()) // magnitude of sampling period
enc.bytes(Profile_period_type, wallNanos.Bytes()) // dimension and unit of period
enc.bytes(Profile_sample_type, wallNanos.Bytes())
enc.int(Profile_period, quantum.Nanoseconds()) // magnitude of sampling period
enc.bytes(Profile_period_type, wallNanos.Bytes()) // dimension and unit of period
enc.int(Profile_time_nanos, time.Now().UnixNano()) // start (real) time of profile

start := nanotime()
startNano := nanotime()

// Read profile events from the channel
// until it is closed by StopProfiler.
Expand All @@ -345,9 +346,8 @@ func profile(w io.Writer) {
enc.bytes(Profile_sample, sample.Bytes())
}

end := nanotime()
enc.int(Profile_time_nanos, start) // start time of profile
enc.int(Profile_duration_nanos, end-start) // duration of profile
endNano := nanotime()
enc.int(Profile_duration_nanos, endNano-startNano)

err := gz.Close() // Close reports any prior write error
if flushErr := bufw.Flush(); err == nil {
Expand All @@ -359,10 +359,8 @@ func profile(w io.Writer) {
// nanotime returns the time in nanoseconds since epoch.
// It is implemented by runtime.nanotime using the linkname hack;
// runtime.nanotime is defined for all OSs/ARCHS and uses the
// monotonic system clock, which there is otherwise no way to access.
//
// Should that function ever go away, here are two inferior but more
// portable implementations:
// monotonic system clock, which there is no portable way to access.
// Should that function ever go away, these alternatives exist:
//
// // POSIX only. REALTIME not MONOTONIC. 17ns.
// var tv syscall.Timeval
Expand All @@ -372,6 +370,12 @@ func profile(w io.Writer) {
// // Portable. REALTIME not MONOTONIC. 46ns.
// return time.Now().Nanoseconds()
//
// // POSIX only. Adds a dependency.
// import "golang.org/x/sys/unix"
// var ts unix.Timespec
// unix.ClockGettime(CLOCK_MONOTONIC, &ts) // can't fail
// return unix.TimespecToNsec(ts)
//
//go:linkname nanotime runtime.nanotime
func nanotime() int64

Expand Down
83 changes: 83 additions & 0 deletions starlark/profile_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,83 @@
// Copyright 2019 The Bazel Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

package starlark_test

import (
"bytes"
"fmt"
"io/ioutil"
"os"
"os/exec"
"strings"
"testing"

"go.starlark.net/starlark"
)

// TestProfile is a simple integration test that the profiler
// emits minimally plausible pprof-compatible output.
func TestProfile(t *testing.T) {
prof, err := ioutil.TempFile("", "profile_test")
if err != nil {
t.Fatal(err)
}
defer prof.Close()
defer os.Remove(prof.Name())
if err := starlark.StartProfile(prof); err != nil {
t.Fatal(err)
}

const src = `
def fibonacci(n):
res = list(range(n))
for i in res[2:]:
res[i] = res[i-2] + res[i-1]
return res
fibonacci(100000)
`

thread := new(starlark.Thread)
if _, err := starlark.ExecFile(thread, "foo.star", src, nil); err != nil {
_ = starlark.StopProfile()
t.Fatal(err)
}
if err := starlark.StopProfile(); err != nil {
t.Fatal(err)
}
prof.Sync()
cmd := exec.Command("go", "tool", "pprof", "-top", prof.Name())
cmd.Stderr = new(bytes.Buffer)
cmd.Stdout = new(bytes.Buffer)
if err := cmd.Run(); err != nil {
t.Fatalf("pprof failed: %v; output=<<%s>>", err, cmd.Stderr)
}

// Typical output (may vary by go release):
//
// Type: wall
// Time: Apr 4, 2019 at 11:10am (EDT)
// Duration: 251.62ms, Total samples = 250ms (99.36%)
// Showing nodes accounting for 250ms, 100% of 250ms total
// flat flat% sum% cum cum%
// 320ms 100% 100% 320ms 100% fibonacci
// 0 0% 100% 320ms 100% foo.star
//
// We'll assert a few key substrings are present.
got := fmt.Sprint(cmd.Stdout)
for _, want := range []string{
"flat%",
"fibonacci",
"foo.star",
} {
if !strings.Contains(got, want) {
t.Errorf("output did not contain %q", want)
}
}
if t.Failed() {
t.Logf("stderr=%v", cmd.Stderr)
t.Logf("stdout=%v", cmd.Stdout)
}
}

0 comments on commit 61fc542

Please sign in to comment.