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