thread slowing down so much

D

Droopy

Hi,

I am writing a C# program that is calling C++ legacy code.
I wrote a C++ managed wrapper for this legacy code.
It seems to work well.
The legacy code is handling serial (RS232 or RS422) lines.
To keep a serial line "alive", i have to call regularly a function.
A c# thread is calling about every 25 ms this function (based on
"WaitOne (25, false)" function).
Usually, this function is called every 30 ms.
But after a while (about 30 minutes), this function is called after a
few hundreds of ms or even a few seconds !
I know Windows is not a real time OS and some background processes can
be run by DotNet runtime like garbage collection but still !

I use heavily Debug.Writeline to trace my program.
I run the debug version of my program outside of Visual Studio
environment.
This morning, I had a log of 1,7 GB for about 16 hours of test running.
Analysing it, I saw no log during 1 minute 38 seconds.
It means also no log from other C# threads, 100% C# managed !
Usually, I have about 400 log lines/second.

What's going on ?
The deadline is coming for this program, please help me.

My configuration :

Pentium 4 2.8 GHz HyperTheading
512 MB RAM
Windows XP Professional SP1
Visual Studio 2003 v 7.1.3088
DotNet Framework 1.1 v 1.1.4322

Thanks in advance,

Droopy.
 
N

Nicholas Paldino [.NET/C# MVP]

Droopy,

It looks like you are using a class that is a managed wrapper around an
unmanaged resource. Are you sure you are disposing of the resource
properly?

Can you show the code?
 
D

Droopy

Droopy,

It looks like you are using a class that is a managed wrapper
around an
unmanaged resource. Are you sure you are disposing of the resource
properly?

Can you show the code?

No I am not sure.
It is the first time I mix managed and unmanaged code.

Here is the code for the "keep alive" thread :

the C# thread function :

public void ItTaskProc ()
{
Util.TraceOther ("ItTaskProc thread started");

TimeSpan maxItTaskElapsedTime = TimeSpan.MinValue;
TimeSpan minItTaskElapsedTime = TimeSpan.MaxValue;
DateTime dtCurrent = DateTime.Now;
DateTime dtLast = DateTime.MinValue;

try
{
while (true)
{
Util.TraceOther ("before WaitOne");
if (_itTaskEvent.WaitOne (25, false))
{
Util.TraceOther ("ItTaskProc end asked");
break;
}
Util.TraceOther ("after WaitOne");
Util.TraceOther ("before ItTask");
ItTask ();
Util.TraceOther ("after ItTask");

dtLast = dtCurrent;
dtCurrent = DateTime.Now;

TimeSpan diff = dtCurrent.Subtract (dtLast);
if (minItTaskElapsedTime > diff)
{
minItTaskElapsedTime = diff;
Util.TraceOther ("New mininimum ItTaskElapsedTime =
" + minItTaskElapsedTime);
}
if (maxItTaskElapsedTime < diff)
{
maxItTaskElapsedTime = diff;
Util.TraceOther ("New maximum ItTaskElapsedTime =
" + maxItTaskElapsedTime);
}
}
}
catch (Exception ex)
{
Util.TraceError ("ItTaskProc: Exception catched: " + ex);
EventArgs ea = new EventArgs ();
if (OnConnectionFailed != null)
OnConnectionFailed (this, ea);
}
finally
{
_itTaskEvent.Reset ();
}
Util.TraceOther ("ItTaskProc ended gracefully");
}


calling this c# function where "_transport" is an instance of the C++
managed wrapper :

public void ItTask ()
{
_transport.ItTask ();
}

here it is the C++ managed function that is calling the C++ unmanaged
wrapper called "_unmanaged" (not really a wrapper because the C++ unmanaged
class is a subclass of the C++ legacy entry point) :

void TrspPortManaged::ItTask ()
{
_unmanaged->ItTask ();
}

here is the C++ unmanaged function where EnterCS and LeaveCS handle
critical sections shared with legacy code :

void UMTrspPort::ItTask( void)
{
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::ItTask before EnterCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
EnterCS (__FILE__,__LINE__);
Debug::WriteLine
(String::Format (S"{0} - UMTrspPort::ItTask before ItTask",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));

cTrspPort::ItTask ();

Debug::WriteLine
(String::Format (S"{0} - UMTrspPort::ItTask after ItTask",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
LeaveCS(__FILE__,__LINE__);
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::ItTask after LeaveCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
}

I don't think there is a disposing problem in this "keep alive thread".

Here is the declaration for the unmanaged C++ class, subclass from the C++
unmanaged legacy code class called "cTrspPort" :

class UMTrspPort : public cTrspPort
{
private:
char _bufIn __nogc [260];
unsigned short _size;
PFUNC _pCallback;

public:
UMTrspPort ();
void AddCallback (PFUNC pCallback);
void TraceLine (String *message);
void TraceError (String *message);


// Virtuals

//
===========================================================================
=
// vpFreeMsg
// Ask memory buffer for incoming data
//
===========================================================================
=
virtual void * vpFreeMsg (unsigned short NbByte);

//
===========================================================================
=
// vMsgIn
// new incoming message
// returns 0 if OK.
//
===========================================================================
=
virtual unsigned char vMsgIn (int MsgOk);

// outgoing message sent
virtual void vMsgOut (unsigned long Tag, unsigned short Err);

// no added value, redefined to add critical section
void ItTask( void);

// no added value, redefined to add critical section
unsigned short MsgOut (void *pMsg, unsigned long NbByte, unsigned
long Tag);
};

If there is a disposing problem, it should be in incoming or outgoing
message functions here above :

vpFreeMsg is called by legacy code to get a buffer to copy incoming data :

void * UMTrspPort::vpFreeMsg (unsigned short NbByte)
{
_size = NbByte;
char *ptr = _bufIn;
return ((void *) ptr);
}

vMsgIn is called by legacy code when there is incoming data :

unsigned char UMTrspPort::vMsgIn (int MsgOk)
{
CommEventData *data = new CommEventData ();
data->EventType = CommEventType::Session;
data->UcnData = new unsigned char __gc [_size];
Marshal::Copy (_bufIn, data->UcnData, 0, _size);

if (_pCallback)
_pCallback (data);
else
TraceError ("UMTrspPort::vMsgIn no callback defined");

return 0;
}

MsgOut is called by legacy code to send outgoing data :

unsigned short UMTrspPort::MsgOut (void *pMsg, unsigned long NbByte,
unsigned long Tag)
{
char *pm = (char *) pMsg;
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut before EnterCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
EnterCS (__FILE__,__LINE__);
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut after EnterCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));

unsigned short retCode = cTrspPort::MsgOut (pMsg, NbByte, Tag);

Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut before LeaveCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
LeaveCS(__FILE__,__LINE__);
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut after LeaveCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));

return retCode;
}

vMsgOut is called by legacy code when outgoing data is really sent

void UMTrspPort::vMsgOut (unsigned long Tag, unsigned short Err)
{
if (Err != 0)
{
TraceError (String::Format ("UMTrspPort::vMsgOut Tag={0}, Err=
0x{1}", Tag.ToString (), Err.ToString (S"X2")));
}

CommEventData *data = new CommEventData ();

data->EventType = CommEventType::vMsgOut;
data->UlData = Tag;

if (_pCallback)
_pCallback (data);
else
TraceError ("UMTrspPort::vMsgOut no callback defined");
}


Sorry, it is a lot of code but I give you only the minimum.
Thanks for your answer,

Droopy.
 
D

Droopy

Please give me a clue !


Droopy,

It looks like you are using a class that is a managed wrapper
around an
unmanaged resource. Are you sure you are disposing of the resource
properly?

Can you show the code?

No I am not sure.
It is the first time I mix managed and unmanaged code.

Here is the code for the "keep alive" thread :

the C# thread function :

public void ItTaskProc ()
{
Util.TraceOther ("ItTaskProc thread started");

TimeSpan maxItTaskElapsedTime = TimeSpan.MinValue;
TimeSpan minItTaskElapsedTime = TimeSpan.MaxValue;
DateTime dtCurrent = DateTime.Now;
DateTime dtLast = DateTime.MinValue;

try
{
while (true)
{
Util.TraceOther ("before WaitOne");
if (_itTaskEvent.WaitOne (25, false))
{
Util.TraceOther ("ItTaskProc end asked");
break;
}
Util.TraceOther ("after WaitOne");
Util.TraceOther ("before ItTask");
ItTask ();
Util.TraceOther ("after ItTask");

dtLast = dtCurrent;
dtCurrent = DateTime.Now;

TimeSpan diff = dtCurrent.Subtract (dtLast);
if (minItTaskElapsedTime > diff)
{
minItTaskElapsedTime = diff;
Util.TraceOther ("New mininimum ItTaskElapsedTime
=
" + minItTaskElapsedTime);
}
if (maxItTaskElapsedTime < diff)
{
maxItTaskElapsedTime = diff;
Util.TraceOther ("New maximum ItTaskElapsedTime =
" + maxItTaskElapsedTime);
}
}
}
catch (Exception ex)
{
Util.TraceError ("ItTaskProc: Exception catched: " + ex);
EventArgs ea = new EventArgs ();
if (OnConnectionFailed != null)
OnConnectionFailed (this, ea);
}
finally
{
_itTaskEvent.Reset ();
}
Util.TraceOther ("ItTaskProc ended gracefully");
}


calling this c# function where "_transport" is an instance of the C++
managed wrapper :

public void ItTask ()
{
_transport.ItTask ();
}

here it is the C++ managed function that is calling the C++ unmanaged
wrapper called "_unmanaged" (not really a wrapper because the C++
unmanaged class is a subclass of the C++ legacy entry point) :

void TrspPortManaged::ItTask ()
{
_unmanaged->ItTask ();
}

here is the C++ unmanaged function where EnterCS and LeaveCS handle
critical sections shared with legacy code :

void UMTrspPort::ItTask( void)
{
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::ItTask before EnterCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
EnterCS (__FILE__,__LINE__);
Debug::WriteLine
(String::Format (S"{0} - UMTrspPort::ItTask before ItTask",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));

cTrspPort::ItTask ();

Debug::WriteLine
(String::Format (S"{0} - UMTrspPort::ItTask after ItTask",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
LeaveCS(__FILE__,__LINE__);
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::ItTask after LeaveCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
}

I don't think there is a disposing problem in this "keep alive
thread".

Here is the declaration for the unmanaged C++ class, subclass from the
C++ unmanaged legacy code class called "cTrspPort" :

class UMTrspPort : public cTrspPort
{
private:
char _bufIn __nogc [260];
unsigned short _size;
PFUNC _pCallback;

public:
UMTrspPort ();
void AddCallback (PFUNC pCallback);
void TraceLine (String *message);
void TraceError (String *message);


// Virtuals

//
====================================================================== =
==== =
// vpFreeMsg
// Ask memory buffer for incoming data
//
====================================================================== =
==== =
virtual void * vpFreeMsg (unsigned short NbByte);

//
====================================================================== =
==== =
// vMsgIn
// new incoming message
// returns 0 if OK.
//
====================================================================== =
==== =
virtual unsigned char vMsgIn (int MsgOk);

// outgoing message sent
virtual void vMsgOut (unsigned long Tag, unsigned short Err);

// no added value, redefined to add critical section
void ItTask( void);

// no added value, redefined to add critical section
unsigned short MsgOut (void *pMsg, unsigned long NbByte, unsigned
long Tag);
};

If there is a disposing problem, it should be in incoming or outgoing
message functions here above :

vpFreeMsg is called by legacy code to get a buffer to copy incoming
data :

void * UMTrspPort::vpFreeMsg (unsigned short NbByte)
{
_size = NbByte;
char *ptr = _bufIn;
return ((void *) ptr);
}

vMsgIn is called by legacy code when there is incoming data :

unsigned char UMTrspPort::vMsgIn (int MsgOk)
{
CommEventData *data = new CommEventData ();
data->EventType = CommEventType::Session;
data->UcnData = new unsigned char __gc [_size];
Marshal::Copy (_bufIn, data->UcnData, 0, _size);

if (_pCallback)
_pCallback (data);
else
TraceError ("UMTrspPort::vMsgIn no callback defined");

return 0;
}

MsgOut is called by legacy code to send outgoing data :

unsigned short UMTrspPort::MsgOut (void *pMsg, unsigned long NbByte,
unsigned long Tag)
{
char *pm = (char *) pMsg;
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut before EnterCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
EnterCS (__FILE__,__LINE__);
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut after EnterCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));

unsigned short retCode = cTrspPort::MsgOut (pMsg, NbByte, Tag);

Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut before LeaveCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
LeaveCS(__FILE__,__LINE__);
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut after LeaveCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));

return retCode;
}

vMsgOut is called by legacy code when outgoing data is really sent

void UMTrspPort::vMsgOut (unsigned long Tag, unsigned short Err)
{
if (Err != 0)
{
TraceError (String::Format ("UMTrspPort::vMsgOut Tag={0},
Err=
0x{1}", Tag.ToString (), Err.ToString (S"X2")));
}

CommEventData *data = new CommEventData ();

data->EventType = CommEventType::vMsgOut;
data->UlData = Tag;

if (_pCallback)
_pCallback (data);
else
TraceError ("UMTrspPort::vMsgOut no callback defined");
}


Sorry, it is a lot of code but I give you only the minimum.
Thanks for your answer,

Droopy.
 
D

Droopy

I check for memory leak with a memory profiler.
Did not find memory link in my code but it seems there are memory links
in the String usage made when logging => I disabled tracing and then ...
no problem !
So it seems I have to make a refactoring in my logging routines because
I still use "Debug.WriteLine".

Besides, I cannot compile a "Release" version.
In Debug mode, I had a linker error LNK4210 that I solved using the MSDN
article #814472.

In Release mode, I have following errors :

with /MD parameter :

3 errors LNK2001 ("__argc", "__argv", "__mbctype")
4 errors LNK2005 ("delete" + "new") for msvcrt.lib (MSVCC71.dll)
1 error LNK2019 __mbctype referenced in function "void __stdcall
_AfxAbbreviateName ..."

with /MT parameter :

2 errors LNK2005 for libcmt.lib (typinfo.obj)
10 errors LNK2005 for msvcrt.lib (MSVCC71.dll)
4 errors LNK2005 for msvcrt.lib (cinitexe.obj)
1 error LNK2019

Thanks in advance for your help.

Please give me a clue !


Droopy,

It looks like you are using a class that is a managed wrapper
around an
unmanaged resource. Are you sure you are disposing of the resource
properly?

Can you show the code?

No I am not sure.
It is the first time I mix managed and unmanaged code.

Here is the code for the "keep alive" thread :

the C# thread function :

public void ItTaskProc ()
{
Util.TraceOther ("ItTaskProc thread started");

TimeSpan maxItTaskElapsedTime = TimeSpan.MinValue;
TimeSpan minItTaskElapsedTime = TimeSpan.MaxValue;
DateTime dtCurrent = DateTime.Now;
DateTime dtLast = DateTime.MinValue;

try
{
while (true)
{
Util.TraceOther ("before WaitOne");
if (_itTaskEvent.WaitOne (25, false))
{
Util.TraceOther ("ItTaskProc end asked");
break;
}
Util.TraceOther ("after WaitOne");
Util.TraceOther ("before ItTask");
ItTask ();
Util.TraceOther ("after ItTask");

dtLast = dtCurrent;
dtCurrent = DateTime.Now;

TimeSpan diff = dtCurrent.Subtract (dtLast);
if (minItTaskElapsedTime > diff)
{
minItTaskElapsedTime = diff;
Util.TraceOther ("New mininimum ItTaskElapsedTime
=
" + minItTaskElapsedTime);
}
if (maxItTaskElapsedTime < diff)
{
maxItTaskElapsedTime = diff;
Util.TraceOther ("New maximum ItTaskElapsedTime =
" + maxItTaskElapsedTime);
}
}
}
catch (Exception ex)
{
Util.TraceError ("ItTaskProc: Exception catched: " + ex);
EventArgs ea = new EventArgs ();
if (OnConnectionFailed != null)
OnConnectionFailed (this, ea);
}
finally
{
_itTaskEvent.Reset ();
}
Util.TraceOther ("ItTaskProc ended gracefully");
}


calling this c# function where "_transport" is an instance of the C++
managed wrapper :

public void ItTask ()
{
_transport.ItTask ();
}

here it is the C++ managed function that is calling the C++ unmanaged
wrapper called "_unmanaged" (not really a wrapper because the C++
unmanaged class is a subclass of the C++ legacy entry point) :

void TrspPortManaged::ItTask ()
{
_unmanaged->ItTask ();
}

here is the C++ unmanaged function where EnterCS and LeaveCS handle
critical sections shared with legacy code :

void UMTrspPort::ItTask( void)
{
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::ItTask before EnterCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
EnterCS (__FILE__,__LINE__);
Debug::WriteLine
(String::Format (S"{0} - UMTrspPort::ItTask before ItTask",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));

cTrspPort::ItTask ();

Debug::WriteLine
(String::Format (S"{0} - UMTrspPort::ItTask after ItTask",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
LeaveCS(__FILE__,__LINE__);
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::ItTask after LeaveCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
}

I don't think there is a disposing problem in this "keep alive
thread".

Here is the declaration for the unmanaged C++ class, subclass from the
C++ unmanaged legacy code class called "cTrspPort" :

class UMTrspPort : public cTrspPort
{
private:
char _bufIn __nogc [260];
unsigned short _size;
PFUNC _pCallback;

public:
UMTrspPort ();
void AddCallback (PFUNC pCallback);
void TraceLine (String *message);
void TraceError (String *message);


// Virtuals

//
======================================================================
=
==== =
// vpFreeMsg
// Ask memory buffer for incoming data
//
======================================================================
=
==== =
virtual void * vpFreeMsg (unsigned short NbByte);

//
======================================================================
=
==== =
// vMsgIn
// new incoming message
// returns 0 if OK.
//
======================================================================
=
==== =
virtual unsigned char vMsgIn (int MsgOk);

// outgoing message sent
virtual void vMsgOut (unsigned long Tag, unsigned short Err);

// no added value, redefined to add critical section
void ItTask( void);

// no added value, redefined to add critical section
unsigned short MsgOut (void *pMsg, unsigned long NbByte, unsigned
long Tag);
};

If there is a disposing problem, it should be in incoming or outgoing
message functions here above :

vpFreeMsg is called by legacy code to get a buffer to copy incoming
data :

void * UMTrspPort::vpFreeMsg (unsigned short NbByte)
{
_size = NbByte;
char *ptr = _bufIn;
return ((void *) ptr);
}

vMsgIn is called by legacy code when there is incoming data :

unsigned char UMTrspPort::vMsgIn (int MsgOk)
{
CommEventData *data = new CommEventData ();
data->EventType = CommEventType::Session;
data->UcnData = new unsigned char __gc [_size];
Marshal::Copy (_bufIn, data->UcnData, 0, _size);

if (_pCallback)
_pCallback (data);
else
TraceError ("UMTrspPort::vMsgIn no callback defined");

return 0;
}

MsgOut is called by legacy code to send outgoing data :

unsigned short UMTrspPort::MsgOut (void *pMsg, unsigned long NbByte,
unsigned long Tag)
{
char *pm = (char *) pMsg;
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut before EnterCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
EnterCS (__FILE__,__LINE__);
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut after EnterCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));

unsigned short retCode = cTrspPort::MsgOut (pMsg, NbByte, Tag);

Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut before LeaveCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));
LeaveCS(__FILE__,__LINE__);
Debug::WriteLine
(String::Format ("{0} - UMTrspPort::MsgOut after LeaveCS",
DateTime::get_Now ().ToString ("HH:mm:ss:fff: ")));

return retCode;
}

vMsgOut is called by legacy code when outgoing data is really sent

void UMTrspPort::vMsgOut (unsigned long Tag, unsigned short Err)
{
if (Err != 0)
{
TraceError (String::Format ("UMTrspPort::vMsgOut Tag={0},
Err=
0x{1}", Tag.ToString (), Err.ToString (S"X2")));
}

CommEventData *data = new CommEventData ();

data->EventType = CommEventType::vMsgOut;
data->UlData = Tag;

if (_pCallback)
_pCallback (data);
else
TraceError ("UMTrspPort::vMsgOut no callback defined");
}


Sorry, it is a lot of code but I give you only the minimum.
Thanks for your answer,

Droopy.
 
D

Droopy

I got no answer in mpd.languages.vc !
I thought it was a kind of faq but it doesn't seem.
I can believe I am the only one to get this problem !
Did I ask it wrongly ?
 

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