public async Task InitializeAsync(
CTLConfig config,
CosmosClient cosmosClient,
ILogger logger)
{
this.initializationResult = await Utils.CreateDatabaseAndContainerAsync(config, cosmosClient);
if (this.initializationResult.CreatedDatabase)
{
logger.LogInformation("Created database for execution");
}
if (this.initializationResult.CreatedContainer)
{
logger.LogInformation("Created collection for execution");
}
if (config.PreCreatedDocuments > 0)
{
logger.LogInformation("Pre-populating {0} documents", config.PreCreatedDocuments);
IReadOnlyDictionary <string, IReadOnlyList <Dictionary <string, string> > > insertedDocuments = await Utils.PopulateDocumentsAsync(config, logger, new List <Container>() { cosmosClient.GetContainer(config.Database, config.Collection) });
this.initializationResult.InsertedDocuments = insertedDocuments[config.Collection].Count;
}
}
public async Task RunAsync(
CTLConfig config,
CosmosClient cosmosClient,
ILogger logger,
IMetrics metrics,
CancellationToken cancellationToken)
{
try
{
await this.ExecuteOperationsAsync(config, logger, metrics, this.initializationResult, this.readWriteQueryPercentage, cancellationToken);
}
catch (Exception unhandledException)
{
logger.LogError(unhandledException, "Unhandled exception executing {0}", nameof(ReadWriteQueryScenario));
}
finally
{
if (this.initializationResult.CreatedDatabase)
{
await cosmosClient.GetDatabase(config.Database).DeleteAsync();
}
else
{
foreach (string createdCollection in this.initializationResult.CreatedContainers)
{
await cosmosClient.GetContainer(config.Database, createdCollection).DeleteContainerAsync();
}
}
}
}
private static bool ShouldContinue(
Stopwatch stopwatch,
long iterationCount,
CTLConfig config)
{
TimeSpan maxDurationTime = config.RunningTimeDurationAsTimespan;
long maxNumberOfOperations = config.Operations;
if (maxDurationTime == null)
{
return(iterationCount < maxNumberOfOperations);
}
if (maxDurationTime.TotalMilliseconds < stopwatch.ElapsedMilliseconds)
{
return(false);
}
if (maxNumberOfOperations < 0)
{
return(true);
}
return(iterationCount < maxNumberOfOperations);
}
public async Task InitializeAsync(
CTLConfig config,
CosmosClient cosmosClient,
ILogger logger)
{
if (!TryParseReadWriteQueryPercentages(config.ReadWriteQueryPercentage, out this.readWriteQueryPercentage))
{
logger.LogError("Cannot correctly parse {0} = {1}", nameof(config.ReadWriteQueryPercentage), config.ReadWriteQueryPercentage);
return;
}
this.initializationResult = await CreateDatabaseAndContainersAsync(config, cosmosClient);
if (this.initializationResult.CreatedDatabase)
{
logger.LogInformation("Created database for execution");
}
if (this.initializationResult.CreatedContainers.Count > 0)
{
logger.LogInformation("Created {0} collections for execution", this.initializationResult.CreatedContainers.Count);
}
logger.LogInformation("Pre-populating {0} documents", config.Operations);
this.createdDocuments = await PopulateDocumentsAsync(config, logger, this.initializationResult.Containers);
}
private static IMetricsRoot ConfigureReporting(
CTLConfig config,
ILogger logger)
{
if (!string.IsNullOrEmpty(config.GraphiteEndpoint))
{
logger.LogInformation($"Using Graphite server at {config.GraphiteEndpoint}:{config.GraphitePort}");
return(new MetricsBuilder()
.Report.ToGraphite(
options => {
options.Graphite.BaseUri = new Uri($"{config.GraphiteEndpoint}:{config.GraphitePort}");
options.ClientPolicy.BackoffPeriod = TimeSpan.FromSeconds(30);
options.ClientPolicy.FailuresBeforeBackoff = 5;
options.ClientPolicy.Timeout = TimeSpan.FromSeconds(10);
options.FlushInterval = TimeSpan.FromSeconds(config.ReportingIntervalInSeconds);
})
.Build());
}
return(new MetricsBuilder()
.Report.ToConsole(
options => {
options.FlushInterval = TimeSpan.FromSeconds(config.ReportingIntervalInSeconds);
options.MetricsOutputFormatter = new MetricsJsonOutputFormatter();
})
.Build());
}
/// <summary>
/// Create the database and the required number of collections.
/// </summary>
private static async Task <InitializationResult> CreateDatabaseAndContainersAsync(
CTLConfig config,
CosmosClient cosmosClient)
{
List <string> createdContainers = new List <string>();
List <Container> containers = new List <Container>();
InitializationResult result = new InitializationResult()
{
CreatedDatabase = false
};
Database database;
try
{
database = await cosmosClient.GetDatabase(config.Database).ReadAsync();
}
catch (CosmosException exception) when(exception.StatusCode == System.Net.HttpStatusCode.NotFound)
{
DatabaseResponse databaseResponse = await cosmosClient.CreateDatabaseAsync(config.Database, config.Throughput);
result.CreatedDatabase = true;
database = databaseResponse.Database;
}
int collectionCount = config.CollectionCount;
if (collectionCount <= 0)
{
collectionCount = 1;
}
for (int i = 1; i <= collectionCount; i++)
{
string containerName = $"{config.Collection}_{i}";
Container container;
try
{
container = await database.GetContainer(containerName).ReadContainerAsync();
}
catch (CosmosException exception) when(exception.StatusCode == System.Net.HttpStatusCode.NotFound)
{
container = await database.CreateContainerAsync(containerName, ReadWriteQueryScenario.DefaultPartitionKeyPath);
createdContainers.Add(containerName);
}
containers.Add(container);
}
result.CreatedContainers = createdContainers;
result.Containers = containers;
return(result);
}
private static async Task <IReadOnlyDictionary <string, IReadOnlyList <Dictionary <string, string> > > > PopulateDocumentsAsync(
CTLConfig config,
ILogger logger,
IEnumerable <Container> containers)
{
Dictionary <string, IReadOnlyList <Dictionary <string, string> > > createdDocuments = new Dictionary <string, IReadOnlyList <Dictionary <string, string> > >();
foreach (Container container in containers)
{
long successes = 0;
long failures = 0;
ConcurrentBag <Dictionary <string, string> > createdDocumentsInContainer = new ConcurrentBag <Dictionary <string, string> >();
IEnumerable <Dictionary <string, string> > documentsToCreate = GenerateDocuments(config.Operations);
await Utils.ForEachAsync(documentsToCreate, (Dictionary <string, string> doc)
=> container.CreateItemAsync(doc).ContinueWith(task =>
{
if (task.IsCompletedSuccessfully)
{
createdDocumentsInContainer.Add(doc);
Interlocked.Increment(ref successes);
}
else
{
AggregateException innerExceptions = task.Exception.Flatten();
if (innerExceptions.InnerExceptions.FirstOrDefault(innerEx => innerEx is CosmosException) is CosmosException cosmosException)
{
logger.LogError(cosmosException, "Failure pre-populating container {0}", container.Id);
}
Interlocked.Increment(ref failures);
}
}), 100);
if (successes > 0)
{
logger.LogInformation("Completed pre-populating {0} documents in container {1}.", successes, container.Id);
}
if (failures > 0)
{
logger.LogWarning("Failed pre-populating {0} documents in container {1}.", failures, container.Id);
}
createdDocuments.Add(container.Id, createdDocumentsInContainer.ToList());
}
return(createdDocuments);
}
public static async Task <InitializationResult> CreateDatabaseAndContainerAsync(
CTLConfig config,
CosmosClient cosmosClient)
{
InitializationResult result = new InitializationResult()
{
CreatedDatabase = false,
CreatedContainer = false
};
Database database;
try
{
database = await cosmosClient.GetDatabase(config.Database).ReadAsync();
}
catch (CosmosException exception) when(exception.StatusCode == HttpStatusCode.NotFound)
{
await cosmosClient.CreateDatabaseAsync(config.Database, config.DatabaseThroughput);
result.CreatedDatabase = true;
database = cosmosClient.GetDatabase(config.Database);
}
Container container;
try
{
container = await database.GetContainer(config.Collection).ReadContainerAsync();
}
catch (CosmosException exception) when(exception.StatusCode == HttpStatusCode.NotFound)
{
if (config.Throughput > 0)
{
await database.CreateContainerAsync(config.Collection, $"/{config.CollectionPartitionKey}", config.Throughput);
}
else
{
await database.CreateContainerAsync(config.Collection, $"/{config.CollectionPartitionKey}");
}
result.CreatedContainer = true;
}
return(result);
}
public static async Task <IReadOnlyDictionary <string, IReadOnlyList <Dictionary <string, string> > > > PopulateDocumentsAsync(
CTLConfig config,
ILogger logger,
IEnumerable <Container> containers)
{
Dictionary <string, IReadOnlyList <Dictionary <string, string> > > createdDocuments = new Dictionary <string, IReadOnlyList <Dictionary <string, string> > >();
foreach (Container container in containers)
{
long successes = 0;
long failures = 0;
ConcurrentBag <Dictionary <string, string> > createdDocumentsInContainer = new ConcurrentBag <Dictionary <string, string> >();
IEnumerable <Dictionary <string, string> > documentsToCreate = GenerateDocuments(config.PreCreatedDocuments, config.CollectionPartitionKey);
await Utils.ForEachAsync(documentsToCreate, (Dictionary <string, string> doc)
=> container.CreateItemAsync(doc).ContinueWith(task =>
{
if (task.IsCompletedSuccessfully)
{
createdDocumentsInContainer.Add(doc);
Interlocked.Increment(ref successes);
}
else
{
Utils.LogError(logger, $"Pre-populating {container.Id}", task.Exception);
Interlocked.Increment(ref failures);
}
}), config.Concurrency);
if (successes > 0)
{
logger.LogInformation("Completed pre-populating {0} documents in container {1}.", successes, container.Id);
}
if (failures > 0)
{
logger.LogWarning("Failed pre-populating {0} documents in container {1}.", failures, container.Id);
}
createdDocuments.Add(container.Id, createdDocumentsInContainer.ToList());
}
return(createdDocuments);
}
public static void LogDiagnostics(
ILogger logger,
string operationName,
TimeSpan timerContextLatency,
CTLConfig config,
CosmosDiagnostics cosmosDiagnostics)
{
if (timerContextLatency > config.DiagnosticsThresholdDurationAsTimespan)
{
logger.LogInformation($"{operationName}; LatencyInMs:{timerContextLatency.TotalMilliseconds}; request took more than latency threshold {config.DiagnosticsThresholdDuration}, diagnostics: {cosmosDiagnostics}");
}
CosmosTraceDiagnostics traceDiagnostics = (CosmosTraceDiagnostics)cosmosDiagnostics;
if (traceDiagnostics.IsGoneExceptionHit())
{
logger.LogInformation($"{operationName}; LatencyInMs:{timerContextLatency.TotalMilliseconds}; request contains 410(GoneExceptions), diagnostics:{cosmosDiagnostics}");
return;
}
}
private static async Task PopulateDocumentsAsync(
CTLConfig config,
CosmosClient cosmosClient,
ILogger logger)
{
long successes = 0;
long failures = 0;
Container container = cosmosClient.GetContainer(config.Database, config.Collection);
ConcurrentBag <Dictionary <string, string> > createdDocumentsInContainer = new ConcurrentBag <Dictionary <string, string> >();
IEnumerable <Dictionary <string, string> > documentsToCreate = GenerateDocuments(config.Operations, config.CollectionPartitionKey);
await Utils.ForEachAsync(documentsToCreate, (Dictionary <string, string> doc)
=> container.CreateItemAsync(doc).ContinueWith(task =>
{
if (task.IsCompletedSuccessfully)
{
createdDocumentsInContainer.Add(doc);
Interlocked.Increment(ref successes);
}
else
{
AggregateException innerExceptions = task.Exception.Flatten();
if (innerExceptions.InnerExceptions.FirstOrDefault(innerEx => innerEx is CosmosException) is CosmosException cosmosException)
{
logger.LogError(cosmosException, "Failure pre-populating container {0}", container.Id);
}
Interlocked.Increment(ref failures);
}
}), 100);
if (successes > 0)
{
logger.LogInformation("Completed pre-populating {0} documents in container {1}.", successes, container.Id);
}
if (failures > 0)
{
logger.LogWarning("Failed pre-populating {0} documents in container {1}.", failures, container.Id);
}
}
public async Task RunAsync(
CTLConfig config,
CosmosClient cosmosClient,
ILogger logger,
IMetrics metrics,
string loggingContextIdentifier,
CancellationToken cancellationToken)
{
try
{
await this.ExecuteOperationsAsync(
config,
logger,
metrics,
loggingContextIdentifier,
this.initializationResult,
this.readWriteQueryPercentage,
cancellationToken);
}
catch (Exception unhandledException)
{
Utils.LogError(logger, loggingContextIdentifier, unhandledException);
}
finally
{
if (this.initializationResult.CreatedDatabase)
{
await cosmosClient.GetDatabase(config.Database).DeleteAsync();
}
else
{
foreach (string createdCollection in this.initializationResult.CreatedContainers)
{
await cosmosClient.GetContainer(config.Database, createdCollection).DeleteContainerAsync();
}
}
}
}
public async Task InitializeAsync(
CTLConfig config,
CosmosClient cosmosClient,
ILogger logger)
{
this.initializationResult = await CreateDatabaseAndContainerAsync(config, cosmosClient);
if (this.initializationResult.CreatedDatabase)
{
logger.LogInformation("Created database for execution");
}
if (this.initializationResult.CreatedContainer)
{
logger.LogInformation("Created collection for execution");
}
if (config.Operations > 0)
{
logger.LogInformation("Pre-populating {0} documents", config.Operations);
await PopulateDocumentsAsync(config, cosmosClient, logger);
}
}
/// <summary>
/// Executes the query and does paging using continuations.
/// </summary>
private async static Task ExecuteQueryWithContinuationAndGatherResultsAsync(CTLConfig config,
CosmosClient cosmosClient,
ILogger logger,
IMetrics metrics,
string loggingContextIdentifier,
CancellationToken cancellationToken,
string queryText,
string queryName,
long expectedResults,
SemaphoreSlim concurrencyControlSemaphore)
{
Stopwatch stopWatch = Stopwatch.StartNew();
GaugeOptions documentGauge = new GaugeOptions
{
Name = $"#{queryName} Query with CT received documents",
MeasurementUnit = Unit.Items,
Context = loggingContextIdentifier
};
Container container = cosmosClient.GetContainer(config.Database, config.Collection);
while (stopWatch.Elapsed <= config.RunningTimeDurationAsTimespan &&
!cancellationToken.IsCancellationRequested)
{
// To really debug what happened on the query, having a list of all continuations would be useful.
List <string> allContinuations = new List <string>();
long documentTotal = 0;
string continuation;
await concurrencyControlSemaphore.WaitAsync();
FeedIterator <Dictionary <string, string> > query = container.GetItemQueryIterator <Dictionary <string, string> >(queryText);
try
{
while (query.HasMoreResults)
{
FeedResponse <Dictionary <string, string> > response = await query.ReadNextAsync();
documentTotal += response.Count;
continuation = response.ContinuationToken;
allContinuations.Add(continuation);
if (continuation != null)
{
// Use continuation to paginate on the query instead of draining just the initial query
// This validates that we can indeed move forward with the continuation
query.Dispose();
query = container.GetItemQueryIterator <Dictionary <string, string> >(queryText, continuation);
}
}
query.Dispose();
metrics.Measure.Gauge.SetValue(documentGauge, documentTotal);
if (expectedResults > 0 && expectedResults != documentTotal)
{
StringBuilder errorDetail = new StringBuilder();
errorDetail.AppendLine($"{queryName} Query with CT expected to read {expectedResults} but got {documentTotal}");
foreach (string c in allContinuations)
{
errorDetail.AppendLine($"Continuation: {c}");
}
logger.LogError(errorDetail.ToString());
}
}
catch (CosmosException ce) when(ce.StatusCode == System.Net.HttpStatusCode.TooManyRequests)
{
//Logging 429s is not relevant
}
catch (Exception ex)
{
metrics.Measure.Gauge.SetValue(documentGauge, documentTotal);
StringBuilder errorDetail = new StringBuilder();
errorDetail.AppendLine($"{queryName} Query with CT failure while looping through query.");
foreach (string c in allContinuations)
{
errorDetail.AppendLine($"Continuation: {c}");
}
logger.LogError(ex, errorDetail.ToString());
}
finally
{
concurrencyControlSemaphore.Release();
}
}
stopWatch.Stop();
}
/// <summary>
/// Executes the query and drains all results
/// </summary>
private async static Task ExecuteQueryAndGatherResultsAsync(CTLConfig config,
CosmosClient cosmosClient,
ILogger logger,
IMetrics metrics,
string loggingContextIdentifier,
CancellationToken cancellationToken,
string queryText,
string queryName,
long expectedResults,
SemaphoreSlim concurrencyControlSemaphore)
{
Stopwatch stopWatch = Stopwatch.StartNew();
GaugeOptions documentGauge = new GaugeOptions
{
Name = $"#{queryName} Query received documents",
MeasurementUnit = Unit.Items,
Context = loggingContextIdentifier
};
Container container = cosmosClient.GetContainer(config.Database, config.Collection);
while (stopWatch.Elapsed <= config.RunningTimeDurationAsTimespan &&
!cancellationToken.IsCancellationRequested)
{
long documentTotal = 0;
string continuation = null;
await concurrencyControlSemaphore.WaitAsync();
using FeedIterator <Dictionary <string, string> > query = container.GetItemQueryIterator <Dictionary <string, string> >(queryText);
try
{
while (query.HasMoreResults)
{
FeedResponse <Dictionary <string, string> > response = await query.ReadNextAsync();
documentTotal += response.Count;
continuation = response.ContinuationToken;
}
metrics.Measure.Gauge.SetValue(documentGauge, documentTotal);
if (expectedResults > 0 && expectedResults != documentTotal)
{
StringBuilder errorDetail = new StringBuilder();
errorDetail.AppendLine($"{queryName} Query expected to read {expectedResults} but got {documentTotal}");
errorDetail.AppendLine($"Last continuation: {continuation}");
logger.LogError(errorDetail.ToString());
}
}
catch (CosmosException ce) when(ce.StatusCode == System.Net.HttpStatusCode.TooManyRequests)
{
//Logging 429s is not relevant
}
catch (Exception ex)
{
metrics.Measure.Gauge.SetValue(documentGauge, documentTotal);
StringBuilder errorDetail = new StringBuilder();
errorDetail.AppendLine($"{queryName} Query failure while looping through query.");
errorDetail.AppendLine($"Last continuation: {continuation}");
logger.LogError(ex, errorDetail.ToString());
}
finally
{
concurrencyControlSemaphore.Release();
}
}
stopWatch.Stop();
}
public async Task RunAsync(
CTLConfig config,
CosmosClient cosmosClient,
ILogger logger,
IMetrics metrics,
string loggingContextIdentifier,
CancellationToken cancellationToken)
{
try
{
SemaphoreSlim concurrencyControlSemaphore = new SemaphoreSlim(config.Concurrency);
await Task.WhenAll(
QueryScenario.ExecuteQueryAndGatherResultsAsync(
config,
cosmosClient,
logger,
metrics,
loggingContextIdentifier,
cancellationToken,
queryText: "select * from c",
queryName: "Star",
expectedResults: config.PreCreatedDocuments > 0 ? this.initializationResult.InsertedDocuments : 0,
concurrencyControlSemaphore: concurrencyControlSemaphore),
QueryScenario.ExecuteQueryAndGatherResultsAsync(
config,
cosmosClient,
logger,
metrics,
loggingContextIdentifier,
cancellationToken,
queryText: "select * from c order by c.id",
queryName: "OrderBy",
expectedResults: config.PreCreatedDocuments > 0 ? this.initializationResult.InsertedDocuments : 0,
concurrencyControlSemaphore: concurrencyControlSemaphore),
QueryScenario.ExecuteQueryAndGatherResultsAsync(
config,
cosmosClient,
logger,
metrics,
loggingContextIdentifier,
cancellationToken,
queryText: "select count(1) from c",
queryName: "Aggregates",
expectedResults: 1,
concurrencyControlSemaphore: concurrencyControlSemaphore),
QueryScenario.ExecuteQueryWithContinuationAndGatherResultsAsync(
config,
cosmosClient,
logger,
metrics,
loggingContextIdentifier,
cancellationToken,
queryText: "select * from c",
queryName: "Star",
expectedResults: config.PreCreatedDocuments > 0 ? this.initializationResult.InsertedDocuments : 0,
concurrencyControlSemaphore: concurrencyControlSemaphore),
QueryScenario.ExecuteQueryWithContinuationAndGatherResultsAsync(
config,
cosmosClient,
logger,
metrics,
loggingContextIdentifier,
cancellationToken,
queryText: "select * from c order by c.id",
queryName: "OrderBy",
expectedResults: config.PreCreatedDocuments > 0 ? this.initializationResult.InsertedDocuments : 0,
concurrencyControlSemaphore: concurrencyControlSemaphore),
QueryScenario.ExecuteQueryWithContinuationAndGatherResultsAsync(
config,
cosmosClient,
logger,
metrics,
loggingContextIdentifier,
cancellationToken,
queryText: "select count(1) from c",
queryName: "Aggregates",
expectedResults: 1,
concurrencyControlSemaphore: concurrencyControlSemaphore)
);
}
catch (Exception ex)
{
logger.LogError(ex, "Failure during Query scenario");
}
finally
{
if (this.initializationResult.CreatedContainer)
{
await cosmosClient.GetContainer(config.Database, config.Collection).DeleteContainerStreamAsync();
}
if (this.initializationResult.CreatedDatabase)
{
await cosmosClient.GetDatabase(config.Database).DeleteStreamAsync();
}
}
}
public async Task RunAsync(
CTLConfig config,
CosmosClient cosmosClient,
ILogger logger,
IMetrics metrics,
string loggingContextIdentifier,
CancellationToken cancellationToken)
{
Stopwatch stopWatch = Stopwatch.StartNew();
GaugeOptions documentGauge = new GaugeOptions {
Name = "#Documents received", Context = loggingContextIdentifier
};
TimerOptions readLatencyTimer = new TimerOptions
{
Name = "Latency",
MeasurementUnit = Unit.Requests,
DurationUnit = TimeUnit.Milliseconds,
RateUnit = TimeUnit.Seconds,
Context = loggingContextIdentifier,
Reservoir = () => new App.Metrics.ReservoirSampling.Uniform.DefaultAlgorithmRReservoir()
};
Container container = cosmosClient.GetContainer(config.Database, config.Collection);
try
{
while (stopWatch.Elapsed <= config.RunningTimeDurationAsTimespan)
{
long documentTotal = 0;
string continuation = null;
using FeedIterator <Dictionary <string, string> > changeFeedPull
= container.GetChangeFeedIterator <Dictionary <string, string> >(ChangeFeedStartFrom.Beginning(), ChangeFeedMode.Incremental);
try
{
while (changeFeedPull.HasMoreResults)
{
FeedResponse <Dictionary <string, string> > response;
using (TimerContext timerContext = metrics.Measure.Timer.Time(readLatencyTimer))
{
response = await changeFeedPull.ReadNextAsync();
Utils.LogDiagnostics(
logger: logger,
operationName: nameof(ChangeFeedPullScenario),
timerContextLatency: timerContext.Elapsed,
config: config,
cosmosDiagnostics: response.Diagnostics);
}
documentTotal += response.Count;
continuation = response.ContinuationToken;
if (response.StatusCode == HttpStatusCode.NotModified)
{
break;
}
}
metrics.Measure.Gauge.SetValue(documentGauge, documentTotal);
if (config.PreCreatedDocuments > 0)
{
if (this.initializationResult.InsertedDocuments != documentTotal)
{
Utils.LogError(logger, loggingContextIdentifier, $"The prepopulated documents and the change feed documents don't match. Preconfigured Docs = {this.initializationResult.InsertedDocuments}, Change feed Documents = {documentTotal}.{Environment.NewLine}{continuation}");
}
}
}
catch (Exception ex)
{
metrics.Measure.Gauge.SetValue(documentGauge, documentTotal);
Utils.LogError(logger, loggingContextIdentifier, ex);
}
}
}
catch (Exception ex)
{
Utils.LogError(logger, loggingContextIdentifier, ex);
}
finally
{
stopWatch.Stop();
if (this.initializationResult.CreatedContainer)
{
await cosmosClient.GetContainer(config.Database, config.Collection).DeleteContainerStreamAsync();
}
if (this.initializationResult.CreatedDatabase)
{
await cosmosClient.GetDatabase(config.Database).DeleteStreamAsync();
}
}
}
public async Task RunAsync(
CTLConfig config,
CosmosClient cosmosClient,
ILogger logger,
IMetrics metrics,
string loggingContextIdentifier,
CancellationToken cancellationToken)
{
logger.LogInformation("Initializing counters and metrics.");
CounterOptions documentCounter = new CounterOptions {
Name = "#Documents received", Context = loggingContextIdentifier
};
GaugeOptions leaseGauge = new GaugeOptions {
Name = "#Leases created", Context = loggingContextIdentifier
};
Container leaseContainer = await cosmosClient.GetDatabase(config.Database).CreateContainerAsync(Guid.NewGuid().ToString(), "/id");
try
{
ChangeFeedProcessor changeFeedProcessor = cosmosClient.GetContainer(config.Database, config.Collection)
.GetChangeFeedProcessorBuilder <SimpleItem>("ctlProcessor",
(IReadOnlyCollection <SimpleItem> docs, CancellationToken token) =>
{
metrics.Measure.Counter.Increment(documentCounter, docs.Count);
return(Task.CompletedTask);
})
.WithLeaseContainer(leaseContainer)
.WithInstanceName(Guid.NewGuid().ToString())
.WithStartTime(DateTime.MinValue.ToUniversalTime())
.Build();
await changeFeedProcessor.StartAsync();
logger.LogInformation("Started change feed processor");
await Task.Delay(config.RunningTimeDurationAsTimespan, cancellationToken);
logger.LogInformation("Stopping change feed processor");
await changeFeedProcessor.StopAsync();
// List leases
using FeedIterator <LeaseSchema> leaseIterator = leaseContainer.GetItemQueryIterator <LeaseSchema>();
int leaseTotal = 0;
List <FeedRange> ranges = new List <FeedRange>();
while (leaseIterator.HasMoreResults)
{
FeedResponse <LeaseSchema> response = await leaseIterator.ReadNextAsync();
foreach (LeaseSchema lease in response)
{
if (lease.LeaseToken != null)
{
logger.LogInformation($"Lease for range {lease.LeaseToken}");
ranges.Add(lease.FeedRange.EffectiveRange);
leaseTotal++;
}
}
}
string previousMin = "";
foreach (FeedRange sortedRange in ranges.OrderBy(range => range.Min))
{
if (previousMin != sortedRange.Min)
{
logger.LogError($"Expected a sorted range with Min <{previousMin}> but encountered range <{sortedRange.Min}>:<{sortedRange.Max}>");
}
previousMin = sortedRange.Max;
}
metrics.Measure.Gauge.SetValue(leaseGauge, leaseTotal);
}
catch (Exception ex)
{
logger.LogError(ex, "Failure during Change Feed Processor initialization");
}
finally
{
await leaseContainer.DeleteContainerAsync();
if (this.initializationResult.CreatedDatabase)
{
await cosmosClient.GetDatabase(config.Database).DeleteAsync();
}
if (this.initializationResult.CreatedContainer)
{
await cosmosClient.GetContainer(config.Database, config.Collection).DeleteContainerAsync();
}
}
}
public async Task RunAsync(
CTLConfig config,
CosmosClient cosmosClient,
ILogger logger,
IMetrics metrics,
string loggingContextIdentifier,
CancellationToken cancellationToken)
{
Stopwatch stopWatch = Stopwatch.StartNew();
GaugeOptions documentGauge = new GaugeOptions {
Name = "#Documents received", Context = loggingContextIdentifier
};
Container container = cosmosClient.GetContainer(config.Database, config.Collection);
try
{
while (stopWatch.Elapsed <= config.RunningTimeDurationAsTimespan)
{
long documentTotal = 0;
string continuation = null;
using FeedIterator <Dictionary <string, string> > changeFeedPull
= container.GetChangeFeedIterator <Dictionary <string, string> >(ChangeFeedStartFrom.Beginning(), ChangeFeedMode.Incremental);
try
{
while (changeFeedPull.HasMoreResults)
{
FeedResponse <Dictionary <string, string> > response = await changeFeedPull.ReadNextAsync();
documentTotal += response.Count;
continuation = response.ContinuationToken;
if (response.StatusCode == HttpStatusCode.NotModified)
{
break;
}
}
metrics.Measure.Gauge.SetValue(documentGauge, documentTotal);
if (config.PreCreatedDocuments > 0)
{
if (this.initializationResult.InsertedDocuments == documentTotal)
{
logger.LogInformation($"Success: The number of new documents match the number of pre-created documents: {this.initializationResult.InsertedDocuments}");
}
else
{
logger.LogError($"The prepopulated documents and the change feed documents don't match. Preconfigured Docs = {this.initializationResult.InsertedDocuments}, Change feed Documents = {documentTotal}.{Environment.NewLine}{continuation}");
}
}
}
catch (CosmosException ce) when(ce.StatusCode == System.Net.HttpStatusCode.TooManyRequests)
{
//Logging 429s is not relevant
}
catch (Exception ex)
{
metrics.Measure.Gauge.SetValue(documentGauge, documentTotal);
logger.LogError(ex, "Failure while looping through change feed documents");
}
}
}
catch (Exception ex)
{
logger.LogError(ex, "Failure during Change Feed Pull scenario");
}
finally
{
stopWatch.Stop();
if (this.initializationResult.CreatedContainer)
{
await cosmosClient.GetContainer(config.Database, config.Collection).DeleteContainerStreamAsync();
}
if (this.initializationResult.CreatedDatabase)
{
await cosmosClient.GetDatabase(config.Database).DeleteStreamAsync();
}
}
}
private async Task ExecuteOperationsAsync(
CTLConfig config,
ILogger logger,
IMetrics metrics,
string loggingContextIdentifier,
InitializationResult initializationResult,
ReadWriteQueryPercentage readWriteQueryPercentage,
CancellationToken cancellationToken)
{
logger.LogInformation("Initializing counters and metrics.");
CounterOptions readSuccessMeter = new CounterOptions {
Name = "#Read Successful Operations", Context = loggingContextIdentifier
};
CounterOptions readFailureMeter = new CounterOptions {
Name = "#Read Unsuccessful Operations", Context = loggingContextIdentifier
};
CounterOptions writeSuccessMeter = new CounterOptions {
Name = "#Write Successful Operations", Context = loggingContextIdentifier
};
CounterOptions writeFailureMeter = new CounterOptions {
Name = "#Write Unsuccessful Operations", Context = loggingContextIdentifier
};
CounterOptions querySuccessMeter = new CounterOptions {
Name = "#Query Successful Operations", Context = loggingContextIdentifier
};
CounterOptions queryFailureMeter = new CounterOptions {
Name = "#Query Unsuccessful Operations", Context = loggingContextIdentifier
};
TimerOptions readLatencyTimer = new TimerOptions
{
Name = "Read latency",
MeasurementUnit = Unit.Requests,
DurationUnit = TimeUnit.Milliseconds,
RateUnit = TimeUnit.Seconds,
Context = loggingContextIdentifier,
Reservoir = () => new App.Metrics.ReservoirSampling.Uniform.DefaultAlgorithmRReservoir()
};
TimerOptions writeLatencyTimer = new TimerOptions
{
Name = "Write latency",
MeasurementUnit = Unit.Requests,
DurationUnit = TimeUnit.Milliseconds,
RateUnit = TimeUnit.Seconds,
Context = loggingContextIdentifier,
Reservoir = () => new App.Metrics.ReservoirSampling.Uniform.DefaultAlgorithmRReservoir()
};
TimerOptions queryLatencyTimer = new TimerOptions
{
Name = "Query latency",
MeasurementUnit = Unit.Requests,
DurationUnit = TimeUnit.Milliseconds,
RateUnit = TimeUnit.Seconds,
Context = loggingContextIdentifier,
Reservoir = () => new App.Metrics.ReservoirSampling.Uniform.DefaultAlgorithmRReservoir()
};
SemaphoreSlim concurrencyControlSemaphore = new SemaphoreSlim(config.Concurrency);
Stopwatch stopwatch = Stopwatch.StartNew();
int writeRange = readWriteQueryPercentage.ReadPercentage + readWriteQueryPercentage.WritePercentage;
List <Task> operations = new List <Task>();
for (long i = 0; ShouldContinue(stopwatch, i, config); i++)
{
await concurrencyControlSemaphore.WaitAsync(cancellationToken);
long index = i % 100;
if (index < readWriteQueryPercentage.ReadPercentage)
{
operations.Add(CTLOperationHandler <ItemResponse <Dictionary <string, string> > > .PerformOperationAsync(
createTimerContext: () => metrics.Measure.Timer.Time(readLatencyTimer),
resultProducer: new SingleExecutionResultProducer <ItemResponse <Dictionary <string, string> > >(() => this.CreateReadOperation(
operation: i,
partitionKeyAttributeName: config.CollectionPartitionKey,
containers: initializationResult.Containers,
createdDocumentsPerContainer: this.createdDocuments)),
onSuccess: () =>
{
concurrencyControlSemaphore.Release();
metrics.Measure.Counter.Increment(readSuccessMeter);
},
onFailure: (Exception ex) =>
{
concurrencyControlSemaphore.Release();
metrics.Measure.Counter.Increment(readFailureMeter);
Utils.LogError(logger, loggingContextIdentifier, ex, "Failure during read operation");
},
logDiagnostics: (ItemResponse <Dictionary <string, string> > response, TimeSpan latency) => Utils.LogDiagnostics(
logger: logger,
operationName: "Read",
timerContextLatency: latency,
config: config,
cosmosDiagnostics: response.Diagnostics)));
}
else if (index < writeRange)
{
operations.Add(CTLOperationHandler <ItemResponse <Dictionary <string, string> > > .PerformOperationAsync(
createTimerContext: () => metrics.Measure.Timer.Time(writeLatencyTimer),
resultProducer: new SingleExecutionResultProducer <ItemResponse <Dictionary <string, string> > >(() => this.CreateWriteOperation(
operation: i,
partitionKeyAttributeName: config.CollectionPartitionKey,
containers: initializationResult.Containers,
isContentResponseOnWriteEnabled: config.IsContentResponseOnWriteEnabled)),
onSuccess: () =>
{
concurrencyControlSemaphore.Release();
metrics.Measure.Counter.Increment(writeSuccessMeter);
},
onFailure: (Exception ex) =>
{
concurrencyControlSemaphore.Release();
metrics.Measure.Counter.Increment(writeFailureMeter);
Utils.LogError(logger, loggingContextIdentifier, ex, "Failure during write operation");
},
logDiagnostics: (ItemResponse <Dictionary <string, string> > response, TimeSpan latency) => Utils.LogDiagnostics(
logger: logger,
operationName: "Write",
timerContextLatency: latency,
config: config,
cosmosDiagnostics: response.Diagnostics)));
}
else
{
operations.Add(CTLOperationHandler <FeedResponse <Dictionary <string, string> > > .PerformOperationAsync(
createTimerContext: () => metrics.Measure.Timer.Time(queryLatencyTimer),
resultProducer: new IteratorResultProducer <Dictionary <string, string> >(this.CreateQueryOperation(
operation: i,
containers: initializationResult.Containers)),
onSuccess: () =>
{
concurrencyControlSemaphore.Release();
metrics.Measure.Counter.Increment(querySuccessMeter);
},
onFailure: (Exception ex) =>
{
concurrencyControlSemaphore.Release();
metrics.Measure.Counter.Increment(queryFailureMeter);
Utils.LogError(logger, loggingContextIdentifier, ex, "Failure during query operation");
},
logDiagnostics: (FeedResponse <Dictionary <string, string> > response, TimeSpan latency) => Utils.LogDiagnostics(
logger: logger,
operationName: "Query",
timerContextLatency: latency,
config: config,
cosmosDiagnostics: response.Diagnostics)));
}
}
await Task.WhenAll(operations);
stopwatch.Stop();
logger.LogInformation("[{0}] operations performed in [{1}] seconds.",
operations.Count, stopwatch.Elapsed.TotalSeconds);
}
private static void SetEnvironmentVariables(CTLConfig config)
{
Environment.SetEnvironmentVariable(ClientTelemetryOptions.EnvPropsClientTelemetryEndpoint, config.TelemetryEndpoint);
Environment.SetEnvironmentVariable(ClientTelemetryOptions.EnvPropsClientTelemetrySchedulingInSeconds, config.TelemetryScheduleInSeconds);
}
public static async Task Main(string[] args)
{
using ILoggerFactory loggerFactory = LoggerFactory.Create(builder => builder
.AddConsole());
ILogger logger = loggerFactory.CreateLogger <Program>();
try
{
CTLConfig config = CTLConfig.From(args);
SetEnvironmentVariables(config);
if (config.OutputEventTraces)
{
EnableTraceSourcesToConsole();
}
using CosmosClient client = config.CreateCosmosClient();
string loggingContextIdentifier = $"{config.WorkloadType}{config.LogginContext}";
using (logger.BeginScope(loggingContextIdentifier))
{
IMetricsRoot metrics = ConfigureReporting(config, logger);
ICTLScenario scenario = CreateScenario(config.WorkloadType);
using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource();
await scenario.InitializeAsync(
config : config,
cosmosClient : client,
logger : logger);
logger.LogInformation("Initialization completed.");
if (client.ClientOptions.EnableClientTelemetry.GetValueOrDefault())
{
logger.LogInformation("Telemetry is enabled for CTL.");
}
else
{
logger.LogInformation("Telemetry is disabled for CTL.");
}
List <Task> tasks = new List <Task>
{
scenario.RunAsync(
config: config,
cosmosClient: client,
logger: logger,
metrics: metrics,
loggingContextIdentifier: loggingContextIdentifier,
cancellationToken: cancellationTokenSource.Token),
Task.Run(async() =>
{
// Measure CPU/memory
Process process = Process.GetCurrentProcess();
GaugeOptions processPhysicalMemoryGauge = new GaugeOptions
{
Name = "Process Working Set",
MeasurementUnit = Unit.Bytes,
Context = loggingContextIdentifier
};
GaugeOptions totalCpuGauge = new GaugeOptions
{
Name = "Total CPU",
MeasurementUnit = Unit.Percent,
Context = loggingContextIdentifier
};
GaugeOptions priviledgedCpuGauge = new GaugeOptions
{
Name = "Priviledged CPU",
MeasurementUnit = Unit.Percent,
Context = loggingContextIdentifier
};
GaugeOptions userCpuGauge = new GaugeOptions
{
Name = "User CPU",
MeasurementUnit = Unit.Percent,
Context = loggingContextIdentifier
};
DateTime lastTimeStamp = process.StartTime;
TimeSpan lastTotalProcessorTime = TimeSpan.Zero;
TimeSpan lastUserProcessorTime = TimeSpan.Zero;
TimeSpan lastPrivilegedProcessorTime = TimeSpan.Zero;
while (!cancellationTokenSource.Token.IsCancellationRequested)
{
await Task.Delay(TimeSpan.FromSeconds(config.ReportingIntervalInSeconds));
process.Refresh();
double totalCpuTimeUsed = process.TotalProcessorTime.TotalMilliseconds - lastTotalProcessorTime.TotalMilliseconds;
double privilegedCpuTimeUsed = process.PrivilegedProcessorTime.TotalMilliseconds - lastPrivilegedProcessorTime.TotalMilliseconds;
double userCpuTimeUsed = process.UserProcessorTime.TotalMilliseconds - lastUserProcessorTime.TotalMilliseconds;
lastTotalProcessorTime = process.TotalProcessorTime;
lastPrivilegedProcessorTime = process.PrivilegedProcessorTime;
lastUserProcessorTime = process.UserProcessorTime;
double cpuTimeElapsed = (DateTime.UtcNow - lastTimeStamp).TotalMilliseconds * Environment.ProcessorCount;
lastTimeStamp = DateTime.UtcNow;
metrics.Measure.Gauge.SetValue(totalCpuGauge, totalCpuTimeUsed * 100 / cpuTimeElapsed);
metrics.Measure.Gauge.SetValue(priviledgedCpuGauge, privilegedCpuTimeUsed * 100 / cpuTimeElapsed);
metrics.Measure.Gauge.SetValue(userCpuGauge, userCpuTimeUsed * 100 / cpuTimeElapsed);
metrics.Measure.Gauge.SetValue(processPhysicalMemoryGauge, process.WorkingSet64);
await Task.WhenAll(metrics.ReportRunner.RunAllAsync());
}
})
};
await Task.WhenAny(tasks);
cancellationTokenSource.Cancel();
// Final report
await Task.WhenAll(metrics.ReportRunner.RunAllAsync());
logger.LogInformation($"{nameof(CosmosCTL)} completed successfully.");
}
}
catch (Exception ex)
{
logger.LogError(ex, "Unhandled exception during execution");
}
}
private async Task ExecuteOperationsAsync(
CTLConfig config,
ILogger logger,
IMetrics metrics,
InitializationResult initializationResult,
ReadWriteQueryPercentage readWriteQueryPercentage,
CancellationToken cancellationToken)
{
logger.LogInformation("Initializing counters and metrics.");
CounterOptions readSuccessMeter = new CounterOptions {
Name = "#Read Successful Operations", Context = nameof(WorkloadType.ReadWriteQuery)
};
CounterOptions readFailureMeter = new CounterOptions {
Name = "#Read Unsuccessful Operations", Context = nameof(WorkloadType.ReadWriteQuery)
};
CounterOptions writeSuccessMeter = new CounterOptions {
Name = "#Write Successful Operations", Context = nameof(WorkloadType.ReadWriteQuery)
};
CounterOptions writeFailureMeter = new CounterOptions {
Name = "#Write Unsuccessful Operations", Context = nameof(WorkloadType.ReadWriteQuery)
};
CounterOptions querySuccessMeter = new CounterOptions {
Name = "#Query Successful Operations", Context = nameof(WorkloadType.ReadWriteQuery)
};
CounterOptions queryFailureMeter = new CounterOptions {
Name = "#Query Unsuccessful Operations", Context = nameof(WorkloadType.ReadWriteQuery)
};
TimerOptions readLatencyTimer = new TimerOptions
{
Name = "Read latency",
MeasurementUnit = Unit.Requests,
DurationUnit = TimeUnit.Milliseconds,
RateUnit = TimeUnit.Seconds,
Context = nameof(WorkloadType.ReadWriteQuery),
Reservoir = () => new App.Metrics.ReservoirSampling.Uniform.DefaultAlgorithmRReservoir()
};
TimerOptions writeLatencyTimer = new TimerOptions
{
Name = "Write latency",
MeasurementUnit = Unit.Requests,
DurationUnit = TimeUnit.Milliseconds,
RateUnit = TimeUnit.Seconds,
Context = nameof(WorkloadType.ReadWriteQuery),
Reservoir = () => new App.Metrics.ReservoirSampling.Uniform.DefaultAlgorithmRReservoir()
};
TimerOptions queryLatencyTimer = new TimerOptions
{
Name = "Query latency",
MeasurementUnit = Unit.Requests,
DurationUnit = TimeUnit.Milliseconds,
RateUnit = TimeUnit.Seconds,
Context = nameof(WorkloadType.ReadWriteQuery),
Reservoir = () => new App.Metrics.ReservoirSampling.Uniform.DefaultAlgorithmRReservoir()
};
SemaphoreSlim concurrencyControlSemaphore = new SemaphoreSlim(config.Concurrency);
Stopwatch stopwatch = Stopwatch.StartNew();
int writeRange = readWriteQueryPercentage.ReadPercentage + readWriteQueryPercentage.WritePercentage;
long diagnosticsThresholdDuration = (long)config.DiagnosticsThresholdDurationAsTimespan.TotalMilliseconds;
List <Task> operations = new List <Task>((int)config.Operations);
for (long i = 0; ShouldContinue(stopwatch, i, config); i++)
{
long index = (long)i % 100;
if (index < readWriteQueryPercentage.ReadPercentage)
{
operations.Add(CTLOperationHandler <ItemResponse <Dictionary <string, string> > > .PerformOperationAsync(
semaphoreSlim: concurrencyControlSemaphore,
diagnosticsLoggingThreshold: diagnosticsThresholdDuration,
createTimerContext: () => metrics.Measure.Timer.Time(readLatencyTimer),
resultProducer: new SingleExecutionResultProducer <ItemResponse <Dictionary <string, string> > >(() => this.CreateReadOperation(
operation: i,
containers: initializationResult.Containers,
createdDocumentsPerContainer: this.createdDocuments)),
onSuccess: () => metrics.Measure.Counter.Increment(readSuccessMeter),
onFailure: (Exception ex) =>
{
metrics.Measure.Counter.Increment(readFailureMeter);
logger.LogError(ex, "Failure during read operation");
},
logDiagnostics: (ItemResponse <Dictionary <string, string> > response) => logger.LogInformation("Read request took more than latency threshold {0}, diagnostics: {1}", config.DiagnosticsThresholdDuration, response.Diagnostics.ToString()),
cancellationToken: cancellationToken));
}
else if (index < writeRange)
{
operations.Add(CTLOperationHandler <ItemResponse <Dictionary <string, string> > > .PerformOperationAsync(
semaphoreSlim: concurrencyControlSemaphore,
diagnosticsLoggingThreshold: diagnosticsThresholdDuration,
createTimerContext: () => metrics.Measure.Timer.Time(writeLatencyTimer),
resultProducer: new SingleExecutionResultProducer <ItemResponse <Dictionary <string, string> > >(() => this.CreateWriteOperation(
operation: i,
containers: initializationResult.Containers,
isContentResponseOnWriteEnabled: config.IsContentResponseOnWriteEnabled)),
onSuccess: () => metrics.Measure.Counter.Increment(writeSuccessMeter),
onFailure: (Exception ex) =>
{
metrics.Measure.Counter.Increment(writeFailureMeter);
logger.LogError(ex, "Failure during write operation");
},
logDiagnostics: (ItemResponse <Dictionary <string, string> > response) => logger.LogInformation("Write request took more than latency threshold {0}, diagnostics: {1}", config.DiagnosticsThresholdDuration, response.Diagnostics.ToString()),
cancellationToken: cancellationToken));
}
else
{
operations.Add(CTLOperationHandler <FeedResponse <Dictionary <string, string> > > .PerformOperationAsync(
semaphoreSlim: concurrencyControlSemaphore,
diagnosticsLoggingThreshold: diagnosticsThresholdDuration,
createTimerContext: () => metrics.Measure.Timer.Time(queryLatencyTimer),
resultProducer: new IteratorResultProducer <Dictionary <string, string> >(this.CreateQueryOperation(
operation: i,
containers: initializationResult.Containers)),
onSuccess: () => metrics.Measure.Counter.Increment(querySuccessMeter),
onFailure: (Exception ex) =>
{
metrics.Measure.Counter.Increment(queryFailureMeter);
logger.LogError(ex, "Failure during query operation");
},
logDiagnostics: (FeedResponse <Dictionary <string, string> > response) => logger.LogInformation("Query request took more than latency threshold {0}, diagnostics: {1}", config.DiagnosticsThresholdDuration, response.Diagnostics.ToString()),
cancellationToken: cancellationToken));
}
}
await Task.WhenAll(operations);
stopwatch.Stop();
logger.LogInformation("[{0}] operations performed in [{1}] seconds.",
config.Operations, stopwatch.Elapsed.TotalSeconds);
}
public static async Task Main(string[] args)
{
using ILoggerFactory loggerFactory = LoggerFactory.Create(builder => builder
.AddConsole());
ILogger logger = loggerFactory.CreateLogger <Program>();
try
{
CTLConfig config = CTLConfig.From(args);
if (config.OutputEventTraces)
{
EnableTraceSourcesToConsole();
}
using CosmosClient client = config.CreateCosmosClient();
using (logger.BeginScope(config.WorkloadType))
{
IMetricsRoot metrics = ConfigureReporting(config, logger);
ICTLScenario scenario = CreateScenario(config.WorkloadType);
using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource();
await scenario.InitializeAsync(
config : config,
cosmosClient : client,
logger : logger);
List <Task> tasks = new List <Task>
{
scenario.RunAsync(
config: config,
cosmosClient: client,
logger: logger,
metrics: metrics,
cancellationToken: cancellationTokenSource.Token),
Task.Run(async() =>
{
while (!cancellationTokenSource.Token.IsCancellationRequested)
{
await Task.Delay(TimeSpan.FromSeconds(config.ReportingIntervalInSeconds));
await Task.WhenAll(metrics.ReportRunner.RunAllAsync());
}
})
};
await Task.WhenAny(tasks);
cancellationTokenSource.Cancel();
// Final report
await Task.WhenAll(metrics.ReportRunner.RunAllAsync());
logger.LogInformation($"{nameof(CosmosCTL)} completed successfully.");
}
}
catch (Exception ex)
{
logger.LogError(ex, "Unhandled exception during execution");
}
}