[QE]monitor cpu usage in e2e test case

Author: lilyLuLiu

test/e2e/features/story_microshift.feature

@@ -7,10 +7,7 @@ Feature: Microshift test stories
 		And setting config property "persistent-volume-size" to value "20" succeeds
 		And ensuring network mode user
 		And executing single crc setup command succeeds
-		And get cpu data "Before start"
-		And get memory data "Before start"
 		And starting CRC with default bundle succeeds
-		And get cpu data "After start"
 		And get memory data "After start"
 		And ensuring oc command is available
 		And ensuring microshift cluster is fully operational
@@ -20,8 +17,9 @@ Feature: Microshift test stories
 
 	# End-to-end health check
 
-	@microshift @testdata @linux @windows @darwin @cleanup
+	@microshift @testdata @linux @windows @darwin @cleanup @performance
 	Scenario: Start and expose a basic HTTP service and check after restart
+		And record timestamp "deployment"
 		Given executing "oc create namespace testproj" succeeds
 		And executing "oc config set-context --current --namespace=testproj" succeeds
 		When executing "oc apply -f httpd-example.yaml" succeeds
@@ -36,13 +34,13 @@ Feature: Microshift test stories
 		When executing "oc expose svc httpd-example" succeeds
 		Then stdout should contain "httpd-example exposed"
 		When with up to "20" retries with wait period of "5s" http response from "http://httpd-example-testproj.apps.crc.testing" has status code "200"
-		And get cpu data "After deployment"
 		And get memory data "After deployment"
 		Then executing "curl -s http://httpd-example-testproj.apps.crc.testing" succeeds
 		And stdout should contain "Hello CRC!"
+		And record timestamp "stop"
 		When executing "crc stop" succeeds
-		And get cpu data "After stop"
 		And get memory data "After stop"
+		And record timestamp "start again"
 		And starting CRC with default bundle succeeds
 		And checking that CRC is running
 		And with up to "4" retries with wait period of "1m" http response from "http://httpd-example-testproj.apps.crc.testing" has status code "200"

test/e2e/features/story_openshift.feature

@@ -9,11 +9,11 @@ Feature: 4 Openshift stories
 
 	# End-to-end health check
 
-	@darwin @linux @windows @testdata @story_health @needs_namespace
+	@darwin @linux @windows @testdata @story_health @needs_namespace @performance
 	Scenario: Overall cluster health
 		Given executing "oc new-project testproj" succeeds
-		And get cpu data "After start"
 		And get memory data "After start"
+		And record timestamp "deployment"
 		When executing "oc apply -f httpd-example.yaml" succeeds
 		And executing "oc rollout status deployment httpd-example" succeeds
 		Then stdout should contain "successfully rolled out"
@@ -25,14 +25,14 @@ Feature: 4 Openshift stories
 		Then stdout should contain "httpd-example exposed"
 		When executing "oc expose svc httpd-example" succeeds
 		Then stdout should contain "httpd-example exposed"
-		And get cpu data "After deployment"
-		And get memory data "After deployment"
 		When with up to "20" retries with wait period of "5s" http response from "http://httpd-example-testproj.apps-crc.testing" has status code "200"
 		Then executing "curl -s http://httpd-example-testproj.apps-crc.testing" succeeds
 		And stdout should contain "Hello CRC!"
+		And get memory data "After deployment"
+		And record timestamp "stop"
 		When executing "crc stop" succeeds
-		And get cpu data "After stop"
 		And get memory data "After stop"
+		And record timestamp "start again"
 		And starting CRC with default bundle succeeds
 		And checking that CRC is running
 		And with up to "4" retries with wait period of "1m" http response from "http://httpd-example-testproj.apps-crc.testing" has status code "200"

test/e2e/testsuite/performance.go

@@ -0,0 +1,112 @@
+package testsuite
+
+import (
+	"context"
+	"fmt"
+	"os"
+	"path/filepath"
+	"sync"
+	"time"
+
+	"github.com/crc-org/crc/v2/test/extended/util"
+	"github.com/shirou/gopsutil/v4/cpu"
+)
+
+type Monitor struct {
+	cancelFunc context.CancelFunc
+	isRunning  bool
+	mu         sync.Mutex
+	wg         sync.WaitGroup
+	interval   time.Duration
+}
+
+func NewMonitor(interval time.Duration) *Monitor {
+	return &Monitor{
+		interval: interval,
+	}
+}
+
+func (m *Monitor) Start() error {
+	m.mu.Lock()
+	defer m.mu.Unlock()
+
+	if m.isRunning {
+		return fmt.Errorf("The collector is running")
+	}
+
+	fmt.Printf("Attempt to start CPU collector, interval: %s\n", m.interval)
+
+	//  create a context.WithCancel
+	ctx, cancel := context.WithCancel(context.Background())
+	m.cancelFunc = cancel
+	m.isRunning = true
+
+	// start goroutine
+	m.wg.Add(1)
+	go m.collectLoop(ctx)
+
+	fmt.Println("CPU collector has been successfully started")
+	return nil
+}
+
+func (m *Monitor) Stop() error {
+	m.mu.Lock()
+	defer m.mu.Unlock()
+
+	if !m.isRunning {
+		return fmt.Errorf("The collector is not running")
+	}
+	if m.cancelFunc != nil {
+		m.cancelFunc()
+	}
+	m.isRunning = false
+	m.wg.Wait()
+	fmt.Println("CPU collector has sent a stop signal")
+	// may need wait a while to stop
+	return nil
+}
+
+func (m *Monitor) collectLoop(ctx context.Context) {
+	defer m.wg.Done()
+
+	fmt.Println("--> collect goroutine start...")
+	calcInterval := m.interval
+
+	// Prime cpu.Percent so the subsequent calls with interval=0 return usage
+	// since this priming call. We discard the returned value.
+	_, _ = cpu.Percent(0, false)
+
+	ticker := time.NewTicker(calcInterval)
+	defer ticker.Stop()
+
+	for {
+		select {
+		case <-ctx.Done():
+			fmt.Println("<-- collect goroutine receive stop signal")
+			return // exit goroutine
+		case <-ticker.C:
+			// cpu.Percent with interval=0 returns percent since the last call.
+			totalPercent, err := cpu.Percent(0, false)
+			if err != nil {
+				fmt.Printf("Error: fail to collect CPU data: %v\n", err)
+				// do not block here; wait for next tick or cancellation
+				continue
+			}
+
+			if len(totalPercent) > 0 {
+				data := fmt.Sprintf("[%s], cpu percent: %.2f%%\n",
+					time.Now().Format("15:04:05"), totalPercent[0])
+				wd, err := os.Getwd()
+				if err != nil {
+					fmt.Printf("Error: failed to get working directory: %v\n", err)
+					continue
+				}
+				file := filepath.Join(wd, "../test-results/cpu-consume.txt")
+				err = util.WriteToFile(data, file)
+				if err != nil {
+					fmt.Printf("Error: fail to write to %s: %v\n", file, err)
+				}
+			}
+		}
+	}
+}

test/e2e/testsuite/testsuite.go

@@ -28,7 +28,6 @@ import (
 	crcCmd "github.com/crc-org/crc/v2/test/extended/crc/cmd"
 	"github.com/crc-org/crc/v2/test/extended/util"
 	"github.com/cucumber/godog"
-	"github.com/shirou/gopsutil/v4/cpu"
 	"github.com/shirou/gopsutil/v4/mem"
 	"github.com/spf13/pflag"
 )
@@ -153,7 +152,7 @@ func InitializeTestSuite(tctx *godog.TestSuiteContext) {
 
 		err := crcCmd.DeleteCRC()
 		if err != nil {
-			fmt.Printf("Could not delete CRC VM: %s.", err)
+			fmt.Printf("Could not delete CRC VM: %s.\n", err)
 		}
 
 		err = util.LogMessage("info", "----- Cleaning Up -----")
@@ -169,6 +168,7 @@ func InitializeTestSuite(tctx *godog.TestSuiteContext) {
 }
 
 func InitializeScenario(s *godog.ScenarioContext) {
+	monitor := NewMonitor(1 * time.Second)
 
 	s.Before(func(ctx context.Context, sc *godog.Scenario) (context.Context, error) {
 
@@ -264,12 +264,17 @@ func InitializeScenario(s *godog.ScenarioContext) {
 				}
 			}
 
-			if tag.Name == "@story_health" {
-				if err := getCPUdata("Before start"); err != nil {
-					fmt.Printf("Failed to collect CPU data: %v\n", err)
+			if tag.Name == "@performance" {
+				if err := monitor.Start(); err != nil {
+					fmt.Printf("Failed to start monitor: %v\n", err)
 				}
-				if err := getMemoryData("Before start"); err != nil {
-					fmt.Printf("Failed to collect memory data: %v\n", err)
+				err := getTimestamp("start")
+				if err != nil {
+					fmt.Printf("Failed to get finish getTimestamp: %v\n", err)
+				}
+				err = getMemoryData("Before start")
+				if err != nil {
+					fmt.Printf("Failed to get memory data: %v\n", err)
 				}
 			}
 		}
@@ -398,6 +403,16 @@ func InitializeScenario(s *godog.ScenarioContext) {
 				}
 			}
 
+			if tag.Name == "@performance" {
+				err := getTimestamp("finish")
+				if err != nil {
+					fmt.Printf("Failed to get finish getTimestamp: %v\n", err)
+				}
+				if err := monitor.Stop(); err != nil {
+					fmt.Printf("Failed to stop monitoring: %v\n", err)
+				}
+				fmt.Printf("Collection has stopped\n")
+			}
 		}
 
 		return ctx, nil
@@ -579,8 +594,8 @@ func InitializeScenario(s *godog.ScenarioContext) {
 		EnsureApplicationIsAccessibleViaNodePort)
 	s.Step(`^persistent volume of size "([^"]*)"GB exists$`,
 		EnsureVMPartitionSizeCorrect)
-	s.Step(`^get cpu data "([^"]*)"`,
-		getCPUdata)
+	s.Step(`^record timestamp "([^"]*)"`,
+		getTimestamp)
 	s.Step(`^get memory data "([^"]*)"`,
 		getMemoryData)
 
@@ -1320,20 +1335,6 @@ func deserializeListBlockDeviceCommandOutputToExtractPVSize(lsblkOutput string)
 	return diskSize - (lvmSize + 1), nil
 }
 
-func getCPUdata(content string) error {
-	cpuData, err := cpu.Percent(0, false)
-	if err != nil {
-		return fmt.Errorf("failed to get CPU data: %v", err)
-	}
-	if len(cpuData) == 0 {
-		return fmt.Errorf("no CPU data available")
-	}
-	data := fmt.Sprintf("%s: %.2f%%\n", content, cpuData)
-	wd, _ := os.Getwd()
-	file := filepath.Join(wd, "../test-results/cpu-consume.txt")
-	return util.WriteToFile(data, file)
-}
-
 func getMemoryData(content string) error {
 	v, err := mem.VirtualMemory()
 	if err != nil {
@@ -1351,3 +1352,14 @@ func getMemoryData(content string) error {
 	file := filepath.Join(wd, "../test-results/memory-consume.txt")
 	return util.WriteToFile(data, file)
 }
+
+func getTimestamp(content string) error {
+	data := fmt.Sprintf("[%s], %s\n",
+		time.Now().Format("15:04:05"), content)
+	wd, err := os.Getwd()
+	if err != nil {
+		fmt.Printf("failed to get working directory: %v\n", err)
+	}
+	file := filepath.Join(wd, "../test-results/time-stamp.txt")
+	return util.WriteToFile(data, file)
+}