Delay non-essential startup tasks to improve performance

Author: ankitkumarr

src/WebJobs.Script.WebHost/FileMonitoringService.cs

@@ -23,6 +23,7 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost
 {
     public class FileMonitoringService : IHostedService, IDisposable
     {
+        private const int _delayedWatchersDelaySeconds = 5;
         private readonly ScriptJobHostOptions _scriptOptions;
         private readonly IScriptEventManager _eventManager;
         private readonly IApplicationLifetime _applicationLifetime;
@@ -101,16 +102,6 @@ public Task StopAsync(CancellationToken cancellationToken)
         /// </summary>
         private void InitializeFileWatchers()
         {
-            _debugModeFileWatcher = new AutoRecoveringFileSystemWatcher(_hostLogPath, ScriptConstants.DebugSentinelFileName,
-                   includeSubdirectories: false, changeTypes: WatcherChangeTypes.Created | WatcherChangeTypes.Changed);
-            _debugModeFileWatcher.Changed += OnDebugModeFileChanged;
-            _logger.LogDebug("Debug file watch initialized.");
-
-            _diagnosticModeFileWatcher = new AutoRecoveringFileSystemWatcher(_hostLogPath, ScriptConstants.DiagnosticSentinelFileName,
-                   includeSubdirectories: false, changeTypes: WatcherChangeTypes.Created | WatcherChangeTypes.Changed);
-            _diagnosticModeFileWatcher.Changed += OnDiagnosticModeFileChanged;
-            _logger.LogDebug("Diagnostic file watch initialized.");
-
             if (_scriptOptions.FileWatchingEnabled)
             {
                 _fileEventSource = new FileWatcherEventSource(_eventManager, EventSources.ScriptFiles, _scriptOptions.RootScriptPath);
@@ -126,12 +117,50 @@ private void InitializeFileWatchers()
                     .Subscribe((msg) => ScheduleRestartAsync(false)
                     .ContinueWith(t => _logger.LogCritical(t.Exception.Message),
                         TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously)));
+
+            // Delay starting up for logging and debug file watchers to avoid long start up times
+            Utility.ExecuteAfterDelay(InitializeNonBlockingFileWatchers, TimeSpan.FromSeconds(_delayedWatchersDelaySeconds));
+        }
+
+        /// <summary>
+        /// Initializes the file and directory monitoring that does not need to happen as part of a Host startup
+        /// These watchers can be started after a delay to avoid startup performance issue
+        /// </summary>
+        private void InitializeNonBlockingFileWatchers()
+        {
+            if (_watchersStopped)
+            {
+                return;
+            }
+
+            lock (_stopWatchersLock)
+            {
+                // We need this duplication to avoid race if watchers were stopped just when we acquired the lock
+                if (!_watchersStopped)
+                {
+                    _debugModeFileWatcher = new AutoRecoveringFileSystemWatcher(_hostLogPath, ScriptConstants.DebugSentinelFileName,
+                            includeSubdirectories: false, changeTypes: WatcherChangeTypes.Created | WatcherChangeTypes.Changed);
+                    _debugModeFileWatcher.Changed += OnDebugModeFileChanged;
+                    _logger.LogDebug("Debug file watch initialized.");
+
+                    _diagnosticModeFileWatcher = new AutoRecoveringFileSystemWatcher(_hostLogPath, ScriptConstants.DiagnosticSentinelFileName,
+                           includeSubdirectories: false, changeTypes: WatcherChangeTypes.Created | WatcherChangeTypes.Changed);
+                    _diagnosticModeFileWatcher.Changed += OnDiagnosticModeFileChanged;
+                    _logger.LogDebug("Diagnostic file watch initialized.");
+                }
+            }
         }
 
         private void StopFileWatchers()
         {
+            if (_watchersStopped)
+            {
+                return;
+            }
+
             lock (_stopWatchersLock)
             {
+                // We need this duplication to avoid race if watchers were stopped just when we acquired the lock
                 if (_watchersStopped)
                 {
                     return;

src/WebJobs.Script/Host/DebugManager.cs

@@ -39,9 +39,11 @@ public void NotifyDebug()
             {
                 // create or update the debug sentinel file to trigger a
                 // debug timeout update across all instances
-                string debugSentinelFileName = Path.Combine(_scriptOptions.CurrentValue.LogPath, "Host", ScriptConstants.DebugSentinelFileName);
+                string debugSentinelDirectory = Path.Combine(_scriptOptions.CurrentValue.LogPath, "Host");
+                string debugSentinelFileName = Path.Combine(debugSentinelDirectory, ScriptConstants.DebugSentinelFileName);
                 if (!File.Exists(debugSentinelFileName))
                 {
+                    FileUtility.EnsureDirectoryExists(debugSentinelDirectory);
                     File.WriteAllText(debugSentinelFileName, "This is a system managed marker file used to control runtime debug mode behavior.");
                 }
                 else

src/WebJobs.Script/Host/ScriptHost.cs

@@ -39,6 +39,7 @@ namespace Microsoft.Azure.WebJobs.Script
     public class ScriptHost : JobHost, IScriptJobHost
     {
         internal const int DebugModeTimeoutMinutes = 15;
+        private const int FileSystemCleanupDelay = 30;
         private const string HostAssemblyName = "ScriptHost";
         private const string GeneratedTypeNamespace = "Host";
         internal const string GeneratedTypeName = "Functions";
@@ -47,6 +48,7 @@ public class ScriptHost : JobHost, IScriptJobHost
         private readonly string _storageConnectionString;
         private readonly IDistributedLockManager _distributedLockManager;
         private readonly IFunctionMetadataManager _functionMetadataManager;
+        private readonly IFileLoggingStatusManager _fileLoggingStatusManager;
         private readonly IHostIdProvider _hostIdProvider;
         private readonly IHttpRoutesManager _httpRoutesManager;
         private readonly IProxyMetadataManager _proxyMetadataManager;
@@ -91,6 +93,7 @@ public ScriptHost(IOptions<JobHostOptions> options,
             ILoggerFactory loggerFactory,
             IFunctionInvocationDispatcherFactory functionDispatcherFactory,
             IFunctionMetadataManager functionMetadataManager,
+            IFileLoggingStatusManager fileLoggingStatusManager,
             IProxyMetadataManager proxyMetadataManager,
             IMetricsLogger metricsLogger,
             IOptions<ScriptJobHostOptions> scriptHostOptions,
@@ -116,6 +119,7 @@ public ScriptHost(IOptions<JobHostOptions> options,
             _storageConnectionString = configuration.GetWebJobsConnectionString(ConnectionStringNames.Storage);
             _distributedLockManager = distributedLockManager;
             _functionMetadataManager = functionMetadataManager;
+            _fileLoggingStatusManager = fileLoggingStatusManager;
             _applicationLifetime = applicationLifetime;
             _hostIdProvider = hostIdProvider;
             _httpRoutesManager = httpRoutesManager;
@@ -296,7 +300,7 @@ public async Task InitializeAsync(CancellationToken cancellationToken = default)
 
                 GenerateFunctions(directTypes);
 
-                CleanupFileSystem();
+                ScheduleFileSystemCleanup();
             }
         }
 
@@ -445,7 +449,10 @@ private void PreInitialize()
         /// </summary>
         private void InitializeFileSystem()
         {
-            FileUtility.EnsureDirectoryExists(_hostLogPath);
+            if (_fileLoggingStatusManager.IsFileLoggingEnabled)
+            {
+                FileUtility.EnsureDirectoryExists(_hostLogPath);
+            }
 
             if (!_environment.IsFileSystemReadOnly())
             {
@@ -521,14 +528,15 @@ private void AddFunctionDescriptors()
         /// <summary>
         /// Clean up any old files or directories.
         /// </summary>
-        private void CleanupFileSystem()
+        private void ScheduleFileSystemCleanup()
         {
-            if (ScriptOptions.FileLoggingMode != FileLoggingMode.Never)
+            Utility.ExecuteAfterDelay(() =>
             {
-                // initiate the cleanup in a background task so we don't
-                // delay startup
-                Task.Run(() => PurgeOldLogDirectories());
-            }
+                if (ScriptOptions.FileLoggingMode != FileLoggingMode.Never)
+                {
+                    PurgeOldLogDirectories();
+                }
+            }, TimeSpan.FromSeconds(FileSystemCleanupDelay));
         }
 
         /// <summary>

src/WebJobs.Script/Utility.cs

@@ -681,6 +681,17 @@ public static bool CheckAppOffline(IEnvironment environment, string scriptPath)
             return false;
         }
 
+        public static void ExecuteAfterDelay(Action targetAction, TimeSpan delay, CancellationToken cancellationToken = default)
+        {
+            Task.Delay(delay, cancellationToken).ContinueWith(_ =>
+            {
+                if (!cancellationToken.IsCancellationRequested)
+                {
+                    targetAction();
+                }
+            }, TaskContinuationOptions.OnlyOnRanToCompletion);
+        }
+
         public static bool TryCleanUrl(string url, out string cleaned)
         {
             cleaned = null;

test/WebJobs.Script.Tests/ScriptHostTests.cs

@@ -89,17 +89,36 @@ public void LoadHostConfig_ParseError_Throws()
         [Fact]
         public static async Task OnDebugModeFileChanged_TriggeredWhenDebugFileUpdated()
         {
+            var loggerProvider = new TestLoggerProvider();
+            var loggerFactory = new LoggerFactory();
+            loggerFactory.AddProvider(loggerProvider);
+
             var host = new HostBuilder()
-                .ConfigureDefaultTestWebScriptHost(runStartupHostedServices: true)
+                 .ConfigureDefaultTestWebScriptHost(_ => { },
+                options =>
+                {
+                    options.ScriptPath = Path.GetTempPath();
+                    options.LogPath = Path.GetTempPath();
+                },
+                runStartupHostedServices: true,
+                rootServices =>
+                {
+                    rootServices.AddSingleton<ILoggerFactory>(loggerFactory);
+                })
+                .ConfigureServices(s =>
+                {
+                    s.AddSingleton<ILoggerFactory>(loggerFactory);
+                })
                 .Build();
 
             ScriptHost scriptHost = host.GetScriptHost();
-            string debugSentinelFilePath = Path.Combine(scriptHost.ScriptOptions.RootLogPath, "Host", ScriptConstants.DebugSentinelFileName);
 
-            // Write the initial file.
+            string debugSentinelDirectory = Path.Combine(scriptHost.ScriptOptions.RootLogPath, "Host");
+            string debugSentinelFilePath = Path.Combine(debugSentinelDirectory, ScriptConstants.DebugSentinelFileName);
             if (!File.Exists(debugSentinelFilePath))
             {
-                File.WriteAllText(debugSentinelFilePath, string.Empty);
+                FileUtility.EnsureDirectoryExists(debugSentinelDirectory);
+                File.WriteAllText(debugSentinelFilePath, "This is a system managed marker file used to control runtime debug mode behavior.");
             }
 
             // first put the host into a non-debug state
@@ -114,6 +133,12 @@ await TestHelpers.Await(() =>
             },
             userMessageCallback: () => $"Expected InDebugMode to be false. Now: {DateTime.UtcNow}; Sentinel LastWriteTime: {File.GetLastWriteTimeUtc(debugSentinelFilePath)}; LastDebugNotify: {debugState.LastDebugNotify}.");
 
+            // File Watchers for debug and diagnostic task are delayed during startup.
+            await TestHelpers.Await(() =>
+            {
+                return loggerProvider.GetAllLogMessages().Any(m => m.FormattedMessage.Contains("Debug file watch initialized."));
+            }, timeout: 30000, userMessageCallback: () => $"File watchers did not initialize in time");
+
             // verify that our file watcher for the debug sentinel file is configured
             // properly by touching the file and ensuring that our host goes into
             // debug mode
@@ -173,7 +198,11 @@ public void NotifyDebug_UpdatesDebugMarkerFileAndTimestamp()
             var debugManager = _fixture.Host.Services.GetService<IDebugManager>();
 
             string debugSentinelFileName = Path.Combine(host.ScriptOptions.RootLogPath, "Host", ScriptConstants.DebugSentinelFileName);
-            File.Delete(debugSentinelFileName);
+            if (File.Exists(debugSentinelFileName))
+            {
+                File.Delete(debugSentinelFileName);
+            }
+
             debugState.LastDebugNotify = DateTime.MinValue;
 
             Assert.False(host.InDebugMode);