473,320 Members | 1,831 Online
Bytes | Software Development & Data Engineering Community
Post Job

Home Posts Topics Members FAQ

Join Bytes to post your question to a community of 473,320 software developers and data experts.

thread timing

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.
Nov 16 '05 #1
7 2736
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********@hotmail.com> wrote in message
news:ff**************************@posting.google.c om...
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.

Nov 16 '05 #2
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.

Nov 16 '05 #3

<dr********@hotmail.com> wrote in message
news:11**********************@f14g2000cwb.googlegr oups.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.

Nov 16 '05 #4
I tried setting thread priority to Normal, then it takes more than 200
ms.
Anyway, thanks for your answers.

Droopy.

Nov 16 '05 #5

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.

<dr********@hotmail.com> wrote in message
news:11**********************@f14g2000cwb.googlegr oups.com...
I tried setting thread priority to Normal, then it takes more than 200
ms.
Anyway, thanks for your answers.

Droopy.

Nov 16 '05 #6
"_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.

Nov 16 '05 #7
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:lin e 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

Nov 16 '05 #8

This thread has been closed and replies have been disabled. Please start a new discussion.

Similar topics

4
by: Jeff | last post by:
I am running a worker thread that manipulates some hardware setting every so often. My problem is that the hardware manipulation cannot be interrupted once it has started How can I ensure that...
20
by: Sacha | last post by:
Consider I have a working thread like this, while (1) { if ( g_pObject ) g_pObject->DoOneStep(); } with an class hierarchie like this
16
by: droopytoon | last post by:
Hi, I start a new thread (previous one was "thread timing") because I have isolated my problem. It has nothing to do with calling unmanaged C++ code (I removed it in a test application). I...
2
by: Asad Khan | last post by:
I call the following method from my main form method: uploadThread = new Thread(new ThreadStart (this.doFTPUpload)); uploadThread.Name = "FTP Upload"; uploadThread.Start(); bool...
3
by: gregory_may | last post by:
I have an application where I am using a System Thread to capture the screen & Broadcast it to clients. Its "working", but the timing on the background thread gets wildly erratic at times. Some...
13
by: LordHog | last post by:
Hello all, I have a little application that needs to poll a device (CAN communications) every 10 to 15 ms otherwise the hardware buffer might overflow when there are message burst on the bus. I...
7
by: Boki | last post by:
Multi-thread read/write to a single file. I have two processing threads, thread A and thread B; and I called my queue as Q. Thread A will feed data into Q by user input, the timing is random....
9
by: Jon Slaughter | last post by:
I'm using Thread and ThreadStart to create a thread for testing purposes and I do not want to use a pool because the thread exists for the life time of the app. Eventually I might move on to using...
11
by: Jon Slaughter | last post by:
Is there any way to start a terminated thread without using a pool or creating a new thread object? void counter() { clicks = 0; clock.Start(); while (counterActive) { clicks++;
0
by: ryjfgjl | last post by:
ExcelToDatabase: batch import excel into database automatically...
0
isladogs
by: isladogs | last post by:
The next Access Europe meeting will be on Wednesday 6 Mar 2024 starting at 18:00 UK time (6PM UTC) and finishing at about 19:15 (7.15PM). In this month's session, we are pleased to welcome back...
1
isladogs
by: isladogs | last post by:
The next Access Europe meeting will be on Wednesday 6 Mar 2024 starting at 18:00 UK time (6PM UTC) and finishing at about 19:15 (7.15PM). In this month's session, we are pleased to welcome back...
0
by: Vimpel783 | last post by:
Hello! Guys, I found this code on the Internet, but I need to modify it a little. It works well, the problem is this: Data is sent from only one cell, in this case B5, but it is necessary that data...
0
by: jfyes | last post by:
As a hardware engineer, after seeing that CEIWEI recently released a new tool for Modbus RTU Over TCP/UDP filtering and monitoring, I actively went to its official website to take a look. It turned...
0
by: ArrayDB | last post by:
The error message I've encountered is; ERROR:root:Error generating model response: exception: access violation writing 0x0000000000005140, which seems to be indicative of an access violation...
1
by: PapaRatzi | last post by:
Hello, I am teaching myself MS Access forms design and Visual Basic. I've created a table to capture a list of Top 30 singles and forms to capture new entries. The final step is a form (unbound)...
0
by: CloudSolutions | last post by:
Introduction: For many beginners and individual users, requiring a credit card and email registration may pose a barrier when starting to use cloud servers. However, some cloud server providers now...
0
by: Faith0G | last post by:
I am starting a new it consulting business and it's been a while since I setup a new website. Is wordpress still the best web based software for hosting a 5 page website? The webpages will be...

By using Bytes.com and it's services, you agree to our Privacy Policy and Terms of Use.

To disable or enable advertisements and analytics tracking please visit the manage ads & tracking page.