Closed shiomax closed 3 years ago
worth mentioning how/when you connect and where that lives - obv you need to hold the Client/Container and a need to reestablish all that could easily explain
are you doing release builds in both tests etc.
It´s a static class, we call Initialize once on Application startup for every Type we want to use it as. In this example it does not matter anyhow since it´s just that one Main method. In the real application(s) we called in either in the global asax of the singalr project and in another one alongside the methods that create the asp.net webapi. So the actual project we where gonna use this library are 3 seperate Microservices and in two of those we use CosmosDB. The Console Application here was just for testing to figure out why it´s so much slower. And it appears it´s much slower on .net. Both console applications run 1:1 the same code.
@shiomax (note I dont work for the team or anything) - knowing the initialization is only happening once is pretty important to be definite on as the order of magnitude you are talking about could easily be explained by you reconnecting loads of times instead of holding one client/connection/container. I am not doubting both are the same code. I'm asking how you invoked the run of the app, including that you made sure it was a release build.
I didnt make sure its a release build both are debug builds. I can try that tomorrow. Don't have much fate in that. It´s also not very practical to do that all the time.
But as I said the numbers come from a console application. Those 10 lines is it. It cannot re-run the Initialize methods.
It´s also not very practical to do that all the time. not sure what that means. When comparing perf, its notoriously easy to do something wrong in your test case. When claiming select is broken, being sure is important (which reminds me I have a test suite I must run at some point)
I had missed the fact you showed the Initialize
method and where it is called which seems to rule multiple inits out.
aside: team: would love to know the equivalent of ConnectAsync to trigger initialization of a connection in V3...
I had missed the fact you showed the
Initialize
method and where it is called which seems to rule multiple inits out.aside: team: would love to know the equivalent of ConnectAsync to trigger initialization of a connection in V3...
Maybe, none? Since, the very first query is already up to the same speeds.
Can you show how you construct the queries in V2 as part of the comparison?
Basically the performance difference between NETFX and NET Core is expected, not sure if that order of magnitude, but NET Core should be faster. What I'm interested is in the side by side comparison of the V2 code to see if there is any difference for NETFX on V3 and V2.
I also had a worse-performance experience, upgrading from v2 to v3.
Not 10 x, but still very noticeable running both versions on .net core.
I have tried to reproduce it in the most simple program possible. Could I get any pointers what could be wrong?
It were done on the latest version of the local emulator
private static readonly string EndpointUri = "";
private static readonly string PrimaryKey = "";
private static string databaseId = "TestCosmos";
private static string containerId = "TestCosmos";
public static async Task Main(string[] args)
{
var cosmosClient = new CosmosClient(EndpointUri, PrimaryKey);
var database = cosmosClient.GetDatabase(databaseId);
var container = database.GetContainer(containerId);
for (int i = 0; i < 10; i++)
{
var query = container.GetItemLinqQueryable<SimpleCosmosObject>().Where(x => x.ObjectType == "SimpleCosmosObject");
var feedIterator = query.ToFeedIterator();
int counter = 0;
var watch = System.Diagnostics.Stopwatch.StartNew();
while (feedIterator.HasMoreResults)
{
var results = await feedIterator.ReadNextAsync();
foreach (var result in results)
{
counter++;
}
}
watch.Stop();
var seconds = watch.ElapsedMilliseconds / 1000.0;
Console.WriteLine($"Test took {seconds} seconds to fetch {counter} documents");
}
}
private static readonly string EndpointUri = "";
private static readonly string PrimaryKey = "";
private static string databaseId = "TestCosmos";
private static string containerId = "TestCosmos";
static async Task Main(string[] args)
{
var client = new DocumentClient(new Uri(EndpointUri), PrimaryKey);
Uri collectionUri = UriFactory.CreateDocumentCollectionUri(databaseId, containerId);
for (int i = 0; i < 10; i++)
{
var query = client.CreateDocumentQuery<SimpleCosmosObject>(collectionUri).Where(x => x.ObjectType == "SimpleCosmosObject");
var documentQuery = query.AsDocumentQuery();
int counter = 0;
var watch = System.Diagnostics.Stopwatch.StartNew();
while (documentQuery.HasMoreResults)
{
var results = await documentQuery.ExecuteNextAsync<SimpleCosmosObject>();
foreach (var result in results)
{
counter++;
}
}
watch.Stop();
var seconds = watch.ElapsedMilliseconds / 1000.0;
Console.WriteLine($"Test took {seconds} seconds to fetch {counter} documents");
}
}
The document is 200 lines in cosmos
Here are the results
Sdk V3
Sdk V2
suggest reposting those with a release build run with ctrl-F5. There's no point in doing any perf numbers on a debug build and/or with a debugger attached
Run them with dotnet run -c Release
from the command line. @j82w are the 2 query execution methods equivalent?
@Rfaering Do you see this difference only in queries?
Also @Rfaering can you count the amount of ExecuteNextAsync calls besides the documents, I suspect the reason for the increased latency might be related to doing more calls, not from the actual call itself.
The numbers in release build for Core are about the same (so good in both release and debug) .net does actually get much better, just by going into release build.
This took 311ms.
This took 310ms.
This took 131ms.
This took 150ms.
This took 126ms.
This took 137ms.
This took 136ms.
This took 371ms.
This took 146ms.
This took 144ms.
Still, you gotta be able to debug and you kinda can´t when you x10 every query. It´s not just that one it´s everywhere. 500ms queries turn into 5 seconds. The webapp is not debuggable at all like that. A bit worse would be understandable. But not 10 times. It´s in the teritory where you might actually get rest timeouts that you normally would not (had that too).
With the v2 library it´s 100-150ms without spikes above that in release AND debug mode. It´s pretty much the exact same give or take 10-20ms.
Any ideas why v3 performs so much worse in debug mode? Especially, the part where it ONLY does that on .net is what I don´t understand. But it´s good to know that debug mode (can) have that kind of effect for the next time.
Anyways, we have that implemented in both v2 and v3 pretty much the same way now. It would take about as long as it does swap out nuget packages to go back to v3. But I dont wanna make everybody's life miserable that is developing on that project.
I changed the programs slightly to use MaxItemCount = -1, because we use that in production. Also I am now compiling and running in release mode.
Both send 12 requests to the server and both seems to have the exact same results as before
public static async Task Main(string[] args)
{
var cosmosClient = new CosmosClient(EndpointUri, PrimaryKey);
var database = cosmosClient.GetDatabase(databaseId);
var container = database.GetContainer(containerId);
for (int i = 0; i < 10; i++)
{
var query = container.GetItemLinqQueryable<SimpleCosmosObject>(requestOptions: new QueryRequestOptions() { MaxItemCount = -1 })
.Where(x => x.ObjectType == "SimpleCosmosObject");
var feedIterator = query.ToFeedIterator();
int counter = 0;
int numberOfRequests = 0;
var watch = Stopwatch.StartNew();
while (feedIterator.HasMoreResults)
{
var results = await feedIterator.ReadNextAsync();
foreach (var result in results)
{
counter++;
}
numberOfRequests++;
}
watch.Stop();
var seconds = watch.ElapsedMilliseconds / 1000.0;
Console.WriteLine($"Test took {seconds} seconds to fetch {counter} documents over {numberOfRequests} requests");
}
}
static async Task Main(string[] args)
{
var client = new DocumentClient(new Uri(EndpointUri), PrimaryKey);
Uri collectionUri = UriFactory.CreateDocumentCollectionUri(databaseId, containerId);
for (int i = 0; i < 10; i++)
{
var query = client.CreateDocumentQuery<SimpleCosmosObject>(collectionUri, feedOptions: new FeedOptions() { MaxItemCount = -1 })
.Where(x => x.ObjectType == "SimpleCosmosObject");
var documentQuery = query.AsDocumentQuery();
int counter = 0;
int numberOfRequests = 0;
var watch = System.Diagnostics.Stopwatch.StartNew();
while (documentQuery.HasMoreResults)
{
var results = await documentQuery.ExecuteNextAsync<SimpleCosmosObject>();
foreach (var result in results)
{
counter++;
}
numberOfRequests++;
}
watch.Stop();
var seconds = watch.ElapsedMilliseconds / 1000.0;
Console.WriteLine($"Test took {seconds} seconds to fetch {counter} documents over {numberOfRequests} requests");
}
}
@ealsur should I create a separate ticket for this, as it might not be related to the original ticket?
Please tell me if there is anything you need from me
@Rfaering
@j82w - Same results.
I am not sure what the values should be. But setting all to -1 or the values attached below.
MaxBufferedItemCount = 1000, MaxDegreeOfParallelism = 2, MaxItemCount = -1
Both seems to results in roughly the same numbers
Also note that both are using ConnectionMode.Direct now
public static async Task Main(string[] args)
{
var cosmosClient = new CosmosClient(EndpointUri, PrimaryKey, new CosmosClientOptions() { ConnectionMode = ConnectionMode.Direct });
var database = cosmosClient.GetDatabase(databaseId);
var container = database.GetContainer(containerId);
for (int i = 0; i < 10; i++)
{
var query = container.GetItemLinqQueryable<SimpleCosmosObject>(requestOptions: new QueryRequestOptions() { MaxItemCount = -1, MaxBufferedItemCount = 1000, MaxConcurrency = 2 })
.Where(x => x.ObjectType == "SimpleCosmosObject");
var feedIterator = query.ToFeedIterator();
int counter = 0;
int numberOfRequests = 0;
var watch = Stopwatch.StartNew();
while (feedIterator.HasMoreResults)
{
var results = await feedIterator.ReadNextAsync();
foreach (var result in results)
{
counter++;
}
numberOfRequests++;
}
watch.Stop();
var seconds = watch.ElapsedMilliseconds / 1000.0;
Console.WriteLine($"Test took {seconds} seconds to fetch {counter} documents over {numberOfRequests} requests");
}
}
static async Task Main(string[] args)
{
var client = new DocumentClient(new Uri(EndpointUri), PrimaryKey, new ConnectionPolicy() { ConnectionMode = ConnectionMode.Direct, ConnectionProtocol = Protocol.Tcp });
Uri collectionUri = UriFactory.CreateDocumentCollectionUri(databaseId, containerId);
for (int i = 0; i < 10; i++)
{
var query = client.CreateDocumentQuery<SimpleCosmosObject>(collectionUri, feedOptions: new FeedOptions() { MaxItemCount = -1, MaxBufferedItemCount = 1000, MaxDegreeOfParallelism = 2 })
.Where(x => x.ObjectType == "SimpleCosmosObject");
var documentQuery = query.AsDocumentQuery();
int counter = 0;
int numberOfRequests = 0;
var watch = System.Diagnostics.Stopwatch.StartNew();
while (documentQuery.HasMoreResults)
{
var results = await documentQuery.ExecuteNextAsync<SimpleCosmosObject>();
foreach (var result in results)
{
counter++;
}
numberOfRequests++;
}
watch.Stop();
var seconds = watch.ElapsedMilliseconds / 1000.0;
Console.WriteLine($"Test took {seconds} seconds to fetch {counter} documents over {numberOfRequests} requests");
}
}
@Rfaering are you running this as an x64 application on Windows?
@j82w Most likely. From the screenshots alone. That's ain't Linux or MacOS. Unless he is deep into Windows themes for Linux.
Btw, did anybody else here have a similar experience on .net (not core) in debug mode as me? Or am I the only one?
The SDK itself otherwise I do find to be better. For features like top in cross partition queries (I would not really care as its solveble in other ways manually, but turns out kendos toDatasourceResult
pagination query builder for their widgets does), stream api seems very useful but since we sticked to v2 for the time being there was not much opportunity to really utilize that, no more Uri things (aka overall less cluttered public api), only one package for core AND .net so no more "You need DocumentDB.PartitionKey" in your .net standard class library, but you can only install "DocumentDB.Core.PartitionKey" and then you end up writing weird hacks to workaround that.
Almost, if not 10 times the query times in debug mode is just not acceptable though. Granted, Im very unpatient myself. But still. As I said debugging our actual app turns from totally useable to a chore. We didnt account for those kind of permanent "spikes" ("spikes", because it is consistently that). So it just straight up bearly manages to work, if at all. We have some things where the entire rest request+query etc can take up to 2 seconds. Multiply that by 10 and have a 10 seconds timeout on your rest requests and none of those requests that take that long will work anymore.
@shiomax I had the experience of VS running on x86 when debugging, by default. In the case of Queries, running on x86 will make it so the queries will always go through Gateway Mode since the Interop DLL cannot be loaded for native level processing.
From the screenshot alone, it's hard to tell which is the runtime architecture that is being used to run. Printing ProcessArchitecture
(from RuntimeInformation) might also show if it's running on x86 or x64.
@Rfaering I'm curious, is this only on Queries? If you do point ReadItem operations, do you also see a difference?
Well doing
Console.WriteLine("Running architecture: " + RuntimeInformation.ProcessArchitecture);
Only showed me that I am running x64.
All previous tests were done on documents, placed in a non-partitioned container created by SDK 2.
I have moved them all to a partitioned container, and then running this query in both tests with PartitionKey
var query = client.CreateDocumentQuery<SimpleCosmosObject>(collectionUri, feedOptions: new FeedOptions() { MaxItemCount = -1, MaxBufferedItemCount = 1000, MaxDegreeOfParallelism = 2 })
.Where(x => x.ObjectType == "SimpleCosmosObject")
.Where(x => x.PartitionKey == "PartitionKey1");
It gave me the same results as before!
But it is VERY odd that if I remove all of the predicates (Including PartitionKey), so it simple just fetches all items. The results are very different! Then SDK 3 is much faster!
SDK 3
SDK 2
I also ran the test where I am fetching individual documents.
In this tests the SDK 2 performed best again
for (int i = 0; i < 10; i++)
{
int counter = 0;
int numberOfRequests = 0;
var watch = Stopwatch.StartNew();
foreach (var documentId in documentIds)
{
var doc = await container.ReadItemAsync<SimpleCosmosObject>(documentId, new PartitionKey("PartitionKey1"));
numberOfRequests++;
counter++;
}
watch.Stop();
var seconds = watch.ElapsedMilliseconds / 1000.0;
Console.WriteLine($"Test took {seconds} seconds to fetch {counter} documents over {numberOfRequests} requests");
}
for (int i = 0; i < 10; i++)
{
int counter = 0;
int numberOfRequests = 0;
var watch = System.Diagnostics.Stopwatch.StartNew();
foreach (var documentId in documentIds)
{
var doc = await client.ReadDocumentAsync<SimpleCosmosObject>(UriFactory.CreateDocumentUri(databaseId, containerId, documentId), new RequestOptions() { PartitionKey = new PartitionKey("PartitionKey1") });
numberOfRequests++;
counter++;
}
watch.Stop();
var seconds = watch.ElapsedMilliseconds / 1000.0;
Console.WriteLine($"Test took {seconds} seconds to fetch {counter} documents over {numberOfRequests} requests");
}
@j82w @ealsur - Please let me know if there is something else you want me to test
I have tried to time every request and how long it takes to loop through the items. Why does the SDK 3 takes so much longer?!
while (feedIterator.HasMoreResults)
{
var requestStopWatch = Stopwatch.StartNew();
var results = await feedIterator.ReadNextAsync();
var requestsInSeconds = requestStopWatch.ElapsedMilliseconds / 1000.0;
var loopStopWatch = Stopwatch.StartNew();
foreach (var result in results.ToList())
{
if (result.Double3 < 10000)
{
counter++;
}
}
var loopInSeconds = loopStopWatch.ElapsedMilliseconds / 1000.0;
Console.WriteLine($"Requests costs {results.RequestCharge} RU units and has retrieved {results.Count} items in {requestsInSeconds} seconds, looping through all items took {loopInSeconds} seconds");
numberOfRequests++;
}
while (documentQuery.HasMoreResults)
{
var requestStopWAtch = Stopwatch.StartNew();
var results = await documentQuery.ExecuteNextAsync<SimpleCosmosObject>();
var requestInSeconds = requestStopWAtch.ElapsedMilliseconds / 1000.0;
var loopStopWatch = Stopwatch.StartNew();
foreach (var result in results)
{
if (result.Double3 < 10000)
{
counter++;
}
}
var loopInSeconds = loopStopWatch.ElapsedMilliseconds / 1000.0;
Console.WriteLine($"Requests costs {results.RequestCharge} RU units and has retrieved {results.Count} items in {requestInSeconds} seconds, looping through all items took {loopInSeconds} seconds");
numberOfRequests++;
}
Waaait. How many of the original readings were with the emulator? (It comes as quite a surprise to me that some readings are against the emulator; I'd never consider measuring the perf of an emulator)
@bartelink - I cannot speak for any of @shiomax tests. But for my case, all of them
I will reproduce the same tests tomorrow in a real environment
It's worth mentioning the quality/nature of the network when doing so - i.e. running in a VM in the data centre would be optimal (and would pretty much exclude the network as a factor) but not necessary (and of course the connection mode, which becomes more significant when you're measuring the real thing)
@bartelink - I cannot speak for any of @shiomax tests. But for my case, all of them
I was using cosmosdb in azure with .net running locally on the PC. So the connection was consistently the very same. I´m not really sure it even matters since the performance hit comes from running it with the debugger enabled.
The only thing that makes performance better is to "start without debugging". Release mode itself does not make the difference (as I first thought). But when you start it without debugging (shift+f10), then it´s fast again. 32bit vs 64bit makes a very minor difference. I tried both now. 64bit seems to be a bit faster.
In the v2 library starting it without debugging is also faster, but it is 80ms vs 150ms as opposed to 80ms vs 800ms.
I have run the tests again, against a real database.
It is not easy for me to run the tests from a VM in azure, so network traffic will be a factor that we will have to take into account
SDK 2 is now even faster then SDK 3. And I do not understand how it can take 300 ms to loop through 370 items. I guess it does deserialization on the fly, in SDK 3?
Also it seems that with increased network traffic SDK 3 does even worse
Has anyone found any subsequent workarounds to this issue besides the "start without debugging" option?
It's a very regular occurrence that we have to utilize the Cosmos DB SDK while debugging, and the performance issues we face with this are near enough to force us back to v2 of the SDK.
Please create a new issue if this still reproduces. Several performance improvements have been made in the latest SDK.
Describe the bug On .net 4.7.2 we get horrible performance using the new v3 library. The same Linq query that matches all Documents where one varible is true takes 80-200ms with .net core and over a full second with .net, it also takes only around 150ms with the old v2 library using .net 4.7.2.
To Reproduce We have been using a Repository pattern approach with a generic static class.
Shrunken down Repository
Base class for DocumentDB Entities/Documents.
Test Console Application
I can´t provide you with the classes I used or the documents. But it is a relatively big class with 27 properties and 2 of them being other classes.
Output of that Console Application
.net core
.net 4.7.2
Expected behavior For it to be close/match/exceed to the performance of the old v2 library on .net 4.7.2 or drop support for .net. Because, if the performance is like that it is not feasable to use it. You should make people use the v2 library then. Because otherwise they will have a bad experience. It is quite literally 10 times slower than the old v2 library, but uses the exact same RUs.
Environment summary SDK Version: 3.1.1 OS Version: Windows 10 18362
Additional Information
I also tried to do a SQL query, because I initially thought the LINQ implementation might not be very good (yet). The results are similar.
I also tried it with the StreamingAPI now it takes just about the same amount of time. Even if I skip JSON parsing all together and just read the strings into a List. It still takes roughly 1 second to execute, it might be bit faster (didn´t compare exactly). Point is that is not why it´s that much slower.