diff options
Diffstat (limited to 'compiler_wrapper/rusage_flag.go')
| -rw-r--r-- | compiler_wrapper/rusage_flag.go | 158 |
1 files changed, 107 insertions, 51 deletions
diff --git a/compiler_wrapper/rusage_flag.go b/compiler_wrapper/rusage_flag.go index 690308b2..63469602 100644 --- a/compiler_wrapper/rusage_flag.go +++ b/compiler_wrapper/rusage_flag.go @@ -5,19 +5,23 @@ package main import ( + "encoding/json" "fmt" "os" "path/filepath" - "strings" "syscall" "time" ) func getRusageLogFilename(env env) string { - value, _ := env.getenv("GETRUSAGE") + value, _ := env.getenv("TOOLCHAIN_RUSAGE_OUTPUT") return value } +func isRusageEnabled(env env) bool { + return getRusageLogFilename(env) != "" +} + func lockFileExclusive(fd uintptr) error { maxTries := 100 for i := 0; i < maxTries; i++ { @@ -38,67 +42,119 @@ func lockFileExclusive(fd uintptr) error { return fmt.Errorf("locking file failed after %d tries", maxTries) } -func logRusage(env env, logFileName string, compilerCmd *command) (exitCode int, err error) { - rusageBefore := syscall.Rusage{} - if err := syscall.Getrusage(syscall.RUSAGE_CHILDREN, &rusageBefore); err != nil { - return 0, err - } - compilerCmdWithoutRusage := &command{ +type rusageLog struct { + ExitCode int `json:"exit_code"` + ElapsedRealTime float64 `json:"elapsed_real_time"` + ElapsedUserTime float64 `json:"elapsed_user_time"` + ElapsedSysTime float64 `json:"elapsed_sys_time"` + MaxMemUsed int64 `json:"max_mem_used"` + Compiler string `json:"compiler"` + CompilerArgs []string `json:"compiler_args"` + WorkingDirectory string `json:"working_directory"` +} + +func removeRusageFromCommand(compilerCmd *command) *command { + return &command{ Path: compilerCmd.Path, Args: compilerCmd.Args, - EnvUpdates: append(compilerCmd.EnvUpdates, "GETRUSAGE="), + EnvUpdates: append(compilerCmd.EnvUpdates, "TOOLCHAIN_RUSAGE_OUTPUT="), + } +} + +// maybeCaptureRusage captures rusage for execution of action() +// unless action returns an error or logFileName is "" +// a function is returned which saves the rusage log data at logFileName unless logFileName is "" +// an error is returned if action returns an error, or rusage commands in syscall fails +func maybeCaptureRusage(env env, compilerCmd *command, action func(willLogRusage bool) error) (maybeCommitToFile func(exitCode int) error, err error) { + logFileName := getRusageLogFilename(env) + willLogRusage := isRusageEnabled(env) + if !willLogRusage { + if err := action(willLogRusage); err != nil { + return nil, err + } + return func(int) error { return nil }, nil + } + + rusageBefore := syscall.Rusage{} + if err := syscall.Getrusage(syscall.RUSAGE_CHILDREN, &rusageBefore); err != nil { + return nil, fmt.Errorf("getting initial rusage: %v", err) } startTime := time.Now() - exitCode, err = wrapSubprocessErrorWithSourceLoc(compilerCmdWithoutRusage, - env.run(compilerCmdWithoutRusage, env.stdin(), env.stdout(), env.stderr())) - if err != nil { - return 0, err + + if err := action(willLogRusage); err != nil { + return nil, err } + elapsedRealTime := time.Since(startTime) rusageAfter := syscall.Rusage{} if err := syscall.Getrusage(syscall.RUSAGE_CHILDREN, &rusageAfter); err != nil { - return 0, err - } - elapsedSysTime := time.Duration(rusageAfter.Stime.Nano()-rusageBefore.Stime.Nano()) * time.Nanosecond - elapsedUserTime := time.Duration(rusageAfter.Utime.Nano()-rusageBefore.Utime.Nano()) * time.Nanosecond - // Note: We assume that the compiler takes more heap than any other - // subcommands that we might have executed before. - maxMemUsed := rusageAfter.Maxrss - absCompilerPath := getAbsCmdPath(env, compilerCmd) - - if err := os.MkdirAll(filepath.Dir(logFileName), 0777); err != nil { - return 0, wrapErrorwithSourceLocf(err, "error creating rusage log directory %s", logFileName) + return nil, fmt.Errorf("getting final rusage: %v", err) } - timeUnit := float64(time.Second) - data := fmt.Sprintf("%.5f : %.5f : %.5f : %d : %s : %s\n", - float64(elapsedRealTime)/timeUnit, float64(elapsedUserTime)/timeUnit, float64(elapsedSysTime)/timeUnit, - maxMemUsed, absCompilerPath, - strings.Join(append([]string{filepath.Base(absCompilerPath)}, compilerCmd.Args...), " ")) + return func(exitCode int) error { + elapsedSysTime := time.Duration(rusageAfter.Stime.Nano()-rusageBefore.Stime.Nano()) * time.Nanosecond + elapsedUserTime := time.Duration(rusageAfter.Utime.Nano()-rusageBefore.Utime.Nano()) * time.Nanosecond + // Note: We assume that the compiler takes more heap than any other + // subcommands that we might have executed before. + maxMemUsed := rusageAfter.Maxrss + absCompilerPath := getAbsCmdPath(env, compilerCmd) - // Note: using file mode 0666 so that a root-created log is writable by others. - logFile, err := os.OpenFile(logFileName, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0666) - if err != nil { - return 0, wrapErrorwithSourceLocf(err, "creating rusage logfile %s", logFileName) - } + // We need to temporarily set umask to 0 to ensure 777 permissions are actually 777 + // This effects builderbots in particular + oldMask := env.umask(0) + defer env.umask(oldMask) - // O_APPEND's atomicity guarantees are only for writes up to a certain size. If we don't - // lock the file, we might end up with corrupted records. - // - // Note that Close()'ing the file releases all associated locks. - if err := lockFileExclusive(logFile.Fd()); err != nil { - _ = logFile.Close() - return 0, wrapErrorwithSourceLocf(err, "locking rusage logfile %s: %v", logFileName, err) - } + // We want to know what package is being compiled. The working directory gives us a good clue. + cwd, err := os.Getwd() + if err != nil { + return wrapErrorwithSourceLocf(err, "error getting working directory for rusage log") + } - _, err = logFile.WriteString(data) - closeErr := logFile.Close() - if err != nil { - return 0, wrapErrorwithSourceLocf(err, "writing to rusage logfile %s: %v", logFileName, err) - } - if closeErr != nil { - return 0, wrapErrorwithSourceLocf(err, "closing rusage logfile %s: %v", logFileName, closeErr) - } + if err := os.MkdirAll(filepath.Dir(logFileName), 0777); err != nil { + return wrapErrorwithSourceLocf(err, "error creating rusage log directory %s", logFileName) + } + + timeUnit := float64(time.Second) + + logEntry := rusageLog{ + ExitCode: exitCode, + ElapsedRealTime: float64(elapsedRealTime) / timeUnit, + ElapsedUserTime: float64(elapsedUserTime) / timeUnit, + ElapsedSysTime: float64(elapsedSysTime) / timeUnit, + MaxMemUsed: maxMemUsed, + Compiler: absCompilerPath, + CompilerArgs: compilerCmd.Args, + WorkingDirectory: cwd, + } + + // Note: using file mode 0666 so that a root-created log is writable by others. + logFile, err := os.OpenFile(logFileName, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0666) + if err != nil { + return wrapErrorwithSourceLocf(err, "creating rusage logfile %s", logFileName) + } + + // O_APPEND's atomicity guarantees are only for writes up to a certain size. If we don't + // lock the file, we might end up with corrupted records. + // + // Note that Close()'ing the file releases all associated locks. + if err := lockFileExclusive(logFile.Fd()); err != nil { + _ = logFile.Close() + return wrapErrorwithSourceLocf(err, "locking rusage logfile %s: %v", logFileName, err) + } + + if err := json.NewEncoder(logFile).Encode(logEntry); err != nil { + _ = logFile.Close() + return wrapErrorwithSourceLocf(err, "converting rusage logfile entry to JSON %v", logEntry) + } + + closeErr := logFile.Close() + if err != nil { + return wrapErrorwithSourceLocf(err, "writing to rusage logfile %s: %v", logFileName, err) + } + if closeErr != nil { + return wrapErrorwithSourceLocf(err, "closing rusage logfile %s: %v", logFileName, closeErr) + } - return exitCode, nil + return nil + }, nil } |