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

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

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

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

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

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",
 			},
 		},
 		{

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

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",
 			},
 		},
 		{

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