Performance Question

I've set up an AsyncParallelTask that runs 18 different entity queries to get all of the entities necessary for our grid form to be populated and editable. The main entity has a ton of foreign keys, types, statuses, children, etc, so there are a lot of queries to run.   We tried a giant entity query that used .Include() to pull in all the foreign keys but that query took FOREVER to run. So, I split it up and am running each query independently as an AsyncQuery task in an AsyncParallelTask. Most of the queries are short tables of 3-5 rows and a handful of columns, with a couple of them having 200-300 rows and 20 or so columns. None are large tables with thousands of rows. None have BLOB data in them. The database is Oracle, using the DevArt dotConnect drivers. I am using pre-compiled views in the ModelEF project.
The entire set takes just under 1 minute to run.
First, I broke the 18 queries down and ran each one separately. I.e. One query task for each run.
Then I added back each query one at a time to see what effect each additional query has on the total time. Times are in milliseconds. The logging is all client side and is displayed in a client-side log window as described elsewhere in this forum. The timer starts immediately prior to creating the AsyncParallelTask as in this snippet:

private void InitializeCache()
{
    Logging.TimerStart();
    task = AsyncParallelTask.Create();
    ...
    task.AddAsyncQuery(queryName, x => query, querySpecificCallback);
    ...
    task.Execute(InitializationCallback);
}
private void InitializationCallback(AsyncParallelTaskCompletedArgs args)
{
    Logging.TimerStop();
}

Timings:
1            - 9038.7200
2            - 8805.6945
3            - 8977.1328
4            - 9413.8232
5            - 9569.6812
6            - 9008.5924
7            - 9928.1546
8            - 9382.6516
9            - 9304.7823
10           - 9522.9849
11           - 9819.1170
12           - 9024.2361
13           - 9694.4298
14           - 9351.5400
15           - 10099.7280
16           - 9741.2500
17           - 10582.8940
18           - 10333.8556

1            - 9985.7012, 9810.7346
1+2          - 10998.5140
1+2+3        - 13736.2736
1 to 4       - 15233.2812
1-5          - 19135.6341
1-6          - 20859.5651
1-7          - 24581.1580
1-8          - 26080.3900
1-9          - 30593.7030
1-10        - 32208.2180
1-11        - 35689.7266
1-12        - 40383.2564, 36399.0270, 38258.0331,
1-13        - 41418.6368
1-14        - 45418.3866
1-15        - 47433.8568
1-16        - 48622.9544
1-17        - 55391.4640
1-18        - 58385.8935, 56948.4435

So, my question is:
What is each query doing that is taking 10 seconds? What are the queries doing that increment the total time by 3-4 seconds? Is there anything I can do to optimize this code / these queries / the EF loading times / the Entity construction time? Etc. Do you have any tips about enabling/disabling things at run time that can speed it up, for example, disabling the PropertyInterceptors on classes until AFTER the Async load has happened?
Thanks,
Simon

The generated SQL is quite normal looking, given how ugly some EF SQL can be, and the SQL response times running those queries are near instant.
I am going to add a counter to my logging so I can count how many times some things fire. Maybe I have out of control processes happening when the EntityManager assembles the items. I'm also going to look at what is happening if I run those same queries asynchronously and synchronously in the server-side DomainModel (from a unit test project) and what is happening if I run those same queries in the ServerModelEF project too. Thanks for the tips. I'll get back to you.

In test 3, did you also use the AsyncParallelTask?

Edited by kimj - 01-Oct-2009 at 2:15pm

This is interesting. Using the AsyncParallelTask in the DomainModel project (Server side only) sped up the load from 1.04s to 0.84s. Nice. Here's the test:

[TestMethod]
public void InitializationQueriesAsync()
{
    var em = new DomainModelEntityManager();
    em.InitializeEntityManager();
    var timerStart = DateTime.Now;
    var task = AsyncParallelTask.Create();
    task.AddAsyncQuery("BusAssociates", x => em.BusAssociates, null);
    ...
    task.AddAsyncQuery("Zones", x => em.Zones, null);

    //See blog: http://jasondotnet.spaces.live.com/blog/cns!BD40DBF53845E64F!170.entry
    //for how the AutoResetEvent is used
    this._TestTrigger = new AutoResetEvent(false);
    task.Execute(InitCompleted);
    this._TestTrigger.WaitOne();

    var elapsedTime = Math.Round(DateTime.Now.Subtract(timerStart).TotalMilliseconds / 1000, 2);
    double target = 1; //seconds
    Assert.IsTrue(elapsedTime < target, String.Format("Query Initialization took {0}s, it should be less than {1}s", elapsedTime, target));
}

AutoResetEvent _TestTrigger;

public void InitCompleted(AsyncParallelTaskCompletedArgs args) {
    this._TestTrigger.Set();
}

Edited by skingaby - 02-Oct-2009 at 7:02am

I did not realize that. I have changed it to do this:

[TestMethod]
public void InitializationQueries()
{
    ServerModelEF.ModelEntities em = new ModelEntities();
    var timerStart = DateTime.Now;
    var items01 = from item in em.BusAssociates select item;
    ScanAll(items01);
    ...
    var items19 = from item in em.Zones select item;
    ScanAll(items19);
    var elapsedTime = Math.Round(DateTime.Now.Subtract(timerStart).TotalMilliseconds / 1000, 2);
    double target = 1; //seconds
    Assert.IsTrue(elapsedTime < target, String.Format("Query Initialization took {0}s, it should be less than {1}s", elapsedTime, target));
}

private void ScanAll(IQueryable qry)
{
    foreach (var item in qry)
    {
        //do nothing
    }
}

That should retrieve all the items, shouldn't it?
That brought the timing of the ServerModelEF test up from 1s to 2.3s.

Here's the Daisy Chain version of the test running client side in a Silverlight Unit Test. This one calls em.ExecuteQueryAsync on each of the queries and then calls the next query in that ones callback. Total time is 30 seconds.

[TestClass]
public class DealQueriesSerial : SilverlightTest
{
    
    DomainModelEntityManager _em = new DomainModelEntityManager();

    [TestMethod]
    [Asynchronous]
    public void TestAQueryPerf()
    {
        _em.InitializeEntityManagerCompleted += new EventHandler(TestAQueryPerf_em_InitializeEntityManagerCompleted);
        EnqueueCallback(() => _em.InitializeEntityManager());
    }

    private void TestAQueryPerf_em_InitializeEntityManagerCompleted(object sender, EventArgs e)
    {
        EnqueueCallback(() => Logging.TimerStart());
        EnqueueCallback(() => _em.ExecuteQueryAsync(_em.BusAssociates, TestAQueryPerf_QueryCallback01, null));
    }

    private void TestAQueryPerf_QueryCallback01(EntityFetchedEventArgs args)
    {
        EnqueueCallback(() => _em.ExecuteQueryAsync(_em.Contacts, TestAQueryPerf_QueryCallback02, null));
    }

    ...

    private void TestAQueryPerf_QueryCallback18(EntityFetchedEventArgs args)
    {
        EnqueueTestComplete();
        var elapsedTime = Math.Round(Logging.TimerStop() / 1000, 2);
       
        double target = 1; //seconds
        Assert.IsTrue(elapsedTime < target, String.Format("Query Initialization took {0}s, it should be less than {1}s", elapsedTime, target));
    }
}

I also tried a parallel run by just calling ExecuteAsync on all the queries in one method. This killed the performance and takes over 160 seconds to run. Yeuch.

[TestClass]
public class DealQueriesParallel : SilverlightTest
{
    
    DomainModelEntityManager _em = new DomainModelEntityManager();

    [TestMethod]
    [Asynchronous]
    public void TestAQueryPerf()
    {
        _em.InitializeEntityManagerCompleted += new EventHandler(TestAQueryPerf_em_InitializeEntityManagerCompleted);
        EnqueueCallback(() => _em.InitializeEntityManager());
    }

    private void TestAQueryPerf_em_InitializeEntityManagerCompleted(object sender, EventArgs e)
    {
        EnqueueCallback(() => Logging.TimerStart());
        EnqueueCallback(() => _em.ExecuteQueryAsync(_em.BusAssociates, TestAQueryPerf_QueryCallback, null));
        ...
        EnqueueCallback(() => _em.ExecuteQueryAsync(_em.Zones, TestAQueryPerf_QueryCallback, null));
    }

    private int TestAQueryPerf_QueryCallback_Counter = 0;
    private void TestAQueryPerf_QueryCallback(EntityFetchedEventArgs args)
    {
        TestAQueryPerf_QueryCallback_Counter++;
        if (TestAQueryPerf_QueryCallback_Counter == 19)
        {
            EnqueueTestComplete();
            var elapsedTime = Math.Round(Logging.TimerStop() / 1000, 2);

            double target = 1; //seconds
            Assert.IsTrue(elapsedTime < target, String.Format("Query Initialization took {0}s, it should be less than {1}s", elapsedTime, target));
        }
    }
}

Right.
That's what I think too.

As an aside, what am I looking for in Fiddler? I have the Firefox/Fiddler solution working. Thanks for the link. There's a ton of activity when I run the tests and there are some big chunks of message coming back, but all of the items have a TotalElapsedTime that is a fraction of a second.

Thank you for looking in to this. Performance is DEFINITELY our highest priority. The server-side performance is quite acceptable. One of the configurations runs all the queries in a total of less than 4 seconds. I think there's a configuration that actually loads them in less than 1 second, but I'm not sure off the top of my head. Anyway, when that 4 seconds becomes 30 - 160 seconds to load the same data to the client, that's where we have to find a way to improve the performance significantly.
Thanks, Simon.