Azure-docs: Using stopwatch to record total bulk execution time not working

[jakehockey10]

I've basically utilized the code snippets in this document for my project, and I love the V3 API as opposed to the V2 BulkExecutor API. Thanks for all the hard work!

One problem I'm having is that the stopwatch in this section (https://docs.microsoft.com/en-us/azure/cosmos-db/how-to-migrate-from-bulk-executor-library#execute-operations-concurrently) is reporting that an operation took roughly 1.5 seconds even though I'm importing over 400,000 records in my testing. I'm definitely sitting at my computer waiting for this to complete and I'm experiencing about 5 minutes.

I'm not sure how to diagnose this.

---

Document Details

⚠ Do not edit this section. It is required for docs.microsoft.com ➟ GitHub issue linking.

• ID: b430631a-2e7a-ecd6-39d3-c13ad70a802f
• Version Independent ID: ce8f5067-72a8-f6b1-ef8c-6d8a83ee3fc2
• Content: Migrate from the bulk executor library to the bulk support in Azure Cosmos DB .NET V3 SDK
• Content Source: articles/cosmos-db/how-to-migrate-from-bulk-executor-library.md
• Service: cosmos-db
• GitHub Login: @ealsur
• Microsoft Alias: maquaran

[jakehockey10]

Here is the method that is not reporting the correct Elapsed TimeSpan:

public async Task<BulkOperationResponse<T>> ExecuteTasksAsync<T>(
    IReadOnlyCollection<Task<OperationResponse<T>>> tasks)
{
    _logger.LogInformation($"Executing {tasks.Count} tasks");

    // TODO: This seems to be reporting the wrong time
    var stopwatch = Stopwatch.StartNew();
    await Task.WhenAll(tasks);
    stopwatch.Stop();

    _logger.LogInformation($"Finished {tasks.Count} tasks in {stopwatch.Elapsed}");

    return new BulkOperationResponse<T>
    {
        TotalTimeTaken = stopwatch.Elapsed,
        TotalRequestUnitsConsumed = tasks.Sum(task => task.Result.RequestUnitsConsumed),
        SuccessfulDocuments = tasks.Count(task => task.Result.IsSuccessful),
        Failures = tasks.Where(task => !task.Result.IsSuccessful)
            .Select(task => (task.Result.Item, task.Result.CosmosException)).ToList()
    };
}

And here is how the method is being used:

public async Task<BulkOperationResponse<Source>> BulkInsertSourceDocumentsAsync(
    IEnumerable<Source> documents)
{
    _logger.LogInformation("Beginning bulk insert...");

    var tasks = new List<Task<OperationResponse<Source>>>(documents.Count());
    tasks.AddRange(documents.Select(document =>
        _orderStatusesContainer.CreateItemAsync(document, new PartitionKey(document.CUSTACCOUNT))
            .CaptureOperationResponse(document)));

    var response = await ExecuteTasksAsync(tasks);

    return response;
}

And here is the CaptureOperationResponse extension method:

public static Task<OperationResponse<T>> CaptureOperationResponse<T>(this Task<ItemResponse<T>> task, T item)
{
    return task.ContinueWith(itemResponse =>
    {
        if (itemResponse.IsCompletedSuccessfully)
            return new OperationResponse<T>
            {
                Item = item,
                IsSuccessful = true,
                RequestUnitsConsumed = task.Result.RequestCharge
            };

        var innerExceptions = itemResponse.Exception.Flatten();
        if (innerExceptions.InnerExceptions.FirstOrDefault(innerEx => innerEx is CosmosException) is
            CosmosException cosmosException)
            return new OperationResponse<T>
            {
                Item = item,
                RequestUnitsConsumed = cosmosException.RequestCharge,
                IsSuccessful = false,
                CosmosException = cosmosException
            };

        return new OperationResponse<T>
        {
            Item = item,
            IsSuccessful = false,
            CosmosException = innerExceptions.InnerExceptions.FirstOrDefault()
        };
    });
}

[jakehockey10]

I attempted to use ContinueWith to chain on my Task.WhenAll(tasks) method is awaited, and stop the stopwatch there and return my BulkOperationResponse, but I still get the same really small Elapsed TimeSpan compared to how long I actually wait. It is almost the exact same 1.5 seconds reported despite taking over 5 minutes.

[Mike-Ubezzi-MSFT]

@jakehockey10 Thank you for providing all the detail. We are reviewing this and will have an update for you shortly unless we have additional questions.

[ealsur]

@jakehockey10 Does the operation complete even though it might report 1.5 seconds?

Can you share how are you generating the list of Tasks?

[jakehockey10]

@Mike-Ubezzi-MSFT it looks like Stopwatch.StartNew() isn't being called until the majority of the work is done.

[jakehockey10]

@ealsur my middle code snippet shows how the tasks are being generated

[jakehockey10]

@ealsur I think my code is basically verbatim with the example in the link I provided at the top

[ealsur]

This might be a race condition on resources of the machine.

Technically speaking, the code creates a list of Tasks, it does not await them, and then starts the Stopwatch. So it should just move forward and start the stop watch, it should not wait for any of those Tasks. That being said, maybe the resources are not high enough to handle the volume of Tasks and it is preempting code execution, so it might start some tasks before continuing.

I'll do some testing on a smaller compute and see how it behaves.

[jakehockey10]

Which resources could possibly be causing this on my machine? I have a pretty new i7 processer and 64 GB of RAM?

The Cosmos DB Emulator I'm "talking" to has "rate limiting" turned on. I'm changing my throughput to a higher throughput before running my ETL and restoring it to my default after.

[ealsur]

Ok, something is wrong with the extension samples, for some reason the main thread continues while some tasks are still in progress. Will update this thread and update the code once I fix it.

[jakehockey10]

Great thank you @ealsur

[ealsur]

@jakehockey10 Please see https://github.com/Azure/azure-cosmos-dotnet-v3/pull/1432

Particularly the BulkOperations helper class.

[ealsur]

@Mike-Ubezzi-MSFT @jakehockey10

PR with documentation fix: https://github.com/MicrosoftDocs/azure-docs-pr/pull/112689

[Mike-Ubezzi-MSFT]

@jakehockey10 Update has been published and will be made available in the public facing version of the document in the next 24 hours.
We will now proceed to close this thread. If there are further questions regarding this matter, please comment and we will gladly continue the discussion.

[jakehockey10]

You guys are great. I really, really appreciate the help!