compiler_wrapper: make rusage logs json

Modified rusage logs generated by GETRUSAGE flag.
Output from each entry is now in json format.

BUG=chromium:1156314
TEST=Modified and ran unit tests

Change-Id: Ia2cac4af201854de6d4a2c57e6cd8a4585f0931f
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/third_party/toolchain-utils/+/2585911
Tested-by: Ryan Beltran <ryanbeltran@chromium.org>
Reviewed-by: George Burgess <gbiv@chromium.org>

2 files changed, 36 insertions, 28 deletions

diff --git a/compiler_wrapper/rusage_flag.go b/compiler_wrapper/rusage_flag.go
index 690308b2..e8eb79a7 100644
--- a/compiler_wrapper/rusage_flag.go
+++ b/compiler_wrapper/rusage_flag.go
@@ -5,10 +5,10 @@
 package main
 
 import (
+	"encoding/json"
 	"fmt"
 	"os"
 	"path/filepath"
-	"strings"
 	"syscall"
 	"time"
 )
@@ -38,6 +38,16 @@ func lockFileExclusive(fd uintptr) error {
 	return fmt.Errorf("locking file failed after %d tries", maxTries)
 }
 
+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"`
+}
+
 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 {
@@ -71,10 +81,16 @@ func logRusage(env env, logFileName string, compilerCmd *command) (exitCode int,
 	}
 
 	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...), " "))
+
+	logEntry := rusageLog{
+		ExitCode:        exitCode,
+		ElapsedRealTime: float64(elapsedRealTime) / timeUnit,
+		ElapsedUserTime: float64(elapsedUserTime) / timeUnit,
+		ElapsedSysTime:  float64(elapsedSysTime) / timeUnit,
+		MaxMemUsed:      maxMemUsed,
+		Compiler:        absCompilerPath,
+		CompilerArgs:    compilerCmd.Args,
+	}
 
 	// 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)
@@ -91,7 +107,11 @@ func logRusage(env env, logFileName string, compilerCmd *command) (exitCode int,
 		return 0, wrapErrorwithSourceLocf(err, "locking rusage logfile %s: %v", logFileName, err)
 	}
 
-	_, err = logFile.WriteString(data)
+	if err := json.NewEncoder(logFile).Encode(logEntry); err != nil {
+		_ = logFile.Close()
+		return 0, wrapErrorwithSourceLocf(err, "converting rusage logfile entry to JSON %v", logEntry)
+	}
+
 	closeErr := logFile.Close()
 	if err != nil {
 		return 0, wrapErrorwithSourceLocf(err, "writing to rusage logfile %s: %v", logFileName, err)
diff --git a/compiler_wrapper/rusage_flag_test.go b/compiler_wrapper/rusage_flag_test.go
index bd0f980c..408bdb6c 100644
--- a/compiler_wrapper/rusage_flag_test.go
+++ b/compiler_wrapper/rusage_flag_test.go
@@ -5,6 +5,7 @@
 package main
 
 import (
+	"encoding/json"
 	"errors"
 	"fmt"
 	"io"
@@ -12,7 +13,6 @@ import (
 	"os"
 	"path/filepath"
 	"regexp"
-	"strconv"
 	"strings"
 	"testing"
 )
@@ -92,30 +92,18 @@ func TestLogRusageFileContent(t *testing.T) {
 		if err != nil {
 			t.Errorf("could not read the rusage log file. Error: %s", err)
 		}
-		// Example output:
-		// 0.100318 : 0.103412 : 0.096386 : 6508 : /tmp/compiler_wrapper036306868/x86_64-cros-linux-gnu-gcc.real : x86_64-cros-linux-gnu-gcc.real --sysroot=/tmp/compiler_wrapper036306868/usr/x86_64-cros-linux-gnu main.cc -mno-movbe
-		logParts := strings.Split(string(data), " : ")
-		if len(logParts) != 6 {
-			t.Errorf("unexpected number of rusage log parts. Got: %s", logParts)
-		}
 
-		// First 3 numbers are times in seconds.
-		for i := 0; i < 3; i++ {
-			if _, err := strconv.ParseFloat(logParts[i], 64); err != nil {
-				t.Errorf("unexpected value for index %d. Got: %s", i, logParts[i])
-			}
-		}
-		// Then an int for the memory usage
-		if _, err := strconv.ParseInt(logParts[3], 10, 64); err != nil {
-			t.Errorf("unexpected mem usage. Got: %s", logParts[3])
+		rlog := rusageLog{}
+
+		if err := json.Unmarshal(data, &rlog); err != nil {
+			t.Fatalf("rusage log could not be unmarshalled. Got: %s", data)
 		}
-		// Then the full path of the compiler
-		if logParts[4] != filepath.Join(ctx.tempDir, gccX86_64+".real") {
-			t.Errorf("unexpected compiler path. Got: %s", logParts[4])
+
+		if rlog.Compiler != filepath.Join(ctx.tempDir, gccX86_64+".real") {
+			t.Errorf("unexpected compiler path. Got: %s", rlog.Compiler)
 		}
-		// Then the arguments, prefixes with the compiler basename
-		if matched, _ := regexp.MatchString("x86_64-cros-linux-gnu-gcc.real --sysroot=.* main.cc", logParts[5]); !matched {
-			t.Errorf("unexpected compiler args. Got: %s", logParts[5])
+		if matched, _ := regexp.MatchString("--sysroot=.*", rlog.CompilerArgs[0]); !matched {
+			t.Errorf("unexpected compiler args. Got: %s", rlog.CompilerArgs)
 		}
 	})
 }