Add performance summary

* Reduced default log output, http get/push calls will now only be shown on verbose mode.
* Performance summary displays where time was spent during push operations.
* Push batch support. Instead of pushing possibly hundreds of thousands of packages at once push will now load nupkgs in batches and process them to avoid running out of memory.
* Files are now ordered during upload. Index files will be pushed last to help avoid conflicts on the client when the feed is still incomplete.
* Increased the delay for obtaining a file lock on azure feeds. Cleaned up file lock logging.

Author: emgarten

ReleaseNotes.md

@@ -1,5 +1,12 @@
 # Release Notes
 
+## 2.3.73
+* Reduced default log output, http get/push calls will now only be shown on verbose mode.
+* Performance summary displays where time was spent during push operations.
+* Push batch support. Instead of pushing possibly hundreds of thousands of packages at once push will now load nupkgs in batches and process them to avoid running out of memory.
+* Files are now ordered during upload. Index files will be pushed last to help avoid conflicts on the client when the feed is still incomplete.
+* Increased the delay for obtaining a file lock on azure feeds. Cleaned up file lock logging.
+
 ## 2.3.36
 * Path property in sleet.json can now be a relative path for local feeds
 

build/config.props

@@ -24,7 +24,7 @@
     <RepositoryUrl>https://github.com/emgarten/Sleet</RepositoryUrl>
     <PackageTags>nuget nugetserver nugetfeed</PackageTags>
     <Description>Sleet creates nuget v3.0.0 nupkg feeds.</Description>
-    <Copyright>Copyright © 2017 Justin Emgarten</Copyright>
+    <Copyright>Copyright © 2019 Justin Emgarten</Copyright>
     <PackageIconUrl>https://emgartenstatic.blob.core.windows.net/nupkgs/icons/sleet.png</PackageIconUrl>
   </PropertyGroup>
 

src/Sleet/DeleteAppCommand.cs

@@ -50,7 +50,7 @@ private static void Run(CommandLineApplication cmd, ILogger log)
                 Util.SetVerbosity(log, verbose.HasValue());
 
                 // Create a temporary folder for caching files during the operation.
-                using (var cache = new LocalCache())
+                using (var cache = new LocalCache(new PerfTracker()))
                 {
                     // Load settings and file system.
                     var settings = LocalSettings.Load(optionConfigFile.Value(), SettingsUtility.GetPropertyMappings(propertyOptions.Values));

src/Sleet/Program.cs

@@ -10,7 +10,7 @@ public class Program
     {
         public static int Main(string[] args)
         {
-            var logLevel = LogLevel.Minimal;
+            var logLevel = Util.DefaultLogLevel;
 
             if (CmdUtils.IsDebugModeEnabled())
             {

src/Sleet/PushAppCommand.cs

@@ -54,7 +54,7 @@ private static void Run(CommandLineApplication cmd, ILogger log)
                 Util.SetVerbosity(log, verbose.HasValue());
 
                 // Create a temporary folder for caching files during the operation.
-                using (var cache = new LocalCache())
+                using (var cache = new LocalCache(new PerfTracker()))
                 {
                     // Load settings and file system.
                     var settings = LocalSettings.Load(optionConfigFile.Value(), SettingsUtility.GetPropertyMappings(propertyOptions.Values));

src/Sleet/Sleet.nuspec

@@ -9,7 +9,7 @@
     <licenseUrl>https://github.com/emgarten/Sleet/blob/master/LICENSE.md</licenseUrl>
     <projectUrl>https://github.com/emgarten/Sleet/</projectUrl>
     <description>Sleet is a static feed generator for NuGet package feeds.</description>
-    <copyright>Copyright © 2017 Justin Emgarten</copyright>
+    <copyright>Copyright © 2019 Justin Emgarten</copyright>
     <tags>nuget nugetserver nugetfeed</tags>
     <repository type="git" url="https://github.com/emgarten/Sleet" branch="$branch$" commit="$commit$" />
     <developmentDependency>true</developmentDependency>

src/Sleet/Util.cs

@@ -7,6 +7,8 @@ namespace Sleet
 {
     internal static class Util
     {
+        internal static LogLevel DefaultLogLevel = LogLevel.Information;
+
         internal static ISleetFileSystem CreateFileSystemOrThrow(LocalSettings settings, string sourceName, LocalCache cache)
         {
             var sourceNamePassed = !string.IsNullOrEmpty(sourceName);
@@ -83,7 +85,7 @@ internal static void SetVerbosity(ILogger log, bool verbose)
                 }
                 else
                 {
-                    consoleLogger.VerbosityLevel = LogLevel.Information;
+                    consoleLogger.VerbosityLevel = DefaultLogLevel;
                     consoleLogger.CollapseMessages = true;
                 }
             }

src/SleetLib/Commands/PushCommand.cs

@@ -1,38 +1,70 @@
 using System;
 using System.Collections.Generic;
 using System.IO;
-using System.IO.Compression;
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 using NuGet.Common;
-using NuGet.Packaging;
-using NuGet.Packaging.Core;
 
 namespace Sleet
 {
     public static class PushCommand
     {
+        public const int DefaultBatchSize = 4096;
+
         public static async Task<bool> RunAsync(LocalSettings settings, ISleetFileSystem source, List<string> inputs, bool force, bool skipExisting, ILogger log)
         {
             var token = CancellationToken.None;
             var now = DateTimeOffset.UtcNow;
-            var packages = new List<PackageInput>();
+            var success = false;
+            var perfTracker = source.LocalCache.PerfTracker;
 
             await log.LogAsync(LogLevel.Minimal, $"Reading feed {source.BaseURI.AbsoluteUri}");
 
-            // Read packages before locking the feed.
-            packages.AddRange(await GetPackageInputs(inputs, now, log));
-
-            // Check if already initialized
-            using (var feedLock = await SourceUtility.VerifyInitAndLock(settings, source, log, token))
+            using (var timer = PerfEntryWrapper.CreateSummaryTimer("Total execution time: {0}", perfTracker))
             {
-                // Validate source
-                await SourceUtility.ValidateFeedForClient(source, log, token);
+                // Partition package inputs to avoid reading 100K nuspecs at the same time.
+                var packagePaths = GetPackagePaths(inputs);
+                var inputBatches = packagePaths.Partition(DefaultBatchSize);
+                ISleetFileSystemLock feedLock = null;
 
-                // Push
-                return await PushPackages(settings, source, packages, force, skipExisting, log, token);
+                try
+                {
+                    for (var i = 0; i < inputBatches.Count; i++)
+                    {
+                        var inputBatch = inputBatches[i];
+                        if (inputBatches.Count > 1)
+                        {
+                            await log.LogAsync(LogLevel.Minimal, $"Pushing {inputBatch.Count} packages. Batch: {i+1} / {inputBatches.Count}");
+                        }
+
+                        // Read packages before locking the feed the first time.
+                        var packages = new List<PackageInput>(await GetPackageInputs(inputBatch, now, perfTracker, log));
+
+                        if (feedLock == null)
+                        {
+                            // Check if already initialized
+                            feedLock = await SourceUtility.VerifyInitAndLock(settings, source, log, token);
+
+                            // Validate source
+                            await SourceUtility.ValidateFeedForClient(source, log, token);
+                        }
+
+                        // Push
+                        success = await PushPackages(settings, source, packages, force, skipExisting, log, token);
+                    }
+                }
+                finally
+                {
+                    // Unlock the feed
+                    feedLock?.Dispose();
+                }
             }
+
+            // Write out perf summary
+            await perfTracker.LogSummary(log);
+
+            return success;
         }
 
         /// <summary>
@@ -42,13 +74,23 @@ public static async Task<bool> RunAsync(LocalSettings settings, ISleetFileSystem
         public static async Task<bool> PushPackages(LocalSettings settings, ISleetFileSystem source, List<string> inputs, bool force, bool skipExisting, ILogger log, CancellationToken token)
         {
             var now = DateTimeOffset.UtcNow;
-            var packages = new List<PackageInput>();
+            var success = true;
 
-            // Get packages
-            packages.AddRange(await GetPackageInputs(inputs, now, log));
+            var packagePaths = GetPackagePaths(inputs);
 
-            // Add packages
-            return await PushPackages(settings, source, packages, force, skipExisting, log, token);
+            // Partition input files to avoid reading 100K nuspec files at once.
+            foreach (var inputSegment in packagePaths.Partition(DefaultBatchSize))
+            {
+                var packages = new List<PackageInput>();
+
+                // Get packages
+                packages.AddRange(await GetPackageInputs(inputSegment, now, source.LocalCache.PerfTracker, log));
+
+                // Add packages
+                success &= await PushPackages(settings, source, packages, force, skipExisting, log, token);
+            }
+
+            return success;
         }
 
         /// <summary>
@@ -74,10 +116,11 @@ public static async Task<bool> PushPackages(LocalSettings settings, ISleetFileSy
                 SourceSettings = sourceSettings,
                 Log = log,
                 Source = source,
-                Token = token
+                Token = token,
+                PerfTracker = source.LocalCache.PerfTracker
             };
 
-            await log.LogAsync(LogLevel.Information, "Reading existing package index");
+            await log.LogAsync(LogLevel.Verbose, "Reading existing package index");
 
             var packageIndex = new PackageIndex(context);
             await PushPackages(packages, context, packageIndex, force, skipExisting, log);
@@ -122,9 +165,6 @@ private static async Task PushPackages(List<PackageInput> packageInputs, SleetCo
                     }
                 }
 
-                await log.LogAsync(LogLevel.Minimal, $"Pushing {packageString}");
-                await log.LogAsync(LogLevel.Information, $"Checking if package exists.");
-
                 var exists = false;
 
                 if (package.IsSymbolsPackage)
@@ -140,26 +180,29 @@ private static async Task PushPackages(List<PackageInput> packageInputs, SleetCo
                 {
                     if (skipExisting)
                     {
-                        await log.LogAsync(LogLevel.Minimal, $"Package already exists, skipping {packageString}");
+                        await log.LogAsync(LogLevel.Minimal, $"Skip exisiting package: {packageString}");
                         continue;
                     }
                     else if (force)
                     {
                         toRemove.Add(package);
-                        await log.LogAsync(LogLevel.Information, $"Package already exists, removing {packageString}");
+                        await log.LogAsync(LogLevel.Information, $"Replace existing package: {packageString}");
                     }
                     else
                     {
                         throw new InvalidOperationException($"Package already exists: {packageString}.");
                     }
                 }
+                else
+                {
+                    await log.LogAsync(LogLevel.Minimal, $"Add new package: {packageString}");
+                }
 
                 // Add to list of packages to push
                 toAdd.Add(package);
-                await log.LogAsync(LogLevel.Information, $"Adding {packageString}");
             }
 
-            await log.LogAsync(LogLevel.Minimal, $"Syncing feed files and modifying them locally");
+            await log.LogAsync(LogLevel.Minimal, $"Processing feed changes");
 
             // Add/Remove packages
             var changeContext = SleetOperations.Create(existingPackageSets, toAdd, toRemove);
@@ -169,7 +212,18 @@ private static async Task PushPackages(List<PackageInput> packageInputs, SleetCo
         /// <summary>
         /// Parse input arguments for nupkg paths.
         /// </summary>
-        private static async Task<List<PackageInput>> GetPackageInputs(List<string> inputs, DateTimeOffset now, ILogger log)
+        private static async Task<List<PackageInput>> GetPackageInputs(List<string> packagePaths, DateTimeOffset now, IPerfTracker perfTracker, ILogger log)
+        {
+            using (var timer = PerfEntryWrapper.CreateSummaryTimer("Loaded package nuspecs in {0}", perfTracker))
+            {
+                var tasks = packagePaths.Select(e => new Func<Task<PackageInput>>(() => GetPackageInput(e, log)));
+                var packageInputs = await TaskUtils.RunAsync(tasks, useTaskRun: true, token: CancellationToken.None);
+                var packagesSorted = packageInputs.OrderBy(e => e).ToList();
+                return packagesSorted;
+            }
+        }
+
+        private static List<string> GetPackagePaths(List<string> inputs)
         {
             // Check inputs
             if (inputs.Count < 1)
@@ -178,15 +232,9 @@ private static async Task<List<PackageInput>> GetPackageInputs(List<string> inpu
             }
 
             // Get package inputs
-            var packagePaths = inputs.SelectMany(GetFiles)
-                .Distinct(PathUtility.GetStringComparerBasedOnOS())
-                .ToList();
-
-            var tasks = packagePaths.Select(e => new Func<Task<PackageInput>>(() => GetPackageInput(e, log)));
-            var packageInputs = await TaskUtils.RunAsync(tasks, useTaskRun: true, token: CancellationToken.None);
-            var packagesSorted = packageInputs.OrderBy(e => e).ToList();
-
-            return packagesSorted;
+            return inputs.SelectMany(GetFiles)
+               .Distinct(PathUtility.GetStringComparerBasedOnOS())
+               .ToList();
         }
 
         private static void CheckForDuplicates(List<PackageInput> packages)
@@ -206,7 +254,7 @@ private static void CheckForDuplicates(List<PackageInput> packages)
         private static Task<PackageInput> GetPackageInput(string file, ILogger log)
         {
             // Validate package
-            log.LogInformation($"Reading {file}");
+            log.LogVerbose($"Reading {file}");
             PackageInput packageInput = null;
 
             try
@@ -219,7 +267,7 @@ private static Task<PackageInput> GetPackageInput(string file, ILogger log)
                 log.LogError($"Invalid package '{file}'.");
                 throw;
             }
-            
+
             // Display a message for non-normalized packages
             if (packageInput.Identity.Version.ToString() != packageInput.Identity.Version.ToNormalizedString())
             {

src/SleetLib/Common/SleetFileComparer.cs

@@ -0,0 +1,82 @@
+using System;
+using System.Collections.Generic;
+using System.IO;
+using System.Linq;
+
+namespace Sleet
+{
+    /// <summary>
+    /// Order files in a way that helps avoid clients discovering packages from index files
+    /// before the package files have been uploaded.
+    ///
+    /// Order of upload:
+    /// 1) Nupkg/nuspec files, these are usually the largest and slowest files
+    /// 2) Misc files such as package details pages and catalog entry pages.
+    /// 3) index.json files
+    /// 4) Search page
+    /// 
+    /// </summary>
+    public class SleetFileComparer : IComparer<ISleetFile>
+    {
+        public int Compare(ISleetFile x, ISleetFile y)
+        {
+            if (x == null)
+            {
+                throw new ArgumentNullException(nameof(x));
+            }
+
+            if (y == null)
+            {
+                throw new ArgumentNullException(nameof(y));
+            }
+
+            var priX = GetPriority(x);
+            var priY = GetPriority(y);
+
+            if (priX < priY)
+            {
+                return -1;
+            }
+
+            if (priX > priY)
+            {
+                return 1;
+            }
+
+            // Fallback to string compare
+            return StringComparer.OrdinalIgnoreCase.Compare(x.EntityUri.AbsoluteUri, y.EntityUri.AbsoluteUri);
+        }
+
+        private static int GetPriority(ISleetFile file)
+        {
+            var fileName = file.EntityUri.AbsoluteUri.Split(new[] { '/' }, StringSplitOptions.RemoveEmptyEntries).Last().ToLowerInvariant();
+
+            if (!string.IsNullOrEmpty(fileName))
+            {
+                if (fileName.IndexOf('.') > -1)
+                {
+                    var extension = Path.GetExtension(fileName).ToLowerInvariant();
+                    switch (extension)
+                    {
+                        case "nupkg":
+                            return 1;
+                        case "nuspec":
+                            return 2;
+                    }
+                }
+
+                switch (fileName)
+                {
+                    case "index.json":
+                        // Upload index.json files last after everything else is in place
+                        return 7;
+                    case "query":
+                        // Update search after index files
+                        return 8;
+                }
+            }
+
+            return 5;
+        }
+    }
+}