thread timing

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.
"Droopy" <dr********@hot mail.com> wrote in message
news:ff******** *************** ***@posting.goo gle.com...

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.W aitOne (25, false))
{
Util.TraceLine ("ItTaskProc end asked");
break;
}
Util.TraceLine ("after WaitOne");
Util.TraceLine ("before ItTaskProc");
_serialChannel. ItTask ();
Util.TraceLine ("after ItTaskProc");
progressBarItTa skThread.Perfor mStep ();
if (progressBarItT askThread.Value >= progressBarItTa skThread.Maximu m)
progressBarItTa skThread.Value = progressBarItTa skThread.Minimu m;

dtLast = dtCurrent;
dtCurrent = DateTime.Now;
Util.TraceLine ("dtCurrent= " + dtCurrent.ToStr ing ("HH:mm:ss:f ff: ")
+
", dtLast=" + dtLast.ToString ("HH:mm:ss:f ff: "));

TimeSpan diff = dtCurrent.Subtr act (dtLast);
if (_minItTaskElap sedTime > diff)
{
_minItTaskElaps edTime = diff;
Log ("New mininimum ItTaskElapsedTi me = " + _minItTaskElaps edTime);
}

if (_maxItTaskElap sedTime < diff)
{
_maxItTaskElaps edTime = diff;
Log ("New maximum ItTaskElapsedTi me = " + _maxItTaskElaps edTime);
}
}
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 ItTaskElapsedTi me =
00:00:00.171875 0

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.

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.

<dr********@hot mail.com> wrote in message
news:11******** **************@ f14g2000cwb.goo glegroups.com.. .

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.

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

Droopy.

I don't known what is actualy done in "_serialChannel .ItTask ();" and
"progressBarItT askThread.Perfo rmStep ();" 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.Threadin g;
using System.Diagnost ics;

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

static void Main()
{
string debString;
TimeSpan _minItTaskElaps edTime;
TimeSpan _maxItTaskElaps edTime;
DateTime dtCurrent;
DateTime dtLast;
bool firstRun = true;;
while (true)
{
Debug.WriteLine ("before WaitOne");
if (_itTaskEvent.W aitOne (25, false))
{
Debug.WriteLine ("ItTaskProc end asked");
break;
}
Debug.WriteLine ("after WaitOne");
Debug.WriteLine ("before ItTaskProc");
// Call empty method
ItTask ();
Debug.WriteLine ("after ItTaskProc");
// progressBarItTa skThread.Perfor mStep ();
// if (progressBarItT askThread.Value >= progressBarItTa skThread.Maximu m)
// progressBarItTa skThread.Value = progressBarItTa skThread.Minimu m;

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

TimeSpan diff = dtCurrent.Subtr act (dtLast);
if (_minItTaskElap sedTime > diff)
{
_minItTaskElaps edTime = diff;
debString = String.Format(" New mininimum ItTaskElapsedTi me = {0} "
,_minItTaskElap sedTime);
Debug.WriteLine (debString);
}

if ((_maxItTaskEla psedTime < diff) && !firstRun)
{
_maxItTaskElaps edTime = diff;
debString = String.Format(" New maximum ItTaskElapsedTi me = {0}
",_maxItTaskEla psedTime);
Debug.WriteLine (debString);
}
else if (firstRun)
{
firstRun = false;
}
}
}
static void ItTask ()
{ return;}
}
}

WIlly.

<dr********@hot mail.com> wrote in message
news:11******** **************@ f14g2000cwb.goo glegroups.com.. .

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

Droopy.

"_serialChannel .ItTask ();" is a wrapper to an unmanaged C++ function
that is handling a serial port.
Yes it is a Windows Forms application and
"progressBarItT askThread.Perfo rmStep ();" 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.T oString ("HH:mm:ss:f ff: ") +
System.Threadin g.Thread.Curren tThread.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.

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.BeginRec eive (state.buffer, 0, StateObject.Buf ferSize, 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.clientSoc ket;
Util.TraceLine ("Tcp:ReadCallb ack: Receiving from client = " +
handler.RemoteE ndPoint.ToStrin g () + " ...");

try
{
// Read data from the client socket.
int bytesRead = handler.EndRece ive (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.Socket Exception" 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:ReadCallbac k: 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::vLi nkDown called
15:23:15:718: ItTask thread: TrspPortManaged ::vCommEvent: LinkDown
15:23:15:687: : Tcp:ReadCallbac k: Receiving from client =
127.0.0.1:2944 ...
15:23:15:718: : ReadCallback: Exception catched:
System.Net.Sock ets.SocketExcep tion: Une connexion existante a dû être
fermée par l'hôte distant
at System.Net.Sock ets.Socket.EndR eceive(IAsyncRe sult asyncResult)
at IPRManaged.Tcp. ReadCallback(IA syncResult ar) in
c:\projects\ipr managed\iprmana ged\tcp.cs:line 165
15:23:15:750: ItTask thread: SerialChannel:: TransportCommEv ent:
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.Sock ets.SocketExcep tion: Une connexion existante a
dû être fermée par l'hôte distant
at System.Net.Sock ets.Socket.Rece ive(Byte[] buffer, Int32 offset,
Int32 size, SocketFlags socketFlags)
at System.Net.Sock ets.Socket.Rece ive(Byte[] buffer)
at IPRManaged.IprS ocket.ReadTcpSo cket() in
c:\projects\ipr managed\iprmana ged\iprsocket.c s:line 164
15:23:15:765: ItTask thread: SerialChannel:: TransportCommEv ent: event
queued, #1 items in queue
15:23:15:765: Serial Event: HandleSerialEve ntProc: handling LinkDown
event
15:23:15:765: Serial Event: FormMain::Handl eEvent: 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.Sock ets.SocketExcep tion: Une connexion existante a dû être
fermée par l'hôte distant
at System.Net.Sock ets.Socket.EndR eceive(IAsyncRe sult asyncResult)
at IPRManaged.Tcp. ReadCallback(IA syncResult ar) in
c:\projects\ipr managed\iprmana ged\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 ItTaskElapsedTi me =
00:00:03.500000 0
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