IEF Request Tracing Bug ?
From: Christophe G (ChristopheG_at_discussions.microsoft.com)
Date: 09/27/04
- Previous message: Dave Nelson: "Re: Looking for legacy tools (masm 5.1, etc)"
- Messages sorted by: [ date ] [ thread ]
Date: Mon, 27 Sep 2004 07:15:07 -0700
Microsoft Enterprise Instrumentation version 7.0.5000.0
According to the documentation, an event will be written to the Windows
Application Log indicating that a specific request trace hasn't been stopped
properly before the finalizer of that request was called by the runtime.
The documentation states that this can happen in the following situations:
-> RequestTrace.Dispose is not explicitly invoked (or implicitly by
implementing the C# using statement or equivalent try - finally blocks)
-> The outer request of a nested request ends prematurely before the
nested request
Now the problem that I've encountered, is that this message is not only
written by the Finalize method of a request trace, but that it is possible,
under certain circumstances, which I'll explain in a few seconds, that the
Dispose method of an outer request is doing this.
Another problem that I've noticed in the same situation, is that a
TraceRequestEndEvent is written in the log for the same nested request, but
by the Dispose method of the parent request.
What's the situation now, well asynchronous method invocation inside a
request trace by using BeginInvoke on a delegate.
Code Example:
public class Simulator {
private delegate void SimulationMethodHandler();
public void StartSimulation() {
RequestEventSource firstES = new RequestEventSource("FirstES");
using (RequestTrace firstRequest = new RequestTrace(firstES)) {
SimulationMethodHandler simulationHandler;
simulationHandler = new SimulationMethodHandler(this.SimulationMethod);
simulationHandler.BeginInvoke( null, null);
//Thread.Sleep(2000); // Scenario 1
//Thread.Sleep(4000); // Scenario 2
}
}
private void SimulationMethod () {
//Thread.Sleep(2000); // Scenario 3
RequestEventSource secondES = new RequestEventSource("SecondES");
using (RequestTrace secondRequest = new RequestTrace(secondES)) {
Thread.Sleep(2000); // Do something that takes 2 seconds to complete
}
}
public static void Main () {
try {
Simulator oSimulator = new Simulator();
oSimulator.StartSimulation();
} finally {
Thread.Sleep(5000); // just to make sure the workerthread has ended
Console.WriteLine("simulation done");
Console.ReadLine();
}
}
}
As you can see, after starting the main request trace, I invoke the
SimulationMethod asynchronously. The SimulationMethod then starts another
request trace which will be nested inside the main request.
Because you can't say when a workerthread is available from the ThreadPool,
I'm using Thread.Sleep to simulate different scenarios.
-> Scenario 1: Sleep for 2 seconds to make sure the nested request on the
workerthread has started before the main request is disposed (this is a
realistic situation)
-> Scenario 2: Sleep for 4 seconds to make sure the nested request on the
workerthread has started and stopped before the main request is disposed
-> Scenario 3: Sleep for 2 seconds to make sure the first request has been
disposed on the main thread
When you uncomment the line for scenario 2 or the line for scenario 3,
everything works fine, and no event is written to the Windows Application
Log. The first scenario however will generate an event to the Windows
Application Log saying that the secondRequest hasn't been disposed properly
(which is normal because it is still running on the workerthread), and a
TraceRequestEndEvent is logged for the secondRequest (strange because it is
still running). All of this logging happens in the Dispose method of the
first request trace.
Not only this logging is strange, but also a TraceRequestEndEvent is missing
for the first request (because it has been logged for the second request
instead).
The other 2 scenarios aren't doing this, because in scenario 2, the first
request will be disposed after the second request, and in scenario 3, the
second request trace will be initiated after that the dispose method has been
called on the first request.
The fact that the Dispose method of the first request is logging a "Leak
detection" event to the Windows Application Log and is logging a
TraceRequestEndEvent for the second request (and because of that the first
request is missing his own TraceRequestEndEvent), that may indicate the
presence of a bug or multiple bugs.
Another strange thing is that if the first request has been disposed before
the second request is started (scenario 2), even then the second request will
receive the first request as his parent request,generating a
TraceNestedRequestStartEvent, which is strange because at that moment the
first request shouldn't be available anymore.
The problem is that the current request (which is kept inside the
CallContext) is updated on the workerthread (because the CallContext can span
thread boundaries when using the threadpool) and that the Dispose method of
the first request is assuming that the first request is the current one.
This means that you will have a situation where the main thread is disposing
a request trace that thinks that it is the current request, but it isn't
because the second request on the workerthread is set as the current request
(You can even see this if you write a TraceMessage just before the end of the
using statement of the first request. You will see in the log that the
eventsource isn't firstES but secondES).
The other scenarios don't have this problem, because in scenario 2 the first
request is set back as the current request after the dispose of the second
request, but before the dipsose of the first request, and in scenario 3 the
first request is still the current request because the second request isn't
created yet.
So my question now is, are these bugs or am I missing something ? Because
the documentation of the "Leak detection" feature isn't talking about such a
situation.
So currently the only solution I've got is to delay the creation of the
second request like in scenario 3, but even then it isn't fully bullet-proof.
Any thoughts on this ?
Christophe
ps: I hope this post is still readable
- Previous message: Dave Nelson: "Re: Looking for legacy tools (masm 5.1, etc)"
- Messages sorted by: [ date ] [ thread ]
Relevant Pages
|
