On Wed, 2009-06-17 at 03:49 +0000, Jonathan Pryor wrote:
> Things I find truly interesting is that the DataContext constructor is
> *slow* (which shouldn't be too surprising, as Adrus Moor already told us
> this), but at 348820 ticks to execute it is the most expensive step,
> taking over 3x longer than actually executing the SQL query.
>
> This is insane.
And this has been improved by making AttributedMetaModel lazily
initialize itself in r1171.
Before r1171, DataContext construction was around 350000 ticks within
the unit tests.
In r1171, DataContext construction is around 400 ticks.
Yes, that's around 875x faster.
It's not without it's tradeoffs, though.
Test_NUnit_MsSql.AnyCount.CountExternal03:
Before:
Step 1: 348820 ticks
Step 2: 21105
Step 3: 133918
Step 4: 1850
Step 5: 114779
Total: 620570
After [0]: [ (new / old)*100 % ]
Step 1: 433 ticks [ 0.12% ]
Step 2: 244219 [ 1157.16% ]
Step 3: 45254 [ 33.79% ]
Step 4: 2062 [ 111.46% ]
Step 5: 90545 [ 78.89% ]
Total: 382781 [ 61.68% ]
So for this test, step 2 (the Expression<T> creation) was
*significantly* slower, taking ~12x longer. Step 3, meanwhile, was ~3x
faster, while steps 4 and 5 were roughly comparable (-ish).
Despite Step 2 taking ~12x longer, the entire test ran faster.
That's a trade-off I'm willing to make. :-)
Next we look at
Test_NUnit_MsSql.ReadTest_Complex.F26_DistinctUnion_Count:
Before:
Step 1: 360714 ticks
Step 2: 104669
Step 3: 2829379
Step 4: 549125
Step 5: 2241118
Total: 6523817
After [1]: [ (new / old)*100 % ]
Step 1: 369 ticks [ 0.10% ]
Step 2: 128496 [ 122.76% ]
Step 3: 252783 [ 8.93% ]
Step 4: 8302 [ 1.51% ]
Step 5: 137859 [ 6.15% ]
Total: 528024 [ 8.09% ]
All I can say is, _wow_.
With a win like that, I'm wondering if I need to make anything else
lazy...
(With wins like that, I wonder if QueryCache is needed as much any
more...)
Analysis? Alas, I can't say _why_ this is happening, but I can
conjecture (badly). Step 2 is uniformly slower because the table
loading that used to be performed in the AttributedMetaModel constructor
is now performed during DataContext.GetTable<T>() (via
AttributedMetaModel.GetTable(Type)), so it's largely a movement of time
accounting away from the constructor into Step 2.
Furthermore, while debugging this I'm seeing that some of the laziness
is defeated, as AttributedMetaAssociation.SetupRelationship() starts
pulling in more and more types. However, at least it's restricted to
just the T in Table<T> that's being accessed, instead of all types all
at once (which should still speed up things for Andrus Moor). If I'm
lucky this can be made even lazier.
- Jon
[0] Test_NUnit_MsSql.AnyCount.CountExternal03
#AT(time=0000000011, elapsed=0000000011) BaseSetUp()
#AT(time=0000106794, elapsed=0000106783) START DataContext(IDatabaseContext,
MappingSource, IVendor)
#AT(time=0000107227, elapsed=0000000433) END DataContext(IDatabaseContext,
MappingSource, IVendor)
#AT(time=0000107439, elapsed=0000000212) DataContext.GetTable(typeof(Customer))
#AT(time=0000351658, elapsed=0000244219) START QueryProvider.Execute<Int32>():
Executing expression...
#AT(time=0000351703, elapsed=0000000045) START: GetSelectQuery(), building
Expression query
Call (MethodCallExpression)
..Object: (null)
..Method: Count
..#00000 Constant (ConstantExpression)
....Value: Table(Customer)
#AT(time=0000396957, elapsed=0000045254) END: GetSelectQuery(), building
Expression query
#AT(time=0000396968, elapsed=0000000011) START: GetSelectQuery(), building Sql
query
#AT(time=0000399030, elapsed=0000002062) END: GetSelectQuery(), building Sql
query
SELECT COUNT(*)
FROM [dbo].[Customers]
-- Context: SqlServer Model: AttributedMetaModel Build: 0.19.0.0
#AT(time=0000489575, elapsed=0000090545) END QueryProvider.Execute<Int32>():
Executing expression...
#AT(time=0000489741, elapsed=0000000166) BaseTearDown()
[1] Test_NUnit_MsSql.ReadTest_Complex.F26_DistinctUnion_Count
#AT(time=0000000012, elapsed=0000000012) BaseSetUp()
#AT(time=0000092065, elapsed=0000092053) START DataContext(IDatabaseContext,
MappingSource, IVendor)
#AT(time=0000092434, elapsed=0000000369) END DataContext(IDatabaseContext,
MappingSource, IVendor)
#AT(time=0000092592, elapsed=0000000158) DataContext.GetTable(typeof(Territory))
#AT(time=0000216684, elapsed=0000124092) START
QueryProvider.CreateQuery<Territory>(Table(Territory).Where(t =>
t.TerritoryDescription.StartsWith("A")))
#AT(time=0000216722, elapsed=0000000038) END
QueryProvider.CreateQuery<Territory>(...)
#AT(time=0000216760, elapsed=0000000038) DataContext.GetTable(typeof(Territory))
#AT(time=0000218352, elapsed=0000001592) START
QueryProvider.CreateQuery<Territory>(Table(Territory).Where(terr =>
terr.TerritoryDescription.Contains("i")))
#AT(time=0000218398, elapsed=0000000046) END
QueryProvider.CreateQuery<Territory>(...)
#AT(time=0000219668, elapsed=0000001270) START
QueryProvider.CreateQuery<Territory>(value(DbLinq.Data.Linq.Implementation.QueryProvider`1[nwind.Territory]).Concat(value(DbLinq.Data.Linq.Implementation.QueryProvider`1[nwind.Territory])))
#AT(time=0000219716, elapsed=0000000048) END
QueryProvider.CreateQuery<Territory>(...)
#AT(time=0000220560, elapsed=0000000844) START
QueryProvider.CreateQuery<Territory>(value(DbLinq.Data.Linq.Implementation.QueryProvider`1[nwind.Territory]).Distinct())
#AT(time=0000220623, elapsed=0000000063) END
QueryProvider.CreateQuery<Territory>(...)
#AT(time=0000221088, elapsed=0000000465) START QueryProvider.Execute<Int32>():
Executing expression...
#AT(time=0000221134, elapsed=0000000046) START: GetSelectQuery(), building
Expression query
Call (MethodCallExpression)
..Object: (null)
..Method: Where
..#00000 Constant (ConstantExpression)
....Value: Table(Territory)
..#00001 Quote (UnaryExpression)
....Method :
....Operand Lambda (Expression`1)
......Call Call (MethodCallExpression)
........Object MemberAccess (MemberExpression)
..........Object Parameter (ParameterExpression)
............Parameter: t
..........Member: TerritoryDescription
........Method: StartsWith
........#00000 Constant (ConstantExpression)
..........Value: A
......#000 Parameter (ParameterExpression)
........Parameter: t
Call (MethodCallExpression)
..Object: (null)
..Method: Concat
..#00000 Constant (ConstantExpression)
....Value: DbLinq.Data.Linq.Implementation.QueryProvider`1[nwind.Territory]
..#00001 Constant (ConstantExpression)
....Value: DbLinq.Data.Linq.Implementation.QueryProvider`1[nwind.Territory]
Call (MethodCallExpression)
..Object: (null)
..Method: Distinct
..#00000 Constant (ConstantExpression)
....Value: DbLinq.Data.Linq.Implementation.QueryProvider`1[nwind.Territory]
Call (MethodCallExpression)
..Object: (null)
..Method: Count
..#00000 Constant (ConstantExpression)
....Value: DbLinq.Data.Linq.Implementation.QueryProvider`1[nwind.Territory]
#AT(time=0000473917, elapsed=0000252783) END: GetSelectQuery(), building
Expression query
#AT(time=0000473928, elapsed=0000000011) START: GetSelectQuery(), building Sql
query
#AT(time=0000482230, elapsed=0000008302) END: GetSelectQuery(), building Sql
query
SELECT COUNT(*)
FROM (SELECT DISTINCT *
FROM (SELECT t$.[TerritoryID], t$.[TerritoryDescription], t$.[RegionID]
FROM [dbo].[Territories] AS t$
WHERE (t$.[TerritoryDescription] LIKE 'A%')
UNION ALL
SELECT terr$.[TerritoryID], terr$.[TerritoryDescription], terr$.[RegionID]
FROM [dbo].[Territories] AS terr$
WHERE (terr$.[TerritoryDescription] LIKE '%i%')) AS source1$) AS source$
-- Context: SqlServer Model: AttributedMetaModel Build: 0.19.0.0
#AT(time=0000620089, elapsed=0000137859) END QueryProvider.Execute<Int32>():
Executing expression...
#AT(time=0000620294, elapsed=0000000205) BaseTearDown()
--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"DbLinq" group.
To post to this group, send email to [email protected]
To unsubscribe from this group, send email to
[email protected]
For more options, visit this group at
http://groups.google.com/group/dblinq?hl=en
-~----------~----~----~----~------~----~------~--~---
