From d4141ea04e7737dc605a4299e45734455ad7231e Mon Sep 17 00:00:00 2001 From: Sean Grider Date: Mon, 30 Oct 2023 22:06:12 -0400 Subject: [PATCH 1/4] Added initial support for -t flag to show timings Shows very basic timing data for the Dial stage (TLS setup and BlockingDial) and InvokeRPC method as well as the total time. --- cmd/grpcurl/grpcurl.go | 54 ++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 54 insertions(+) diff --git a/cmd/grpcurl/grpcurl.go b/cmd/grpcurl/grpcurl.go index 475358d5..497c4d98 100644 --- a/cmd/grpcurl/grpcurl.go +++ b/cmd/grpcurl/grpcurl.go @@ -154,6 +154,8 @@ var ( Enable verbose output.`)) veryVerbose = flags.Bool("vv", false, prettify(` Enable very verbose output.`)) + showTimings = flags.Bool("t", false, prettify(` + Display debug timings.`)) serverName = flags.String("servername", "", prettify(` Override server name when validating TLS certificate. This flag is ignored if -plaintext or -insecure is used. @@ -274,6 +276,12 @@ func (cs compositeSource) AllExtensionsForType(typeName string) ([]*desc.FieldDe return exts, nil } +type TimingData struct { + Title string + Value time.Duration + Sub []TimingData +} + func main() { flags.Usage = usage flags.Parse(os.Args[1:]) @@ -362,6 +370,9 @@ func main() { if *veryVerbose { verbosityLevel = 2 } + timingData := []TimingData{} + startTime := time.Now() + s := startTime var symbol string if invoke { @@ -419,12 +430,20 @@ func main() { } dial := func() *grpc.ClientConn { + s := time.Now() + td := TimingData{ + Title: "Dial", + } dialTime := 10 * time.Second if *connectTimeout > 0 { dialTime = time.Duration(*connectTimeout * float64(time.Second)) } ctx, cancel := context.WithTimeout(ctx, dialTime) defer cancel() + defer func() { + td.Value = time.Now().Sub(s) + timingData = append(timingData, td) + }() var opts []grpc.DialOption if *keepaliveTime > 0 { timeout := time.Duration(*keepaliveTime * float64(time.Second)) @@ -451,6 +470,7 @@ func main() { } creds = alts.NewClientCreds(clientOptions) } else if usetls { + s := time.Now() tlsConf, err := grpcurl.ClientTLSConfig(*insecure, *cacert, *cert, *key) if err != nil { fail(err, "Failed to create TLS config") @@ -483,6 +503,10 @@ func main() { if overrideName != "" { opts = append(opts, grpc.WithAuthority(overrideName)) } + td.Sub = append(td.Sub, TimingData{ + Title: "TLS Setup", + Value: time.Now().Sub(s), + }) } else { panic("Should have defaulted to use TLS.") } @@ -500,10 +524,15 @@ func main() { if isUnixSocket != nil && isUnixSocket() { network = "unix" } + s = time.Now() cc, err := grpcurl.BlockingDial(ctx, network, target, creds, opts...) if err != nil { fail(err, "Failed to dial target host %q", target) } + td.Sub = append(td.Sub, TimingData{ + Title: "BlockingDial", + Value: time.Now().Sub(s), + }) return cc } printFormattedStatus := func(w io.Writer, stat *status.Status, formatter grpcurl.Formatter) { @@ -747,6 +776,7 @@ func main() { VerbosityLevel: verbosityLevel, } + s = time.Now() err = grpcurl.InvokeRPC(ctx, descSource, cc, symbol, append(addlHeaders, rpcHeaders...), h, rf.Next) if err != nil { if errStatus, ok := status.FromError(err); ok && *formatError { @@ -755,6 +785,10 @@ func main() { fail(err, "Error invoking method %q", symbol) } } + timingData = append(timingData, TimingData{ + Title: "InvokeRPC", + Value: time.Now().Sub(s), + }) reqSuffix := "" respSuffix := "" reqCount := rf.NumRequests() @@ -767,6 +801,15 @@ func main() { if verbosityLevel > 0 { fmt.Printf("Sent %d request%s and received %d response%s\n", reqCount, reqSuffix, h.NumResponses, respSuffix) } + if *showTimings { + defer func() { + fmt.Printf("== Timing Data == \n") + for _, td := range timingData { + dumpTiming(td, 1) + } + fmt.Printf("\n Total time: %v\n", time.Now().Sub(startTime)) + }() + } if h.Status.Code() != codes.OK { if *formatError { printFormattedStatus(os.Stderr, h.Status, formatter) @@ -778,6 +821,17 @@ func main() { } } +func dumpTiming(td TimingData, lvl int) { + indent := " " + for x := 0; x < lvl - 1; x++ { + indent += indent + } + fmt.Printf("%s%s: %s\n", indent, td.Title, td.Value) + for _, sd := range td.Sub { + dumpTiming(sd, lvl + 1) + } +} + func usage() { fmt.Fprintf(os.Stderr, `Usage: %s [flags] [address] [list|describe] [symbol] From 0f4076a9e47b90b0202c2a4cbc538f52fed04c4c Mon Sep 17 00:00:00 2001 From: Sean Grider Date: Fri, 17 Nov 2023 09:45:51 -0500 Subject: [PATCH 2/4] Made timing data part of the very verbose functionality --- cmd/grpcurl/grpcurl.go | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/cmd/grpcurl/grpcurl.go b/cmd/grpcurl/grpcurl.go index 497c4d98..8ac987f5 100644 --- a/cmd/grpcurl/grpcurl.go +++ b/cmd/grpcurl/grpcurl.go @@ -153,9 +153,7 @@ var ( verbose = flags.Bool("v", false, prettify(` Enable verbose output.`)) veryVerbose = flags.Bool("vv", false, prettify(` - Enable very verbose output.`)) - showTimings = flags.Bool("t", false, prettify(` - Display debug timings.`)) + Enable very verbose output (includes timing data).`)) serverName = flags.String("servername", "", prettify(` Override server name when validating TLS certificate. This flag is ignored if -plaintext or -insecure is used. @@ -801,7 +799,7 @@ func main() { if verbosityLevel > 0 { fmt.Printf("Sent %d request%s and received %d response%s\n", reqCount, reqSuffix, h.NumResponses, respSuffix) } - if *showTimings { + if verbosityLevel > 1 { defer func() { fmt.Printf("== Timing Data == \n") for _, td := range timingData { From 2ff79c3348c81460e1952340427093701699a670 Mon Sep 17 00:00:00 2001 From: Scott Blum Date: Tue, 9 Jan 2024 11:32:17 -0500 Subject: [PATCH 3/4] cleanup --- cmd/grpcurl/grpcurl.go | 90 +++++++++++++++++++++--------------------- 1 file changed, 45 insertions(+), 45 deletions(-) diff --git a/cmd/grpcurl/grpcurl.go b/cmd/grpcurl/grpcurl.go index 8ac987f5..9f29503d 100644 --- a/cmd/grpcurl/grpcurl.go +++ b/cmd/grpcurl/grpcurl.go @@ -274,10 +274,27 @@ func (cs compositeSource) AllExtensionsForType(typeName string) ([]*desc.FieldDe return exts, nil } -type TimingData struct { - Title string - Value time.Duration - Sub []TimingData +type timingData struct { + Title string + Start time.Time + Value time.Duration + Parent *timingData + Sub []*timingData +} + +func (d *timingData) Child(title string) *timingData { + if d == nil { + return nil + } + child := &timingData{Title: title, Start: time.Now()} + d.Sub = append(d.Sub, child) + return child +} + +func (d *timingData) Done() { + if d.Value == 0 { + d.Value = time.Since(d.Start) + } } func main() { @@ -365,12 +382,17 @@ func main() { if *verbose { verbosityLevel = 1 } + + var rootTiming *timingData if *veryVerbose { verbosityLevel = 2 + + rootTiming = &timingData{Title: "Timing Data", Start: time.Now()} + defer func() { + rootTiming.Done() + dumpTiming(rootTiming, 0) + }() } - timingData := []TimingData{} - startTime := time.Now() - s := startTime var symbol string if invoke { @@ -428,20 +450,14 @@ func main() { } dial := func() *grpc.ClientConn { - s := time.Now() - td := TimingData{ - Title: "Dial", - } + dialTiming := rootTiming.Child("Dial") + defer dialTiming.Done() dialTime := 10 * time.Second if *connectTimeout > 0 { dialTime = time.Duration(*connectTimeout * float64(time.Second)) } ctx, cancel := context.WithTimeout(ctx, dialTime) defer cancel() - defer func() { - td.Value = time.Now().Sub(s) - timingData = append(timingData, td) - }() var opts []grpc.DialOption if *keepaliveTime > 0 { timeout := time.Duration(*keepaliveTime * float64(time.Second)) @@ -468,7 +484,9 @@ func main() { } creds = alts.NewClientCreds(clientOptions) } else if usetls { - s := time.Now() + tlsTiming := dialTiming.Child("TLS Setup") + defer tlsTiming.Done() + tlsConf, err := grpcurl.ClientTLSConfig(*insecure, *cacert, *cert, *key) if err != nil { fail(err, "Failed to create TLS config") @@ -501,10 +519,7 @@ func main() { if overrideName != "" { opts = append(opts, grpc.WithAuthority(overrideName)) } - td.Sub = append(td.Sub, TimingData{ - Title: "TLS Setup", - Value: time.Now().Sub(s), - }) + tlsTiming.Done() } else { panic("Should have defaulted to use TLS.") } @@ -522,15 +537,12 @@ func main() { if isUnixSocket != nil && isUnixSocket() { network = "unix" } - s = time.Now() + blockingDialTiming := dialTiming.Child("BlockingDial") + defer blockingDialTiming.Done() cc, err := grpcurl.BlockingDial(ctx, network, target, creds, opts...) if err != nil { fail(err, "Failed to dial target host %q", target) } - td.Sub = append(td.Sub, TimingData{ - Title: "BlockingDial", - Value: time.Now().Sub(s), - }) return cc } printFormattedStatus := func(w io.Writer, stat *status.Status, formatter grpcurl.Formatter) { @@ -774,8 +786,9 @@ func main() { VerbosityLevel: verbosityLevel, } - s = time.Now() + invokeTiming := rootTiming.Child("InvokeRPC") err = grpcurl.InvokeRPC(ctx, descSource, cc, symbol, append(addlHeaders, rpcHeaders...), h, rf.Next) + invokeTiming.Done() if err != nil { if errStatus, ok := status.FromError(err); ok && *formatError { h.Status = errStatus @@ -783,10 +796,6 @@ func main() { fail(err, "Error invoking method %q", symbol) } } - timingData = append(timingData, TimingData{ - Title: "InvokeRPC", - Value: time.Now().Sub(s), - }) reqSuffix := "" respSuffix := "" reqCount := rf.NumRequests() @@ -799,15 +808,6 @@ func main() { if verbosityLevel > 0 { fmt.Printf("Sent %d request%s and received %d response%s\n", reqCount, reqSuffix, h.NumResponses, respSuffix) } - if verbosityLevel > 1 { - defer func() { - fmt.Printf("== Timing Data == \n") - for _, td := range timingData { - dumpTiming(td, 1) - } - fmt.Printf("\n Total time: %v\n", time.Now().Sub(startTime)) - }() - } if h.Status.Code() != codes.OK { if *formatError { printFormattedStatus(os.Stderr, h.Status, formatter) @@ -819,14 +819,14 @@ func main() { } } -func dumpTiming(td TimingData, lvl int) { - indent := " " - for x := 0; x < lvl - 1; x++ { - indent += indent +func dumpTiming(td *timingData, lvl int) { + ind := "" + for x := 0; x < lvl; x++ { + ind += " " } - fmt.Printf("%s%s: %s\n", indent, td.Title, td.Value) + fmt.Printf("%s%s: %s\n", ind, td.Title, td.Value) for _, sd := range td.Sub { - dumpTiming(sd, lvl + 1) + dumpTiming(sd, lvl+1) } } From ac9a9d14b45154bf45a475471fb7d9310b174e09 Mon Sep 17 00:00:00 2001 From: Scott Blum Date: Tue, 9 Jan 2024 11:35:01 -0500 Subject: [PATCH 4/4] fix --- cmd/grpcurl/grpcurl.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/cmd/grpcurl/grpcurl.go b/cmd/grpcurl/grpcurl.go index 9f29503d..2e9b3f0e 100644 --- a/cmd/grpcurl/grpcurl.go +++ b/cmd/grpcurl/grpcurl.go @@ -292,6 +292,9 @@ func (d *timingData) Child(title string) *timingData { } func (d *timingData) Done() { + if d == nil { + return + } if d.Value == 0 { d.Value = time.Since(d.Start) }