optim(redmine): hour stats are also improved

Blueberry.Redmine/RedmineApiClient.cs

@@ -1,6 +1,7 @@
 using Blueberry.Redmine.Dto;
 using Microsoft.Extensions.Logging;
 using System.ComponentModel.DataAnnotations;
+using System.Diagnostics;
 using System.Runtime.InteropServices;
 using System.Text;
 using System.Text.Json;
@@ -118,11 +119,14 @@ namespace Blueberry.Redmine
         private async Task<List<TReturn>> SendRequestWithPagingAsync<TResponse, TReturn>(HttpMethod method, string endpoint, int limit, Func<TResponse, List<TReturn>> itemParser,
             IProgress<(int current, int total)>? progress = null, object? payload = null, CancellationToken? token = null) where TResponse : IResponseList
         {
+            var sw = new Stopwatch();
+            sw.Start();
+
             var offset = 0;
 
             List<TReturn> returnList = [];
 
-            _logger.LogDebug("Starting paged request to {Endpoint} with limit {Limit}", endpoint, limit);
+            _logger.LogDebug("Starting paged request to {Endpoint} with limit {Limit}", endpoint.Split('?')[0], limit);
 
             var path = "";
             if (endpoint.Contains('?'))
@@ -131,7 +135,7 @@ namespace Blueberry.Redmine
                 path = $"{endpoint}?limit={limit}&offset={offset}";
 
             var responseList = await SendRequestAsync<TResponse>(HttpMethod.Get, path, token: token)
-                        ?? throw new NullReferenceException();
+                ?? throw new NullReferenceException();
 
             var total = responseList.TotalCount;
 
@@ -140,16 +144,20 @@ namespace Blueberry.Redmine
             offset += limit;
 
             if (offset >= responseList.TotalCount)
+            {
+                _logger.LogDebug("  + Single request retrieved all {TotalItems} items", returnList.Count);
                 return returnList;
+            }
 
             var remain = total - offset;
 
             var tasks = new Task[(int)Math.Ceiling((double)remain / limit)];
 
-            _logger.LogDebug("Spawning {TaskCount} tasks for remaining {Remaining} items out of {Total}", tasks.Length, remain, total);
-
             List<(int id, IEnumerable<TReturn> items)> responses = [];
 
+            var preparationTime = sw.ElapsedMilliseconds;
+            sw.Restart();
+
             for (int i = 0; i < tasks.Length; i++)
             {
                 var id = i;
@@ -178,25 +186,32 @@ namespace Blueberry.Redmine
                     progress.Report((current, tasks.Length));
                 }
 
-                var completed = tasks.Count(t => t.IsCompleted);
-                _logger.LogDebug("{Completed}/{Total} tasks completed", completed, tasks.Length);
                 await Task.Delay(250);
             }
 
             await Task.WhenAll(tasks);
-            await Task.Delay(100);
-
-            var notCompleted = tasks.Where(t => !t.IsCompletedSuccessfully).ToList();
-            _logger.LogDebug("{NotCompleted} tasks did not complete successfully", notCompleted.Count);
-
-            _logger.LogDebug("All tasks completed, aggregating {total} results from {count} responses", responses.Select(x=>x.items).Count(), responses.Count);
+            await Task.Delay(50);
+            var executionTime = sw.ElapsedMilliseconds;
+            sw.Restart();
 
             foreach (var resp in responses.OrderBy(x => x.id))
             {
                 returnList.AddRange(resp.items);
             }
 
-            _logger.LogDebug("Aggregated total of {TotalItems} items", returnList.Count);
+            _logger.LogDebug("  + Aggregated total of {TotalItems} items from {Count} responses", returnList.Count, responses.Count);
+
+            var aggregationTime = sw.ElapsedMilliseconds;
+            sw.Stop();
+
+            // log times
+            _logger.LogDebug("  + Paging completed in:\n        Preparation: {Preparation}ms\n        Execution:   {Execution}ms\n        Aggregation: {Aggregation}ms\n        Total:       {Total}ms"
+                , preparationTime, executionTime, aggregationTime, preparationTime + executionTime + aggregationTime);
+
+            // log avarege time per task and per item, round them to whole ms
+            _logger.LogDebug("  + Average time per task: {AvgTask}ms, Average time per item: {AvgItem}ms", 
+                Math.Round((double)(preparationTime + executionTime) / tasks.Length + 1), 
+                Math.Round((double)(executionTime) / returnList.Count));
 
             return returnList;
         }