Repository: uber-go/fx (go)

Issue:
Add constructor runtime to fxevent.Run events
**Is your feature request related to a problem? Please describe.**
Recently I had to investigate a service not starting up properly due to dependency construction taking a long time in certain zone. While we log fxevent.Run events when a constructor runs and returns results and/or error, it lacks the information on how long a certain constructor took to run, which barred us from being able to further investigate and find out which part of the DI graph could be slowing down and come up with some hypotheses on what could be going on in that zone.

**Describe the solution you'd like**
I propose that we include the runtime of each constructor in fxevent.Run events.

**Describe alternatives you've considered**
Collecting cpu profiles at application start-up, including provides, runs, invokes, and OnStart hooks, would also have enabled us to identify which constructors are running slower than others. However, in this particular situation, the docker container that's starting the service up was being terminated in the middle of DI graph construction, so optionally emitting CPU profiles at start-up wouldn't have helped us.

**Is this a breaking change?**
This is just adding more information to an fxevent. I don't think this is a breaking change.



Pull request:
feat: add runtime to fxevent.Run events
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 

Patch:
diff --git a/fxevent/console.go b/fxevent/console.go
index d56990c..5b376c8 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/event.go b/fxevent/event.go
index 7babcd4..187a9d8 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 f699a64..09fb298 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/zap.go b/fxevent/zap.go
index 613eb86..9d0c71f 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/module.go b/module.go
index d0aa134..d1986da 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,
 			})
 		}),


Test patch:
diff --git a/fxevent/console_test.go b/fxevent/console_test.go
index fcaa41d..c41c970 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/slog_test.go b/fxevent/slog_test.go
index f8fb18e..3b72ed8 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_test.go b/fxevent/zap_test.go
index a43ae17..3ac3def 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",
 			},
 		},
 		{