Merge pull request #2131 from github/feature/timer-logger-extensions

Add timer extension methods for ILogger

Author: grokys

src/GitHub.App/ViewModels/Dialog/Clone/RepositorySelectViewModel.cs

@@ -108,7 +108,8 @@ public async Task Activate()
 
             try
             {
-                var results = await service.ReadViewerRepositories(connection.HostAddress).ConfigureAwait(true);
+                var results = await log.TimeAsync(nameof(service.ReadViewerRepositories),
+                    () => service.ReadViewerRepositories(connection.HostAddress));
 
                 var yourRepositories = results.Repositories
                     .Where(r => r.Owner == results.Owner)
@@ -121,6 +122,7 @@ public async Task Activate()
                     .OrderBy(x => x.Key)
                     .SelectMany(x => x.Value.Select(y => new RepositoryItemViewModel(y, x.Key)));
                 Items = yourRepositories.Concat(collaboratorRepositories).Concat(orgRepositories).ToList();
+                log.Information("Read {Total} viewer repositories", Items.Count);
                 ItemsView = CollectionViewSource.GetDefaultView(Items);
                 ItemsView.GroupDescriptions.Add(new PropertyGroupDescription(nameof(RepositoryItemViewModel.Group)));
                 ItemsView.Filter = FilterItem;

src/GitHub.InlineReviews/Services/PullRequestSessionService.cs

@@ -97,7 +97,7 @@ public IReadOnlyList<InlineAnnotationModel> BuildAnnotations(
             relativePath = relativePath.Replace("\\", "/");
 
             return pullRequest.CheckSuites
-                ?.SelectMany(checkSuite => checkSuite.CheckRuns.Select(checkRun => new { checkSuite, checkRun}))
+                ?.SelectMany(checkSuite => checkSuite.CheckRuns.Select(checkRun => new { checkSuite, checkRun }))
                 .SelectMany(arg =>
                     arg.checkRun.Annotations
                         .Where(annotation => annotation.Path == relativePath)
@@ -361,17 +361,21 @@ public virtual async Task<PullRequestDetailModel> ReadPullRequestDetail(HostAddr
             var result = await connection.Run(readPullRequest, vars);
 
             var apiClient = await apiClientFactory.Create(address);
-            var files = await apiClient.GetPullRequestFiles(owner, name, number).ToList();
-            var lastCommitModel = await GetPullRequestLastCommitAdapter(address, owner, name, number);
 
-            result.Statuses = (IReadOnlyList<StatusModel>) lastCommitModel.Statuses ?? Array.Empty<StatusModel>();
+            var files = await log.TimeAsync(nameof(apiClient.GetPullRequestFiles),
+                async () => await apiClient.GetPullRequestFiles(owner, name, number).ToList());
+
+            var lastCommitModel = await log.TimeAsync(nameof(GetPullRequestLastCommitAdapter),
+                () => GetPullRequestLastCommitAdapter(address, owner, name, number));
+
+            result.Statuses = (IReadOnlyList<StatusModel>)lastCommitModel.Statuses ?? Array.Empty<StatusModel>();
 
             if (lastCommitModel.CheckSuites == null)
             {
                 result.CheckSuites = Array.Empty<CheckSuiteModel>();
             }
             else
-            { 
+            {
                 result.CheckSuites = lastCommitModel.CheckSuites;
                 foreach (var checkSuite in result.CheckSuites)
                 {
@@ -838,8 +842,8 @@ async Task<LastCommitAdapter> GetPullRequestLastCommitAdapter(HostAddress addres
                          commit => new LastCommitAdapter
                          {
                              Statuses = commit.Commit.Status == null ? null : commit.Commit.Status
-                                 .Select(context => context == null 
-                                     ? null 
+                                 .Select(context => context == null
+                                     ? null
                                      : context.Contexts
                                          .Select(statusContext => new StatusModel
                                          {
@@ -871,7 +875,7 @@ async Task<LastCommitAdapter> GetPullRequestLastCommitAdapter(HostAddress addres
         static void BuildPullRequestThreads(PullRequestDetailModel model)
         {
             var commentsByReplyId = new Dictionary<string, List<CommentAdapter>>();
-           
+
             // Get all comments that are not replies.
             foreach (CommentAdapter comment in model.Reviews.SelectMany(x => x.Comments))
             {
@@ -961,5 +965,5 @@ class LastCommitAdapter
 
             public string HeadSha { get; set; }
         }
-    }   
+    }
 }

src/GitHub.Logging/Logging/ILoggerExtensions.cs

@@ -1,3 +1,6 @@
+using System;
+using System.Globalization;
+using System.Threading.Tasks;
 using Serilog;
 
 namespace GitHub.Logging
@@ -25,5 +28,37 @@ public static void Assert(this ILogger logger, bool condition, string messageTem
 #pragma warning restore Serilog004
             }
         }
+
+        public static void Time(this ILogger logger, string name, Action method)
+        {
+            var startTime = DateTime.Now;
+            method();
+            logger.Verbose("{Name} took {Seconds} seconds", name, FormatSeconds(DateTime.Now - startTime));
+        }
+
+        public static T Time<T>(this ILogger logger, string name, Func<T> method)
+        {
+            var startTime = DateTime.Now;
+            var value = method();
+            logger.Verbose("{Name} took {Seconds} seconds", name, FormatSeconds(DateTime.Now - startTime));
+            return value;
+        }
+
+        public static async Task TimeAsync(this ILogger logger, string name, Func<Task> methodAsync)
+        {
+            var startTime = DateTime.Now;
+            await methodAsync().ConfigureAwait(false);
+            logger.Verbose("{Name} took {Seconds} seconds", name, FormatSeconds(DateTime.Now - startTime));
+        }
+
+        public static async Task<T> TimeAsync<T>(this ILogger logger, string name, Func<Task<T>> methodAsync)
+        {
+            var startTime = DateTime.Now;
+            var value = await methodAsync().ConfigureAwait(false);
+            logger.Verbose("{Name} took {Seconds} seconds", name, FormatSeconds(DateTime.Now - startTime));
+            return value;
+        }
+
+        static string FormatSeconds(TimeSpan timeSpan) => timeSpan.TotalSeconds.ToString("0.##", CultureInfo.InvariantCulture);
     }
-}
+}