search

dotnet / efcore

EF Core is a modern object-database mapper for .NET. It supports LINQ queries, change tracking, updates, and schema migrations.
https://docs.microsoft.com/ef/
MIT License
13.63k stars 3.15k forks source link

DbContext does not clear ChangeTracker after SaveChanges #27670

Closed emanuelefirmani closed 1 year ago

emanuelefirmani commented 2 years ago

Description

I have a DB table with about 70k records. The table has 80 columns. I wrote a batch that updates them all. The batch has a loop that update one by one those records, using always the same DbContext

foreach (var jobNumber in _dbContext.Jobs.Where(x => x.LastUpdateUtc < minRefreshDate).Select(x => x.Number).ToList())
{
    _logger.Information("Start update of Job '{JobNumber}'", jobNumber);
    await UpdateJob(jobNumber, DateTime.MaxValue);

    var sw = Stopwatch.StartNew();
    _dbContext.SaveChanges();
    sw.Stop();

    _logger.Information("End update of Job '{JobNumber}'. Took {elapsedMs}ms", jobNumber, sw.ElapsedMilliseconds);
}

I experience a linear degradation of the execution, as reported by the logs below.

Resolution

I solved the issue by invoking _dbContext.ChangeTracker.Clear() right after invoking _dbContext.SaveChanges().

Proposed fix

Shouldn't the DbContext invoke _dbContext.ChangeTracker.Clear() automatically after a successful call to SaveChanges?

Provider and version information

EF Core version: 5.02 Database provider: Microsoft.EntityFrameworkCore.SqlServer Target framework: .NET 5.0 Operating system: Windows Server 2019 IDE: Rider 2021.3.3

Logs

I list only the "End update" entries, that report the time taken by SaveChanges.

Logs ``` 2022-03-18 15:00:59.232|End update of Job 'foo'. Took 2ms 2022-03-18 15:00:59.555|End update of Job 'foo'. Took 2ms 2022-03-18 15:00:59.815|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:01.148|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:01.399|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:01.681|End update of Job 'foo'. Took 32ms 2022-03-18 15:01:02.100|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:02.513|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:02.813|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:03.060|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:03.341|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:03.652|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:03.930|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:04.272|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:04.571|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:04.825|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:05.132|End update of Job 'foo'. Took 68ms 2022-03-18 15:01:05.508|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:05.757|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:06.065|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:06.316|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:06.593|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:06.876|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:07.104|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:07.577|End update of Job 'foo'. Took 2ms 2022-03-18 15:01:08.005|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:08.488|End update of Job 'foo'. Took 165ms 2022-03-18 15:01:08.733|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:09.062|End update of Job 'foo'. Took 35ms 2022-03-18 15:01:09.455|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:09.682|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:10.081|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:10.465|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:10.749|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:11.283|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:11.538|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:12.041|End update of Job 'foo'. Took 25ms 2022-03-18 15:01:12.307|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:12.583|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:13.231|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:13.655|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:13.914|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:14.219|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:14.708|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:14.960|End update of Job 'foo'. Took 3ms 2022-03-18 15:01:15.201|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:15.437|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:15.678|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:15.928|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:16.181|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:16.426|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:16.688|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:16.918|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:17.607|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:18.099|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:18.338|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:19.058|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:19.322|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:19.604|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:20.164|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:20.426|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:20.683|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:20.957|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:21.184|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:21.425|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:21.660|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:21.910|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:22.135|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:22.407|End update of Job 'foo'. Took 4ms 2022-03-18 15:01:22.648|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:22.902|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:23.390|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:23.846|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:24.091|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:24.525|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:24.773|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:25.020|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:25.264|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:25.522|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:25.803|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:26.050|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:26.294|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:26.561|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:26.793|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:27.076|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:27.327|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:27.694|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:27.958|End update of Job 'foo'. Took 5ms 2022-03-18 15:01:28.258|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:28.503|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:28.875|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:29.133|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:29.382|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:29.628|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:29.891|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:30.172|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:30.429|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:30.659|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:30.925|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:31.191|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:31.437|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:31.678|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:31.917|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:32.171|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:32.437|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:32.715|End update of Job 'foo'. Took 12ms 2022-03-18 15:01:32.992|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:33.269|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:33.510|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:33.762|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:34.056|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:34.415|End update of Job 'foo'. Took 6ms 2022-03-18 15:01:34.656|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:34.886|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:35.195|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:35.456|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:35.715|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:35.974|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:36.248|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:36.504|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:36.848|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:37.341|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:37.727|End update of Job 'foo'. Took 14ms 2022-03-18 15:01:37.988|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:38.248|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:38.487|End update of Job 'foo'. Took 7ms 2022-03-18 15:01:38.749|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:39.041|End update of Job 'foo'. Took 14ms 2022-03-18 15:01:39.309|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:39.552|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:39.799|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:40.071|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:40.306|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:40.560|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:40.817|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:41.088|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:41.474|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:41.721|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:41.956|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:42.297|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:42.577|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:42.947|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:43.210|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:43.441|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:43.677|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:43.931|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:44.197|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:44.441|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:44.696|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:45.052|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:45.287|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:45.559|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:45.823|End update of Job 'foo'. Took 8ms 2022-03-18 15:01:46.070|End update of Job 'foo'. Took 12ms 2022-03-18 15:01:46.375|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:46.633|End update of Job 'foo'. Took 14ms 2022-03-18 15:01:47.013|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:47.275|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:47.541|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:47.973|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:48.306|End update of Job 'foo'. Took 15ms 2022-03-18 15:01:48.572|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:48.814|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:49.076|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:49.318|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:49.556|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:49.800|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:50.065|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:50.314|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:50.559|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:50.804|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:51.064|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:51.330|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:51.648|End update of Job 'foo'. Took 9ms 2022-03-18 15:01:51.995|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:52.260|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:52.526|End update of Job 'foo'. Took 13ms 2022-03-18 15:01:52.770|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:53.018|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:53.511|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:53.780|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:54.051|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:54.334|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:54.595|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:54.869|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:55.147|End update of Job 'foo'. Took 12ms 2022-03-18 15:01:55.393|End update of Job 'foo'. Took 19ms 2022-03-18 15:01:55.666|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:55.906|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:56.174|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:56.497|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:56.766|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:57.006|End update of Job 'foo'. Took 12ms 2022-03-18 15:01:57.261|End update of Job 'foo'. Took 14ms 2022-03-18 15:01:57.521|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:57.799|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:58.086|End update of Job 'foo'. Took 10ms 2022-03-18 15:01:58.583|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:58.865|End update of Job 'foo'. Took 12ms 2022-03-18 15:01:59.317|End update of Job 'foo'. Took 11ms 2022-03-18 15:01:59.802|End update of Job 'foo'. Took 11ms 2022-03-18 15:02:00.106|End update of Job 'foo'. Took 11ms 2022-03-18 15:02:00.684|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:01.047|End update of Job 'foo'. Took 11ms 2022-03-18 15:02:01.299|End update of Job 'foo'. Took 11ms 2022-03-18 15:02:01.840|End update of Job 'foo'. Took 11ms 2022-03-18 15:02:02.491|End update of Job 'foo'. Took 22ms 2022-03-18 15:02:02.774|End update of Job 'foo'. Took 11ms 2022-03-18 15:02:03.030|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:03.395|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:03.751|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:04.267|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:04.624|End update of Job 'foo'. Took 11ms 2022-03-18 15:02:05.230|End update of Job 'foo'. Took 11ms 2022-03-18 15:02:05.680|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:07.371|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:07.653|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:07.976|End update of Job 'foo'. Took 11ms 2022-03-18 15:02:08.441|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:08.853|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:09.103|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:09.362|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:09.665|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:10.128|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:10.542|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:10.883|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:11.256|End update of Job 'foo'. Took 23ms 2022-03-18 15:02:11.508|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:11.785|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:12.068|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:12.350|End update of Job 'foo'. Took 34ms 2022-03-18 15:02:12.611|End update of Job 'foo'. Took 12ms 2022-03-18 15:02:12.982|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:13.369|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:13.636|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:13.889|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:14.211|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:14.460|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:14.702|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:14.989|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:15.319|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:15.599|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:15.857|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:16.114|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:16.463|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:16.812|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:17.114|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:17.445|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:17.698|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:18.020|End update of Job 'foo'. Took 29ms 2022-03-18 15:02:18.314|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:18.789|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:19.115|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:19.521|End update of Job 'foo'. Took 69ms 2022-03-18 15:02:19.775|End update of Job 'foo'. Took 13ms 2022-03-18 15:02:20.035|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:20.283|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:20.560|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:20.845|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:21.097|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:21.380|End update of Job 'foo'. Took 26ms 2022-03-18 15:02:21.649|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:21.890|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:22.324|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:22.590|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:22.835|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:23.108|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:23.364|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:23.643|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:24.056|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:24.320|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:24.582|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:24.828|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:25.084|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:25.411|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:25.751|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:26.032|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:26.374|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:26.661|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:26.908|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:27.165|End update of Job 'foo'. Took 14ms 2022-03-18 15:02:27.426|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:27.665|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:27.922|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:28.252|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:28.517|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:28.788|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:29.063|End update of Job 'foo'. Took 15ms 2022-03-18 15:02:29.337|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:29.715|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:29.993|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:30.237|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:30.515|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:30.869|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:31.120|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:31.370|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:31.621|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:31.923|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:32.224|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:32.471|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:32.727|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:33.033|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:33.295|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:33.562|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:33.804|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:34.122|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:34.434|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:34.756|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:35.034|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:35.274|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:35.517|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:35.887|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:36.149|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:36.431|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:36.739|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:37.035|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:37.292|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:37.565|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:37.817|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:38.113|End update of Job 'foo'. Took 16ms 2022-03-18 15:02:38.527|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:38.772|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:39.038|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:39.305|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:39.552|End update of Job 'foo'. Took 21ms 2022-03-18 15:02:39.807|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:40.062|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:40.341|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:40.657|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:40.978|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:41.308|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:41.561|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:41.849|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:42.113|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:42.383|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:42.649|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:42.906|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:43.193|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:43.459|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:43.791|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:44.071|End update of Job 'foo'. Took 24ms 2022-03-18 15:02:44.340|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:44.613|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:44.866|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:45.117|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:45.398|End update of Job 'foo'. Took 17ms 2022-03-18 15:02:45.644|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:45.896|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:46.188|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:46.442|End update of Job 'foo'. Took 25ms 2022-03-18 15:02:46.714|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:47.022|End update of Job 'foo'. Took 36ms 2022-03-18 15:02:47.274|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:47.519|End update of Job 'foo'. Took 21ms 2022-03-18 15:02:47.789|End update of Job 'foo'. Took 21ms 2022-03-18 15:02:48.055|End update of Job 'foo'. Took 30ms 2022-03-18 15:02:48.317|End update of Job 'foo'. Took 22ms 2022-03-18 15:02:48.580|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:48.836|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:49.099|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:49.369|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:49.865|End update of Job 'foo'. Took 18ms 2022-03-18 15:02:50.144|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:50.403|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:50.710|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:50.981|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:51.324|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:51.599|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:52.041|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:52.299|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:52.577|End update of Job 'foo'. Took 29ms 2022-03-18 15:02:52.833|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:53.105|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:53.355|End update of Job 'foo'. Took 22ms 2022-03-18 15:02:53.720|End update of Job 'foo'. Took 30ms 2022-03-18 15:02:53.973|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:54.355|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:54.688|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:54.984|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:55.314|End update of Job 'foo'. Took 21ms 2022-03-18 15:02:55.610|End update of Job 'foo'. Took 22ms 2022-03-18 15:02:56.109|End update of Job 'foo'. Took 21ms 2022-03-18 15:02:56.354|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:56.630|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:56.875|End update of Job 'foo'. Took 21ms 2022-03-18 15:02:57.195|End update of Job 'foo'. Took 21ms 2022-03-18 15:02:57.500|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:57.900|End update of Job 'foo'. Took 22ms 2022-03-18 15:02:58.161|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:58.518|End update of Job 'foo'. Took 21ms 2022-03-18 15:02:58.853|End update of Job 'foo'. Took 22ms 2022-03-18 15:02:59.115|End update of Job 'foo'. Took 19ms 2022-03-18 15:02:59.471|End update of Job 'foo'. Took 20ms 2022-03-18 15:02:59.730|End update of Job 'foo'. Took 20ms 2022-03-18 15:03:00.088|End update of Job 'foo'. Took 20ms 2022-03-18 15:03:00.351|End update of Job 'foo'. Took 21ms 2022-03-18 15:03:00.690|End update of Job 'foo'. Took 19ms 2022-03-18 15:03:00.956|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:01.223|End update of Job 'foo'. Took 22ms 2022-03-18 15:03:01.492|End update of Job 'foo'. Took 20ms 2022-03-18 15:03:01.777|End update of Job 'foo'. Took 21ms 2022-03-18 15:03:02.048|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:02.361|End update of Job 'foo'. Took 21ms 2022-03-18 15:03:02.637|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:02.900|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:03.227|End update of Job 'foo'. Took 22ms 2022-03-18 15:03:03.576|End update of Job 'foo'. Took 31ms 2022-03-18 15:03:03.828|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:04.263|End update of Job 'foo'. Took 32ms 2022-03-18 15:03:04.586|End update of Job 'foo'. Took 33ms 2022-03-18 15:03:04.898|End update of Job 'foo'. Took 22ms 2022-03-18 15:03:05.177|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:05.483|End update of Job 'foo'. Took 21ms 2022-03-18 15:03:05.979|End update of Job 'foo'. Took 21ms 2022-03-18 15:03:06.278|End update of Job 'foo'. Took 22ms 2022-03-18 15:03:06.677|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:06.972|End update of Job 'foo'. Took 22ms 2022-03-18 15:03:07.501|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:07.758|End update of Job 'foo'. Took 21ms 2022-03-18 15:03:08.065|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:08.416|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:08.732|End update of Job 'foo'. Took 22ms 2022-03-18 15:03:09.201|End update of Job 'foo'. Took 22ms 2022-03-18 15:03:09.546|End update of Job 'foo'. Took 35ms 2022-03-18 15:03:09.873|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:10.128|End update of Job 'foo'. Took 21ms 2022-03-18 15:03:10.460|End update of Job 'foo'. Took 42ms 2022-03-18 15:03:10.743|End update of Job 'foo'. Took 33ms 2022-03-18 15:03:11.442|End update of Job 'foo'. Took 22ms 2022-03-18 15:03:11.745|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:12.349|End update of Job 'foo'. Took 30ms 2022-03-18 15:03:12.636|End update of Job 'foo'. Took 33ms 2022-03-18 15:03:12.885|End update of Job 'foo'. Took 22ms 2022-03-18 15:03:13.327|End update of Job 'foo'. Took 32ms 2022-03-18 15:03:13.631|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:13.959|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:14.463|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:14.745|End update of Job 'foo'. Took 32ms 2022-03-18 15:03:15.115|End update of Job 'foo'. Took 22ms 2022-03-18 15:03:15.440|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:15.955|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:16.231|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:16.504|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:16.764|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:17.143|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:17.465|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:17.736|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:18.227|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:18.501|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:18.767|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:19.040|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:19.406|End update of Job 'foo'. Took 125ms 2022-03-18 15:03:19.755|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:20.050|End update of Job 'foo'. Took 50ms 2022-03-18 15:03:20.313|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:20.567|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:20.843|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:21.097|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:21.360|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:21.820|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:22.119|End update of Job 'foo'. Took 23ms 2022-03-18 15:03:22.522|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:22.822|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:23.217|End update of Job 'foo'. Took 33ms 2022-03-18 15:03:23.600|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:23.879|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:24.130|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:24.392|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:24.741|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:25.025|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:25.406|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:25.678|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:25.953|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:26.293|End update of Job 'foo'. Took 35ms 2022-03-18 15:03:26.601|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:26.953|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:27.215|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:27.483|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:27.763|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:28.031|End update of Job 'foo'. Took 44ms 2022-03-18 15:03:28.299|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:28.574|End update of Job 'foo'. Took 38ms 2022-03-18 15:03:28.851|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:29.102|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:29.362|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:29.650|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:29.925|End update of Job 'foo'. Took 24ms 2022-03-18 15:03:30.253|End update of Job 'foo'. Took 40ms 2022-03-18 15:03:30.574|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:30.853|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:31.157|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:31.428|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:31.706|End update of Job 'foo'. Took 36ms 2022-03-18 15:03:31.964|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:32.265|End update of Job 'foo'. Took 31ms 2022-03-18 15:03:32.542|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:32.793|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:33.236|End update of Job 'foo'. Took 34ms 2022-03-18 15:03:33.739|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:34.245|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:34.547|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:34.835|End update of Job 'foo'. Took 39ms 2022-03-18 15:03:35.342|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:35.603|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:35.912|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:36.194|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:36.481|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:36.765|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:37.044|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:37.316|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:37.691|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:38.189|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:38.445|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:38.710|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:38.962|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:39.354|End update of Job 'foo'. Took 31ms 2022-03-18 15:03:39.605|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:40.044|End update of Job 'foo'. Took 25ms 2022-03-18 15:03:40.328|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:40.633|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:40.982|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:41.426|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:41.723|End update of Job 'foo'. Took 33ms 2022-03-18 15:03:42.023|End update of Job 'foo'. Took 33ms 2022-03-18 15:03:42.325|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:42.879|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:43.324|End update of Job 'foo'. Took 32ms 2022-03-18 15:03:43.650|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:43.976|End update of Job 'foo'. Took 26ms 2022-03-18 15:03:44.283|End update of Job 'foo'. Took 37ms 2022-03-18 15:03:44.548|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:45.037|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:45.315|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:45.686|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:45.961|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:46.271|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:46.535|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:46.812|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:47.094|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:47.363|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:47.629|End update of Job 'foo'. Took 30ms 2022-03-18 15:03:47.931|End update of Job 'foo'. Took 37ms 2022-03-18 15:03:48.381|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:48.681|End update of Job 'foo'. Took 30ms 2022-03-18 15:03:48.969|End update of Job 'foo'. Took 34ms 2022-03-18 15:03:49.255|End update of Job 'foo'. Took 30ms 2022-03-18 15:03:49.517|End update of Job 'foo'. Took 32ms 2022-03-18 15:03:49.794|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:50.065|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:50.368|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:50.628|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:50.894|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:51.438|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:51.706|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:51.989|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:52.624|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:52.892|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:53.201|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:53.504|End update of Job 'foo'. Took 30ms 2022-03-18 15:03:53.808|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:54.083|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:54.403|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:54.655|End update of Job 'foo'. Took 27ms 2022-03-18 15:03:54.972|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:55.445|End update of Job 'foo'. Took 33ms 2022-03-18 15:03:55.729|End update of Job 'foo'. Took 30ms 2022-03-18 15:03:55.984|End update of Job 'foo'. Took 28ms 2022-03-18 15:03:56.512|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:56.810|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:57.072|End update of Job 'foo'. Took 33ms 2022-03-18 15:03:57.342|End update of Job 'foo'. Took 31ms 2022-03-18 15:03:57.628|End update of Job 'foo'. Took 31ms 2022-03-18 15:03:57.932|End update of Job 'foo'. Took 38ms 2022-03-18 15:03:58.246|End update of Job 'foo'. Took 31ms 2022-03-18 15:03:58.511|End update of Job 'foo'. Took 29ms 2022-03-18 15:03:59.034|End update of Job 'foo'. Took 44ms 2022-03-18 15:03:59.345|End update of Job 'foo'. Took 30ms 2022-03-18 15:03:59.743|End update of Job 'foo'. Took 30ms 2022-03-18 15:04:00.061|End update of Job 'foo'. Took 30ms 2022-03-18 15:04:00.350|End update of Job 'foo'. Took 44ms 2022-03-18 15:04:00.883|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:01.255|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:01.528|End update of Job 'foo'. Took 30ms 2022-03-18 15:04:01.901|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:02.398|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:02.702|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:02.993|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:03.708|End update of Job 'foo'. Took 30ms 2022-03-18 15:04:03.980|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:04.348|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:04.629|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:04.938|End update of Job 'foo'. Took 49ms 2022-03-18 15:04:05.448|End update of Job 'foo'. Took 29ms 2022-03-18 15:04:05.794|End update of Job 'foo'. Took 29ms 2022-03-18 15:04:06.628|End update of Job 'foo'. Took 30ms 2022-03-18 15:04:07.022|End update of Job 'foo'. Took 46ms 2022-03-18 15:04:07.347|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:07.841|End update of Job 'foo'. Took 29ms 2022-03-18 15:04:08.126|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:08.534|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:08.845|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:09.107|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:09.402|End update of Job 'foo'. Took 29ms 2022-03-18 15:04:09.917|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:10.211|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:10.677|End update of Job 'foo'. Took 30ms 2022-03-18 15:04:10.933|End update of Job 'foo'. Took 30ms 2022-03-18 15:04:11.291|End update of Job 'foo'. Took 30ms 2022-03-18 15:04:11.641|End update of Job 'foo'. Took 42ms 2022-03-18 15:04:12.058|End update of Job 'foo'. Took 43ms 2022-03-18 15:04:12.407|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:12.788|End update of Job 'foo'. Took 51ms 2022-03-18 15:04:13.090|End update of Job 'foo'. Took 60ms 2022-03-18 15:04:13.480|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:13.811|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:14.072|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:14.385|End update of Job 'foo'. Took 30ms 2022-03-18 15:04:14.728|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:15.216|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:15.486|End update of Job 'foo'. Took 30ms 2022-03-18 15:04:16.079|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:16.361|End update of Job 'foo'. Took 39ms 2022-03-18 15:04:16.717|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:17.128|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:17.409|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:17.674|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:18.021|End update of Job 'foo'. Took 48ms 2022-03-18 15:04:18.491|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:18.758|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:19.067|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:19.343|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:19.630|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:19.940|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:20.212|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:20.477|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:20.809|End update of Job 'foo'. Took 31ms 2022-03-18 15:04:21.095|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:21.366|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:21.659|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:21.936|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:22.228|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:22.535|End update of Job 'foo'. Took 45ms 2022-03-18 15:04:22.812|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:23.075|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:23.440|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:23.713|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:23.973|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:24.276|End update of Job 'foo'. Took 41ms 2022-03-18 15:04:24.573|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:24.866|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:25.143|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:25.483|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:25.780|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:26.085|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:26.474|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:26.742|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:27.182|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:27.464|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:27.725|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:28.136|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:28.611|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:28.925|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:29.387|End update of Job 'foo'. Took 32ms 2022-03-18 15:04:29.672|End update of Job 'foo'. Took 41ms 2022-03-18 15:04:30.067|End update of Job 'foo'. Took 45ms 2022-03-18 15:04:30.438|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:30.742|End update of Job 'foo'. Took 45ms 2022-03-18 15:04:31.016|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:31.288|End update of Job 'foo'. Took 38ms 2022-03-18 15:04:31.607|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:31.964|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:32.265|End update of Job 'foo'. Took 41ms 2022-03-18 15:04:32.552|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:32.826|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:33.122|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:33.401|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:33.692|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:34.050|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:34.436|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:34.703|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:35.021|End update of Job 'foo'. Took 46ms 2022-03-18 15:04:35.406|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:35.703|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:35.976|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:36.300|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:36.729|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:37.020|End update of Job 'foo'. Took 50ms 2022-03-18 15:04:37.305|End update of Job 'foo'. Took 40ms 2022-03-18 15:04:37.614|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:37.944|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:38.206|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:38.505|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:38.778|End update of Job 'foo'. Took 33ms 2022-03-18 15:04:39.277|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:39.560|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:39.876|End update of Job 'foo'. Took 41ms 2022-03-18 15:04:40.195|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:40.482|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:40.918|End update of Job 'foo'. Took 54ms 2022-03-18 15:04:41.306|End update of Job 'foo'. Took 40ms 2022-03-18 15:04:41.596|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:41.867|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:42.328|End update of Job 'foo'. Took 43ms 2022-03-18 15:04:42.821|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:43.168|End update of Job 'foo'. Took 41ms 2022-03-18 15:04:43.444|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:43.746|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:44.310|End update of Job 'foo'. Took 41ms 2022-03-18 15:04:44.650|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:44.948|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:45.295|End update of Job 'foo'. Took 40ms 2022-03-18 15:04:45.666|End update of Job 'foo'. Took 34ms 2022-03-18 15:04:45.997|End update of Job 'foo'. Took 42ms 2022-03-18 15:04:46.344|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:46.744|End update of Job 'foo'. Took 50ms 2022-03-18 15:04:47.204|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:47.520|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:47.900|End update of Job 'foo'. Took 51ms 2022-03-18 15:04:48.208|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:48.523|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:48.945|End update of Job 'foo'. Took 38ms 2022-03-18 15:04:49.380|End update of Job 'foo'. Took 40ms 2022-03-18 15:04:49.653|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:50.116|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:50.507|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:50.819|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:51.096|End update of Job 'foo'. Took 39ms 2022-03-18 15:04:51.418|End update of Job 'foo'. Took 59ms 2022-03-18 15:04:51.730|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:52.012|End update of Job 'foo'. Took 54ms 2022-03-18 15:04:52.318|End update of Job 'foo'. Took 45ms 2022-03-18 15:04:52.634|End update of Job 'foo'. Took 38ms 2022-03-18 15:04:52.916|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:53.258|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:53.645|End update of Job 'foo'. Took 35ms 2022-03-18 15:04:53.917|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:54.237|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:54.512|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:54.947|End update of Job 'foo'. Took 41ms 2022-03-18 15:04:55.222|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:55.527|End update of Job 'foo'. Took 39ms 2022-03-18 15:04:55.829|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:56.137|End update of Job 'foo'. Took 38ms 2022-03-18 15:04:56.609|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:57.082|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:57.448|End update of Job 'foo'. Took 38ms 2022-03-18 15:04:57.732|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:58.096|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:58.396|End update of Job 'foo'. Took 40ms 2022-03-18 15:04:58.740|End update of Job 'foo'. Took 36ms 2022-03-18 15:04:59.052|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:59.467|End update of Job 'foo'. Took 37ms 2022-03-18 15:04:59.743|End update of Job 'foo'. Took 37ms 2022-03-18 15:05:00.048|End update of Job 'foo'. Took 63ms 2022-03-18 15:05:00.356|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:00.841|End update of Job 'foo'. Took 44ms 2022-03-18 15:05:01.122|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:01.406|End update of Job 'foo'. Took 37ms 2022-03-18 15:05:01.690|End update of Job 'foo'. Took 37ms 2022-03-18 15:05:02.021|End update of Job 'foo'. Took 46ms 2022-03-18 15:05:02.389|End update of Job 'foo'. Took 53ms 2022-03-18 15:05:02.972|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:03.312|End update of Job 'foo'. Took 43ms 2022-03-18 15:05:03.627|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:03.917|End update of Job 'foo'. Took 44ms 2022-03-18 15:05:04.220|End update of Job 'foo'. Took 42ms 2022-03-18 15:05:04.508|End update of Job 'foo'. Took 38ms 2022-03-18 15:05:05.071|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:05.414|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:05.800|End update of Job 'foo'. Took 37ms 2022-03-18 15:05:06.087|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:06.523|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:06.856|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:07.141|End update of Job 'foo'. Took 38ms 2022-03-18 15:05:07.449|End update of Job 'foo'. Took 38ms 2022-03-18 15:05:07.786|End update of Job 'foo'. Took 38ms 2022-03-18 15:05:08.283|End update of Job 'foo'. Took 50ms 2022-03-18 15:05:08.557|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:08.959|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:09.233|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:10.286|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:10.595|End update of Job 'foo'. Took 37ms 2022-03-18 15:05:10.870|End update of Job 'foo'. Took 38ms 2022-03-18 15:05:11.343|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:12.040|End update of Job 'foo'. Took 59ms 2022-03-18 15:05:12.429|End update of Job 'foo'. Took 135ms 2022-03-18 15:05:12.873|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:13.297|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:13.873|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:14.531|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:22.242|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:23.029|End update of Job 'foo'. Took 47ms 2022-03-18 15:05:23.333|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:23.715|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:24.074|End update of Job 'foo'. Took 38ms 2022-03-18 15:05:24.460|End update of Job 'foo'. Took 42ms 2022-03-18 15:05:24.908|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:25.238|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:25.555|End update of Job 'foo'. Took 38ms 2022-03-18 15:05:25.945|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:26.271|End update of Job 'foo'. Took 42ms 2022-03-18 15:05:26.998|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:27.505|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:35.064|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:35.832|End update of Job 'foo'. Took 45ms 2022-03-18 15:05:36.281|End update of Job 'foo'. Took 50ms 2022-03-18 15:05:47.434|End update of Job 'foo'. Took 42ms 2022-03-18 15:05:47.883|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:48.633|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:49.112|End update of Job 'foo'. Took 51ms 2022-03-18 15:05:49.800|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:50.125|End update of Job 'foo'. Took 46ms 2022-03-18 15:05:50.428|End update of Job 'foo'. Took 43ms 2022-03-18 15:05:50.786|End update of Job 'foo'. Took 42ms 2022-03-18 15:05:51.090|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:51.447|End update of Job 'foo'. Took 44ms 2022-03-18 15:05:52.174|End update of Job 'foo'. Took 44ms 2022-03-18 15:05:52.575|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:52.899|End update of Job 'foo'. Took 45ms 2022-03-18 15:05:53.183|End update of Job 'foo'. Took 44ms 2022-03-18 15:05:53.456|End update of Job 'foo'. Took 43ms 2022-03-18 15:05:53.761|End update of Job 'foo'. Took 40ms 2022-03-18 15:05:54.065|End update of Job 'foo'. Took 52ms 2022-03-18 15:05:54.438|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:54.819|End update of Job 'foo'. Took 45ms 2022-03-18 15:05:55.227|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:55.523|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:55.797|End update of Job 'foo'. Took 39ms 2022-03-18 15:05:56.113|End update of Job 'foo'. Took 47ms 2022-03-18 15:05:56.416|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:56.687|End update of Job 'foo'. Took 41ms 2022-03-18 15:05:56.972|End update of Job 'foo'. Took 44ms 2022-03-18 15:05:57.287|End update of Job 'foo'. Took 42ms 2022-03-18 15:05:57.719|End update of Job 'foo'. Took 45ms 2022-03-18 15:05:58.011|End update of Job 'foo'. Took 55ms 2022-03-18 15:05:58.318|End update of Job 'foo'. Took 42ms 2022-03-18 15:05:58.595|End update of Job 'foo'. Took 42ms 2022-03-18 15:05:58.997|End update of Job 'foo'. Took 42ms 2022-03-18 15:05:59.313|End update of Job 'foo'. Took 47ms 2022-03-18 15:05:59.651|End update of Job 'foo'. Took 42ms 2022-03-18 15:05:59.956|End update of Job 'foo'. Took 43ms 2022-03-18 15:06:00.344|End update of Job 'foo'. Took 40ms 2022-03-18 15:06:00.647|End update of Job 'foo'. Took 41ms 2022-03-18 15:06:01.275|End update of Job 'foo'. Took 64ms 2022-03-18 15:06:01.775|End update of Job 'foo'. Took 50ms 2022-03-18 15:06:02.167|End update of Job 'foo'. Took 57ms 2022-03-18 15:06:02.743|End update of Job 'foo'. Took 47ms 2022-03-18 15:06:03.182|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:03.497|End update of Job 'foo'. Took 53ms 2022-03-18 15:06:03.786|End update of Job 'foo'. Took 42ms 2022-03-18 15:06:04.100|End update of Job 'foo'. Took 46ms 2022-03-18 15:06:04.511|End update of Job 'foo'. Took 42ms 2022-03-18 15:06:05.970|End update of Job 'foo'. Took 42ms 2022-03-18 15:06:06.600|End update of Job 'foo'. Took 46ms 2022-03-18 15:06:07.067|End update of Job 'foo'. Took 42ms 2022-03-18 15:06:07.548|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:07.867|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:08.240|End update of Job 'foo'. Took 42ms 2022-03-18 15:06:08.727|End update of Job 'foo'. Took 41ms 2022-03-18 15:06:10.340|End update of Job 'foo'. Took 41ms 2022-03-18 15:06:10.811|End update of Job 'foo'. Took 42ms 2022-03-18 15:06:18.506|End update of Job 'foo'. Took 76ms 2022-03-18 15:06:18.808|End update of Job 'foo'. Took 41ms 2022-03-18 15:06:19.251|End update of Job 'foo'. Took 43ms 2022-03-18 15:06:19.766|End update of Job 'foo'. Took 43ms 2022-03-18 15:06:20.077|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:20.379|End update of Job 'foo'. Took 44ms 2022-03-18 15:06:20.795|End update of Job 'foo'. Took 43ms 2022-03-18 15:06:21.462|End update of Job 'foo'. Took 47ms 2022-03-18 15:06:21.757|End update of Job 'foo'. Took 43ms 2022-03-18 15:06:22.182|End update of Job 'foo'. Took 44ms 2022-03-18 15:06:22.539|End update of Job 'foo'. Took 47ms 2022-03-18 15:06:22.861|End update of Job 'foo'. Took 46ms 2022-03-18 15:06:23.198|End update of Job 'foo'. Took 43ms 2022-03-18 15:06:23.515|End update of Job 'foo'. Took 60ms 2022-03-18 15:06:23.794|End update of Job 'foo'. Took 43ms 2022-03-18 15:06:24.303|End update of Job 'foo'. Took 47ms 2022-03-18 15:06:24.932|End update of Job 'foo'. Took 52ms 2022-03-18 15:06:25.449|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:25.765|End update of Job 'foo'. Took 43ms 2022-03-18 15:06:26.058|End update of Job 'foo'. Took 44ms 2022-03-18 15:06:26.439|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:26.823|End update of Job 'foo'. Took 43ms 2022-03-18 15:06:27.135|End update of Job 'foo'. Took 53ms 2022-03-18 15:06:27.450|End update of Job 'foo'. Took 49ms 2022-03-18 15:06:27.905|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:28.240|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:28.746|End update of Job 'foo'. Took 44ms 2022-03-18 15:06:29.291|End update of Job 'foo'. Took 57ms 2022-03-18 15:06:29.651|End update of Job 'foo'. Took 46ms 2022-03-18 15:06:30.091|End update of Job 'foo'. Took 46ms 2022-03-18 15:06:30.416|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:30.782|End update of Job 'foo'. Took 65ms 2022-03-18 15:06:31.094|End update of Job 'foo'. Took 44ms 2022-03-18 15:06:31.429|End update of Job 'foo'. Took 54ms 2022-03-18 15:06:31.825|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:32.125|End update of Job 'foo'. Took 46ms 2022-03-18 15:06:32.569|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:32.905|End update of Job 'foo'. Took 53ms 2022-03-18 15:06:33.202|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:33.543|End update of Job 'foo'. Took 47ms 2022-03-18 15:06:34.014|End update of Job 'foo'. Took 63ms 2022-03-18 15:06:34.310|End update of Job 'foo'. Took 49ms 2022-03-18 15:06:34.770|End update of Job 'foo'. Took 48ms 2022-03-18 15:06:35.191|End update of Job 'foo'. Took 51ms 2022-03-18 15:06:35.483|End update of Job 'foo'. Took 44ms 2022-03-18 15:06:35.821|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:36.103|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:36.538|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:36.823|End update of Job 'foo'. Took 49ms 2022-03-18 15:06:37.263|End update of Job 'foo'. Took 47ms 2022-03-18 15:06:37.651|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:38.059|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:38.427|End update of Job 'foo'. Took 53ms 2022-03-18 15:06:38.739|End update of Job 'foo'. Took 46ms 2022-03-18 15:06:39.032|End update of Job 'foo'. Took 56ms 2022-03-18 15:06:39.348|End update of Job 'foo'. Took 44ms 2022-03-18 15:06:39.637|End update of Job 'foo'. Took 44ms 2022-03-18 15:06:39.937|End update of Job 'foo'. Took 44ms 2022-03-18 15:06:40.227|End update of Job 'foo'. Took 46ms 2022-03-18 15:06:40.713|End update of Job 'foo'. Took 54ms 2022-03-18 15:06:41.011|End update of Job 'foo'. Took 59ms 2022-03-18 15:06:41.407|End update of Job 'foo'. Took 45ms 2022-03-18 15:06:41.705|End update of Job 'foo'. Took 47ms 2022-03-18 15:06:42.024|End update of Job 'foo'. Took 47ms 2022-03-18 15:06:42.341|End update of Job 'foo'. Took 46ms 2022-03-18 15:06:42.613|End update of Job 'foo'. Took 48ms 2022-03-18 15:06:42.995|End update of Job 'foo'. Took 52ms 2022-03-18 15:06:43.282|End update of Job 'foo'. Took 47ms 2022-03-18 15:06:43.566|End update of Job 'foo'. Took 47ms 2022-03-18 15:06:43.889|End update of Job 'foo'. Took 51ms 2022-03-18 15:06:44.179|End update of Job 'foo'. Took 46ms 2022-03-18 15:06:44.507|End update of Job 'foo'. Took 52ms 2022-03-18 15:06:44.795|End update of Job 'foo'. Took 48ms ```
ajcvickers commented 2 years ago

This is by-design. DbContext is designed to allow multiple changes with continued tracking between calls to SaveChanges. The state of tracked entities is updated to reflect their state in the database after each call.

The batch has a loop that update one by one those records, using always the same DbContext

This is a very unusual way of doing things. Typically, all the changes constituting a single unit-of-work should be made on a single context instance, and then SaveChanges should be called so that database updates can be batched. Then a new context instance should be used for the next unit-of-work. Context creation is cheap, and if necessary context pooling can be used to further reduce the cost of using multiple context instances.

emanuelefirmani commented 2 years ago

Each update is a UoW, because it requires a call to an API that takes quite long. Creating 70k instances of DbContext seems a bit excessive.

May I ask why should the DbContext track changes across calls to SaveChanges? As SaveChanges closes the UoW, the DbContext should go back to its initial state. I really don't see any reason for such behavior, that comes with relevant drawbacks.

Thanks

ajcvickers commented 2 years ago

SaveChanges does not necessarily close the unit-of-work. A single unit-of-work, especially with a transaction, can involve multiple calls to SaveChanges.

stevendarby commented 2 years ago

I would like to understand this problem a bit more, as I think maybe it's asking the wrong question- I think the implication is that having lots of Unchanged entities in the tracker slows down generation of the save statement considerably.

It's clear that it's by design that save changes doesn't and shouldn't clear the change tracker (by default at least). But is the degradation shown here within the expected amount? Is it pointing to a performance problem in the save process that could be improved?

The code doesn't actually show any entities being loaded into the tracker, as it only materialises a list of, presumably, numbers. Nor does it show any entities being modified. What does UpdateJob do? There could be more to explore here...

emanuelefirmani commented 2 years ago

The method UpdateJob does actually update the Job enyity. The performance degradation is in my opinion excessive: saving went from 2ms to 50ms after 1000 executions. At least, it violates the least astonishment principle

ErikEJ commented 2 years ago

@emanuelefirmani I you would like this investigated further a complete runnable repro would be very helpful.

emanuelefirmani commented 2 years ago

Here you are: https://github.com/emanuelefirmani/EntityFrameworkPerformance

The test performance_should_not_degrade fails if the degradation of performance extends the execution times more than 10x when confronting the first 10% updates with the last 10%. The number of updates is parameterized. Run the test with 5000 updates only after applying the fix, otherwise you'll wait a looooong time (up to 222ms per update).

Commit 4bc7c26 makes the tests to pass.

roji commented 2 years ago

This is likely a duplicate of #9422.

We know that change tracking performance is something that can be improved, and we haven't yet gotten around to focusing on that particular area.

However, as stated above, tracking such a large number of entity instances isn't recommended. We could (and intend do) improve the degree of degradation, but the basic pattern will likely remain problematic.

ErikEJ commented 2 years ago

@emanuelefirmani I updated your code:

        var jobsToBeUpdated = _context.Jobs.Where(x => x.LastUpdatedAt < minRefreshDate).ToList();

        foreach (var job in jobsToBeUpdated)
        { 
            job.LastUpdatedAt = DateTime.Now;
        }

        var sw = Stopwatch.StartNew();
        _context.SaveChanges();
        sw.Stop();

and got 50 (100) , 389 (1000) and 631 (5000) ms

roji commented 2 years ago

One general note... I really recommend writing benchmarks with BenchmarkDotNet, rather than rolling your own benchmarks as unit tests. BenchmarkDotNet takes care of many aspects of benchmarking (exclude warmup, exclude overhead, decide how many iterations to run...).

emanuelefirmani commented 2 years ago

@ErikEJ, unfortunately your piece of code does not work on my real business case: in order to update a job, I have to call an API, which takes 3-400ms. The API may return an exception when called 70k times, that's why I have to save each single job after its update: if the API throws an exception, at least the previous jobs are stored

ErikEJ commented 2 years ago

@emanuelefirmani Then maybe get the list of Ids, and then create a new DbContext per API call. (Or even use Pooling)

stevendarby commented 2 years ago

The manual call to clear the change tracker seems to be a fine workaround. Good to know there is something already tracking performance improvements to change detection.

roji commented 2 years ago

Then maybe get the list of Ids, and then create a new DbContext per API call. (Or even use Pooling)

I'd expect using pooled contexts to be similar to using the same context with Clear, otherwise that would be quite interesting...

emanuelefirmani commented 2 years ago

I used the PooledDbContextFactory as reported here: https://docs.microsoft.com/en-us/ef/core/performance/advanced-performance-topics It brilliantly solves my problem.

I still have, anyway, the strange feeling that DbContext was not fair, because of its unexpected behavior that I never faced in more than a dozen years.

I do thank you all for your support, which I highly appreciated.

ErikEJ commented 2 years ago

The EF Core DbContext has only existed for 7 years..

emanuelefirmani commented 2 years ago

Ok, sorry, I remember of .net 3.5. Probably, for my specific need, Dapper is a better fit, because I don't need any stateful representation of my DB

ajzbrun commented 1 year ago

I'm on .Net 6, and there's some kind of issue still with this, because by default my code is throwing that the changes cannot be saved because there's already an entity with the same Id being tracked (which I know that's true and I know where it's the tracked entity).

Now, if I use the line _dbContext.ChangeTracker.Clear() immediately after the SaveChanges() for this tracked entity, it doesn't throw the exception, but it doesn't save the changes either.

So...

roji commented 1 year ago

@ajzbrun please open a new issue with a minimal, runnable code sample showing the problem.