Fix some time measurement for istioctl bug-report command

[Abirdcfly]

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())
 	}

[istio-policy-bot]

🤔 🐛 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]

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]

/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]

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]

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