Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

workload: extend the command-line interface #37929

Merged
merged 1 commit into from
Aug 14, 2019
Merged

workload: extend the command-line interface #37929

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
150 changes: 150 additions & 0 deletions pkg/workload/cli/format.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,150 @@
// Copyright 2019 The Cockroach Authors.
//
// Use of this software is governed by the Business Source License
// included in the file licenses/BSL.txt.
//
// As of the Change Date specified in that file, in accordance with
// the Business Source License, use of this software will be governed
// by the Apache License, Version 2.0, included in the file
// licenses/APL.txt.

package cli

import (
"fmt"
"io"
"time"

"github.com/cockroachdb/cockroach/pkg/workload/histogram"
)

// outputFormat is the interface used to output results incrementally
// during a workload run.
type outputFormat interface {
// rampDone is called once when the ramp-up period completes, if
// configured.
rampDone()
// outputError is called when an error is encountered.
outputError(err error)
// outputTick is called when the main loop considers it useful
// to emit one row of results.
outputTick(startElapsed time.Duration, t histogram.Tick)
// outputTotal is called at the end, using the main histogram
// collector.
outputTotal(startElapsed time.Duration, t histogram.Tick)
// outputResult is called at the end, using the result histogram
// collector.
outputResult(startElapsed time.Duration, t histogram.Tick)
}

// textFormatter produces output meant for quick parsing by humans. The
// data is printed as fixed-width columns. Summary rows
// are printed at the end.
type textFormatter struct {
i int
numErr int
}

func (f *textFormatter) rampDone() {
f.i = 0
}

func (f *textFormatter) outputError(_ error) {
f.numErr++
}

func (f *textFormatter) outputTick(startElapsed time.Duration, t histogram.Tick) {
if f.i%20 == 0 {
fmt.Println("_elapsed___errors__ops/sec(inst)___ops/sec(cum)__p50(ms)__p95(ms)__p99(ms)_pMax(ms)")
}
f.i++
fmt.Printf("%7.1fs %8d %14.1f %14.1f %8.1f %8.1f %8.1f %8.1f %s\n",
startElapsed.Seconds(),
f.numErr,
float64(t.Hist.TotalCount())/t.Elapsed.Seconds(),
float64(t.Cumulative.TotalCount())/startElapsed.Seconds(),
time.Duration(t.Hist.ValueAtQuantile(50)).Seconds()*1000,
time.Duration(t.Hist.ValueAtQuantile(95)).Seconds()*1000,
time.Duration(t.Hist.ValueAtQuantile(99)).Seconds()*1000,
time.Duration(t.Hist.ValueAtQuantile(100)).Seconds()*1000,
t.Name,
)
}

const totalHeader = "\n_elapsed___errors_____ops(total)___ops/sec(cum)__avg(ms)__p50(ms)__p95(ms)__p99(ms)_pMax(ms)"

func (f *textFormatter) outputTotal(startElapsed time.Duration, t histogram.Tick) {
f.outputFinal(startElapsed, t, "__total")
}

func (f *textFormatter) outputResult(startElapsed time.Duration, t histogram.Tick) {
f.outputFinal(startElapsed, t, "__result")
}

func (f *textFormatter) outputFinal(
startElapsed time.Duration, t histogram.Tick, titleSuffix string,
) {
fmt.Println(totalHeader + titleSuffix)
if t.Cumulative == nil {
return
}
if t.Cumulative.TotalCount() == 0 {
return
}
fmt.Printf("%7.1fs %8d %14d %14.1f %8.1f %8.1f %8.1f %8.1f %8.1f %s\n",
startElapsed.Seconds(),
f.numErr,
t.Cumulative.TotalCount(),
float64(t.Cumulative.TotalCount())/startElapsed.Seconds(),
time.Duration(t.Cumulative.Mean()).Seconds()*1000,
time.Duration(t.Cumulative.ValueAtQuantile(50)).Seconds()*1000,
time.Duration(t.Cumulative.ValueAtQuantile(95)).Seconds()*1000,
time.Duration(t.Cumulative.ValueAtQuantile(99)).Seconds()*1000,
time.Duration(t.Cumulative.ValueAtQuantile(100)).Seconds()*1000,
t.Name,
)
}

// jsonFormatter produces output that is machine-readable. The time is
// printed using absolute timestamps. No summary row is printed at the
// end.
type jsonFormatter struct {
w io.Writer
numErr int
}

func (f *jsonFormatter) rampDone() {}

func (f *jsonFormatter) outputError(_ error) {
f.numErr++
}

func (f *jsonFormatter) outputTick(startElapsed time.Duration, t histogram.Tick) {
// Note: we use fmt.Printf here instead of json.Marshal to ensure
// that float values do not get printed with a uselessly large
// number of decimals.
fmt.Fprintf(f.w, `{"time":"%s",`+
`"errs":%d,`+
`"avgt":%.1f,`+
`"avgl":%.1f,`+
`"p50l":%.1f,`+
`"p95l":%.1f,`+
`"p99l":%.1f,`+
`"maxl":%.1f,`+
`"type":"%s"`+
"}\n",
t.Now.UTC().Format(time.RFC3339Nano),
f.numErr,
float64(t.Hist.TotalCount())/t.Elapsed.Seconds(),
float64(t.Cumulative.TotalCount())/startElapsed.Seconds(),
time.Duration(t.Hist.ValueAtQuantile(50)).Seconds()*1000,
time.Duration(t.Hist.ValueAtQuantile(95)).Seconds()*1000,
time.Duration(t.Hist.ValueAtQuantile(99)).Seconds()*1000,
time.Duration(t.Hist.ValueAtQuantile(100)).Seconds()*1000,
t.Name,
)
}

func (f *jsonFormatter) outputTotal(startElapsed time.Duration, t histogram.Tick) {}

func (f *jsonFormatter) outputResult(startElapsed time.Duration, t histogram.Tick) {}
115 changes: 115 additions & 0 deletions pkg/workload/cli/format_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,115 @@
// Copyright 2019 The Cockroach Authors.
//
// Use of this software is governed by the Business Source License
// included in the file licenses/BSL.txt.
//
// As of the Change Date specified in that file, in accordance with
// the Business Source License, use of this software will be governed
// by the Apache License, Version 2.0, included in the file
// licenses/APL.txt.

package cli

import (
"bytes"
"os"
"testing"
"time"

"github.com/cockroachdb/cockroach/pkg/util/leaktest"
"github.com/cockroachdb/cockroach/pkg/workload/histogram"
"github.com/stretchr/testify/require"
)

func Example_text_formatter() {
testFormatter(&textFormatter{})

// output:
// _elapsed___errors__ops/sec(inst)___ops/sec(cum)__p50(ms)__p95(ms)__p99(ms)_pMax(ms)
// 0.5s 0 2.0 2.0 503.3 503.3 503.3 503.3 read
// 1.5s 0 0.7 1.3 335.5 335.5 335.5 335.5 read
//
// _elapsed___errors_____ops(total)___ops/sec(cum)__avg(ms)__p50(ms)__p95(ms)__p99(ms)_pMax(ms)__total
// 2.0s 0 2 1.0 411.0 335.5 503.3 503.3 503.3 read
//
// _elapsed___errors_____ops(total)___ops/sec(cum)__avg(ms)__p50(ms)__p95(ms)__p99(ms)_pMax(ms)__result
// 4.0s 0 2 0.5 411.0 335.5 503.3 503.3 503.3 woo
}

func Example_json_formatter() {
testFormatter(&jsonFormatter{w: os.Stdout})

// output:
// {"time":"0001-01-01T00:00:00.5Z","errs":0,"avgt":2.0,"avgl":2.0,"p50l":503.3,"p95l":503.3,"p99l":503.3,"maxl":503.3,"type":"read"}
// {"time":"0001-01-01T00:00:01.5Z","errs":0,"avgt":0.7,"avgl":1.3,"p50l":335.5,"p95l":335.5,"p99l":335.5,"maxl":335.5,"type":"read"}
}

func testFormatter(formatter outputFormat) {
reg := histogram.NewRegistry(time.Second)

start := time.Time{}

reg.GetHandle().Get("read").Record(time.Second / 2)
reg.Tick(func(t histogram.Tick) {
// Make output deterministic.
t.Elapsed = time.Second / 2
t.Now = start.Add(t.Elapsed)

formatter.outputTick(t.Elapsed, t)
})

reg.GetHandle().Get("read").Record(time.Second / 3)
reg.Tick(func(t histogram.Tick) {
// ditto.
t.Elapsed = 3 * time.Second / 2
t.Now = start.Add(t.Elapsed)

formatter.outputTick(t.Elapsed, t)
})

resultTick := histogram.Tick{Name: "woo"}
reg.Tick(func(t histogram.Tick) {
// ditto.
t.Elapsed = 2 * time.Second
t.Now = start.Add(t.Elapsed)

formatter.outputTotal(t.Elapsed, t)
resultTick.Now = t.Now
resultTick.Cumulative = t.Cumulative
})
formatter.outputResult(4*time.Second, resultTick)
}

// TestJSONStructure ensures that the JSON output is parsable.
func TestJSONStructure(t *testing.T) {
defer leaktest.AfterTest(t)()

var buf bytes.Buffer
f := jsonFormatter{w: &buf}
reg := histogram.NewRegistry(time.Second)

start := time.Time{}

reg.GetHandle().Get("read").Record(time.Second / 2)
reg.Tick(func(t histogram.Tick) {
// Make output deterministic.
t.Elapsed = time.Second
t.Now = start.Add(t.Elapsed)

f.outputTick(time.Second, t)
})

const expected = `
{
"time":"0001-01-01T00:00:01Z",
"avgl":1,
"avgt":1,
"errs":0,
"maxl":503.3,
"p50l":503.3,
"p95l":503.3,
"p99l":503.3,
"type":"read"
}`
require.JSONEq(t, expected, buf.String())
}
70 changes: 23 additions & 47 deletions pkg/workload/cli/run.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -56,6 +56,10 @@ var pprofport = sharedFlags.Int("pprofport", 33333, "Port for pprof endpoint.")
var dataLoader = sharedFlags.String("data-loader", `INSERT`,
"How to load initial table data. Options are INSERT and IMPORT")

var displayEvery = runFlags.Duration("display-every", time.Second, "How much time between every one-line activity reports.")

var displayFormat = runFlags.String("display-format", "simple", "Output display format (simple, incremental-json)")

var histograms = runFlags.String(
"histograms", "",
"File to write per-op incremental and cumulative histogram data.")
Expand Down Expand Up @@ -306,6 +310,16 @@ func startPProfEndPoint(ctx context.Context) {
func runRun(gen workload.Generator, urls []string, dbName string) error {
ctx := context.Background()

var formatter outputFormat
switch *displayFormat {
case "simple":
formatter = &textFormatter{}
case "incremental-json":
formatter = &jsonFormatter{w: os.Stdout}
default:
return errors.Errorf("unknown display format: %s", *displayFormat)
}

startPProfEndPoint(ctx)
initDB, err := gosql.Open(`cockroach`, strings.Join(urls, ` `))
if err != nil {
Expand Down Expand Up @@ -394,8 +408,7 @@ func runRun(gen workload.Generator, urls []string, dbName string) error {
}
}()

var numErr int
ticker := time.NewTicker(time.Second)
ticker := time.NewTicker(*displayEvery)
defer ticker.Stop()
done := make(chan os.Signal, 3)
signal.Notify(done, exitSignals...)
Expand All @@ -422,11 +435,11 @@ func runRun(gen workload.Generator, urls []string, dbName string) error {
jsonEnc = json.NewEncoder(jsonF)
}

everySecond := log.Every(time.Second)
for i := 0; ; {
everySecond := log.Every(*displayEvery)
for {
select {
case err := <-errCh:
numErr++
formatter.outputError(err)
if *tolerateErrors {
if everySecond.ShouldLog() {
log.Error(ctx, err)
Expand All @@ -438,21 +451,7 @@ func runRun(gen workload.Generator, urls []string, dbName string) error {
case <-ticker.C:
startElapsed := timeutil.Since(start)
reg.Tick(func(t histogram.Tick) {
if i%20 == 0 {
fmt.Println("_elapsed___errors__ops/sec(inst)___ops/sec(cum)__p50(ms)__p95(ms)__p99(ms)_pMax(ms)")
}
i++
fmt.Printf("%8s %8d %14.1f %14.1f %8.1f %8.1f %8.1f %8.1f %s\n",
time.Duration(startElapsed.Seconds()+0.5)*time.Second,
numErr,
float64(t.Hist.TotalCount())/t.Elapsed.Seconds(),
float64(t.Cumulative.TotalCount())/startElapsed.Seconds(),
time.Duration(t.Hist.ValueAtQuantile(50)).Seconds()*1000,
time.Duration(t.Hist.ValueAtQuantile(95)).Seconds()*1000,
time.Duration(t.Hist.ValueAtQuantile(99)).Seconds()*1000,
time.Duration(t.Hist.ValueAtQuantile(100)).Seconds()*1000,
t.Name,
)
formatter.outputTick(startElapsed, t)
if jsonEnc != nil && rampDone == nil {
_ = jsonEnc.Encode(t.Snapshot())
}
Expand All @@ -463,7 +462,7 @@ func runRun(gen workload.Generator, urls []string, dbName string) error {
case <-rampDone:
rampDone = nil
start = timeutil.Now()
i = 0
formatter.rampDone()
reg.Tick(func(t histogram.Tick) {
t.Cumulative.Reset()
t.Hist.Reset()
Expand All @@ -474,32 +473,11 @@ func runRun(gen workload.Generator, urls []string, dbName string) error {
if ops.Close != nil {
ops.Close(ctx)
}
const totalHeader = "\n_elapsed___errors_____ops(total)___ops/sec(cum)__avg(ms)__p50(ms)__p95(ms)__p99(ms)_pMax(ms)"
fmt.Println(totalHeader + `__total`)
startElapsed := timeutil.Since(start)
printTotalHist := func(t histogram.Tick) {
if t.Cumulative == nil {
return
}
if t.Cumulative.TotalCount() == 0 {
return
}
fmt.Printf("%7.1fs %8d %14d %14.1f %8.1f %8.1f %8.1f %8.1f %8.1f %s\n",
startElapsed.Seconds(), numErr,
t.Cumulative.TotalCount(),
float64(t.Cumulative.TotalCount())/startElapsed.Seconds(),
time.Duration(t.Cumulative.Mean()).Seconds()*1000,
time.Duration(t.Cumulative.ValueAtQuantile(50)).Seconds()*1000,
time.Duration(t.Cumulative.ValueAtQuantile(95)).Seconds()*1000,
time.Duration(t.Cumulative.ValueAtQuantile(99)).Seconds()*1000,
time.Duration(t.Cumulative.ValueAtQuantile(100)).Seconds()*1000,
t.Name,
)
}

startElapsed := timeutil.Since(start)
resultTick := histogram.Tick{Name: ops.ResultHist}
reg.Tick(func(t histogram.Tick) {
printTotalHist(t)
formatter.outputTotal(startElapsed, t)
if jsonEnc != nil {
// Note that we're outputting the delta from the last tick. The
// cumulative histogram can be computed by merging all of the
Expand All @@ -515,9 +493,7 @@ func runRun(gen workload.Generator, urls []string, dbName string) error {
}
}
})

fmt.Println(totalHeader + `__result`)
printTotalHist(resultTick)
formatter.outputResult(startElapsed, resultTick)

if h, ok := gen.(workload.Hookser); ok {
if h.Hooks().PostRun != nil {
Expand Down