Resolves #2444 - detailed traces and metrics for host init

Author: paulbatum

src/WebJobs.Script/Diagnostics/MetricEventNames.cs

@@ -7,9 +7,14 @@ public static class MetricEventNames
     {
         // host level events
         public const string ApplicationStartLatency = "host.application.start";
-        public const string HostStartupLatency = "host.startup.latency";
         public const string ApplicationInsightsEnabled = "host.applicationinsights.enabled";
         public const string ApplicationInsightsDisabled = "host.applicationinsights.disabled";
+        public const string HostStartupLatency = "host.startup.latency";
+        public const string HostStartupReadFunctionMetadataLatency = "host.startup.readfunctionmetadata.latency";
+        public const string HostStartupInitializeBindingProvidersLatency = "host.startup.initializebindingproviders.latency";
+        public const string HostStartupCreateMetadataProviderLatency = "host.startup.createmetadataprovider.latency";
+        public const string HostStartupGetFunctionDescriptorsLatency = "host.startup.getfunctiondescriptors.latency";
+        public const string HostStartupPurgeLogDirectoriesLatency = "host.startup.purgelogdirectories.latency";
 
         // function level events
         public const string FunctionInvokeLatency = "function.invoke.latency";

src/WebJobs.Script/Host/ScriptHost.cs

@@ -385,6 +385,7 @@ public void Initialize()
 
                 // Allow tests to modify anything initialized by host.json
                 ScriptConfig.OnConfigurationApplied?.Invoke(ScriptConfig);
+                TraceWriter.Verbose("Host configuration applied.");
 
                 // only after configuration has been applied and loggers have been created, raise the initializing event
                 HostInitializing?.Invoke(this, EventArgs.Empty);
@@ -406,6 +407,7 @@ public void Initialize()
                     includeSubdirectories: false, changeTypes: WatcherChangeTypes.Created | WatcherChangeTypes.Changed);
 
                 _debugModeFileWatcher.Changed += OnDebugModeFileChanged;
+                TraceWriter.Verbose("Debug file watch initialized.");
 
                 var storageString = AmbientConnectionStringProvider.Instance.GetConnectionString(ConnectionStringNames.Storage);
                 if (storageString == null)
@@ -422,8 +424,12 @@ public void Initialize()
                         .Where(f => string.Equals(f.Source, EventSources.ScriptFiles, StringComparison.Ordinal))
                         .Subscribe(e => OnFileChanged(e.FileChangeArguments));
 
+                    TraceWriter.Verbose("File event source initialized.");
+
                     // take a snapshot so we can detect function additions/removals
                     _directorySnapshot = Directory.EnumerateDirectories(ScriptConfig.RootScriptPath).ToImmutableArray();
+
+                    TraceWriter.Verbose("Created directory snapshot.");
                 }
 
                 // If a file change should result in a restart, we debounce the event to
@@ -437,45 +443,62 @@ public void Initialize()
                 _shutdown = Shutdown;
                 _shutdown = _shutdown.Debounce(500);
 
-                // Scan the function.json early to determine the binding extensions used
-                var functionMetadata = ReadFunctionMetadata(ScriptConfig, TraceWriter, _startupLogger, FunctionErrors, _settingsManager);
+                Collection<FunctionMetadata> functionMetadata;
+                using (metricsLogger.LatencyEvent(MetricEventNames.HostStartupReadFunctionMetadataLatency))
+                {
+                    // Scan the function.json early to determine the binding extensions used
+                    functionMetadata = ReadFunctionMetadata(ScriptConfig, TraceWriter, _startupLogger, FunctionErrors, _settingsManager);
+                    TraceWriter.Verbose("Function metadata read.");
+                }
+
                 var extensionLoader = new ExtensionLoader(ScriptConfig, TraceWriter, _startupLogger);
                 var usedBindingTypes = extensionLoader.DiscoverBindingTypes(functionMetadata);
 
                 var bindingProviders = LoadBindingProviders(ScriptConfig, hostConfigObject, TraceWriter, _startupLogger, usedBindingTypes);
                 ScriptConfig.BindingProviders = bindingProviders;
+                TraceWriter.Verbose("Binding providers loaded.");
 
                 var coreBinder = bindingProviders.OfType<CoreExtensionsScriptBindingProvider>().First();
                 coreBinder.AppDirectory = ScriptConfig.RootScriptPath;
 
                 // Allow BindingProviders to initialize
-                foreach (var bindingProvider in ScriptConfig.BindingProviders)
+                using (metricsLogger.LatencyEvent(MetricEventNames.HostStartupInitializeBindingProvidersLatency))
                 {
-                    try
+                    foreach (var bindingProvider in ScriptConfig.BindingProviders)
                     {
-                        bindingProvider.Initialize();
-                    }
-                    catch (Exception ex)
-                    {
-                        // If we're unable to initialize a binding provider for any reason, log the error
-                        // and continue
-                        string errorMsg = string.Format("Error initializing binding provider '{0}'", bindingProvider.GetType().FullName);
-                        TraceWriter.Error(errorMsg, ex);
-                        _startupLogger?.LogError(0, ex, errorMsg);
+                        try
+                        {
+                            bindingProvider.Initialize();
+                        }
+                        catch (Exception ex)
+                        {
+                            // If we're unable to initialize a binding provider for any reason, log the error
+                            // and continue
+                            string errorMsg = string.Format("Error initializing binding provider '{0}'", bindingProvider.GetType().FullName);
+                            TraceWriter.Error(errorMsg, ex);
+                            _startupLogger?.LogError(0, ex, errorMsg);
+                        }
                     }
+                    TraceWriter.Verbose("Binding providers initialized.");
                 }
+
                 extensionLoader.LoadBuiltinExtensions(usedBindingTypes);
 
                 var directTypes = GetDirectTypes(functionMetadata);
                 extensionLoader.LoadDirectlyReferencedExtensions(directTypes);
                 extensionLoader.LoadCustomExtensions();
+                TraceWriter.Verbose("Extension loading complete.");
 
                 // Now all extensions have been loaded, the metadata is finalized.
                 // There's a single script binding instance that services all extensions.
                 // give that script binding the metadata for all loaded extensions so it can dispatch to them.
-                var generalProvider = ScriptConfig.BindingProviders.OfType<GeneralScriptBindingProvider>().First();
-                var metadataProvider = this.CreateMetadataProvider();
-                generalProvider.CompleteInitialization(metadataProvider);
+                using (metricsLogger.LatencyEvent(MetricEventNames.HostStartupCreateMetadataProviderLatency))
+                {
+                    var generalProvider = ScriptConfig.BindingProviders.OfType<GeneralScriptBindingProvider>().First();
+                    var metadataProvider = this.CreateMetadataProvider();
+                    generalProvider.CompleteInitialization(metadataProvider);
+                    TraceWriter.Verbose("Metadata provider created.");
+                }
 
                 // Do this after we've loaded the custom extensions. That gives an extension an opportunity to plug in their own implementations.
                 if (storageString != null)
@@ -504,7 +527,13 @@ public void Initialize()
                 };
 
                 // read all script functions and apply to JobHostConfiguration
-                Collection<FunctionDescriptor> functions = GetFunctionDescriptors(functionMetadata);
+                Collection<FunctionDescriptor> functions;
+                using (metricsLogger.LatencyEvent(MetricEventNames.HostStartupGetFunctionDescriptorsLatency))
+                {
+                    functions = GetFunctionDescriptors(functionMetadata);
+                    TraceWriter.Verbose("Function descriptors read.");
+                }
+
                 Collection<CustomAttributeBuilder> typeAttributes = CreateTypeAttributes(ScriptConfig);
                 string typeName = string.Format(CultureInfo.InvariantCulture, "{0}.{1}", GeneratedTypeNamespace, GeneratedTypeName);
 
@@ -524,7 +553,11 @@ public void Initialize()
 
                 if (ScriptConfig.FileLoggingMode != FileLoggingMode.Never)
                 {
-                    PurgeOldLogDirectories();
+                    using (metricsLogger.LatencyEvent(MetricEventNames.HostStartupPurgeLogDirectoriesLatency))
+                    {
+                        PurgeOldLogDirectories();
+                        TraceWriter.Verbose("Old log directories purged.");
+                    }
                 }
             }
         }

test/WebJobs.Script.Tests/ScriptHostTests.cs

@@ -1119,14 +1119,14 @@ public void Initialize_Sanitizes_HostJsonLog()
 
             // for formatting
             var hostJson = JObject.Parse(hostJsonSanitized);
-            string expectedMessgae = $"Host configuration file read:{Environment.NewLine}{hostJson}";
+            string expectedMessage = $"Host configuration file read:{Environment.NewLine}{hostJson}";
 
             var logger = loggerProvider.CreatedLoggers.Single(l => l.Category == LogCategories.Startup);
-            var logMessage = logger.LogMessages.Single(l => l.FormattedMessage.StartsWith("Host configuration ")).FormattedMessage;
-            Assert.Equal(expectedMessgae, logMessage);
+            var logMessage = logger.LogMessages.Single(l => l.FormattedMessage.StartsWith("Host configuration file read")).FormattedMessage;
+            Assert.Equal(expectedMessage, logMessage);
 
-            var traceMessage = traceWriter.GetTraces().Single(t => t.Message.StartsWith("Host configuration ")).Message;
-            Assert.Equal(expectedMessgae, traceMessage);
+            var traceMessage = traceWriter.GetTraces().Single(t => t.Message.StartsWith("Host configuration file read")).Message;
+            Assert.Equal(expectedMessage, traceMessage);
         }
 
         [Fact]