Fix some time measurement for istioctl bug-report command #46406

Abirdcfly · 2023-08-09T04:34:38Z

Please provide a description of this PR:

The deferred call's arguments are evaluated immediately, but the function call is not executed until the surrounding function returns.

There's a quick way to tell if the runtime is correct: manually add a 1s delay using time.Sleep(time.Second) in each function that needs to log time, and if the time is still less than 1s in the log, then it must be wrong.
The diff is as follows:

diff --git a/tools/bug-report/pkg/bugreport/bugreport.go b/tools/bug-report/pkg/bugreport/bugreport.go
index 33cbd7db7b..9c01fc3610 100644
--- a/tools/bug-report/pkg/bugreport/bugreport.go
+++ b/tools/bug-report/pkg/bugreport/bugreport.go
@@ -213,6 +213,7 @@ func runBugReportCommand(ctx cli.Context, _ *cobra.Command, logOpts *log.Options
 func dumpRevisionsAndVersions(ctx cli.Context, resources *cluster2.Resources, istioNamespace string, dryRun bool) {
 	defer logRuntime(time.Now(), "Done getting control plane revisions/versions")
 
+	time.Sleep(time.Second)
 	text := ""
 	text += fmt.Sprintf("CLI version:\n%s\n\n", version.Info.LongForm())
 
@@ -379,6 +380,7 @@ func getFromCluster(f func(params *content.Params) (map[string]string, error), p
 			logRuntime(time.Now(), "Done getting from cluster for %v", runtime.FuncForPC(reflect.ValueOf(f).Pointer()).Name())
 		}()
 
+		time.Sleep(time.Second)
 		out, err := f(params)
 		appendGlobalErr(err)
 		if err == nil {
@@ -402,6 +404,7 @@ func getProxyLogs(runner *kubectlcmd.Runner, config *config.BugReportConfig, res
 			logRuntime(time.Now(), "Done getting from proxy logs for %v/%v/%v", namespace, pod, container)
 		}()
 
+		time.Sleep(time.Second)
 		clog, cstat, imp, err := getLog(runner, resources, config, namespace, pod, container)
 		appendGlobalErr(err)
 		lock.Lock()
@@ -426,6 +429,7 @@ func getIstiodLogs(runner *kubectlcmd.Runner, config *config.BugReportConfig, re
 			logRuntime(time.Now(), "Done getting Istiod logs for %v/%v", namespace, pod)
 		}()
 
+		time.Sleep(time.Second)
 		clog, _, _, err := getLog(runner, resources, config, namespace, pod, common.DiscoveryContainerName)
 		appendGlobalErr(err)
 		writeFile(filepath.Join(archive.IstiodPath(tempDir, namespace, pod), "discovery.log"), clog, config.DryRun)
@@ -445,6 +449,7 @@ func getOperatorLogs(runner *kubectlcmd.Runner, config *config.BugReportConfig,
 			logRuntime(time.Now(), "Done getting operator logs for %v/%v", namespace, pod)
 		}()
 
+		time.Sleep(time.Second)
 		clog, _, _, err := getLog(runner, resources, config, namespace, pod, common.OperatorContainerName)
 		appendGlobalErr(err)
 		writeFile(filepath.Join(archive.OperatorPath(tempDir, namespace, pod), "operator.log"), clog, config.DryRun)
@@ -465,6 +470,7 @@ func getCniLogs(runner *kubectlcmd.Runner, config *config.BugReportConfig, resou
 			logRuntime(time.Now(), "Done getting CNI logs for %v", pod)
 		}()
 
+		time.Sleep(time.Second)
 		clog, _, _, err := getLog(runner, resources, config, namespace, pod, "")
 		appendGlobalErr(err)
 		writeFile(filepath.Join(archive.CniPath(tempDir, pod), "cni.log"), clog, config.DryRun)
@@ -478,6 +484,7 @@ func getLog(runner *kubectlcmd.Runner, resources *cluster2.Resources, config *co
 ) (string, *processlog.Stats, int, error) {
 	defer logRuntime(time.Now(), "Done getting logs only for %v/%v/%v", namespace, pod, container)
 
+	time.Sleep(time.Second)
 	log.Infof("Getting logs for %s/%s/%s...", namespace, pod, container)
 	clog, err := runner.Logs(namespace, pod, container, false, config.DryRun)
 	if err != nil {
@@ -501,6 +508,7 @@ func runAnalyze(config *config.BugReportConfig, params *content.Params, analyzeT
 
 	defer logRuntime(time.Now(), "Done running Istio analyze on all namespaces and report")
 
+	time.Sleep(time.Second)
 	common.LogAndPrintf("Running Istio analyze on all namespaces and report as below:")
 	out, err := content.GetAnalyze(newParam.SetIstioNamespace(config.IstioNamespace), analyzeTimeout)
 	if err != nil {
@@ -515,6 +523,7 @@ func runAnalyze(config *config.BugReportConfig, params *content.Params, analyzeT
 
 func writeFiles(dir string, files map[string]string, dryRun bool) {
 	defer logRuntime(time.Now(), "Done writing files for dir %v", dir)
+	time.Sleep(time.Second)
 	for fname, text := range files {
 		writeFile(filepath.Join(dir, fname), text, dryRun)
 	}
@@ -531,6 +540,7 @@ func writeFile(path, text string, dryRun bool) {
 
 	defer logRuntime(time.Now(), "Done writing file for path %v", path)
 
+	time.Sleep(time.Second)
 	if err := os.WriteFile(path, []byte(text), 0o644); err != nil {
 		log.Errorf(err.Error())
 	}

The deferred call's arguments are evaluated immediately, but the function call is not executed until the surrounding function returns.

istio-policy-bot · 2023-08-09T04:34:40Z

🤔 🐛 You appear to be fixing a bug in Go code, yet your PR doesn't include updates to any test files. Did you forget to add a test?

Courtesy of your friendly test nag.

istio-testing · 2023-08-09T04:34:49Z

Hi @Abirdcfly. Thanks for your PR.

I'm waiting for a istio member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

hanxiaop · 2023-08-09T04:59:08Z

/ok-to-test

ymesika

It makes sense but there other places in this file with similar capture of the time for the logRuntime and you didn't update those too?
Any reason not to?

Abirdcfly · 2023-08-09T13:10:06Z

other places in this file with similar capture of the time for the logRuntime and you didn't update those too?

There are 2 ways to use logRuntime in this file, some of them are correct, let me write a simplified example to show: https://go.dev/play/p/PcNBHSwcCKp

package main

import (
	"fmt"
	"time"
)

func main() {
	Use1()
	Use2()
}

func Use1() {
	defer logRuntime(time.Now(), "use1")
	time.Sleep(time.Second)
}
func Use2() {
	defer func() {
		fmt.Println("do something")
		logRuntime(time.Now(), "use2")
	}()
	time.Sleep(time.Second)
}
func logRuntime(start time.Time, format string, args ...any) {
	fmt.Printf("runtime %s %s\n", time.Since(start), format)
}

Abirdcfly · 2023-08-09T13:11:18Z

And maybe this issue is helpful: golang/go#60048

Fix some time measurement for istioctl bug-report command

f0f9e8b

The deferred call's arguments are evaluated immediately, but the function call is not executed until the surrounding function returns.

Abirdcfly requested a review from a team as a code owner August 9, 2023 04:34

istio-policy-bot added area/test and release release-notes-none Indicates a PR that does not require release notes. labels Aug 9, 2023

istio-testing added needs-ok-to-test size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Aug 9, 2023

istio-testing added ok-to-test Set this label allow normal testing to take place for a PR not submitted by an Istio org member. and removed needs-ok-to-test labels Aug 9, 2023

ymesika reviewed Aug 9, 2023

View reviewed changes

howardjohn approved these changes Aug 9, 2023

View reviewed changes

istio-testing merged commit fabd6f7 into istio:master Aug 9, 2023

Abirdcfly deleted the bugreport branch August 10, 2023 05:42

Abirdcfly mentioned this pull request Aug 10, 2023

add Abirdcfly to members istio/community#1175

Merged

7 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix some time measurement for istioctl bug-report command #46406

Fix some time measurement for istioctl bug-report command #46406

Abirdcfly commented Aug 9, 2023 •

edited by istio-policy-bot

Loading

istio-policy-bot commented Aug 9, 2023

istio-testing commented Aug 9, 2023

hanxiaop commented Aug 9, 2023

ymesika left a comment

Abirdcfly commented Aug 9, 2023

Abirdcfly commented Aug 9, 2023

Fix some time measurement for istioctl bug-report command #46406

Fix some time measurement for istioctl bug-report command #46406

Conversation

Abirdcfly commented Aug 9, 2023 • edited by istio-policy-bot Loading

istio-policy-bot commented Aug 9, 2023

istio-testing commented Aug 9, 2023

hanxiaop commented Aug 9, 2023

ymesika left a comment

Choose a reason for hiding this comment

Abirdcfly commented Aug 9, 2023

Abirdcfly commented Aug 9, 2023

Abirdcfly commented Aug 9, 2023 •

edited by istio-policy-bot

Loading