Fix measuring time during work item migration (#2736)

A have already fixed this in PR #2706 but it was broken (basically
reverted) back in #2712. Now the processing of 10 000 items says, it
will finish in 4 minutes and this time rapidly decreases – after
processing 1000 items, the remainig time is only only 1 minute.

There are two main problems.

The duration of activity is not measured, but set to fixed time of 10
seconds using
`activity?.SetEndTime(activity.StartTimeUtc.AddSeconds(10));`. I assume,
that you did it because the `Duration` was zero when you accessed it
when calculating `average`. This is because the `Duration` is not
dynamic – it will not retur actual duration of activity. It is possible
to set it directly to some fixed time with `SetEndTime`. But in our case
when we need real duration of activity, we must stop it. When
`activity.Stop()` is called, `Duration` is set to real time it has taken
and so we need to stop the activity before we access `Duration`.

The second problem si calculating average and remaining time. In
description of #2712 you wrote:

> Removed the `ProgressTimer` class and associated logic, replacing it
with simpler calculations for average and remaining time during work
item processing.

It is not possible to count average and remaining time during work item
processing, because that is processing of just single one work item –
that means, the duration of activity you count with is just the duration
of processing 1 item. There is no information about how long all the
processing already took.

So say the processing is stable and to process one item always takes 1
second. This value is `activity.Duration`. Now you calculate average as:

`var average = new TimeSpan(0, 0, 0, 0,
(int)(activity.Duration.TotalMilliseconds / _current));`

So if first item was processed, average time is 1 / 1 that means 1 s. If
second item is processed, average time is 1 / 2 = 0,5 s. After 10
processed item the average is 1 / 10 = 0,1 s. So every processed item
decreases average time even if the processing takes always the same
time.

We really need something _above_ the one processed item and that is the
`ProgressTimer` class. Because we need to track cumulative processing
time of every item and calculate average as this cumulative time divided
by processed items. And this class also handles retrying, so if the item
is processed three times (two times failed), it is taken into account.

Author: MrHinsh

src/MigrationTools.Clients.TfsObjectModel/Processors/TfsWorkItemMigrationProcessor.cs

@@ -37,6 +37,35 @@ namespace MigrationTools.Processors
     /// <processingtarget>Work Items</processingtarget>
     public class TfsWorkItemMigrationProcessor : TfsProcessor
     {
+        private class ProgressTimer
+        {
+            private TimeSpan _totalProcessedTime = TimeSpan.Zero;
+
+            public ProgressTimer(int totalCount)
+            {
+                TotalCount = totalCount;
+            }
+
+            public int TotalCount { get; private set; }
+            public int ProcessedCount { get; private set; }
+            public TimeSpan TotalProcessedTime => _totalProcessedTime;
+
+            public void AddProcessedItem(TimeSpan processDuration, bool addToTotal)
+            {
+                if (addToTotal)
+                {
+                    TotalCount++;
+                }
+                ProcessedCount++;
+                _totalProcessedTime += processDuration;
+            }
+
+            public TimeSpan AverageTime => ProcessedCount > 0
+                ? TimeSpan.FromSeconds(TotalProcessedTime.TotalSeconds / ProcessedCount)
+                : TotalProcessedTime;
+
+            public TimeSpan RemainingTime => TimeSpan.FromTicks(AverageTime.Ticks * (TotalCount - ProcessedCount));
+        }
 
         private static int _count = 0;
         private static int _current = 0;
@@ -147,6 +176,8 @@ protected override void InternalExecute()
                 _current = 1;
                 _count = sourceWorkItems.Count;
                 _totalWorkItem = sourceWorkItems.Count;
+                ProgressTimer progressTimer = new ProgressTimer(_totalWorkItem);
+
                 ProcessorActivity.SetTag("source_workitems_to_process", sourceWorkItems.Count);
                 foreach (WorkItemData sourceWorkItemData in sourceWorkItems)
                 {
@@ -163,7 +194,7 @@ protected override void InternalExecute()
                     {
                         try
                         {
-                            ProcessWorkItemAsync(sourceWorkItemData, Options.WorkItemCreateRetryLimit).Wait();
+                            ProcessWorkItemAsync(sourceWorkItemData, progressTimer, Options.WorkItemCreateRetryLimit).Wait();
 
                             stopwatch.Stop();
                             var processingTime = stopwatch.Elapsed.TotalMilliseconds;
@@ -407,7 +438,6 @@ private WorkItemData CreateWorkItem_Shell(ProjectData destProject, WorkItemData
                 activity?.SetTagsFromOptions(Options);
                 activity?.SetTag("http.request.method", "GET");
                 activity?.SetTag("migrationtools.client", "TfsObjectModel");
-                activity?.SetEndTime(activity.StartTimeUtc.AddSeconds(10));
 
                 WorkItem newwit;
                 if (destProject.ToProject().WorkItemTypes.Contains(destType))
@@ -580,14 +610,13 @@ private void ProcessWorkItemEmbeddedLinks(WorkItemData sourceWorkItem, WorkItemD
             }
         }
 
-        private async Task ProcessWorkItemAsync(WorkItemData sourceWorkItem, int retryLimit = 5, int retries = 0)
+        private async Task ProcessWorkItemAsync(WorkItemData sourceWorkItem, ProgressTimer progressTimer, int retryLimit = 5, int retries = 0)
         {
             using (var activity = ActivitySourceProvider.ActivitySource.StartActivity("ProcessWorkItemAsync", ActivityKind.Client))
             {
                 activity?.SetTagsFromOptions(Options);
                 activity?.SetTag("http.request.method", "GET");
                 activity?.SetTag("migrationtools.client", "TfsObjectModel");
-                activity?.SetEndTime(activity.StartTimeUtc.AddSeconds(10));
                 activity?.SetTag("SourceURL", Source.Options.Collection.ToString());
                 activity?.SetTag("SourceWorkItem", sourceWorkItem.Id);
                 activity?.SetTag("TargetURL", Target.Options.Collection.ToString());
@@ -676,7 +705,7 @@ private async Task ProcessWorkItemAsync(WorkItemData sourceWorkItem, int retryLi
                             {"Retrys", retries },
                             {"RetryLimit", retryLimit }
                             });
-                        await ProcessWorkItemAsync(sourceWorkItem, retryLimit, retries);
+                        await ProcessWorkItemAsync(sourceWorkItem, progressTimer, retryLimit, retries);
                     }
                     else
                     {
@@ -692,15 +721,15 @@ private async Task ProcessWorkItemAsync(WorkItemData sourceWorkItem, int retryLi
                     Telemetry.TrackException(ex, activity.Tags);
                     throw ex;
                 }
-                var average = new TimeSpan(0, 0, 0, 0, (int)(activity.Duration.TotalMilliseconds / _current));
-                var remaining = new TimeSpan(0, 0, 0, 0, (int)(average.TotalMilliseconds * _count));
+                activity?.Stop();
+                progressTimer.AddProcessedItem(activity.Duration, retries > 0);
                 TraceWriteLine(LogEventLevel.Information,
-                    "Average time of {average:%s}.{average:%fff} per work item and {remaining:%h} hours {remaining:%m} minutes {remaining:%s}.{remaining:%fff} seconds estimated to completion",
+                    "Average time of {average:%s}.{average:%fff} per work item and {remaining:%h} hours {remaining:%m} minutes {remaining:%s} seconds estimated to completion.",
                     new Dictionary<string, object>() {
-                    {"average", average},
-                    {"remaining", remaining}
+                        { "average", progressTimer.AverageTime },
+                        { "remaining", progressTimer.RemainingTime }
                     });
-                activity?.Stop();
+
                 activity?.SetStatus(ActivityStatusCode.Error);
                 activity?.SetTag("http.response.status_code", "200");