Marterializing derived models have high .net time with many rows/instances shown by ORMProfiler

Posts   
 
    
Puser
User
Posts: 228
Joined: 20-Sep-2012
# Posted on: 18-Sep-2019 11:09:15   

LLBLGenPro 5.5 (5.5.1) RTM 28-12-2018 AccessDB/SQL DB ORM Profiler 2.0.1

Hi Frans,

I use the functionality of Derived Models a lot. And I have always wondered why the .net time in the ORM Profiler shows so high numbers compared to the db time. I guess it has something todo with the materialization through the 'underlying' Entities. It is especially noticeable with (not saying it's the cause of) high number of rows/instances and/or higher number of fields/properties.

Do you think there might be some quick wins here? I see lots of entity initialization and field initialization code in the Entities where that might/should/would not be happening when using it for loading Derived Models (or could be skipped in that case).

How do you look at this?

I have prepared a screenshot for you where you can see the difference between db time and .net time especially with high number of rows (although there are some entities with higher/lower number of field also that make up for differences)

best regards

Attachments
Filename File size Added on Approval
db and dotnet times for Derived Models from ORM profiler 18-9-2019.png 53,542 18-Sep-2019 11:09.27 Approved
Otis avatar
Otis
LLBLGen Pro Team
Posts: 39570
Joined: 17-Aug-2003
# Posted on: 18-Sep-2019 12:33:30   

The DTO projections don't materialize any entities. The data is projected directly into DTO objects. The whole projection lambda is compiled into a materializer which gets the row passed in and is then executed, which produces an object.

As the lambda's are compiled, the first time will be a little slow. If you e.g. run a projection multiple times, it should be much quicker, as the compiled lambda is cached. The more complex the DTO, the longer it takes to parse the lambda and compile it.

Additionally, each derived element in a DTO projection is also a nested query, which are merged in memory. So if you e.g. have a DTO 'Customer' which has a derived element collection 'Orders' and each Order DTO in that collection has a collection 'OrderDetails' and you fetch a set of these Customer DTOs, you will see 3 queries, which are merged at runtime, same way as prefetch paths. This of course takes time with large sets.

The number in the .NET column therefore doesn't say much where the performance is going. So a .NET profiler is needed to see where a bottleneck is, and more importantly: IF there's a bottleneck. Our materializer pipeline is very fast, but it's a good thing to put it to the test in a benchmark, so we'll see if we can build a DTO tree with nested elements and see how fast these are fetched.

Frans Bouma | Lead developer LLBLGen Pro
Puser
User
Posts: 228
Joined: 20-Sep-2012
# Posted on: 18-Sep-2019 13:21:18   

As I can see the IQueryable<...> is called for the fetch, but this just calls the expression func, not the compiled projector.

Maybe I'm doing something wrong here?

My code:

public async Task<List<CoreProjectReadModel>> GetAllCoreProjectReadModelsAsync()
        {
            using (var adapter = _adapterFactory.CreateDataAccessAdapter())
            {
                return await GetCoreProjectReadModelQuery(adapter).ToListAsync();
            }
        }

        private IQueryable<CoreProjectReadModel> GetCoreProjectReadModelQuery(IDataAccessAdapter adapter)
        {
            return new LinqMetaData(adapter)
                .Project
                .ProjectToCoreProjectReadModel();
        }

generated code:

 public static partial class CoreProjectReadModelLinqProjection
    {
        private static readonly System.Linq.Expressions.Expression<Func<VA.Pac.DomainData.EntityClasses.ProjectEntity, VA.Pac.RootDto.CoreProjectReadModel.CoreProjectReadModel>> CoreProjectReadModelProjectorExpression = CreateCoreProjectReadModelProjectionFunc();

        private static readonly Func<VA.Pac.DomainData.EntityClasses.ProjectEntity, VA.Pac.RootDto.CoreProjectReadModel.CoreProjectReadModel> CompiledCoreProjectReadModelProjector = CreateCoreProjectReadModelProjectionFunc().Compile();

        /// <summary>Empty static ctor for triggering initialization of static members in a thread-safe manner</summary>
        static CoreProjectReadModelLinqProjection() { }

//THIS ONE IS CALLED AND IS NOT COMPILED
        public static IQueryable<VA.Pac.RootDto.CoreProjectReadModel.CoreProjectReadModel> ProjectToCoreProjectReadModel(this IQueryable<VA.Pac.DomainData.EntityClasses.ProjectEntity> baseQuery)
        {
            return baseQuery.Select(CoreProjectReadModelProjectorExpression);
        }

//THIS ONE IS NOT CALLED
        public static VA.Pac.RootDto.CoreProjectReadModel.CoreProjectReadModel ProjectToCoreProjectReadModel(this VA.Pac.DomainData.EntityClasses.ProjectEntity entity)
        {
            return CompiledCoreProjectReadModelProjector(entity);
        }

        private static System.Linq.Expressions.Expression<Func<VA.Pac.DomainData.EntityClasses.ProjectEntity, VA.Pac.RootDto.CoreProjectReadModel.CoreProjectReadModel>> CreateCoreProjectReadModelProjectionFunc()
        {
            return p_0 => new CoreProjectReadModel()
            {
                AdministratieTitel = p_0.AdministratieTitel,

<CUT>
Puser
User
Posts: 228
Joined: 20-Sep-2012
# Posted on: 18-Sep-2019 13:42:08   

I did set breakpoints and counters on the Entity initializations and it looks like that running the projection also runs

private void InitClassEmpty(IValidator validator, IEntityFields2 fields)

for every entity in the projection. But strange thing is, it looks like this InitClassEmpty is called 2x the number of fields in the projection for that entity..., so if I select 17 fields from 'Project' the InitClassEmpty is called 34 times for the ProjectEntity... I'm dazzled...

Otis avatar
Otis
LLBLGen Pro Team
Posts: 39570
Joined: 17-Aug-2003
# Posted on: 18-Sep-2019 13:54:28   

The method that's called in the DTO Persistence isn't pre-compiled, correct. What it does is it creates an expression tree for the elements in the dto and the related elements. This lambda is in the projection of the linq query and will be compiled when the query is ran.

When the data from the datareader is fetched, for each row that compiled lambda is executed. So it's not the same compiled lambda as the one in the persistence class, as that's used for in-memory projections, as these aren't ran through our pipeline, they benefit from a compiled lambda, hence it's precompiled simple_smile

You see some hits on breakpoints in entities. This is normal. During the processing of the expression tree, the engine creates some dummy instances to obtain information, as we don't have a central meta data database in memory. The query itself doesn't materialize any entity instances. If you see 1000s of hits on the breakpoint in an entity class when fetching 1000s of DTOs, then something's off.

In our RawDataAccessBencher benchmark, I've created a DTO for SalesOrderheader and two related elements: SalesOrderDetail and Customer. This is equivalent to the eager loading graph we're using for the prefetch path benchmark. Projection looks like:


private static System.Linq.Expressions.Expression<Func<AdventureWorks.Dal.Adapter.EntityClasses.SalesOrderHeaderEntity, LLBLGenPro.Dtos.DtoClasses.SalesOrderHeaderDto>> CreateProjectionFunc()
{
    return p__0 => new LLBLGenPro.Dtos.DtoClasses.SalesOrderHeaderDto()
    {
        AccountNumber = p__0.AccountNumber,
        BillToAddressId = p__0.BillToAddressId,
        Comment = p__0.Comment,
        CreditCardApprovalCode = p__0.CreditCardApprovalCode,
        CreditCardId = p__0.CreditCardId,
        CurrencyRateId = p__0.CurrencyRateId,
        Customer = new LLBLGenPro.Dtos.DtoClasses.SalesOrderHeaderDtoTypes.CustomerDto()
        {
            AccountNumber = p__0.Customer.AccountNumber,
            CustomerId = p__0.Customer.CustomerId,
            ModifiedDate = p__0.Customer.ModifiedDate,
            PersonId = p__0.Customer.PersonId,
            Rowguid = p__0.Customer.Rowguid,
            StoreId = p__0.Customer.StoreId,
            TerritoryId = p__0.Customer.TerritoryId,
        },
        CustomerId = p__0.CustomerId,
        DueDate = p__0.DueDate,
        Freight = p__0.Freight,
        ModifiedDate = p__0.ModifiedDate,
        OnlineOrderFlag = p__0.OnlineOrderFlag,
        OrderDate = p__0.OrderDate,
        PurchaseOrderNumber = p__0.PurchaseOrderNumber,
        RevisionNumber = p__0.RevisionNumber,
        Rowguid = p__0.Rowguid,
        SalesOrderDetails = p__0.SalesOrderDetails.Select(p__1 => new LLBLGenPro.Dtos.DtoClasses.SalesOrderHeaderDtoTypes.SalesOrderDetailDto()
        {
            CarrierTrackingNumber = p__1.CarrierTrackingNumber,
            LineTotal = p__1.LineTotal,
            ModifiedDate = p__1.ModifiedDate,
            OrderQty = p__1.OrderQty,
            ProductId = p__1.ProductId,
            Rowguid = p__1.Rowguid,
            SalesOrderDetailId = p__1.SalesOrderDetailId,
            SalesOrderId = p__1.SalesOrderId,
            SpecialOfferId = p__1.SpecialOfferId,
            UnitPrice = p__1.UnitPrice,
            UnitPriceDiscount = p__1.UnitPriceDiscount,
        }).ToList(),
        SalesOrderId = p__0.SalesOrderId,
        SalesOrderNumber = p__0.SalesOrderNumber,
        SalesPersonId = p__0.SalesPersonId,
        ShipDate = p__0.ShipDate,
        ShipMethodId = p__0.ShipMethodId,
        ShipToAddressId = p__0.ShipToAddressId,
        Status = p__0.Status,
        SubTotal = p__0.SubTotal,
        TaxAmt = p__0.TaxAmt,
        TerritoryId = p__0.TerritoryId,
        TotalDue = p__0.TotalDue,
// __LLBLGENPRO_USER_CODE_REGION_START ProjectionRegion_SalesOrderHeader 
// __LLBLGENPRO_USER_CODE_REGION_END 
    };
}

So it contains a nested set and a nested individual element. This is fetched using:

using(var adapter = new DataAccessAdapter())
{
    var metaData = new LinqMetaData(adapter);
    var q = from soh in metaData.SalesOrderHeader
            where soh.SalesOrderId > 50000 && soh.SalesOrderId <= 51000
            select soh;
    return q.ProjectToSalesOrderHeaderDto().ToList();
}

It's very fast. Entity fetches:


Change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (10 runs), no caching
------------------------------------------------------------------------------
LLBLGen Pro v5.6.0.0 (v5.6.0)                : 45,95ms (1,21ms)
Linq to Sql v4.0.0.0 (v4.8.3761.0)          : 47,32ms (1,72ms)
Entity Framework Core v2.2.6.0 (v2.2.6.19169) : 79,03ms (1,18ms)

Memory usage, per iteration
------------------------------------------------------------------------------
Linq to Sql v4.0.0.0 (v4.8.3761.0)          : 7.272 KB (7.446.720 bytes)
Entity Framework Core v2.2.6.0 (v2.2.6.19169) : 17.168 KB (17.580.696 bytes)
LLBLGen Pro v5.6.0.0 (v5.6.0)                : 19.415 KB (19.881.776 bytes)

DTO Projection, same data:

Non-change tracking fetches, eager load fetches, 3-node split graph, 1000 root elements (10 runs), no caching
------------------------------------------------------------------------------
LLBLGen Pro v5.6.0.0 (v5.6.0), Poco DTO graph : 23,50ms (0,70ms)

Memory usage, per iteration
------------------------------------------------------------------------------
LLBLGen Pro v5.6.0.0 (v5.6.0), Poco DTO graph : 8.793 KB (9.004.368 bytes)

The speed and memory usage also illustrate that it doesn't materialize to entities first before it projects to DTOs (that also would be very inefficient wink )

It fetches in total 6768 rows.


Starting bench runs...

Eager Load fetches
-------------------------
[13:41:38] # of elements fetched: 6768 (4768 + 1000 + 1000).    Fetch took: 23,58ms.
[13:41:38] # of elements fetched: 6768 (4768 + 1000 + 1000).    Fetch took: 22,84ms.
[13:41:38] # of elements fetched: 6768 (4768 + 1000 + 1000).    Fetch took: 23,40ms.
[13:41:38] # of elements fetched: 6768 (4768 + 1000 + 1000).    Fetch took: 23,40ms.
[13:41:38] # of elements fetched: 6768 (4768 + 1000 + 1000).    Fetch took: 23,61ms.
[13:41:38] # of elements fetched: 6768 (4768 + 1000 + 1000).    Fetch took: 23,11ms.
[13:41:39] # of elements fetched: 6768 (4768 + 1000 + 1000).    Fetch took: 22,98ms.
[13:41:39] # of elements fetched: 6768 (4768 + 1000 + 1000).    Fetch took: 23,14ms.
[13:41:39] # of elements fetched: 6768 (4768 + 1000 + 1000).    Fetch took: 25,47ms.
[13:41:39] # of elements fetched: 6768 (4768 + 1000 + 1000).    Fetch took: 23,43ms.

So the pipeline itself isn't slowing things down. I think this is on ms access? the .net time in the profiler is all the time spent on .NET side, from the start of ExecuteReader to closing the reader. So if there's time lost when moving to the next row in a resultset, that time is also added to the .NET time. The DB time is the time spent in the ExecuteReader call, which is the time it takes to execute the query and formulate the resultset in the DB. All time consuming it is then added to the .NET time. This is both the materialization time of an element from a row, but also the handling of the resultset.

So a .net profiler will reveal where the most time is wasted, you're otherwise guessing simple_smile One thing we can rule out: the dto projection itself isn't slowing it down in any way.

Frans Bouma | Lead developer LLBLGen Pro
Puser
User
Posts: 228
Joined: 20-Sep-2012
# Posted on: 20-Sep-2019 17:33:05   

Thanks for your comprehensive answer.

I can confirm that only some initialization code creates (empty) entities. Consider that are initialization routines that fill defaults and maybe use (external) services from injection (I dont use that though), these could potentially become a bottleneck for those routines will effectivally be called but the outcome never be used (for the dummies). I can imagine you use the code for entities directly from the generated templates. These dont have any extra user-code. But also imagine in practice users do have this. Then every query will run this initialization code. I guess 2 x the number of references fields will new up these dummy instances. For small resultsets this can be a large percentage. I don't know which metadata the lambda projection will use for it's execution but all user code is pointless and maybe even some of your generated code will never be used in that case. Maybe you can win some speed if in the init it 'knows' that it's called from the lambda and can skip pointless code? But I must admit the most time is spend in the DB, beit Access or SQL, so it's just super optimizing here. But I know you've been working hard on this optimizing (cpu and memory) the past year, so as we say in Holland: do your profit of it wink

best regards!

Otis avatar
Otis
LLBLGen Pro Team
Posts: 39570
Joined: 17-Aug-2003
# Posted on: 23-Sep-2019 11:51:13   

Puser wrote:

Thanks for your comprehensive answer.

I can confirm that only some initialization code creates (empty) entities. Consider that are initialization routines that fill defaults and maybe use (external) services from injection (I dont use that though), these could potentially become a bottleneck for those routines will effectivally be called but the outcome never be used (for the dummies). I can imagine you use the code for entities directly from the generated templates. These dont have any extra user-code. But also imagine in practice users do have this. Then every query will run this initialization code. I guess 2 x the number of references fields will new up these dummy instances. For small resultsets this can be a large percentage.

Where we can avoid creating a dummy we do, it's in the question of Linq a bit problematic as all we have is types, so to get anything we need to instantiate a dummy. In theory this is indeed very fast (they never showed up on profiles that they need optimizing), but you have a good point that the instantiation can take longer in some cases. We could add an optimized codepath to avoid all that as we don't need it for this particular situation.

I don't know which metadata the lambda projection will use for it's execution but all user code is pointless and maybe even some of your generated code will never be used in that case. Maybe you can win some speed if in the init it 'knows' that it's called from the lambda and can skip pointless code? But I must admit the most time is spend in the DB, beit Access or SQL, so it's just super optimizing here. But I know you've been working hard on this optimizing (cpu and memory) the past year, so as we say in Holland: do your profit of it wink best regards!

simple_smile A .net profile will show you the bottlenecks. The code to generate queries is indeed highly optimized, we haven't found ways to make that faster except to avoid creating queries altogether (cache them), which requires additional logic to decide whether to pull one from the cache or not which tends to be on par with simply generate the query.

however if the entity uses e.g. DI, initializes fields with values and the like, all to get the field objects, it's not efficient. We'll look into making that more efficient in the future, thanks for the idea! simple_smile

Frans Bouma | Lead developer LLBLGen Pro