where are my threads blocking problems?

M

Mr. Mountain

In the following code I simulate work being done on different threads by
sleeping a couple methods for about 40 ms. However, some of these methods
that should finish in about 40 -80 ms take as long as 2300 ms to complete.
This is fairly rare, but the test code below will definitely show it.

Somehow, I must not have my design right.

The idea of this code is that I do two different types of processing (
1-starting and 2-ending) based on unique ID numbers. For example, for ID #1,
I can do the start process or the end process, and I can do them in any
order (start doesn't have to be called before end in a particular slice of
time). The restriction is that I can't begin one of these processes while
the other one is in progress. In that case I have to wait. But only the
thead handling ID #1 processing (and only for the one blocked method) should
wait. Any other processing for other ID numbers should be able to proceed
without regard for the fact that ID #1 has to wait for one of its processes
to complete.

The two processes are called by different threads and I don't create those
threads (ASP.NET does).

(In case anyone wants to know what the practical use of this code is, it is
used in an ASP.NET app to initialize a session and then clean up/terminate a
session. ASP.NET reuses session numbers, so I have been forced to be sure
that I am do not begin initializing a session if that same session number is
in the process of being ended. The inverse situation also applies. However,
please direct any comments on ASP.NET sessions or session ID reuse to
another newsgroup topic. Thanks.)

I appreciate anyone pointing out design or implementation problems with this
code in regard to threading.

You can build this code as a C# console app and run it. It has a hard-coded
parameter in Main() determining how long it will run (loop over the tests).

(I apologize for the messy Main method that is used to start the testing.)

using System;
using System.Threading;
using System.Collections;

namespace testing
{
/// <summary>
/// solution for cleaning up sessions where sessionID can be reused.
/// </summary>
public class SessionStarter
{
private const int waitTime = 4000;//used in TryEnter
private static bool keepTesting = true;
private static TimeSpan maxTime = TimeSpan.MinValue;
private static string maxMethodName = "none";

private class ActiveSession
{
public string SessionID;

public ActiveSession(string sessionID)
{
this.SessionID = sessionID;
}//ctor
}//struct ActiveSession

private static Hashtable sessionsBeingProcessed = new Hashtable();

private static void CheckForConflictingSession(string sessionID, out
ActiveSession mySession)
{
DateTime start = DateTime.Now;
if (Monitor.TryEnter(sessionsBeingProcessed, waitTime))
{
try
{
if (sessionsBeingProcessed.Contains(sessionID))
{
mySession = sessionsBeingProcessed[sessionID] as ActiveSession;
Console.WriteLine(">>>>>>>>> " + Thread.CurrentThread.Name + ": " +
sessionID + " is already being processed! <<<<<<<<<");
}
else
{
mySession = new ActiveSession(sessionID);
sessionsBeingProcessed.Add(sessionID, mySession);
Console.WriteLine(Thread.CurrentThread.Name + ": " + sessionID + "
added to sessionsBeingProcessed");
}
}
finally
{
Monitor.Exit(sessionsBeingProcessed);
}
}
else
{
keepTesting = false;
Exception e = new Exception(Thread.CurrentThread.Name + ": " +
"Exception: could not get lock on sessionsBeingProcessed for " + sessionID);
//log it
throw e;
}
TimeSpan ts = DateTime.Now - start;
if (ts > maxTime){ maxTime = ts; maxMethodName =
"CheckForConflictingSession";}
Console.WriteLine(Thread.CurrentThread.Name + ":
CheckForConflictingSession time: " + ts.TotalMilliseconds);

}//CheckForConflictingSession

public static void StartSession(string sessionID, int workAmount)
{
DateTime start = DateTime.Now;
Console.WriteLine(Thread.CurrentThread.Name + ": " + "entering
StartSession method: " + sessionID);
ActiveSession mySession;
CheckForConflictingSession(sessionID, out mySession);
HelpStartSession(sessionID, mySession, workAmount);
TimeSpan ts = DateTime.Now - start;
if (ts > maxTime){ maxTime = ts; maxMethodName = "StartSession";}
Console.WriteLine(Thread.CurrentThread.Name + ": StartSession time: " +
ts.TotalMilliseconds);
}//StartSession

private static void HelpStartSession(string sessionID, ActiveSession
mySession, int workAmount)
{
bool entered2 = Monitor.TryEnter(mySession, waitTime);
if (entered2)
{
Console.WriteLine(Thread.CurrentThread.Name + ": " + sessionID + " is OK
to be initialized.");

try
{
//do all work
Console.WriteLine(Thread.CurrentThread.Name + ": " + "Starting session
" + sessionID + " initialization...");
Thread.Sleep(workAmount);
Console.WriteLine(Thread.CurrentThread.Name + ": " + "Finished session
" + sessionID + " initialization...");
}
catch (Exception )
{
keepTesting = false;
Exception me = new Exception("Exception: Unable to complete session " +
sessionID + " initialization.");
//log it
throw me;
}
finally
{
//Monitor.Pulse(mySession);
sessionsBeingProcessed.Remove(sessionID);
Monitor.Exit(mySession);
Console.WriteLine(Thread.CurrentThread.Name + ": " + sessionID + " is
unlocked by StartSession");
}
}
else
{
keepTesting = false;
Exception me2 = new Exception("Timed out. Could not get Monitor to start
sessionID " + sessionID);
//log it
throw me2;
}

}//HelpStartSession

public static void EndSession(string sessionID, int workAmount)
{
DateTime start = DateTime.Now;
Console.WriteLine(Thread.CurrentThread.Name + ": " + "entering EndSession
method: " + sessionID);
ActiveSession mySession;
CheckForConflictingSession(sessionID, out mySession);
HelpEndSession(sessionID, mySession, workAmount);
TimeSpan ts = DateTime.Now - start;
if (ts > maxTime){ maxTime = ts; maxMethodName = "EndSession";}
Console.WriteLine(Thread.CurrentThread.Name + ": EndSession time: " +
ts.TotalMilliseconds);
}//EndSession

private static void HelpEndSession(string sessionID, ActiveSession
mySession, int workAmount)
{
bool entered2 = Monitor.TryEnter(mySession, waitTime);
if (entered2)
{

Console.WriteLine(Thread.CurrentThread.Name + ": " + sessionID + " is OK
to be terminated.");

try
{
//do all work
Console.WriteLine(Thread.CurrentThread.Name + ": " + "Beginning session
" + sessionID + " termination...");
Thread.Sleep(workAmount);
Console.WriteLine(Thread.CurrentThread.Name + ": " + "Completed session
" + sessionID + " termination.");
}
catch (Exception e)
{
keepTesting = false;
//log it, etc.
throw e;
}
finally
{
//Monitor.Pulse(mySession);
sessionsBeingProcessed.Remove(sessionID);
Monitor.Exit(mySession);
Console.WriteLine(Thread.CurrentThread.Name + ": " + sessionID + " is
unlocked by EndSession");
}
}
else
{
keepTesting = false;
//log and throw exception
Exception ex = new Exception(Thread.CurrentThread.Name + ": " + "Timed
Out. Could not get Monitor to end sessionID " + sessionID);
//log
throw ex;
}
}//HelpEndSession


public static void Main(string[] args)
{
SessionStarter ss = new SessionStarter();

DateTime timeLimit = DateTime.Now.AddMinutes(120.5015);

Thread startSessionThread;
Thread endSessionThread;
Thread startSessionThread2;
Thread endSessionThread2;
Thread startSessionThread3;
Thread endSessionThread3;
Thread startSessionThread4;
Thread endSessionThread4;
Thread startSessionThread5;
Thread endSessionThread5;

Random r = new Random();

while (keepTesting && DateTime.Now < timeLimit)
{
startSessionThread = new Thread(
new ThreadStart(ss.Start));
startSessionThread.Name = "startThread1";

endSessionThread = new Thread(
new ThreadStart(ss.End));
endSessionThread.Name = "endThread1";

startSessionThread2 = new Thread(
new ThreadStart(ss.Start2));
startSessionThread2.Name = "startThread2";

endSessionThread2 = new Thread(
new ThreadStart(ss.End2));
endSessionThread2.Name = "endThread2";

startSessionThread3 = new Thread(
new ThreadStart(ss.Start3));
startSessionThread3.Name = "startThread3";

endSessionThread3 = new Thread(
new ThreadStart(ss.End3));
endSessionThread3.Name = "endThread3";

startSessionThread4 = new Thread(
new ThreadStart(ss.Start4));
startSessionThread4.Name = "startThread4";

endSessionThread4 = new Thread(
new ThreadStart(ss.End4));
endSessionThread4.Name = "endThread4";


startSessionThread5 = new Thread(
new ThreadStart(ss.Start5));
startSessionThread5.Name = "startThread5";

endSessionThread5 = new Thread(
new ThreadStart(ss.End5));
endSessionThread5.Name = "endThread5";

Thread[] threads = new Thread[10];
int[] ordering = new int[10];
try
{
for (int i = 0; i < 10; ++i)
{
ordering = -1;
}

for (int i = 0; i < 10; ++i)
{
int count = 0;
while (count < 25)
{
int j = r.Next(10);
bool duplicate = false;
for (int k = 0; k < ordering.Length; k++)
{
if (ordering[k] == j)
{
duplicate = true;
break;
}
}
if (!duplicate)
{
ordering = j;
break;
}
}
if (ordering < 0)
{
throw new Exception("error in setting up test");
}
}

threads[ordering[0]] = startSessionThread;
threads[ordering[1]] = endSessionThread;
threads[ordering[2]] = endSessionThread2;
threads[ordering[3]] = startSessionThread2;
threads[ordering[4]] = endSessionThread3;
threads[ordering[5]] = startSessionThread3;
threads[ordering[6]] = endSessionThread4;
threads[ordering[7]] = startSessionThread4;
threads[ordering[8]] = endSessionThread5;
threads[ordering[9]] = startSessionThread5;

for (int i = 0; i < 10; ++i)
{
threads.Start();
}
}
catch (Exception e)
{
keepTesting = false;
Console.WriteLine(e.Message);
}
finally
{
startSessionThread.Join();
endSessionThread.Join();
startSessionThread2.Join();
endSessionThread2.Join();
startSessionThread3.Join();
endSessionThread3.Join();
startSessionThread4.Join();
endSessionThread4.Join();
startSessionThread5.Join();
endSessionThread5.Join();
Console.WriteLine();
Console.WriteLine(" --------------- repeating test ---------------");
}
}

Console.Write("Main is finished. (Max time = " +
maxTime.TotalMilliseconds + " from " + maxMethodName + ")");
Console.Read();
}


#region ThreadStart Delegates
public void Start()
{
StartSession("Betty", 41);
}
public void Start2()
{
StartSession("Boop", 41);
}
public void Start3()
{
StartSession("Spunky", 41);
}
public void Start4()
{
StartSession("Grampy", 41);
}
public void Start5()
{
StartSession("Freddy", 41);
}

public void End()
{
EndSession("Betty", 41);
}
public void End2()
{
EndSession("Boop", 41);
}
public void End3()
{
EndSession("Spunky", 41);
}
public void End4()
{
EndSession("Grampy", 41);
}
public void End5()
{
EndSession("Freddy", 41);
}
#endregion


}//class SessionStarter

}//namespace
 
M

Mr. Mountain

I have tested this code further and I do not believe it has any thread
concurrency errors. I hope I'm right. However, I would be willing to pay a
fee to the first person who can point out a valid thread concurrency error
in the code. In other words, if it can suffer from a race condition or
deadlock, just point out the problem and I'll pay you a cash reward
according to the guidelines below.

I'm hope I'm not going to violate any etiquette or other rules by making
this offer. If I am, please let me know. On the other hand, this could be
really fun (and profitable)!

I will pay US$75 via PayPal to the first person who makes a post with a
threading error (as defined above)pointed out in the code. If PayPal isn't
acceptable to the winner, I'll pay via another means (credit card or mailing
a bank check).

This offer is valid for 48 hours from the time of this post.

It is not necessary to specify how to fix the problem -- just identify the
problem and explain why it is a thread concurrency problem.

If the first answer doesn't fully explain the problem, the reward will be
granted to the first subsequent post that does fully explain the problem.
The subsequent post could be from the same person -- in other words, more
than 1 attempt is allowed.

If it isn't really clear that an answer is correct, or there is some other
debate, I suggest that the experts on the newsgroup could act as judges to
decide which answer wins the cash reward. That could also be a fun process,
if it is needed.

If this offer violates any applicable laws in any region it shall not be
valid in that region. If anyone know of a reason that an offer like this
should not be made, please let me know. Otherwise, I"m offering this reward
in good faith and I will pay up to the first person who provides the answer.

Finally, if anyone thinks I should take this question to ExpertsExchange or
Google Answers or some place other than this newsgroup, let me know.
However, there isn't any reason we could establish newsgroups dedicated to
questions with rewards offered. The newsgroups could define the rules up
front and maybe be monitored...
 
J

Jon Skeet [C# MVP]

Mr. Mountain said:
In the following code I simulate work being done on different threads by
sleeping a couple methods for about 40 ms. However, some of these methods
that should finish in about 40 -80 ms take as long as 2300 ms to complete.
This is fairly rare, but the test code below will definitely show it.

Somehow, I must not have my design right.

A couple of things you have wrong:

1) Your access to keepTesting isn't thread-safe. See
http://www.pobox.com/~skeet/csharp/threads/volatility.shtml

2) I can see where you're testing for the session already being used,
but I can't see where you're then waiting to actually do the work later
on. As far as I can see you're just noticing that it was already being
processed, but then doing the other method anyway.

What error are you actually seeing? What should we be looking out for?
 
M

Mr. Mountain

Hi Jon,

Thanks for your reply. It would not really surprise me if you find problems
with my code, but I haven't actually found anything specific. In fact, the
code works well in a lot of different tests. My main concern is the
excessively long times reported to complete a method that should finish in
about 41 ms. I don't see how/why StartSession, for example, could take 2300
ms on rare occasions.

In regard to your comments about keepTesting, I don't really care about
Main() or keepTesting, or similar fields.
keepTesting is only set to false to end the test and I don't really care if
it this field is thread safe because it isn't part of the code that will
eventually move into production. I know this field is a crappy hack, but I'm
working under a tight time deadline and I am trying to just focus on the
parts of this test code that will be moved into production.

The only important methods are these:
CheckForConflictingSession
StartSession
HelpStartSession
EndSession
HelpEndSession
....and please ignore, as much as possible, any fields or methods used within
these for displaying test results or running the test loop.

I performed another test yesterday. This code shows what I did. (And I have
started using log4net now instead of Console.Write in order to more closely
examine all the output.) If anyone wants the complete code now that I have
made some changes, please let me know. I have not changed any of the core
logic in the above mentioned methods. I just changed the logging and added
another test as described below. The new code requires log4net to be run.

In order to prove that the code does indeed provide the thread
synchronization required, I added a hashtable called checkList. It contains
a check value (int) for each sessionID. Each time a particular sessionID is
being processed, the integer value (named check) which is stored in the
hashtable under the sessionID key, is incremented. When that session ID is
finished being processed, the value in the hashtable is decremented.

The code has to be designed so that a sessionID is only being processed by
one of the two methods at any point in time (and once a method starts
processing, it must finish before the other method can process that
sessionID). The hashtable (checkList) will catch a situation where a
sessionID starts being processed by more than one method.

In the test code, I increment and decrement the check value inside
HelpStartSession, in a synchronized block (after Monitor.TryEnter
successfully returns). Everything works correctly and no sessionID is ever
processed by more than 1 method at a time. This test gives me a lot of
confidence that the code works correctly. (I ran the test for 2 hours with 5
simultaneous application instances open -- so that's 10 hours of testing
with no serious errors. However, I continue to see the long completion times
reported by StartSession and EndSession.)

To finish the test, I temporarily moved the code to increment 'check' out of
the synchronized block in HelpStartSession and up to StartSession. As
expected, check then sometimes gets values of 0 or 2, whereas in the correct
code (check incremented within the 'locked' block) check always has a value
of 1. The temporary code is shown below as commented-out code in
StartSession.

public static void StartSession(string sessionID, int workAmount)
{
DateTime start = DateTime.Now;
logger.Info(Thread.CurrentThread.Name + ": " + "entering StartSession
method: " + sessionID);

//NOTE: if this code is uncommented, it shows that the synchronization is in
fact working
//int check = (int)checkList[sessionID];
//checkList[sessionID] = check + 1;
//logger.Info(Thread.CurrentThread.Name + " processing count = " + (check +
1).ToString());

ActiveSession mySession;
CheckForConflictingSession(sessionID, out mySession);
HelpStartSession(sessionID, mySession, workAmount);
TimeSpan ts = DateTime.Now - start;
if (ts > maxTime){ maxTime = ts; maxMethodName = "StartSession";}
logger.Info(Thread.CurrentThread.Name + ": StartSession time: " +
ts.TotalMilliseconds);
}//StartSession

private static void HelpStartSession(string sessionID, ActiveSession
mySession, int workAmount)
{
bool entered2 = Monitor.TryEnter(mySession, waitTime);
if (entered2)
{
logger.Info(Thread.CurrentThread.Name + ": " + sessionID + " is OK to be
initialized.");

try
{
int check = (int)checkList[sessionID];
checkList[sessionID] = check + 1;
logger.Info(Thread.CurrentThread.Name + " processing count = " + (check +
1).ToString());

//do all work
Thread.Sleep(workAmount/3);
logger.Info(Thread.CurrentThread.Name + ": Starting session " + sessionID
+ " initialization...");
Thread.Sleep(workAmount/3);
logger.Debug("");
Thread.Sleep(workAmount/3);
logger.Info(Thread.CurrentThread.Name + ": " + "Finished session " +
sessionID + " initialization.");
}
catch (Exception )
{
keepTesting = false;
Exception me = new Exception("Exception: Unable to complete session " +
sessionID + " initialization.");
logger.Error(me);
throw me;
}
finally
{
if ((int)checkList[sessionID] != 1)
{
logger.Error("ERROR: count = " + (int)checkList[sessionID]);
}
checkList[sessionID] = (int)checkList[sessionID] - 1;

sessionsBeingProcessed.Remove(sessionID);
Monitor.Exit(mySession);
logger.Info(Thread.CurrentThread.Name + ": " + sessionID + " is unlocked
by StartSession");
}
}
else
{
keepTesting = false;
Exception me2 = new Exception("Timed out. Could not get Monitor to start
sessionID " + sessionID);
logger.Error(me2);
throw me2;
}

}//HelpStartSession
 
M

Mr. Mountain

If anyone wants to earn 500 points on Experts Exchange, I posted the
question there also.
 
J

Jon Skeet [C# MVP]

Mr. Mountain said:
Thanks for your reply. It would not really surprise me if you find problems
with my code, but I haven't actually found anything specific. In fact, the
code works well in a lot of different tests. My main concern is the
excessively long times reported to complete a method that should finish in
about 41 ms. I don't see how/why StartSession, for example, could take 2300
ms on rare occasions.

I can see why it would if an exception were thrown, and you were
running under the debugger. I can't say I've seen it though.
In regard to your comments about keepTesting, I don't really care about
Main() or keepTesting, or similar fields.
keepTesting is only set to false to end the test and I don't really care if
it this field is thread safe because it isn't part of the code that will
eventually move into production. I know this field is a crappy hack, but I'm
working under a tight time deadline and I am trying to just focus on the
parts of this test code that will be moved into production.

Okay.

I still don't understand what your code was doing though - as I said
before, you seem (in the previous code - I haven't looked at the new
code yet) to check whether or not another thread is processing a
session, but if it is you still do the processing anyway. Isn't that
against the whole point?
 
M

Mr. Mountain

Hi Jon,
I appreciate your feedback. See my comments inline.
Mountain

Jon Skeet said:
I can see why it would if an exception were thrown, and you were
running under the debugger. I can't say I've seen it though.


Okay.

I still don't understand what your code was doing though - as I said
before, you seem (in the previous code - I haven't looked at the new
code yet) to check whether or not another thread is processing a
session, but if it is you still do the processing anyway. Isn't that
against the whole point?

The new code is exactly the same except for the addition of a new check to
validate that it is doing what it is supposed to do.

The code does indeed prevent more than one thread from processing a session
at the same time. However, I think the problem, from your perspective, is
that I named my methods inappropriately. The method name
"CheckForConflictingSession" seems a bit misleading as I am considering your
comments. This method does indeed let processing continue even if there is a
potentially conflicting session. However, it sets the stage for the
StartSession and EndSession methods to correctly deal with a situation where
a conflict could exist. So it might be better to say that this method is
doing some checking, but not actually handling the conflicts. It also
briefly locks on the whole hashtable (sesssionsBeingProcessed). The Start-
and EndSession methods do not lock this collection. They only lock a single
object that is extracted from the collection. This allows a very fine
grained degree of control, which I think is what you have recommended in
your various articles.

I appreciate your input.

I did post this on Google Answers. I offered $50 just for an indepth code
review, regardless of whether any specific threading problems are pointed
out, or not. So if you feel like going thru the code in greater detail,
maybe you can do it thru Google Answers.

Thanks
 
M

Mr. Mountain

If you have the ability to answer questions thru Google Answers, please go
there to get $50 for answering my question about this code. The question
there is based on this same code, but it is different in the sense that it
does not require anyone to find/prove that the code has a threading problem.
Just do a review of my code to answer the post on Google Answers. Thanks.

The $75 offer here is about to expire later today. So if you do find a
threading problem in the code and you also provide a reply thru Google
Answers, I guess I'll be paying you $125. But the $75 offer expires soon.
(The $50 from Google answers won't expire so soon.)
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Top