diff --git a/runsc/cli/BUILD b/runsc/cli/BUILD index df7226ca0..208754bc4 100644 --- a/runsc/cli/BUILD +++ b/runsc/cli/BUILD @@ -25,6 +25,7 @@ go_library( "//runsc/config", "//runsc/flag", "//runsc/specutils", + "//runsc/starttime", "//runsc/version", "@com_github_google_subcommands//:go_default_library", "@org_golang_x_sys//unix:go_default_library", diff --git a/runsc/cli/main.go b/runsc/cli/main.go index 0e79ef39b..3f7e5b48b 100644 --- a/runsc/cli/main.go +++ b/runsc/cli/main.go @@ -41,6 +41,7 @@ import ( "gvisor.dev/gvisor/runsc/config" "gvisor.dev/gvisor/runsc/flag" "gvisor.dev/gvisor/runsc/specutils" + "gvisor.dev/gvisor/runsc/starttime" "gvisor.dev/gvisor/runsc/version" ) @@ -133,6 +134,9 @@ func Main() { // case that does not occur. _ = time.Local.String() + // Set the start time as soon as possible. + startTime := starttime.Get() + var emitters log.MultiEmitter if *debugLogFD > -1 { f := os.NewFile(uintptr(*debugLogFD), "debug log file") @@ -140,7 +144,7 @@ func Main() { emitters = append(emitters, newEmitter(conf.DebugLogFormat, f)) } else if len(conf.DebugLog) > 0 && specutils.IsDebugCommand(conf, subcommand) { - f, err := specutils.DebugLogFile(conf.DebugLog, subcommand, "" /* name */) + f, err := specutils.DebugLogFile(conf.DebugLog, subcommand, "" /* name */, startTime) if err != nil { util.Fatalf("error opening debug log file in %q: %v", conf.DebugLog, err) } diff --git a/runsc/container/BUILD b/runsc/container/BUILD index db792464a..135a918cb 100644 --- a/runsc/container/BUILD +++ b/runsc/container/BUILD @@ -33,8 +33,10 @@ go_library( "//runsc/config", "//runsc/console", "//runsc/donation", + "//runsc/profile", "//runsc/sandbox", "//runsc/specutils", + "//runsc/starttime", "@com_github_cenkalti_backoff//:go_default_library", "@com_github_gofrs_flock//:go_default_library", "@com_github_opencontainers_runtime_spec//specs-go:go_default_library", diff --git a/runsc/container/container.go b/runsc/container/container.go index e00154370..35495fc5a 100644 --- a/runsc/container/container.go +++ b/runsc/container/container.go @@ -47,8 +47,10 @@ import ( "gvisor.dev/gvisor/runsc/config" "gvisor.dev/gvisor/runsc/console" "gvisor.dev/gvisor/runsc/donation" + "gvisor.dev/gvisor/runsc/profile" "gvisor.dev/gvisor/runsc/sandbox" "gvisor.dev/gvisor/runsc/specutils" + "gvisor.dev/gvisor/runsc/starttime" ) const cgroupParentAnnotation = "dev.gvisor.spec.cgroup-parent" @@ -1200,7 +1202,18 @@ func (c *Container) createGoferProcess(spec *specs.Spec, conf *config.Config, bu } } if specutils.IsDebugCommand(conf, "gofer") { - if err := donations.DonateDebugLogFile("debug-log-fd", conf.DebugLog, "gofer", test); err != nil { + // The startTime here can mean one of two things: + // - If this is the first gofer started at the same time as the sandbox, + // then this starttime will exactly match the one used by the sandbox + // itself (i.e. `Sandbox.StartTime`). This is desirable, such that the + // first gofer's log filename will have the exact same timestamp as + // the sandbox's log filename timestamp. + // - If this is not the first gofer, then this starttime will be later + // than the sandbox start time; this is desirable such that we can + // distinguish the gofer log filenames between each other. + // In either case, `starttime.Get` gets us the timestamp we want. + startTime := starttime.Get() + if err := donations.DonateDebugLogFile("debug-log-fd", conf.DebugLog, "gofer", test, startTime); err != nil { return nil, nil, nil, err } } @@ -1701,6 +1714,7 @@ func (c *Container) donateGoferProfileFDs(conf *config.Config, donations *donati // into a single file. profSuffix := ".gofer." + c.ID const profFlags = os.O_CREATE | os.O_WRONLY | os.O_TRUNC + profile.UpdatePaths(conf, starttime.Get()) if conf.ProfileBlock != "" { if err := donations.OpenAndDonate("profile-block-fd", conf.ProfileBlock+profSuffix, profFlags); err != nil { return err diff --git a/runsc/donation/donation.go b/runsc/donation/donation.go index f128eafed..0ea2297b7 100644 --- a/runsc/donation/donation.go +++ b/runsc/donation/donation.go @@ -20,6 +20,7 @@ import ( "fmt" "os" "os/exec" + "time" "gvisor.dev/gvisor/pkg/log" "gvisor.dev/gvisor/runsc/specutils" @@ -75,11 +76,11 @@ func (f *Agency) OpenAndDonate(flag, path string, flags int) error { // DonateDebugLogFile is similar to DonateAndClose but handles the opening of // the file using specutils.DebugLogFile() for convenience. It's a noop, if // path is empty. -func (f *Agency) DonateDebugLogFile(flag, logPattern, command, test string) error { +func (f *Agency) DonateDebugLogFile(flag, logPattern, command, test string, timestamp time.Time) error { if len(logPattern) == 0 { return nil } - file, err := specutils.DebugLogFile(logPattern, command, test) + file, err := specutils.DebugLogFile(logPattern, command, test, timestamp) if err != nil { return fmt.Errorf("opening debug log file in %q: %v", logPattern, err) } diff --git a/runsc/profile/BUILD b/runsc/profile/BUILD index 16c055a5c..af5e1f0c9 100644 --- a/runsc/profile/BUILD +++ b/runsc/profile/BUILD @@ -14,6 +14,7 @@ go_library( deps = [ "//pkg/log", "//pkg/sentry/control", + "//runsc/config", "//runsc/flag", ], ) diff --git a/runsc/profile/profile.go b/runsc/profile/profile.go index 64b5369f1..f01c9b6c9 100644 --- a/runsc/profile/profile.go +++ b/runsc/profile/profile.go @@ -16,13 +16,17 @@ package profile import ( + "fmt" "os" "runtime" "runtime/pprof" "runtime/trace" + "strings" + "time" "gvisor.dev/gvisor/pkg/log" "gvisor.dev/gvisor/pkg/sentry/control" + "gvisor.dev/gvisor/runsc/config" "gvisor.dev/gvisor/runsc/flag" ) @@ -177,3 +181,26 @@ func Start(opts Opts) func() { return stopProfiling } + +// UpdatePaths updates profiling-related file paths in the given config. +func UpdatePaths(conf *config.Config, timestamp time.Time) { + if !conf.ProfileEnable { + return + } + conf.ProfileCPU = updatePath(conf.ProfileCPU, timestamp) + conf.ProfileHeap = updatePath(conf.ProfileHeap, timestamp) + conf.ProfileMutex = updatePath(conf.ProfileMutex, timestamp) + conf.ProfileBlock = updatePath(conf.ProfileBlock, timestamp) +} + +func updatePath(path string, now time.Time) string { + path = strings.ReplaceAll(path, "%TIMESTAMP%", fmt.Sprintf("%d", now.Unix())) + path = strings.ReplaceAll(path, "%YYYY%", now.Format("2006")) + path = strings.ReplaceAll(path, "%MM%", now.Format("01")) + path = strings.ReplaceAll(path, "%DD%", now.Format("02")) + path = strings.ReplaceAll(path, "%HH%", now.Format("15")) + path = strings.ReplaceAll(path, "%II%", now.Format("04")) + path = strings.ReplaceAll(path, "%SS%", now.Format("05")) + path = strings.ReplaceAll(path, "%NN%", fmt.Sprintf("%09d", now.Nanosecond())) + return path +} diff --git a/runsc/sandbox/BUILD b/runsc/sandbox/BUILD index 8a76fa2da..83ba8ba60 100644 --- a/runsc/sandbox/BUILD +++ b/runsc/sandbox/BUILD @@ -48,8 +48,10 @@ go_library( "//runsc/config", "//runsc/console", "//runsc/donation", + "//runsc/profile", "//runsc/sandbox/bpf", "//runsc/specutils", + "//runsc/starttime", "//tools/xdp/cmd", "@com_github_cenkalti_backoff//:go_default_library", "@com_github_cilium_ebpf//:go_default_library", diff --git a/runsc/sandbox/sandbox.go b/runsc/sandbox/sandbox.go index 0724ad338..76e582319 100644 --- a/runsc/sandbox/sandbox.go +++ b/runsc/sandbox/sandbox.go @@ -60,7 +60,9 @@ import ( "gvisor.dev/gvisor/runsc/config" "gvisor.dev/gvisor/runsc/console" "gvisor.dev/gvisor/runsc/donation" + "gvisor.dev/gvisor/runsc/profile" "gvisor.dev/gvisor/runsc/specutils" + "gvisor.dev/gvisor/runsc/starttime" ) const ( @@ -188,6 +190,9 @@ type Sandbox struct { // to the entire pod. MountHints *boot.PodMountHints `json:"mountHints"` + // StartTime is the time the sandbox was started. + StartTime time.Time `json:"startTime"` + // child is set if a sandbox process is a child of the current process. // // This field isn't saved to json, because only a creator of sandbox @@ -285,6 +290,7 @@ func New(conf *config.Config, args *Args) (*Sandbox, error) { MetricMetadata: conf.MetricMetadata(), MetricServerAddress: conf.MetricServer, MountHints: args.MountHints, + StartTime: starttime.Get(), } if args.Spec != nil && args.Spec.Annotations != nil { s.PodName = args.Spec.Annotations[podNameAnnotation] @@ -763,11 +769,11 @@ func (s *Sandbox) createSandboxProcess(conf *config.Config, args *Args, startSyn } } if specutils.IsDebugCommand(conf, "boot") { - if err := donations.DonateDebugLogFile("debug-log-fd", conf.DebugLog, "boot", test); err != nil { + if err := donations.DonateDebugLogFile("debug-log-fd", conf.DebugLog, "boot", test, s.StartTime); err != nil { return err } } - if err := donations.DonateDebugLogFile("panic-log-fd", conf.PanicLog, "panic", test); err != nil { + if err := donations.DonateDebugLogFile("panic-log-fd", conf.PanicLog, "panic", test, s.StartTime); err != nil { return err } covFilename := conf.CoverageReport @@ -775,7 +781,7 @@ func (s *Sandbox) createSandboxProcess(conf *config.Config, args *Args, startSyn covFilename = os.Getenv("GO_COVERAGE_FILE") } if covFilename != "" && coverage.Available() { - if err := donations.DonateDebugLogFile("coverage-fd", covFilename, "cov", test); err != nil { + if err := donations.DonateDebugLogFile("coverage-fd", covFilename, "cov", test, s.StartTime); err != nil { return err } } @@ -817,6 +823,7 @@ func (s *Sandbox) createSandboxProcess(conf *config.Config, args *Args, startSyn return err } const profFlags = os.O_CREATE | os.O_WRONLY | os.O_TRUNC + profile.UpdatePaths(conf, s.StartTime) if err := donations.OpenAndDonate("profile-block-fd", conf.ProfileBlock, profFlags); err != nil { return err } @@ -1095,7 +1102,7 @@ func (s *Sandbox) createSandboxProcess(conf *config.Config, args *Args, startSyn donations.Donate("profiling-metrics-fd", stdios[1]) cmd.Args = append(cmd.Args, "--profiling-metrics-fd-lossy=true") } else if conf.ProfilingMetricsLog != "" { - if err := donations.DonateDebugLogFile("profiling-metrics-fd", conf.ProfilingMetricsLog, "metrics", test); err != nil { + if err := donations.DonateDebugLogFile("profiling-metrics-fd", conf.ProfilingMetricsLog, "metrics", test, s.StartTime); err != nil { return err } cmd.Args = append(cmd.Args, "--profiling-metrics-fd-lossy=false") diff --git a/runsc/specutils/specutils.go b/runsc/specutils/specutils.go index 0503e2258..e6373e8c9 100644 --- a/runsc/specutils/specutils.go +++ b/runsc/specutils/specutils.go @@ -528,12 +528,12 @@ func WaitForReady(pid int, timeout time.Duration, ready func() (bool, error)) er // // - %COMMAND%: is replaced with 'command' // - %TEST%: is replaced with 'test' (omitted by default) -func DebugLogFile(logPattern, command, test string) (*os.File, error) { +func DebugLogFile(logPattern, command, test string, timestamp time.Time) (*os.File, error) { if strings.HasSuffix(logPattern, "/") { // Default format: /runsc.log...txt logPattern += "runsc.log.%TIMESTAMP%.%COMMAND%.txt" } - logPattern = strings.Replace(logPattern, "%TIMESTAMP%", time.Now().Format("20060102-150405.000000"), -1) + logPattern = strings.Replace(logPattern, "%TIMESTAMP%", timestamp.Format("20060102-150405.000000"), -1) logPattern = strings.Replace(logPattern, "%COMMAND%", command, -1) logPattern = strings.Replace(logPattern, "%TEST%", test, -1) diff --git a/runsc/starttime/BUILD b/runsc/starttime/BUILD new file mode 100644 index 000000000..1b86ab3b0 --- /dev/null +++ b/runsc/starttime/BUILD @@ -0,0 +1,14 @@ +load("//tools:defs.bzl", "go_library") + +package( + default_applicable_licenses = ["//:license"], + licenses = ["notice"], +) + +go_library( + name = "starttime", + srcs = [ + "starttime.go", + ], + visibility = ["//runsc:__subpackages__"], +) diff --git a/runsc/starttime/starttime.go b/runsc/starttime/starttime.go new file mode 100644 index 000000000..62a91019f --- /dev/null +++ b/runsc/starttime/starttime.go @@ -0,0 +1,35 @@ +// 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 starttime holds the time the `runsc` command started. +// It is useful in order to plumb this time wherever needed. +package starttime + +import ( + "sync" + "time" +) + +var ( + setOnce sync.Once + startTime time.Time +) + +// Get returns the time the `runsc` command started. +func Get() time.Time { + setOnce.Do(func() { + startTime = time.Now() + }) + return startTime +}