1*760c253cSXin Li// Copyright 2019 The ChromiumOS Authors 2*760c253cSXin Li// Use of this source code is governed by a BSD-style license that can be 3*760c253cSXin Li// found in the LICENSE file. 4*760c253cSXin Li 5*760c253cSXin Lipackage main 6*760c253cSXin Li 7*760c253cSXin Liimport ( 8*760c253cSXin Li "encoding/json" 9*760c253cSXin Li "fmt" 10*760c253cSXin Li "os" 11*760c253cSXin Li "path/filepath" 12*760c253cSXin Li "syscall" 13*760c253cSXin Li "time" 14*760c253cSXin Li) 15*760c253cSXin Li 16*760c253cSXin Lifunc getRusageLogFilename(env env) string { 17*760c253cSXin Li value, _ := env.getenv("TOOLCHAIN_RUSAGE_OUTPUT") 18*760c253cSXin Li return value 19*760c253cSXin Li} 20*760c253cSXin Li 21*760c253cSXin Lifunc isRusageEnabled(env env) bool { 22*760c253cSXin Li return getRusageLogFilename(env) != "" 23*760c253cSXin Li} 24*760c253cSXin Li 25*760c253cSXin Lifunc lockFileExclusive(fd uintptr) error { 26*760c253cSXin Li maxTries := 100 27*760c253cSXin Li for i := 0; i < maxTries; i++ { 28*760c253cSXin Li const seekSet = 0 29*760c253cSXin Li err := syscall.FcntlFlock(fd, syscall.F_SETLKW, &syscall.Flock_t{ 30*760c253cSXin Li Type: syscall.F_WRLCK, 31*760c253cSXin Li Whence: seekSet, 32*760c253cSXin Li Start: 0, 33*760c253cSXin Li Len: 0, 34*760c253cSXin Li }) 35*760c253cSXin Li if err == nil { 36*760c253cSXin Li return nil 37*760c253cSXin Li } 38*760c253cSXin Li if err != syscall.EINTR { 39*760c253cSXin Li return fmt.Errorf("locking file: %v", err) 40*760c253cSXin Li } 41*760c253cSXin Li } 42*760c253cSXin Li return fmt.Errorf("locking file failed after %d tries", maxTries) 43*760c253cSXin Li} 44*760c253cSXin Li 45*760c253cSXin Litype rusageLog struct { 46*760c253cSXin Li ExitCode int `json:"exit_code"` 47*760c253cSXin Li ElapsedRealTime float64 `json:"elapsed_real_time"` 48*760c253cSXin Li ElapsedUserTime float64 `json:"elapsed_user_time"` 49*760c253cSXin Li ElapsedSysTime float64 `json:"elapsed_sys_time"` 50*760c253cSXin Li MaxMemUsed int64 `json:"max_mem_used"` 51*760c253cSXin Li Compiler string `json:"compiler"` 52*760c253cSXin Li CompilerArgs []string `json:"compiler_args"` 53*760c253cSXin Li WorkingDirectory string `json:"working_directory"` 54*760c253cSXin Li} 55*760c253cSXin Li 56*760c253cSXin Lifunc removeRusageFromCommand(compilerCmd *command) *command { 57*760c253cSXin Li return &command{ 58*760c253cSXin Li Path: compilerCmd.Path, 59*760c253cSXin Li Args: compilerCmd.Args, 60*760c253cSXin Li EnvUpdates: append(compilerCmd.EnvUpdates, "TOOLCHAIN_RUSAGE_OUTPUT="), 61*760c253cSXin Li } 62*760c253cSXin Li} 63*760c253cSXin Li 64*760c253cSXin Li// maybeCaptureRusage captures rusage for execution of action() 65*760c253cSXin Li// unless action returns an error or logFileName is "" 66*760c253cSXin Li// a function is returned which saves the rusage log data at logFileName unless logFileName is "" 67*760c253cSXin Li// an error is returned if action returns an error, or rusage commands in syscall fails 68*760c253cSXin Lifunc maybeCaptureRusage(env env, compilerCmd *command, action func(willLogRusage bool) error) (maybeCommitToFile func(exitCode int) error, err error) { 69*760c253cSXin Li logFileName := getRusageLogFilename(env) 70*760c253cSXin Li willLogRusage := isRusageEnabled(env) 71*760c253cSXin Li if !willLogRusage { 72*760c253cSXin Li if err := action(willLogRusage); err != nil { 73*760c253cSXin Li return nil, err 74*760c253cSXin Li } 75*760c253cSXin Li return func(int) error { return nil }, nil 76*760c253cSXin Li } 77*760c253cSXin Li 78*760c253cSXin Li rusageBefore := syscall.Rusage{} 79*760c253cSXin Li if err := syscall.Getrusage(syscall.RUSAGE_CHILDREN, &rusageBefore); err != nil { 80*760c253cSXin Li return nil, fmt.Errorf("getting initial rusage: %v", err) 81*760c253cSXin Li } 82*760c253cSXin Li startTime := time.Now() 83*760c253cSXin Li 84*760c253cSXin Li if err := action(willLogRusage); err != nil { 85*760c253cSXin Li return nil, err 86*760c253cSXin Li } 87*760c253cSXin Li 88*760c253cSXin Li elapsedRealTime := time.Since(startTime) 89*760c253cSXin Li rusageAfter := syscall.Rusage{} 90*760c253cSXin Li if err := syscall.Getrusage(syscall.RUSAGE_CHILDREN, &rusageAfter); err != nil { 91*760c253cSXin Li return nil, fmt.Errorf("getting final rusage: %v", err) 92*760c253cSXin Li } 93*760c253cSXin Li 94*760c253cSXin Li return func(exitCode int) error { 95*760c253cSXin Li elapsedSysTime := time.Duration(rusageAfter.Stime.Nano()-rusageBefore.Stime.Nano()) * time.Nanosecond 96*760c253cSXin Li elapsedUserTime := time.Duration(rusageAfter.Utime.Nano()-rusageBefore.Utime.Nano()) * time.Nanosecond 97*760c253cSXin Li // Note: We assume that the compiler takes more heap than any other 98*760c253cSXin Li // subcommands that we might have executed before. 99*760c253cSXin Li maxMemUsed := rusageAfter.Maxrss 100*760c253cSXin Li absCompilerPath := getAbsCmdPath(env, compilerCmd) 101*760c253cSXin Li 102*760c253cSXin Li // We need to temporarily set umask to 0 to ensure 777 permissions are actually 777 103*760c253cSXin Li // This effects builderbots in particular 104*760c253cSXin Li oldMask := env.umask(0) 105*760c253cSXin Li defer env.umask(oldMask) 106*760c253cSXin Li 107*760c253cSXin Li // We want to know what package is being compiled. The working directory gives us a good clue. 108*760c253cSXin Li cwd, err := os.Getwd() 109*760c253cSXin Li if err != nil { 110*760c253cSXin Li return wrapErrorwithSourceLocf(err, "error getting working directory for rusage log") 111*760c253cSXin Li } 112*760c253cSXin Li 113*760c253cSXin Li if err := os.MkdirAll(filepath.Dir(logFileName), 0777); err != nil { 114*760c253cSXin Li return wrapErrorwithSourceLocf(err, "error creating rusage log directory %s", logFileName) 115*760c253cSXin Li } 116*760c253cSXin Li 117*760c253cSXin Li timeUnit := float64(time.Second) 118*760c253cSXin Li 119*760c253cSXin Li logEntry := rusageLog{ 120*760c253cSXin Li ExitCode: exitCode, 121*760c253cSXin Li ElapsedRealTime: float64(elapsedRealTime) / timeUnit, 122*760c253cSXin Li ElapsedUserTime: float64(elapsedUserTime) / timeUnit, 123*760c253cSXin Li ElapsedSysTime: float64(elapsedSysTime) / timeUnit, 124*760c253cSXin Li MaxMemUsed: maxMemUsed, 125*760c253cSXin Li Compiler: absCompilerPath, 126*760c253cSXin Li CompilerArgs: compilerCmd.Args, 127*760c253cSXin Li WorkingDirectory: cwd, 128*760c253cSXin Li } 129*760c253cSXin Li 130*760c253cSXin Li // Note: using file mode 0666 so that a root-created log is writable by others. 131*760c253cSXin Li logFile, err := os.OpenFile(logFileName, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0666) 132*760c253cSXin Li if err != nil { 133*760c253cSXin Li return wrapErrorwithSourceLocf(err, "creating rusage logfile %s", logFileName) 134*760c253cSXin Li } 135*760c253cSXin Li 136*760c253cSXin Li // O_APPEND's atomicity guarantees are only for writes up to a certain size. If we don't 137*760c253cSXin Li // lock the file, we might end up with corrupted records. 138*760c253cSXin Li // 139*760c253cSXin Li // Note that Close()'ing the file releases all associated locks. 140*760c253cSXin Li if err := lockFileExclusive(logFile.Fd()); err != nil { 141*760c253cSXin Li _ = logFile.Close() 142*760c253cSXin Li return wrapErrorwithSourceLocf(err, "locking rusage logfile %s: %v", logFileName, err) 143*760c253cSXin Li } 144*760c253cSXin Li 145*760c253cSXin Li if err := json.NewEncoder(logFile).Encode(logEntry); err != nil { 146*760c253cSXin Li _ = logFile.Close() 147*760c253cSXin Li return wrapErrorwithSourceLocf(err, "converting rusage logfile entry to JSON %v", logEntry) 148*760c253cSXin Li } 149*760c253cSXin Li 150*760c253cSXin Li closeErr := logFile.Close() 151*760c253cSXin Li if err != nil { 152*760c253cSXin Li return wrapErrorwithSourceLocf(err, "writing to rusage logfile %s: %v", logFileName, err) 153*760c253cSXin Li } 154*760c253cSXin Li if closeErr != nil { 155*760c253cSXin Li return wrapErrorwithSourceLocf(err, "closing rusage logfile %s: %v", logFileName, closeErr) 156*760c253cSXin Li } 157*760c253cSXin Li 158*760c253cSXin Li return nil 159*760c253cSXin Li }, nil 160*760c253cSXin Li} 161