thread timing

[Droopy]

Hi,

I don't understand why sometimes, a loop running in a thread takes
much more time than usual.
I have a thread that must call each 20 ms a C++ unmanaged function.
I made a C++ managed wrapper for calling this function from C# (see
below _serialChannel.ItTask ()).
It works great but for this timing problem.
Here below, the main loop for this thread :

while (true)
{
Util.TraceLine ("before WaitOne");
if (_itTaskEvent.WaitOne (25, false))
{
Util.TraceLine ("ItTaskProc end asked");
break;
}
Util.TraceLine ("after WaitOne");
Util.TraceLine ("before ItTaskProc");
_serialChannel.ItTask ();
Util.TraceLine ("after ItTaskProc");
progressBarItTaskThread.PerformStep ();
if (progressBarItTaskThread.Value >= progressBarItTaskThread.Maximum)
progressBarItTaskThread.Value = progressBarItTaskThread.Minimum;

dtLast = dtCurrent;
dtCurrent = DateTime.Now;
Util.TraceLine ("dtCurrent=" + dtCurrent.ToString ("HH:mm:ss:fff: ")
+
", dtLast=" + dtLast.ToString ("HH:mm:ss:fff: "));

TimeSpan diff = dtCurrent.Subtract (dtLast);
if (_minItTaskElapsedTime > diff)
{
_minItTaskElapsedTime = diff;
Log ("New mininimum ItTaskElapsedTime = " + _minItTaskElapsedTime);
}

if (_maxItTaskElapsedTime < diff)
{
_maxItTaskElapsedTime = diff;
Log ("New maximum ItTaskElapsedTime = " + _maxItTaskElapsedTime);
}
}


Here is the log output :

09:14:06:546: ItTask thread: before WaitOne
09:14:06:578: ItTask thread: after WaitOne
09:14:06:578: ItTask thread: before ItTaskProc
09:14:06:578: ItTask thread: after ItTaskProc
09:14:06:578: ItTask thread: dtCurrent=09:14:06:578: ,
dtLast=09:14:06:546:
09:14:06:578: ItTask thread: before WaitOne
09:14:06:609: ItTask thread: after WaitOne
09:14:06:609: ItTask thread: before ItTaskProc
09:14:06:609: ItTask thread: after ItTaskProc
09:14:06:609: ItTask thread: dtCurrent=09:14:06:609: ,
dtLast=09:14:06:578:
09:14:06:609: ItTask thread: before WaitOne
09:14:06:640: ItTask thread: after WaitOne
09:14:06:640: ItTask thread: before ItTaskProc
09:14:06:656: ItTask thread: after ItTaskProc
09:14:06:656: ItTask thread: dtCurrent=09:14:06:656: ,
dtLast=09:14:06:609:
09:14:06:796: ItTask thread: before WaitOne
09:14:06:828: ItTask thread: after WaitOne
09:14:06:828: ItTask thread: before ItTaskProc
09:14:06:828: ItTask thread: after ItTaskProc
09:14:06:828: ItTask thread: dtCurrent=09:14:06:828: ,
dtLast=09:14:06:656:
09:14:06:828: ItTask thread: New maximum ItTaskElapsedTime =
00:00:00.1718750

As you can see, the loop runs usually in 30-40 ms but the last one run
in 171 ms !
I set priority for this thread to ThreadPriority.Highest.

Can anyone help me to understand this behaviour ?

Thanks in advance.

Regards,

Droopy.

 

[Willy Denoyette [MVP]]

Don't ever assume that a task will end in a fixed amount of time, your
thread will NOT be on the CPU all the time, Windows is no hard real time OS.
For the same reason, don't assume you can call a function every x msec's.
Every thread in the system has a max. quantum (OS version dependent) to be
on the CPU, the scheduler will pre-empt and switch to another (higher
priority) thread. When there is no higher priority runable thread available,
the scheduler will scan the same priority list (in a round-robin fashion).
To prevent starvation, the scheduler can lower thread priorities and boost
the priority of others.

Willy.

 

[droopytoon]

Thanks for the answer.
I understand of course that Windows is not a real time OS.
I don't really care when I call WaitOne with 20 or 25 ms timeout if it
takes 30 ms but I thought that 171 ms when an average time of 30-40 ms
was observed is not normal, even for a non real time OS !

Droopy.

 

[Willy Denoyette [MVP]]

Thanks for the answer.
I understand of course that Windows is not a real time OS.
I don't really care when I call WaitOne with 20 or 25 ms timeout if it
takes 30 ms but I thought that 171 ms when an average time of 30-40 ms
was observed is not normal, even for a non real time OS !

That depends on the number of runable threads waiting to be scheduled,
because of the "little game" you play by setting your thread priority to
'highest' possible, you are delaying the scheduling of lower priority theads
untils the scheduler decides that your game must end and he boost the
(dynamic) priority of the other runable threads and lowers your threads
(dynamic) priority. In general you better off running your threads with
normal priority this way you don't disturb the scheduler job (and not to
forget the GC and Finalizers job in a managed application).

Willy.

 

[droopytoon]

I tried setting thread priority to Normal, then it takes more than 200
ms.
Anyway, thanks for your answers.

Droopy.

 

[Willy Denoyette [MVP]]

I don't known what is actualy done in "_serialChannel.ItTask ();" and
"progressBarItTaskThread.PerformStep ();" also I 'm not sure this is a
Windows Forms application but I guess so.
Also I'm not clear how you log your messages but supposed you are writing
them to disk, there's a chance your thread is waiting for IO rundown when
flushing the buffer.
Therefore I've written a small console application using the same algorithm
as the one you posted, but here I'm writing debug messages to the debugger
output.
When I ran this the average remains at 30 msec. with a single max. of
50msec. early in the process, this without running other CPU intensive
tasks.

#define DEBUG
using System;
using System.Threading;
using System.Diagnostics;

namespace Willys
{
class Tester
{
static AutoResetEvent _itTaskEvent = new AutoResetEvent(false);

static void Main()
{
string debString;
TimeSpan _minItTaskElapsedTime;
TimeSpan _maxItTaskElapsedTime;
DateTime dtCurrent;
DateTime dtLast;
bool firstRun = true;;
while (true)
{
Debug.WriteLine ("before WaitOne");
if (_itTaskEvent.WaitOne (25, false))
{
Debug.WriteLine ("ItTaskProc end asked");
break;
}
Debug.WriteLine ("after WaitOne");
Debug.WriteLine ("before ItTaskProc");
// Call empty method
ItTask ();
Debug.WriteLine ("after ItTaskProc");
// progressBarItTaskThread.PerformStep ();
// if (progressBarItTaskThread.Value >= progressBarItTaskThread.Maximum)
// progressBarItTaskThread.Value = progressBarItTaskThread.Minimum;

dtLast = dtCurrent;
dtCurrent = DateTime.Now;
debString = String.Format("dtCurrent= {0}: , dtLast= {1} )",
dtCurrent.ToString("HH:mm:ss:fff"),
dtLast.ToString("HH:mm:ss:fff") );
Debug.WriteLine (debString);

TimeSpan diff = dtCurrent.Subtract (dtLast);
if (_minItTaskElapsedTime > diff)
{
_minItTaskElapsedTime = diff;
debString = String.Format("New mininimum ItTaskElapsedTime = {0} "
,_minItTaskElapsedTime);
Debug.WriteLine (debString);
}

if ((_maxItTaskElapsedTime < diff) && !firstRun)
{
_maxItTaskElapsedTime = diff;
debString = String.Format("New maximum ItTaskElapsedTime = {0}
",_maxItTaskElapsedTime);
Debug.WriteLine (debString);
}
else if (firstRun)
{
firstRun = false;
}
}
}
static void ItTask ()
{ return;}
}
}

WIlly.

 

[droopytoon]

"_serialChannel.ItTask ();" is a wrapper to an unmanaged C++ function
that is handling a serial port.
Yes it is a Windows Forms application and
"progressBarItTaskThread.PerformStep ();" is a ProgressBar used to
signal that the thread is running.
Here below is the code that log messages :

public class Util
{
// lock (typeof (Util)) does not seem to work
private static object forLocking = new object ();

public static void TraceLine (string message)
{
lock (forLocking)
{
Debug.WriteLine
(DateTime.Now.ToString ("HH:mm:ss:fff: ") +
System.Threading.Thread.CurrentThread.Name +
": " + message);
}
}
}

At first, I thought that the call to unmanaged code was the source of
my problem but if you take a close look to my logs, you will see that
the time is not "lost" in calling "_serialChannel.ItTask ();" but it is
"lost" between the end of the loop (log for "dtCurrent" and "dtLast ")
and the begin of the loop (log for "before WaitOne") !
Again, thanks for you time,

Pierre.

 

[droopytoon]

Anyway, this is not a blocking problem for me.
I now really have a problem because I can "freeze" the "ItTask" thread.
When this thread is frozen, the serial port protocol generate a "link
down".

My application is listening for command from clients on a TCP port in
other threads (see code here below) :

....
client.BeginReceive (state.buffer, 0, StateObject.BufferSize, 0,
new AsyncCallback (ReadCallback), state);
}

public void ReadCallback (IAsyncResult ar)
{
// Retrieve the state object and the handler socket
// from the asynchronous state object.
StateObject state = (StateObject) ar.AsyncState;
Socket handler = state.clientSocket;
Util.TraceLine ("Tcp:ReadCallback: Receiving from client = " +
handler.RemoteEndPoint.ToString () + " ...");

try
{
// Read data from the client socket.
int bytesRead = handler.EndReceive (ar);
....

I have some connections opened (main channel + unsollicited channel +
client channel).
When the client closes, it closes all its connections and everything is
OK.
I tried to simulate a "crash" in the client by stopping it (via the
menu Debug->Stop Debugging) to force it not to close its connections.
My application catches a "Sockets.SocketException" for each connection
that is interrupted.
At this moment, my "ItTask" thread is frozen more than 3 seconds for 3
connections opened with client (see logs here below).
It automatically continue when these exceptions are "handled".

15:23:12:281: ItTask thread: before WaitOne
15:23:12:281: : Tcp:ReadCallback: Receiving from client =
127.0.0.1:2943 ...
15:23:15:687: ItTask thread: after WaitOne
15:23:15:687: ItTask thread: before ItTaskProc
15:23:15:687: ItTask thread: UMTrspPort::vLinkDown called
15:23:15:718: ItTask thread: TrspPortManaged::vCommEvent: LinkDown
15:23:15:687: : Tcp:ReadCallback: Receiving from client =
127.0.0.1:2944 ...
15:23:15:718: : ReadCallback: Exception catched:
System.Net.Sockets.SocketException: Une connexion existante a dû être
fermée par l'hôte distant
at System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult)
at IPRManaged.Tcp.ReadCallback(IAsyncResult ar) in
c:\projects\iprmanaged\iprmanaged\tcp.cs:line 165
15:23:15:750: ItTask thread: SerialChannel::TransportCommEvent:
CommEventType LinkDown received
15:23:15:750: : ReadCallback: handling finished for client =
127.0.0.1:2943 on 127.0.0.1:1414
15:23:15:765: IprSocket #33 read thread: ReadTcpSocket Exception
catched System.Net.Sockets.SocketException: Une connexion existante a
dû être fermée par l'hôte distant
at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset,
Int32 size, SocketFlags socketFlags)
at System.Net.Sockets.Socket.Receive(Byte[] buffer)
at IPRManaged.IprSocket.ReadTcpSocket() in
c:\projects\iprmanaged\iprmanaged\iprsocket.cs:line 164
15:23:15:765: ItTask thread: SerialChannel::TransportCommEvent: event
queued, #1 items in queue
15:23:15:765: Serial Event: HandleSerialEventProc: handling LinkDown
event
15:23:15:765: Serial Event: FormMain::HandleEvent: CommEventType
LinkDown received
15:23:15:781: ItTask thread: after ItTaskProc
15:23:15:781: IprSocket #33 read thread: ReadTcpSocket thread finished,
IprSocket #33 on 127.0.0.1:2945, remote host #1, remote socket #1,
connected = True, running = False, listener = False
The thread 'IprSocket #33 read thread' (0xc28) has exited with code 0
(0x0).
15:23:15:781: : ReadCallback: Exception catched:
System.Net.Sockets.SocketException: Une connexion existante a dû être
fermée par l'hôte distant
at System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult)
at IPRManaged.Tcp.ReadCallback(IAsyncResult ar) in
c:\projects\iprmanaged\iprmanaged\tcp.cs:line 165
15:23:15:796: ItTask thread: dtCurrent=15:23:15:781: ,
dtLast=15:23:12:281:
15:23:15:796: ItTask thread: New maximum ItTaskElapsedTime =
00:00:03.5000000
15:23:15:796: Serial Event: LinkDown, stopping Timecode thread

I hope I am clear enough, feel free to ask for more code or more
explanations.

So my question is :

Why is my ItTask frozen, it has nothing to do with socket handling ?
Thanks in advance,

Droopy