From 113cf439b1ff23237c316a412067ab9a3b34fabb Mon Sep 17 00:00:00 2001 From: Etienne Perot Date: Mon, 13 May 2024 18:26:29 -0700 Subject: [PATCH] Add `metricsviz_cli` tool to manually create charts from profiling metrics. This is part of a series of changes to add metric charts in performance benchmarks. Comes with a test, which also serves as an end-to-end-ish test of profiling metric functionality from collection to charting. Including `metricsviz` in a `go_binary` requires making it non-`testonly`, which in turn means removing the `dockerutil` dependency, so this uses an interface to break the dependency on `dockerutil.Container`. PiperOrigin-RevId: 633394898 --- test/metricsviz/BUILD | 3 +- test/metricsviz/metricsviz.go | 63 ++++++++-- test/metricsviz/metricsviz_cli/BUILD | 23 ++++ .../metricsviz_cli/metricsviz_cli.go | 40 ++++++ .../metricsviz_cli/metricsviz_cli_test.go | 114 ++++++++++++++++++ test/metricsviz/metricsviz_publish.go | 7 +- 6 files changed, 232 insertions(+), 18 deletions(-) create mode 100644 test/metricsviz/metricsviz_cli/BUILD create mode 100644 test/metricsviz/metricsviz_cli/metricsviz_cli.go create mode 100644 test/metricsviz/metricsviz_cli/metricsviz_cli_test.go diff --git a/test/metricsviz/BUILD b/test/metricsviz/BUILD index 8ab4b7849..201fa0b7b 100644 --- a/test/metricsviz/BUILD +++ b/test/metricsviz/BUILD @@ -7,7 +7,6 @@ package( go_library( name = "metricsviz", - testonly = 1, srcs = [ "metricsviz.go", "metricsviz_groups.go", @@ -17,7 +16,7 @@ go_library( deps = [ "//pkg/metric", "//pkg/metric:metric_go_proto", - "//pkg/test/dockerutil", + "@com_github_docker_docker//api/types:go_default_library", "@com_github_go_echarts_go_echarts_v2//charts:go_default_library", "@com_github_go_echarts_go_echarts_v2//components:go_default_library", "@com_github_go_echarts_go_echarts_v2//opts:go_default_library", diff --git a/test/metricsviz/metricsviz.go b/test/metricsviz/metricsviz.go index d1e837540..51516face 100644 --- a/test/metricsviz/metricsviz.go +++ b/test/metricsviz/metricsviz.go @@ -22,6 +22,7 @@ import ( "fmt" "hash/adler32" "os" + "path" "regexp" "slices" "sort" @@ -30,6 +31,7 @@ import ( "testing" "time" + "github.com/docker/docker/api/types" "github.com/go-echarts/go-echarts/v2/charts" "github.com/go-echarts/go-echarts/v2/components" "github.com/go-echarts/go-echarts/v2/opts" @@ -37,7 +39,6 @@ import ( "google.golang.org/protobuf/encoding/protojson" "gvisor.dev/gvisor/pkg/metric" mpb "gvisor.dev/gvisor/pkg/metric/metric_go_proto" - "gvisor.dev/gvisor/pkg/test/dockerutil" ) // MetricName is the name of a metric. @@ -438,6 +439,9 @@ func Parse(logs string, hasPrefix bool) (*Data, error) { if hasPrefix && !strings.HasPrefix(line, metric.MetricsPrefix) { continue } + if line == "" { + continue + } metricsLineFound = true lineData := strings.TrimPrefix(line, metric.MetricsPrefix) @@ -561,17 +565,25 @@ func slugify(s string) string { return s } +// Container represents a container that can be stopped and from which we can +// get logs. +type Container interface { + Stop(context.Context) error + Status(context.Context) (types.ContainerState, error) + Logs(context.Context) (string, error) +} + // FromContainerLogs parses a container's logs and reports metrics data // found within. // The container must be stopped or stoppable by the time this is called. -func FromContainerLogs(ctx context.Context, testLike testing.TB, container *dockerutil.Container) { +func FromContainerLogs(ctx context.Context, testLike testing.TB, container Container) { FromNamedContainerLogs(ctx, testLike, container, "") } // FromNamedContainerLogs parses a container's logs and reports metrics data // found within, making note of the container's name on the results page. // The container must be stopped or stoppable by the time this is called. -func FromNamedContainerLogs(ctx context.Context, testLike testing.TB, container *dockerutil.Container, containerName string) { +func FromNamedContainerLogs(ctx context.Context, testLike testing.TB, container Container, containerName string) { // If the container is not stopped, stop it. // This is necessary to flush the profiling metrics logs. st, err := container.Status(ctx) @@ -604,7 +616,7 @@ func FromNamedContainerLogs(ctx context.Context, testLike testing.TB, container if err != nil { testLike.Fatalf("Failed to generate HTML: %v", err) } - if err := publishHTMLFn(ctx, testLike, htmlOptions, html); err != nil { + if err := publishHTMLFn(ctx, testLike.Logf, htmlOptions, html); err != nil { testLike.Fatalf("Failed to publish HTML: %v", err) } } @@ -612,24 +624,50 @@ func FromNamedContainerLogs(ctx context.Context, testLike testing.TB, container // FromProfilingMetricsLogFile parses a profiling metrics log file // (as created by --profiling-metrics-log) and reports metrics data within. func FromProfilingMetricsLogFile(ctx context.Context, testLike testing.TB, logFile string) { + if err := fromFile(ctx, testLike.Name(), logFile, false, testLike.Logf); err != nil { + testLike.Fatalf("Failed to process metrics logs file: %v", err) + } +} + +// FromFile reads a file and detects whether it is a profiling metrics log +// file or a file with GVISOR_METRICS-prefixed lines. +// Either way, it parses the metrics data and reports it. +func FromFile(ctx context.Context, logFile string, logFn func(string, ...any)) error { contents, err := os.ReadFile(logFile) if err != nil { - testLike.Fatalf("Failed to read log file: %v", err) + return fmt.Errorf("failed to read log file: %w", err) } - data, err := Parse(string(contents), false) + logName := strings.TrimSuffix(path.Base(logFile), ".log") + for _, line := range strings.Split(string(contents), "\n") { + if strings.HasPrefix(line, metric.MetricsPrefix) { + return fromFile(ctx, logName, logFile, true, logFn) + } + if strings.HasPrefix(line, metric.TimeColumn) { + return fromFile(ctx, logName, logFile, false, logFn) + } + } + return fmt.Errorf("could not recognize %q as a metrics log file", logFile) +} + +func fromFile(ctx context.Context, name, logFile string, hasPrefix bool, logFn func(string, ...any)) error { + contents, err := os.ReadFile(logFile) + if err != nil { + return fmt.Errorf("failed to read log file: %w", err) + } + data, err := Parse(string(contents), hasPrefix) if err != nil { if errors.Is(err, ErrNoMetricData) { - return // No metric data in the logs, so stay quiet. + return nil // No metric data in the logs, so stay quiet. } - testLike.Fatalf("Failed to parse metrics data: %v", err) + return fmt.Errorf("failed to parse metrics data: %w", err) } htmlOptions := HTMLOptions{ - Title: testLike.Name(), + Title: name, When: data.startTime, } html, err := data.ToHTML(htmlOptions) if err != nil { - testLike.Fatalf("Failed to generate HTML: %v", err) + return fmt.Errorf("failed to generate HTML: %w", err) } if strings.HasSuffix(logFile, ".log") { // Best-effort conversion to HTML next to the .log file in the directory, @@ -637,7 +675,8 @@ func FromProfilingMetricsLogFile(ctx context.Context, testLike testing.TB, logFi // publishing step later on. _ = os.WriteFile(strings.TrimSuffix(logFile, ".log")+".html", []byte(html), 0644) } - if err := publishHTMLFn(ctx, testLike, htmlOptions, html); err != nil { - testLike.Fatalf("Failed to publish HTML: %v", err) + if err := publishHTMLFn(ctx, logFn, htmlOptions, html); err != nil { + return fmt.Errorf("failed to publish HTML: %w", err) } + return nil } diff --git a/test/metricsviz/metricsviz_cli/BUILD b/test/metricsviz/metricsviz_cli/BUILD new file mode 100644 index 000000000..d9e8ec00e --- /dev/null +++ b/test/metricsviz/metricsviz_cli/BUILD @@ -0,0 +1,23 @@ +load("//tools:defs.bzl", "go_binary") + +package( + default_applicable_licenses = ["//:license"], + licenses = ["notice"], +) + +go_binary( + name = "metricsviz_cli", + srcs = ["metricsviz_cli.go"], + deps = ["//test/metricsviz"], +) + +go_test( + name = "metricsviz_cli_test", + srcs = ["metricsviz_cli_test.go"], + data = [":metricsviz_cli"], + deps = [ + "//pkg/metric", + "//pkg/test/testutil", + "//test/metricsviz", + ], +) diff --git a/test/metricsviz/metricsviz_cli/metricsviz_cli.go b/test/metricsviz/metricsviz_cli/metricsviz_cli.go new file mode 100644 index 000000000..c3209abd8 --- /dev/null +++ b/test/metricsviz/metricsviz_cli/metricsviz_cli.go @@ -0,0 +1,40 @@ +// Copyright 2024 The gVisor Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// metricsviz_cli visualizes metrics from profiling metrics logs. +package main + +import ( + "context" + "fmt" + "os" + + "gvisor.dev/gvisor/test/metricsviz" +) + +func main() { + ctx := context.Background() + if len(os.Args) < 2 { + fmt.Fprintf(os.Stderr, "Usage: %s /path/to/profiling_metrics.log\n", os.Args[0]) + os.Exit(2) + } + for _, arg := range os.Args[1:] { + if err := metricsviz.FromFile(ctx, arg, func(format string, args ...any) { + fmt.Fprintf(os.Stdout, format+"\n", args...) + }); err != nil { + fmt.Fprintln(os.Stderr, err) + os.Exit(1) + } + } +} diff --git a/test/metricsviz/metricsviz_cli/metricsviz_cli_test.go b/test/metricsviz/metricsviz_cli/metricsviz_cli_test.go new file mode 100644 index 000000000..dd2e21f6d --- /dev/null +++ b/test/metricsviz/metricsviz_cli/metricsviz_cli_test.go @@ -0,0 +1,114 @@ +// Copyright 2024 The gVisor Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Package metricsviz_cli_test tests metricsviz_cli. +package metricsviz_cli_test + +import ( + "context" + "fmt" + "math/rand/v2" + "os" + "os/exec" + "path" + "strings" + "testing" + "time" + + "gvisor.dev/gvisor/pkg/metric" + "gvisor.dev/gvisor/pkg/test/testutil" + "gvisor.dev/gvisor/test/metricsviz" +) + +func TestMetricsvizCLI(t *testing.T) { + ctx := context.Background() + cliPath, err := testutil.FindFile("test/metricsviz/metricsviz_cli/metricsviz_cli") + if err != nil { + t.Fatalf("Failed to find metricsviz_cli: %v", err) + } + const testMetricName = "/metricsviz_cli_test/counter" + testMetric := metric.MustCreateNewUint64Metric(testMetricName, true, fmt.Sprintf("test counter for %s", t.Name())) + if err := metric.Initialize(); err != nil { + t.Fatalf("Failed to initialize metrics: %v", err) + } + tempDir := t.TempDir() + for _, lossy := range []bool{true, false} { + t.Run(fmt.Sprintf("lossy=%v", lossy), func(t *testing.T) { + logFilePath := path.Join(tempDir, fmt.Sprintf("lossy=%v.log", lossy)) + logFile, err := os.Create(logFilePath) + if err != nil { + t.Fatalf("Failed to create log file %q: %v", logFilePath, err) + } + err = metric.StartProfilingMetrics(metric.ProfilingMetricsOptions[*os.File]{ + Sink: logFile, + Lossy: lossy, + Metrics: testMetricName, + Rate: time.Millisecond, + }) + if err != nil { + t.Fatalf("Failed to start profiling metrics: %v", err) + } + + // Generate some counter increments for 25ms. + waitCtx, waitCancel := context.WithTimeout(ctx, 25*time.Millisecond) + defer waitCancel() + for waitCtx.Err() == nil { + testMetric.Increment() + select { + case <-waitCtx.Done(): + case <-time.After(time.Millisecond): + if lossy { + // Also inject some crap in the logs to verify that it can deal + // with text being written in the middle of metrics data. + randomLogs := [][]byte{ + []byte("some log"), + []byte("some log with a newline\n"), + []byte("a log with\rcarriage return in the middle"), + []byte("a log with\nmultiple\nnewlines"), + []byte{0x01, 0x02, 0x00, 0x03}, // Non-ASCII bytes. + } + if _, err := logFile.Write(randomLogs[rand.IntN(len(randomLogs))]); err != nil { + t.Fatalf("Failed to write random log: %v", err) + } + } + } + } + + metric.StopProfilingMetrics() + logFileContents, err := os.ReadFile(logFilePath) + if err != nil { + t.Fatalf("Failed to read log file %q: %v", logFilePath, err) + } + if len(logFileContents) == 0 { + t.Fatalf("Log file %q is empty", logFilePath) + } + t.Logf("Log file %q contents:\n%s\n(end of log file contents)", logFilePath, string(logFileContents)) + + if output, err := exec.CommandContext(ctx, cliPath, logFilePath).CombinedOutput(); err != nil { + t.Fatalf("Failed to run metricsviz_cli: %v (output: %s)", err, strings.TrimSpace(string(output))) + } + if err = metricsviz.FromFile(ctx, logFilePath, t.Logf); err != nil { + t.Fatalf("Failed to generate metricsviz from %q: %v", logFilePath, err) + } + expectedHTMLPath := path.Join(tempDir, fmt.Sprintf("lossy=%v.html", lossy)) + htmlStat, err := os.Stat(expectedHTMLPath) + if err != nil { + t.Fatalf("Failed to stat %q: %v", expectedHTMLPath, err) + } + if htmlStat.Size() == 0 { + t.Fatalf("HTML file %q is empty", expectedHTMLPath) + } + }) + } +} diff --git a/test/metricsviz/metricsviz_publish.go b/test/metricsviz/metricsviz_publish.go index 966dfeb0c..61a184878 100644 --- a/test/metricsviz/metricsviz_publish.go +++ b/test/metricsviz/metricsviz_publish.go @@ -20,7 +20,6 @@ import ( "os" "path/filepath" "strings" - "testing" "time" ) @@ -30,7 +29,7 @@ var publishHTMLFn = publishHTML // publishHTML publishes the HTML contents to a sane file location and // writes the path to the logger. -func publishHTML(ctx context.Context, testLike testing.TB, htmlOptions HTMLOptions, html string) error { +func publishHTML(ctx context.Context, logFn func(format string, args ...any), htmlOptions HTMLOptions, html string) error { // We don't use the test's temporary directory here because it is deleted at // the end of the test, but we want to keep the HTML around later for // viewing. So we just use a new temporary directory in `/tmp` here. @@ -55,9 +54,9 @@ func publishHTML(ctx context.Context, testLike testing.TB, htmlOptions HTMLOptio return fmt.Errorf("failed to chmod %q: %w", htmlPath, err) } if htmlOptions.ContainerName == "" { - testLike.Logf("******** METRICS CHARTS: file://%s ********", htmlPath) + logFn("******** METRICS CHARTS: file://%s ********", htmlPath) } else { - testLike.Logf("******** METRICS CHARTS (%s): file://%s ********", htmlOptions.ContainerName, htmlPath) + logFn("******** METRICS CHARTS (%s): file://%s ********", htmlOptions.ContainerName, htmlPath) } return nil }