auth_perf.go

// Copyright 2019 The Chromium OS Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

package arc

import (
	"context"
	"encoding/json"
	"fmt"
	"math"
	"os"
	"path/filepath"
	"regexp"
	"sort"
	"strconv"
	"strings"
	"time"

	"chromiumos/tast/common/perf"
	"chromiumos/tast/common/testexec"
	"chromiumos/tast/errors"
	"chromiumos/tast/local/arc"
	"chromiumos/tast/local/arc/optin"
	"chromiumos/tast/local/chrome"
	"chromiumos/tast/local/cpu"
	"chromiumos/tast/local/disk"
	"chromiumos/tast/local/power"
	"chromiumos/tast/lsbrelease"
	"chromiumos/tast/testing"
)

type testParam struct {
	username string
	password string
	// maxErrorBootCount is the number of maximum allowed boot errors.
	maxErrorBootCount int
	chromeArgs        []string
	dropCaches        bool
	oDirect           bool
}

var resultPropRegexp = regexp.MustCompile(`OK,(\d+)`)

func init() {
	testing.AddTest(&testing.Test{
		Func:         AuthPerf,
		LacrosStatus: testing.LacrosVariantNeeded,
		Desc:         "Measure auth times in ARC",
		Contacts: []string{
			"khmel@chromium.org", // Original author.
			"niwa@chromium.org",  // Tast port author.
			"arc-performance@google.com",
		},
		Attr:         []string{"group:crosbolt", "crosbolt_perbuild"},
		SoftwareDeps: []string{"chrome", "chrome_internal"},
		// This test steps through opt-in flow 10 times and each iteration takes 20~40 seconds.
		Timeout: 20 * time.Minute,
		Params: []testing.Param{{
			Name:              "managed",
			ExtraSoftwareDeps: []string{"android_p"},
			Val: testParam{
				username:          "arc.AuthPerf.managed_username",
				password:          "arc.AuthPerf.managed_password",
				maxErrorBootCount: 1,
			},
		}, {
			Name:              "managed_vm",
			ExtraSoftwareDeps: []string{"android_vm"},
			Val: testParam{
				username:          "arc.AuthPerf.managed_username",
				password:          "arc.AuthPerf.managed_password",
				maxErrorBootCount: 3,
			},
		}, {
			Name:              "unmanaged",
			ExtraSoftwareDeps: []string{"android_p"},
			Val: testParam{
				maxErrorBootCount: 1,
			},
		}, {
			Name:              "unmanaged_o_direct_vm",
			ExtraSoftwareDeps: []string{"android_vm"},
			Val: testParam{
				dropCaches:        true,
				maxErrorBootCount: 3,
				oDirect:           true,
			},
		}, {
			Name:              "unmanaged_rt_vcpu_vm",
			ExtraSoftwareDeps: []string{"android_vm"},
			Val: testParam{
				maxErrorBootCount: 3,
				chromeArgs:        []string{"--enable-features=ArcRtVcpuDualCore,ArcRtVcpuQuadCore"},
			},
		}, {
			Name:              "unmanaged_dalvik_memory_profile_vm",
			ExtraSoftwareDeps: []string{"android_vm"},
			Val: testParam{
				maxErrorBootCount: 3,
				chromeArgs:        []string{"--enable-features=ArcUseDalvikMemoryProfile"},
			},
		}, {
			Name:              "unmanaged_virtio_blk_vm",
			ExtraSoftwareDeps: []string{"android_vm"},
			Val: testParam{
				maxErrorBootCount: 3,
				chromeArgs:        []string{"--enable-features=ArcEnableVirtioBlkForData"},
			},
		}, {
			Name:              "unmanaged_vm",
			ExtraSoftwareDeps: []string{"android_vm"},
			Val: testParam{
				maxErrorBootCount: 3,
			},
		}},
		VarDeps: []string{
			"arc.AuthPerf.managed_username",
			"arc.AuthPerf.managed_password",
			"arc.perfAccountPool",
		},
	})
}

// measuredValues stores measured times in milliseconds.
type measuredValues struct {
	playStoreShownTime float64
	accountCheckTime   float64
	checkinTime        float64
	networkWaitTime    float64
	signInTime         float64
	bootTime           float64
	energyUsage        *power.RAPLValues
}

// createChrome creates Chrome session used to perform ARC opt-ins. Normally it is created only
// once per test run. However, if error is found, Chrome session is recreated.
func createChrome(ctx context.Context, gaia chrome.Option, param testParam) (*chrome.Chrome, *chrome.TestConn, error) {
	args := append(arc.DisableSyncFlags(), "--arc-force-show-optin-ui")
	if param.chromeArgs != nil {
		args = append(args, param.chromeArgs...)
	}

	cr, err := chrome.New(ctx,
		chrome.ARCSupported(),
		chrome.RestrictARCCPU(),
		gaia,
		chrome.ExtraArgs(args...))
	if err != nil {
		return nil, nil, err
	}

	tconn, err := cr.TestAPIConn(ctx)
	if err != nil {
		cr.Close(ctx)
		return nil, nil, err
	}

	return cr, tconn, nil
}

// AuthPerf steps through multiple opt-ins and collects checkin time, network wait time,
// sign-in time and Play Store shown time.
// It also reports average, min and max results.
func AuthPerf(ctx context.Context, s *testing.State) {
	const (
		// successBootCount is the number of passing ARC boots to collect results.
		successBootCount = 7
	)

	param := s.Param().(testParam)
	maxErrorBootCount := param.maxErrorBootCount

	var gaia chrome.Option
	if param.username != "" {
		gaia = chrome.GAIALogin(chrome.Creds{User: s.RequiredVar(param.username), Pass: s.RequiredVar(param.password)})
	} else {
		gaia = chrome.GAIALoginPool(s.RequiredVar("arc.perfAccountPool"))
	}

	cr, tconn, err := createChrome(ctx, gaia, param)
	if err != nil {
		s.Fatal("Failed to connect to Chrome: ", err)
	}
	defer func() {
		cr.Close(ctx)
	}()

	errorCount := 0
	var playStoreShownTimes []float64
	var accountCheckTimes []float64
	var checkinTimes []float64
	var networkWaitTimes []float64
	var signInTimes []float64
	var bootTimes []float64
	var energyUsage []*power.RAPLValues

	for len(playStoreShownTimes) < successBootCount {
		s.Logf("Running ARC opt-in iteration #%d out of %d",
			len(playStoreShownTimes)+1, successBootCount)

		v, err := bootARC(ctx, s, cr, tconn)
		logcatName := ""
		if err == nil {
			// Append Play Store shown time in ms for quick reference.
			logcatName = fmt.Sprintf("logcat_ok_%d.log", int(v.playStoreShownTime))
		} else {
			logcatName = fmt.Sprintf("logcat_error_%d.log", errorCount)
		}
		logcatFilePath := filepath.Join(s.OutDir(), logcatName)
		if err := dumpLogcat(ctx, s, logcatFilePath); err != nil {
			s.Log("Failed to dump logcat: ", err)
		}
		if err != nil {
			errorCount++
			s.Logf("Error found during the ARC boot: %v - logcat was dumped to %s",
				err, logcatFilePath)

			if errorCount > maxErrorBootCount {
				s.Fatalf("Too many ARC boot errors (%d time(s)), last error: %q", errorCount, err)
			}

			cr.Close(ctx)
			cr, tconn, err = createChrome(ctx, gaia, param)
			if err != nil {
				s.Fatal("Failed to re-connect to Chrome: ", err)
			}
			defer cr.Close(ctx)

			continue
		}

		playStoreShownTimes = append(playStoreShownTimes, v.playStoreShownTime)
		accountCheckTimes = append(accountCheckTimes, v.accountCheckTime)
		checkinTimes = append(checkinTimes, v.checkinTime)
		networkWaitTimes = append(networkWaitTimes, v.networkWaitTime)
		signInTimes = append(signInTimes, v.signInTime)
		bootTimes = append(bootTimes, v.bootTime)
		if v.energyUsage != nil {
			energyUsage = append(energyUsage, v.energyUsage)
		}
	}

	perfValues := perf.NewValues()

	// Array for generating comma separated results.
	var resultForLog []string

	version, err := chromeOSVersion()
	if err != nil {
		s.Fatal("Can't get ChromeOS version: ", err)
	}
	resultForLog = append(resultForLog, version, strconv.Itoa(len(playStoreShownTimes)))

	reportResult := func(name string, samples []float64) {
		for _, x := range samples {
			perfValues.Append(perf.Metric{
				Name:      name,
				Unit:      "milliseconds",
				Direction: perf.SmallerIsBetter,
				Multiple:  true,
			}, x)
		}

		var sum float64
		var max float64
		min := math.MaxFloat64
		for _, x := range samples {
			sum += x
			max = math.Max(x, max)
			min = math.Min(x, min)
		}
		samplesLen := len(samples)
		average := sum / float64(samplesLen)

		samplesStr, err := json.Marshal(samples)
		if err != nil {
			s.Log("Failed to marshal slice: ", err)
			samplesStr = []byte("unknown")
		}
		sort.Float64s(samples)
		median := samples[samplesLen/2]
		if samplesLen%2 == 0 {
			median = (median + samples[samplesLen/2-1]) / 2
		}

		s.Logf("%s - average: %d, median: %d, range %d - %d based on %d samples (%s)",
			name, int(average), int(median), int(min), int(max), samplesLen, samplesStr)
		resultForLog = append(resultForLog, strconv.Itoa(int(min)),
			strconv.Itoa(int(average)), strconv.Itoa(int(max)))
	}

	reportResult("play_store_shown_time", playStoreShownTimes)
	reportResult("account_check_time", accountCheckTimes)
	reportResult("checkin_time", checkinTimes)
	reportResult("network_wait_time", networkWaitTimes)
	reportResult("sign_in_time", signInTimes)
	reportResult("boot_time", bootTimes)

	for _, rapl := range energyUsage {
		rapl.ReportPerfMetrics(perfValues, "power_")
	}

	// Outputs comma separated results to the log.
	// It is used in many sheet tables to automate paste operations.
	s.Log(strings.Join(resultForLog, ","))

	if err = perfValues.Save(s.OutDir()); err != nil {
		s.Fatal("Failed saving perf data: ", err)
	}
}

// readResultProp reads the system property set by ARC to save provisioning flow step result.
func readResultProp(ctx context.Context, a *arc.ARC, propName string) (float64, error) {
	out, err := a.Command(ctx, "getprop", propName).Output(testexec.DumpLogOnError)
	if err != nil {
		return 0, errors.Wrapf(err, "failed to get the result property %q", propName)
	}

	outStr := string(out)
	m := resultPropRegexp.FindStringSubmatch(outStr)
	if m == nil {
		return 0, errors.Errorf("Result property %q could not be parsed: %q", propName, outStr)
	}

	return strconv.ParseFloat(m[1], 64)
}

// coolDownConfig returns the config to wait for the machine to cooldown for AuthPerf tests.
// This has higher temperature (46 to 61c) threshold to let pass AMD low-end devices that
// frequently fail due to higher temperatures.
func coolDownConfig() cpu.CoolDownConfig {
	return cpu.CoolDownConfig{
		PollTimeout:          300 * time.Second,
		PollInterval:         2 * time.Second,
		TemperatureThreshold: 61000,
		CoolDownMode:         cpu.CoolDownPreserveUI,
	}
}

// bootARC performs one ARC boot iteration, opt-out and opt-in again.
// It calculates the time when the Play Store appears and set of ARC auth times.
func bootARC(ctx context.Context, s *testing.State, cr *chrome.Chrome, tconn *chrome.TestConn) (measuredValues, error) {
	var v measuredValues

	// Opt out.
	if err := optin.SetPlayStoreEnabled(ctx, tconn, false); err != nil {
		return v, err
	}

	s.Log("Waiting for Android data directory to be removed")
	if err := waitForAndroidDataRemoved(ctx); err != nil {
		return v, err
	}

	s.Log("Waiting for ARC to stop")
	if err := waitForARCStopped(ctx); err != nil {
		return v, err
	}

	// Enable O_DIRECT on ARCVM block device
	if s.Param().(testParam).oDirect {
		if err := arc.WriteArcvmDevConf(ctx, "O_DIRECT=true"); err != nil {
			return v, err
		}
	} else {
		if err := arc.WriteArcvmDevConf(ctx, ""); err != nil {
			return v, err
		}
	}
	defer arc.RestoreArcvmDevConf(ctx)

	// Drop host OS caches if test config requires it for predictable results.
	if s.Param().(testParam).dropCaches {
		if err := disk.DropCaches(ctx); err != nil {
			return v, errors.Wrap(err, "failed to drop caches")
		}
	}

	if err := cpu.WaitUntilStabilized(ctx, coolDownConfig()); err != nil {
		s.Fatal("Failed to wait until CPU is stabilized: ", err)
	}

	energyBefore, err := power.NewRAPLSnapshot()
	if err != nil {
		s.Error("Energy status is not available for this board")
	}

	startTime := time.Now()

	// Opt in. From performance perspective, optin longer than 90 seconds is failure.
	// This also aligned with global 20 minute timeout.
	shorterCtx, cancel := context.WithTimeout(ctx, 90*time.Second)
	defer cancel()

	s.Log("Waiting for ARC opt-in flow to complete")
	if err := optin.Perform(shorterCtx, cr, tconn); err != nil {
		return v, err
	}

	s.Log("Waiting for Play Store window to be shown")
	if err := optin.WaitForPlayStoreShown(shorterCtx, tconn, time.Minute); err != nil {
		return v, err
	}

	v.playStoreShownTime = time.Now().Sub(startTime).Seconds() * 1000

	// energyBefore could be nil (not considered an error) on non-Intel CPUs.
	if energyBefore != nil {
		v.energyUsage, err = energyBefore.DiffWithCurrentRAPL()
		if err != nil {
			s.Fatal("Failed to get RAPL values: ", err)
		}
	}

	a, err := arc.New(ctx, s.OutDir())
	if err != nil {
		return v, errors.Wrap(err, "failed to connect ARC")
	}
	defer a.Close(ctx)

	// Read sign-in results via properties.
	if v.signInTime, err = readResultProp(ctx, a, "dev.arc.accountsignin.result"); err != nil {
		return v, err
	}
	if v.accountCheckTime, err = readResultProp(ctx, a, "dev.arc.accountcheck.result"); err != nil {
		return v, err
	}
	if v.networkWaitTime, err = readResultProp(ctx, a, "dev.arc.networkwait.result"); err != nil {
		return v, err
	}
	if v.checkinTime, err = readResultProp(ctx, a, "dev.arc.accountcheckin.result"); err != nil {
		return v, err
	}

	// Calculate
	//   * kernel boot time as a difference init process started and preStartTime.
	var ret struct {
		Provisioned bool `json:"provisioned"`
		TOSNeeded   bool `json:"tosNeeded"`
		// mini-ARC started
		PreStartTime float64 `json:"preStartTime"`
		// ARC started.
		StartTime float64 `json:"startTime"`
	}

	if err := tconn.Eval(ctx, "tast.promisify(chrome.autotestPrivate.getArcState)()", &ret); err != nil {
		return v, errors.Wrap(err, "failed to run getArcState()")
	}
	if ret.PreStartTime == 0 {
		return v, errors.New("cannot get ARC pre-start time")
	}

	output, err := a.Command(ctx, "stat", "-c", "%z", "/proc/1").Output(testexec.DumpLogOnError)
	if err != nil {
		return v, errors.Wrap(err, "failed to get init process start time")
	}
	timeStr := strings.TrimSpace(string(output))
	testing.ContextLogf(ctx, "ARC pre-start time: %f UNIX ms, and /init proc time %q", ret.PreStartTime, timeStr)
	preStartTimeNS := (int64)(ret.PreStartTime * 1000000.0)
	tPreStart := time.Unix(preStartTimeNS/1000000000, preStartTimeNS%1000000000)
	tInit, err := time.Parse("2006-01-02 15:04:05.999999999 -0700", timeStr)
	if err != nil {
		tInit, err = time.ParseInLocation("2006-01-02 15:04:05.999999999", timeStr, time.Local)
	}
	if err != nil {
		return v, errors.Wrap(err, "failed to parse time")
	}
	v.bootTime = float64(tInit.Sub(tPreStart).Milliseconds())
	return v, nil
}

// waitForAndroidDataRemoved waits for Android data directory to be removed.
func waitForAndroidDataRemoved(ctx context.Context) error {
	const androidDataDirPath = "/opt/google/containers/android/rootfs/android-data/data"

	if err := testing.Poll(ctx, func(ctx context.Context) error {
		if _, err := os.Stat(androidDataDirPath); !os.IsNotExist(err) {
			return errors.New("Android data still exists")
		}
		return nil
	}, &testing.PollOptions{Timeout: 10 * time.Second}); err != nil {
		return errors.Wrap(err, "failed to wait for Android data directory to be removed")
	}
	return nil
}

// waitForARCStopped waits for ARC to stop.
func waitForARCStopped(ctx context.Context) error {
	if err := testing.Poll(ctx, func(ctx context.Context) error {
		if exist, err := arc.InitExists(); err != nil {
			return testing.PollBreak(err)
		} else if exist {
			return errors.New("ARC is not yet stopped")
		}
		return nil
	}, &testing.PollOptions{Timeout: 30 * time.Second}); err != nil {
		return errors.Wrap(err, "failed to wait for ARC to stop")
	}
	return nil
}

// chromeOSVersion returns the Chrome OS version string. (e.g. "12345.0.0")
func chromeOSVersion() (string, error) {
	m, err := lsbrelease.Load()
	if err != nil {
		return "", err
	}
	val, ok := m[lsbrelease.Version]
	if !ok {
		return "", errors.Errorf("failed to find %s in /etc/lsb-release", lsbrelease.Version)
	}
	return val, nil
}

// dumpLogcat dumps logcat output to a log file in the test result directory.
func dumpLogcat(ctx context.Context, s *testing.State, filePath string) error {
	a, err := arc.New(ctx, s.OutDir())
	if err != nil {
		return errors.Wrap(err, "failed to connect ARC")
	}
	defer a.Close(ctx)

	logFile, err := os.Create(filePath)
	if err != nil {
		return errors.Wrap(err, "failed to create log file")
	}
	defer logFile.Close()
	cmd := a.Command(ctx, "logcat", "-d")
	cmd.Stdout = logFile
	cmd.Stderr = logFile
	return cmd.Run()
}