Attempting async call blocks application

Hi,

I've looked around this forum for an answer to this but can't quite find what I'm looking for.

Here's a basic test case, stripped down to its essentials:

    private static readonly LightSpeedContext<MyUnitOfWork> s_context = 
        new LightSpeedContext<MyUnitOfWork>( "Sample" );

    public IList<Person> GetAllPeople()
    {
        using( MyUnitOfWork context = s_context.CreateUnitOfWork() )
        {
            return context.Persons.ToList();
        }
    }

And here's the calling code:

    bool isDone = false;
    Thread t = new Thread( ( ) =>
        {
            GetAllPeople();
            isDone = true;
        } );
    t.Start();

    while( !done )
    {
        Console.WriteLine( DateTime.Now.ToLongTimeString() );
    }

What happens here is that the new thread blocks the main thread from executing. The while loop is never entered. As far as I can understand from other posts on the subject, this should work. Am I missing something?

Edit: I should perhaps also note that the call to the database takes a lot of time, around 20 seconds, so it's not just that the call is finished before the while loop has a chance to be entered.

Regards,

Faner

Yes, it should work. I gave it a quick try and it worked for me. In fact at first I saw the opposite symptom: the tight loop in the while loop starved the background database query thread. When I added a Thread.Sleep the worker thread was able to run to completion:

bool isDone = false;
Thread t = new Thread(() =>
  {
    Console.WriteLine("Starting worker thread");
    using (var u = _context.CreateUnitOfWork())
      u.Find<Contribution>();
    isDone = true;
    Console.WriteLine("Exiting worker thread");
  });
t.Start();

while (!isDone)
{
  Console.WriteLine(DateTime.Now.ToLongTimeString());
  Thread.Sleep(20);
}
Console.WriteLine("Exiting");

Output:

09:44:31
Starting worker thread
09:44:31
09:44:31
... snipped ...
09:44:32
09:44:32
Exiting worker thread
Exiting

Try adding some logging and a Thread.Sleep to see if you can figure out what is blocking and where. You might also want to switch over to an AutoResetEvent or other synchronisation object to avoid the busy-wait and see if that helps. Failing that, if you can provide us with a buildable project (console or class library containing NUnit test) that exhibits the error then we can try it here.

Ok thanks,

At least I know I'm not just missing something obvious.

In my real implementation, there is no busy-wait or sleep problem, as the main thread and other worker threads all have other things to do, including appropriate waits. It's just that they all stop doing anything as soon as I reach the database lookup. What's more, Visual Studio also stops responding to input. It takes input (the gui works), but as soon as I ask it to stop debugging for example, it stops responding completely until the database lookup is done. A hung up thread shouldn't cause this.

I'm beginning to think there's something else amiss here, perhaps not related to Lightspeed at all. If I run the test case, wait all that time and then run it again, sometimes (not very often) it all just falls through in a heart beat. I suspect there's something about the initial database lookup/connection that's taking so long. I will also attempt to run it without debugging later on tonight to see what happens.

Don't know if it helps, but my setup is an SQL Server 2008 R2 Express database, on the local machine (8 core, 9 gigs of ram, Windows 7), Visual Studio 2010, .Net 4.0, Lightspeed Nightly from 2012-04-30 and the connection string pointing out the database using the workstation's network name (not localhost or ip address).

If my further investigation is unsuccessful in finding anything, I will put a test case together for you.

Thanks!

Faner

Ok,

I did a bit more of testing. What I found is that it's probably not the lookup itself, as it all works fine if the connection string is incorrect, causing an exception later on.

I've also created a test project which gave me the following output. I included some of the dll loading in case it tells you anything.

2012-04-02 19:41:01
2012-04-02 19:41:01
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Users\Faner\Documents\Visual Studio 2010\Projects\LightSpeedTest\LightSpeedTest\bin\Debug\Mindscape.LightSpeed.Linq.dll'
2012-04-02 19:41:28
2012-04-02 19:41:28
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Runtime.Serialization\v4.0_4.0.0.0__b77a5c561934e089\System.Runtime.Serialization.dll', Skipped loading symbols. Module is optimized and the debugger option 'Just My Code' is enabled.
2012-04-02 19:41:28
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Data.Services\v4.0_4.0.0.0__b77a5c561934e089\System.Data.Services.dll'
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Data.Services.Client\v4.0_4.0.0.0__b77a5c561934e089\System.Data.Services.Client.dll', Skipped loading symbols. Module is optimized and the debugger option 'Just My Code' is enabled.
2012-04-02 19:41:28
2012-04-02 19:41:28
2012-04-02 19:41:28
2012-04-02 19:41:28
2012-04-02 19:41:28
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_32\System.Transactions\v4.0_4.0.0.0__b77a5c561934e089\System.Transactions.dll', Skipped loading symbols. Module is optimized and the debugger option 'Just My Code' is enabled.
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_32\System.EnterpriseServices\v4.0_4.0.0.0__b03f5f7f11d50a3a\System.EnterpriseServices.dll', Skipped loading symbols. Module is optimized and the debugger option 'Just My Code' is enabled.
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_32\System.EnterpriseServices\v4.0_4.0.0.0__b03f5f7f11d50a3a\System.EnterpriseServices.Wrapper.dll', Skipped loading symbols. Module is optimized and the debugger option 'Just My Code' is enabled.
2012-04-02 19:41:28
2012-04-02 19:41:28
The thread '<No Name>' (0x2cac) has exited with code 0 (0x0).
The thread 'vshost.RunParkingWindow' (0x3030) has exited with code 0 (0x0).
The thread '<No Name>' (0x2a70) has exited with code 0 (0x0).

However, I did one thing to the test project that seems to work every time, following your example which is to change the line

var foo = uow.TestObjects.ToList();

into

 var foo = uow.Find<TestObject>().ToList();

There seems to be something going on with the immediate use of LINQ there.

Thoughts? Does the test project work in the same way for you?

Regards

Faner

Your test project runs fine for me. The database thread is entered, LightSpeed kicks off the LINQ query on the database thread, the foreground thread keeps printing, and when the LINQ query returns, the database thread exits and then the foreground thread drops out of the print loop.

3/04/2012 09:31:10
3/04/2012 09:31:10
Entering thread 09:31:10
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Users\Ivan\Desktop\Customer test cases\Faner_LightSpeedTest\LightSpeedTest\bin\Debug\Mindscape.LightSpeed.Linq.dll'
3/04/2012 09:31:10
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Data.Services.Client\v4.0_4.0.0.0__b77a5c561934e089\System.Data.Services.Client.dll'
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Runtime.Serialization\v4.0_4.0.0.0__b77a5c561934e089\System.Runtime.Serialization.dll'
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Data.Services\v4.0_4.0.0.0__b77a5c561934e089\System.Data.Services.dll'
3/04/2012 09:31:10
3/04/2012 09:31:10
... snipped ...
3/04/2012 09:31:16
3/04/2012 09:31:16
Exiting thread 09:31:16
The thread '<No Name>' (0x1b74) has exited with code 0 (0x0).
Finished

You observe that sometimes it falls through very quickly which makes it sound like some sort of database locking issue. But if changing from LINQ to Find reliably yields then that couldn't be down to the database.

You could try adding extra logging to capture timestamps within the thread method -- when does the thread start running? -- and turning on LightSpeed SQL logging, to try to pin down where the hold-up is occurring.

I also note that your DLL loads seem to be happening after the 27-second delay whereas mine are happening at the beginning of the 6-second delay. What happens if you force the LINQ DLL to load before entering the thread, e.g. by performing a dummy operation?

Ok, I did as you asked (please find the example project once again attached), here's the result:

Step into: Stepping over non-user code 'LightSpeedTest.Program..'
19:15:30:691 - waiting...
19:15:30:722 - waiting...
19:15:30:745 - Starting lookup...
'LightSpeedTest.vshost.exe' (Managed (v4.0.30319)): Loaded 'C:\Users\Faner\Documents\Visual Studio 2010\Projects\LightSpeedTest\LightSpeedTest\bin\Debug\Mindscape.LightSpeed.Linq.dll'
The thread '<No Name>' (0x1664) has exited with code 0 (0x0).
19:15:57:284 - waiting...
19:15:57:326 - waiting...
*** snip ***
19:15:57:449 - waiting...
19:15:57:459
SELECT
  [TestObjects].[Id] AS [TestObjects.Id],
  [TestObjects].[Name] AS [TestObjects.Name]
FROM
  [TestObjects]

--> Time:   1 ms
--> Result: System.Data.SqlClient.SqlDataReader


Test1
Test2
Test3
19:15:57:487
SELECT
  [OtherTestObjects].[Id] AS [OtherTestObjects.Id],
  [OtherTestObjects].[Name] AS [OtherTestObjects.Name]
FROM
  [OtherTestObjects]

--> Time:   0 ms
--> Result: System.Data.SqlClient.SqlDataReader


OtherTest3
OtherTest1
19:15:57:490 - waiting...
OtherTest2
19:15:57:532 - Finished lookup.

So, it seems, it happens only when the LINQ dll is loaded. Loading the assembly is what seems to be taking time. You can clearly see that the second lookup was pretty much instant. The same is true if I force the assembly to be loaded earlier, no problem at the lookup then.

Just to be clear, using Find< T > solves my problem, it works just as well. I would just very much like to know what the problem is, and maybe you do too.

Thanks

Faner

...oh and in case I didn't say earlier, running it without debugging is fine too. Sounds more like a Visual Studio problem than a problem with LightSpeed, it's just so wierd that it would have a problem with loading symbols from the LightSpeed LINQ assembly.

Faner

Wow, that's really weird. I can't imagine what would cause just that one DLL to load slowly under the debugger. My first thought was that maybe you had a symbol server configured but that symbol server was slow or didn't exist, but I'd expect that to affect the base LightSpeed DLL too. Also, I assume this doesn't happen if you load the LINQ DLL on the main thread, or you'd have noticed it earlier. Is that right? (If so, it could give you a workaround that doesn't force you to fall back to query objects -- get the DLL to load on the foreground thread so it's all ready by the time the background thread needs it.)

Anyway, glad to hear you have an acceptable workaround and we'll keep our eyes open to understand what might have been going on here. Thanks for all the info!

Actually, which thread first caused the DLL load didn't matter. Only reason I hadn't noticed earlier was simply because I hadn't used LINQ lookups directly before.

I'll get back to you in case I run into any more useful info.

Thank you for you quick responses!

Faner