.NET Native - Perf: LINQ queries run slower on Release mode

[abdu292]

Friends, I was doing some performance testing before I publish the app on to the store. However here is one critical issue I am seeing.

The below code takes around 8 second to run in Release mode, but runs within just 2 seconds in debug mode. (where the related tables are very small tables and the number of records in the main table is 150)

If the code runs within 2 seconds in debug mode (with debug overhead), I would expect to run this within milliseconds in release mode. If I double the records (150=>300), the amount of time it takes also doubles (as one would expect). I know from the docs using Anonymous LINQ query can result in poor performance in RC1, and I believe it is fixed in RC2. Even it did not, wondering if the "Include" comes under this category, and this is the reason for the performance issue. If so, do we know how we can refactor the "include" that gives me better performance (may be more than debug)?

public async Task<IList<Student>> GetStudentsAsync() { var students = await _context.Students .Include(b => b.Addresses) .Include(b => b.Emails) .Include(b => b.Titles) .Include(b => b.Phones) .Include(b => b.Websites) .ToListAsync();

return students; }

I am using Visual Studio 2015, UWP 5.1.0, Native Tools 1.3.1, Entityframework Core RC2 and SQLite.

[ErikEJ]

This will load all data from all tables?

[abdu292]

@ErikEJ Yes, it does and that is part of the requirement. Those tables are very tiny.

[divega]

Since you say the query executes much faster in Debug than Release mode and yours is a UWP application, I believe this might be due to a performance limitation in the way .NET Native applications execute in-memory compiled LINQ expressions (which is a mechanism EF Core uses a lot):

Expressions don't actually get compiled into IL and then translated to native code by a JIT compiler as would normally happen in a non-native .NET application (because there isn't a JIT compiler when executing a .NET Native app) so they are interpreted instead.

Depending on what the slowest part is, a possible workaround would to execute multiple individual queries, e.g.:

public IList<Student> GetStudents()
{
    _context.Addresses.Load();
    _context.Emails.Load();
    _context.Titles.Load();
    _context.Phones.Load();
    _context.Websites.Load();
    return _context.Students.ToList();
}

Note that:

1. I am assuming that this query is supposed to load every row from these tables into memory. Assuming the query results are tracked by the context (they are by default) the relationships will get fixed up in-memory and Student instances will get their navigation properties populated.
2. There is actually no advantage in using async the way you were using it your code with the SQLite provider. SQLite does not do async I/O, and we don't try to do any kind of compensation for that in either our ADO.NET provider or EF provider. If you want the whole loading of this data to happen in a different thread from the UI thread for responsiveness you may try explicitly doing it with something like var students = await Task.Run(x => x.GetStudents());

[abdu292]

Thank you @divega for your response. I tried refactoring my code to load the tables individually with Load() method, and it appears that the number of seconds it takes has no much difference. If it was 8 seconds, now it is around 7 seconds. I consistently checked many times and I can see there is a one second different in the new version of code. However, from a user's stand point it is still too much.

I am using repository pattern in data layer and a service layer (initially I was using file system, and converted to SQLite, it was easy for me to do the conversion because of the Repository pattern), and yes with two different Universal Class Libraries for each layer. Do we know if these two layers of abstractions can cause this performance issue? (I tried removing the layers in debug mode and deploy on to my device and found there is no difference at all, though I did not try in release. Testing release in UWP is very time consuming as we know).

Also, thank you again for giving the information on Async with SQLite. I never knew this. also, do you mean students = await Task.Run(GetStudents()) or Am I missing any other syntax that the Task gets contextual information and you call the method with the lamda variable like x.GetStudents()

[divega]

How many rows do these queries return from the database? Could you share the model or otherwise provide some information about the number of columns on each table and types used? Hopefully we will be able to find something in either EF Core or in .NET Native to make things faster.

Re Task.Run(), I was referring to the overload that takes a sync delegate. But I didn't actually try to compile what I wrote and most likely it was wrong: if it just takes a Func<T> the it should be var students = await Task.Run(() => GetStudents()).

[abdu292]

I have 150 records now in the main table and each related table will have 4-6 associated rows for each of those main rows. Here is the outline of my model,

Student => 1 integer property, 5 (below) navigational properties of IList<T>, 2 string properties, 5 get only string properties which are [NotMapped], 1 DateTime property 5 Other entities (Address, Email, Website, Titile, Phone) => 2 integer properties, 1 Navigational property to Student, 1 Enum property, 1 string property (get only, that converts string to enum)

I am not sure, if it important to say here, as indicated above, all the 5 related class has a get only string property that converts the string to enum with the help of an extension method like so public static T ConvertToEnum<T>(this string enumString) => (T)Enum.Parse(typeof(T), enumString);

Yes, Task.Run accepts Func as well as Action. So we are good there. Thank you for the note!

[abdu292]

Hello Again, FYI. I just tried removing the Enum conversion from all the five related tables and created another release package. However the performance is still the same and no noticeable impact.

[abdu292]

Here is the repro of the issue I created, if that helps to resolve the issue quickly. Thanks!

Note (Preferably, please use phone device that's where performance matters): Try running the below in both Debug and Release modes.

1. Run the app => tap "Tap to insert" button for the first time. Please wait until the "All Done!" status (I gave 250 samples to insert as default, given all are tiny models, you may change the number using the editable box in the left)
2. Now tap "Tap to Load" button, and see the seconds it takes (milliseconds and seconds are displayed on the screen)
3. Close the app using the Bottom App bar button and repeat ONLY Step 2 again (Step one is required only once, if repeated it would double the Students count). See the seconds it takes.

EDIT : Ignore the previous attachement. Here is the updated one. SQLitePerf.zip

@divega or others. Please let me know if you need more info. Thank you again.

[abdu292]

@divega Wondering if you got a chance to look at my comments. Thanks!

[divega]

@abdu292 I saw your comments. It will take at least a few days to evaluate if there is any short term solution to this.

[abdu292]

Great! Thank you @divega

[mvermef]

I am in a similar situation with building related to .Net Tool Chain compilation. 0.2ms versus 18.8 seconds, is the amount of time we are talking when an Include is involved... 245 rows in primary table (Hotels) and the foreign key table has about 856 rows. var hotels = Hotels.Include(h -> h.Comments);

no .Net Tool chain involved = .2ms .Net Tool chain => 18.8 seconds.

[rowanmiller]

@natemcmaster can you get this into a format where we can hand it off to .NET Native team (talk to me or @divega)

[natemcmaster]

This slow performance is likely due to the .NET Native compiler. In UWP 1.3, the compiler added a feature called universal shared genetics. Before this, most EF queries with "include" didn't work at all. USG allows these types of queries to work, but its slow performance is a known issue. The compiler team has been working on this for a while. Obviously, it's something we hope to improve in future releases of UWP tooling.

[divega]

@natemcmaster We were suspicious that this one would actually be due to a different aspect of .NET Native: LINQ expression trees cannot be compiled into IL to be executed in memory but instead are interpreted.

In any case, we still need to put a repro together and hand it off to the .NET Native team for them to evaluate if they can improve the performance.

[abdu292]

@natemcmaster @divega Thanks for the update. However the performance is still the same if we use "Load" too. So do we know if both Include & Load are the same as to how these work under the hood?

[divega]

@abdu292 yes, ultimately most of the code is the same.

[abdu292]

@divega Okay. Thank you!

I already provided a repro in one of my previous posts. Can we leverage the same to give to the .NET Native team? I thought you all got a chance to run my repro solution.

[mvermef]

This going to be a sit and wait or is there a work around to this performance degradation, based on your comment of IL interpretation over compilation (missing jit in native) was there only solution to rush something out the door for native compilation time frame they were under? I have an idea but it's a cumbersome workaround at best, just going to be quadruple the amount of code to get the same effect. I would like to stay with EF as the orm in place since it's what I use most of the time.

[abdu292]

@natemcmaster @divega @rowanmiller With the EntityFrameworkCore RTM release date on 27th of June (in a few weeks), Would this be feasible to target resolving this issue by RTM?

[divega]

@abdu292 @mvermef the .NET Native team is aware of this issue and the repro. We haven't heard back yet from them on any recommendations to change EF Core code or possible improvements in their bits. Note that we have assigned the issue to the 1.0.1 milestone, meaning that we don't necessarily expect a fix in the RTM time frame. That said if there is anything low hanging we can tackle in the next few days, we'll try to do it.

[abdu292]

@natemcmaster @divega @rowanmiller Thank you for the update. So, Is there any APi for us to use to write raw T-SQL queries within our EntityFrameworkCore context? If no, any other work-around that you can think of (Just until this issue is resolved)? And that would enable to us to go ahead and publish our apps. Thanks!

[divega]

You can try FromSql() to run raw SQL queries, but I doubt it will give you better performance as it shares most of the same mechanics with LINQ queries for object materialization.

If I was trying to workaround this issue I would approach it by:

1. First, identifying the set of queries in the application that don't perform acceptably with the amount of data expected to be used in production (given what we know about this issue, I would expect those to be queries that retrieve relatively large numbers of rows).
2. Then, applying one of the following strategies (depending which one works best on each query):
   1. Reduce the number of rows retrieved: this may involve rethinking how the user interacts with the application, e.g. require the user to type a filter criteria instead of displaying the full table in a list.
   2. Retrieve the data in the background while the user can perform other actions.
   3. Use handcrafted materialization code against plain ADO.NET classes or some micro-ORM (not sure which ones currently offer UWP support) and potentially attach them to the application's DbContext.

By the way, another thing I would test is tracking vs. no tracking queries.

[natemcmaster]

Is there any APi for us to use to write raw T-SQL queries within our EntityFrameworkCore context?

@abdu292 if .FromSql doesn't work, EF provides API to expose the lower-level ADO.NET components. As @divega suggests, you can write your SQL queries directly as an ADO.NET DbCommand and execute it on the same connection DbContext is using.

var connection = _context.Database.GetDbConnection();
using (var command = connection.CreateCommand())
{
    command.CommandText = @"SELECT * FROM FooBar"; // raw SQL here
    // etc. Google/bing "ado.net command" to see numerous examples of how to use DbCommand
}

[divega]

Thanks @natemcmaster for adding those details. You will most likely have to open and close the connection since EF typically keeps it closed until needed.

[abdu292]

@natemcmaster @divega Thank you for the information on how FromSql works and also on the ado.net. However, I spent a huge amount of time (research in release mode is time consuming and painful) to research on this and it doesn't look like data retrieval taking any time whether it is with "Include" of EF or ADO.NET APIs like ExecuteReader, etc.

The actual time consuming part is when the retrieved data maps back to the class objects. Especially it takes double the time of EF when we map the data to class models after reading the db using ADO.NET ExecuteReader. EF does a great job there.

I am wondering why this issue is closed. Is this because it should be investigated by the .NET Native team? Any response on my above comment would be much appreciated!

[divega]

Oops, I must have clicked on the close button instead of comment! 😓 Thanks for pointing it out!

The actual time consuming part is when the retrieved data maps back to the class objects

That was my expectation. The code that does that part of the work is a compiled expression.

[abdu292]

Sure. Thank you!

That was my expectation. The code that does that part of the work is a compiled expression.

Interesting. I thought it happens when retrieving the data (as we experience in the data centric apps). And this was the very reason I asked for the api to write T-SQL (raw) queries. Nonetheless, that was a great info on how we can get connection/use command etc within ef context. I got a great hands-on while researching.

I continue asking and the next would be, is there any way I can exclude only just one method/at last a class from Native compilation (may be via Runtime Directives) and can regain the performance. I am not very much familiar with rd, but read somewhere it helps to exclude reflection based code/something similar. Thank you again!

[abdu292]

@mvermef

I have an idea but it's a cumbersome workaround at best, just going to be quadruple the amount of code to get the same effect.

Were you able to workaround on this issue? Would you mind sharing that cumbersome idea? (I tried many of them as mentioned in my previous posts, but no joy so far)

Thanks!

[mvermef]

negative workaround :(

[abdu292]

Any one feels any performance difference on this issue, with the new .NET Native Tool 1.4?

[rowanmiller]

@natemcmaster can you hand off an issue to the .NET Native folks so that they can address this

[natemcmaster]

@rowanmiller It's already been handed off (via internal msft email thread with @mattwhilden.) 😄

@abdu292 I'm not aware of any major updates to expression interpretation in .NET Native 1.4.

[MattWhilden]

Oh goodness. I agreed to take a look at this and then got pulled away on a family emergency... Consider this my public shaming and I'll push this to the front of my work queue.

That said, System.Linq.Expression are all interpreted on .NET Native and their runtime performance is general: faster if you're only calling them once or twice, slower if you're doing things in a hot loop. It's possible that there's some bottleneck somewhere we can get patched up but it'll probably need to be worked around for the time being.

[mvermef]

for what ever it is worth, Include( p => p.SomeNavigationCollection) does actually compile nicely under Release. Right now I am seeing .72ms with a GroupBy

@natemcmaster I did get it to pull that UWP 5.2 version in finally on my main desktop not sure on my Surface yet, I have a bad feeling that my install of VS 2015 might need to be uninstalled or repaired on my Surface Pro3 :( even after the Update 3 reattempt.

[MattWhilden]

If you're working with 5.2, beware the dragons: https://social.msdn.microsoft.com/Forums/en-US/e766a904-7346-4f76-bad2-852d3b301b0e/known-issue-version-52-of-microsoftnetcoreuniversalwindowsplatform-delisted-all?forum=Win10SDKToolsIssues We're working on getting a fixed 5.2.1 out but it's not ready just yet.

[mvermef]

Knew it was delisted but didn't realize it was that bad, knew about the clrcompression issue listed in the corefx repository. Really noticed after day 2 of release ;P

[MattWhilden]

Yep. There are workarounds you can hack into your project.json but wanted to make sure you didn't get caught by more issues.

[natemcmaster]

@MattWhilden what are the workarounds? We should to add them to the EF getting started guides.

[MattWhilden]

https://github.com/dotnet/corefx/issues/9711 and https://github.com/dotnet/corefx/issues/9743 have workarounds. Hopefully we'll get the new package out soon.

[abdu292]

@mvermef

for what ever it is worth, Include( p => p.SomeNavigationCollection) does actually compile nicely under Release. Right now I am seeing .72ms with a GroupBy

Do you mean ".Include" is performant even in release mode? Is that with UWP 5.2.0? I ask this because my "include" queries are slow (5 includes in a query and I am calling it in one shot)

[mvermef]

18 seconds was what I was getting before in release build, now its like it was in debug without native tool chain.

[abdu292]

Wow! I did not realize UWP 5.2.0 is more performant. However the existing known issues are preventing me to upgrade to it. Though there are workarounds the team doesn't encourage to upgrade at this point. Let me see if I can give it a try.

[abdu292]

I tried a release build on UWP 5.2.0 on the repro project (the project which I attached above in one of my previous posts) and here is how it looks like (no much difference, 8 seconds still too much from a user's stand point to load 150 rows)

Linq with "Include"

5.1.0 => 14544ms (14s) 5.2.0 => 8833ms (8s)

[DrewScoggins]

I am going to collect some traces and take a look at this. See if we can track down what exactly we are spending our time on.

[MattWhilden]

For those keeping score at home, Drew is a perf Dev on the .NET team so this issue has found its way out of my fumbling hands and into those of an actual expert.

[mvermef]

😆

[abdu292]

@DrewScoggins Wondering if any joy so far with this. Thanks a ton for your work on this!

[DrewScoggins]

I was able to sit down and take a look at this today, so I wanted to update this issue. I was looking at this on my dev box and not a phone, and I was only seeing a regression of about 4x between Core and .NET Native (90ms to 360ms). Since this seems quite a bit different than what you were seeing on the phone I am going to get a phone setup and take more traces there and take a look at them tomorrow.

[abdu292]

@DrewScoggins Did you get a chance to test this on a phone yet? Any hope to get this fixed any time sooner? Thanks for your effort on this!