From 57f8ff4fcdb127210671fdc524a9a794ffef4828 Mon Sep 17 00:00:00 2001 From: Taiwon Chung <2008812+tchung1118@users.noreply.github.com> Date: Wed, 9 Oct 2024 15:37:18 -0400 Subject: [PATCH] feat: add runtime to fxevent.Run events (#1240) This PR adds runtime info of constructors and decorators to Run events, and the runtime of every constructor and decorator (including ones created by fx.Supply and fx.Replace) will be logged when logging Run events. This will help us identify which part of the dependency graph takes long to construct. Closes #1213 --- fxevent/console.go | 2 +- fxevent/console_test.go | 16 +++++++++------- fxevent/event.go | 3 +++ fxevent/slog.go | 1 + fxevent/slog_test.go | 15 +++++++++------ fxevent/zap.go | 1 + fxevent/zap_test.go | 15 +++++++++------ module.go | 4 ++++ 8 files changed, 37 insertions(+), 20 deletions(-) diff --git a/fxevent/console.go b/fxevent/console.go index d56990c0a..5b376c823 100644 --- a/fxevent/console.go +++ b/fxevent/console.go @@ -109,7 +109,7 @@ func (l *ConsoleLogger) LogEvent(event Event) { if e.ModuleName != "" { moduleStr = fmt.Sprintf(" from module %q", e.ModuleName) } - l.logf("RUN\t%v: %v%v", e.Kind, e.Name, moduleStr) + l.logf("RUN\t%v: %v in %s%v", e.Kind, e.Name, e.Runtime, moduleStr) if e.Err != nil { l.logf("Error returned: %+v", e.Err) } diff --git a/fxevent/console_test.go b/fxevent/console_test.go index fcaa41d3d..c41c97048 100644 --- a/fxevent/console_test.go +++ b/fxevent/console_test.go @@ -267,27 +267,29 @@ func TestConsoleLogger(t *testing.T) { }, { name: "Run", - give: &Run{Name: "bytes.NewBuffer()", Kind: "constructor"}, - want: "[Fx] RUN\tconstructor: bytes.NewBuffer()\n", + give: &Run{Name: "bytes.NewBuffer()", Kind: "constructor", Runtime: 10 * time.Nanosecond}, + want: "[Fx] RUN\tconstructor: bytes.NewBuffer() in 10ns\n", }, { name: "Run with module", give: &Run{ Name: "bytes.NewBuffer()", Kind: "constructor", + Runtime: 50 * time.Millisecond, ModuleName: "myModule", }, - want: "[Fx] RUN\tconstructor: bytes.NewBuffer() from module \"myModule\"\n", + want: "[Fx] RUN\tconstructor: bytes.NewBuffer() in 50ms from module \"myModule\"\n", }, { name: "RunError", give: &Run{ - Name: "bytes.NewBuffer()", - Kind: "constructor", - Err: errors.New("terrible constructor error"), + Name: "bytes.NewBuffer()", + Kind: "constructor", + Runtime: 5 * time.Second, + Err: errors.New("terrible constructor error"), }, want: joinLines( - "[Fx] RUN\tconstructor: bytes.NewBuffer()", + "[Fx] RUN\tconstructor: bytes.NewBuffer() in 5s", "[Fx] Error returned: terrible constructor error", ), }, diff --git a/fxevent/event.go b/fxevent/event.go index 7babcd4a0..187a9d8af 100644 --- a/fxevent/event.go +++ b/fxevent/event.go @@ -203,6 +203,9 @@ type Run struct { // ModuleName is the name of the module in which the function belongs. ModuleName string + // Runtime specifies how long it took to run this function. + Runtime time.Duration + // Err is non-nil if the function returned an error. // If fx.RecoverFromPanics is used, this will include panics. Err error diff --git a/fxevent/slog.go b/fxevent/slog.go index f699a64b2..09fb298c7 100644 --- a/fxevent/slog.go +++ b/fxevent/slog.go @@ -204,6 +204,7 @@ func (l *SlogLogger) LogEvent(event Event) { l.logEvent("run", slog.String("name", e.Name), slog.String("kind", e.Kind), + slog.String("runtime", e.Runtime.String()), slogMaybeModuleField(e.ModuleName), ) } diff --git a/fxevent/slog_test.go b/fxevent/slog_test.go index f8fb18e44..3b72ed8cc 100644 --- a/fxevent/slog_test.go +++ b/fxevent/slog_test.go @@ -342,11 +342,12 @@ func TestSlogLogger(t *testing.T) { }, { name: "Run", - give: &Run{Name: "bytes.NewBuffer()", Kind: "constructor"}, + give: &Run{Name: "bytes.NewBuffer()", Kind: "constructor", Runtime: 3 * time.Millisecond}, wantMessage: "run", wantFields: map[string]interface{}{ - "name": "bytes.NewBuffer()", - "kind": "constructor", + "name": "bytes.NewBuffer()", + "kind": "constructor", + "runtime": "3ms", }, }, { @@ -355,12 +356,14 @@ func TestSlogLogger(t *testing.T) { Name: "bytes.NewBuffer()", Kind: "constructor", ModuleName: "myModule", + Runtime: 3 * time.Millisecond, }, wantMessage: "run", wantFields: map[string]interface{}{ - "name": "bytes.NewBuffer()", - "kind": "constructor", - "module": "myModule", + "name": "bytes.NewBuffer()", + "kind": "constructor", + "module": "myModule", + "runtime": "3ms", }, }, { diff --git a/fxevent/zap.go b/fxevent/zap.go index 613eb8653..9d0c71fba 100644 --- a/fxevent/zap.go +++ b/fxevent/zap.go @@ -179,6 +179,7 @@ func (l *ZapLogger) LogEvent(event Event) { l.logEvent("run", zap.String("name", e.Name), zap.String("kind", e.Kind), + zap.String("runtime", e.Runtime.String()), moduleField(e.ModuleName), ) } diff --git a/fxevent/zap_test.go b/fxevent/zap_test.go index a43ae170e..3ac3def70 100644 --- a/fxevent/zap_test.go +++ b/fxevent/zap_test.go @@ -274,11 +274,12 @@ func TestZapLogger(t *testing.T) { }, { name: "Run", - give: &Run{Name: "bytes.NewBuffer()", Kind: "constructor"}, + give: &Run{Name: "bytes.NewBuffer()", Kind: "constructor", Runtime: time.Second}, wantMessage: "run", wantFields: map[string]interface{}{ - "name": "bytes.NewBuffer()", - "kind": "constructor", + "name": "bytes.NewBuffer()", + "kind": "constructor", + "runtime": "1s", }, }, { @@ -287,12 +288,14 @@ func TestZapLogger(t *testing.T) { Name: "bytes.NewBuffer()", Kind: "constructor", ModuleName: "myModule", + Runtime: time.Millisecond, }, wantMessage: "run", wantFields: map[string]interface{}{ - "name": "bytes.NewBuffer()", - "kind": "constructor", - "module": "myModule", + "name": "bytes.NewBuffer()", + "kind": "constructor", + "module": "myModule", + "runtime": "1ms", }, }, { diff --git a/module.go b/module.go index d0aa13404..d1986dafd 100644 --- a/module.go +++ b/module.go @@ -200,6 +200,7 @@ func (m *module) provide(p provide) { Name: funcName, Kind: "provide", ModuleName: m.name, + Runtime: ci.Runtime, Err: ci.Error, }) }), @@ -232,6 +233,7 @@ func (m *module) supply(p provide) { m.log.LogEvent(&fxevent.Run{ Name: fmt.Sprintf("stub(%v)", typeName), Kind: "supply", + Runtime: ci.Runtime, ModuleName: m.name, }) }), @@ -356,6 +358,7 @@ func (m *module) decorate(d decorator) (err error) { Name: funcName, Kind: "decorate", ModuleName: m.name, + Runtime: ci.Runtime, Err: ci.Error, }) }), @@ -387,6 +390,7 @@ func (m *module) replace(d decorator) error { Name: fmt.Sprintf("stub(%v)", typeName), Kind: "replace", ModuleName: m.name, + Runtime: ci.Runtime, Err: ci.Error, }) }),