private static bool AddStatementToAggregatedCallTree(
ProfilerEvent?currentProfilerEvent,
ref AggregatedEventNode currentAggregatedEventNode,
ref Stack <ProfilerEvent> callStack)
{
if (currentAggregatedEventNode.Parent == null)
{
// Do not add statements to root node
return(true);
}
// If there are two consecutive statements then first we need to calculate the duration for the previous
// one and pop it from the statement call stack.
// Then we push the current statement event into the stack
if (currentAggregatedEventNode.Parent != null && currentAggregatedEventNode.EvaluatedType == EventType.Statement ||
// Function or sql statement called for previous statement has just ended
currentAggregatedEventNode.EvaluatedType == EventType.StopMethod &&
!currentAggregatedEventNode.IsExecutingFunction)
{
currentAggregatedEventNode = currentAggregatedEventNode.PopEventFromCallStackAndCalculateDuration(currentProfilerEvent.Value.TimeStampRelativeMSec);
}
currentAggregatedEventNode.EvaluatedType = EventType.Statement;
currentAggregatedEventNode = currentAggregatedEventNode.PushEventIntoCallStack(currentProfilerEvent.Value);
return(true);
}
private static void PopEventFromCallStackForPreviousAlStopMethodEvent(
ProfilerEvent?previousProfilerEvent,
ProfilerEvent?currentProfilerEvent,
ref AggregatedEventNode currentAggregatedEventNode)
{
if (previousProfilerEvent.HasValue && previousProfilerEvent.Value.Type == EventType.StopMethod &&
previousProfilerEvent.Value.SubType != EventSubType.SqlEvent)
{
// We have already calculated duration for the previous statement
// and pop it from the statement call stack.
// We should never pop root event. This can happen if we miss some events in the begining.
if (currentAggregatedEventNode.Parent != null)
{
if (!currentProfilerEvent.HasValue || // Previous event is the last one.
// The current event is none AL event. It comes after stop event. Need to pop the the current aggregated node. Only close AL events.
(currentProfilerEvent.Value.IsNonAlEvent && previousProfilerEvent.Value.IsAlEvent) ||
// Here we have statement after function call.
currentProfilerEvent.Value.Type == EventType.Statement ||
// Here we have funtion call in the end of other function.
currentProfilerEvent.Value.Type == EventType.StopMethod ||
// If we have two consecutive root method calls
(currentAggregatedEventNode.OriginalType == EventType.StartMethod &&
currentAggregatedEventNode.IsAlEvent))
{
currentAggregatedEventNode = currentAggregatedEventNode.PopEventFromCallStackAndCalculateDuration(previousProfilerEvent.Value.TimeStampRelativeMSec);
}
}
}
}
/// <summary>
/// Processes aggregated event. This method calls either <see cref="AggregatedEventNode.PushEventIntoCallStack"/> or
/// <see cref="AggregatedEventNode.PopEventFromCallStackAndCalculateDuration"/> on the <see cref="currentAggregatedEventNode"/>.
/// </summary>
/// <param name="previousProfilerEvent">Previous profiler event which was processed.</param>
/// <param name="currentProfilerEvent">Profiler event which currently being processed.</param>
/// <param name="currentAggregatedEventNode">Current aggregated event in the call tree.</param>
/// <returns>Returns <c>true</c> if event was valid and should not be skipped.</returns>
internal static bool AddProfilerEventToAggregatedCallTree(
ProfilerEvent?previousProfilerEvent,
ProfilerEvent?currentProfilerEvent,
ref AggregatedEventNode currentAggregatedEventNode,
ref Stack <ProfilerEvent> callStack)
{
bool skipCurrentEvent;
/*if (PopEventFromCallStackIfSomeEventsWereMissing(previousProfilerEvent, currentProfilerEvent, ref currentAggregatedEventNode, ref callStack, out skipCurrentEvent))
* {
* return skipCurrentEvent;
* }
*
* PopEventFromCallStackForPreviousAlStopMethodEvent(previousProfilerEvent, currentProfilerEvent, ref currentAggregatedEventNode, ref callStack);*/
if (!currentProfilerEvent.HasValue)
{
return(true);
}
switch (currentProfilerEvent.Value.Type)
{
case EventType.Statement:
return(AddStatementToAggregatedCallTree(currentProfilerEvent, ref currentAggregatedEventNode, ref callStack));
case EventType.StartMethod:
return(AddStartMethodToAggregatedCallTree(previousProfilerEvent, currentProfilerEvent, ref currentAggregatedEventNode, ref callStack));
case EventType.StopMethod:
return(AddStopMethodToAggregatedCallTree(currentProfilerEvent, ref currentAggregatedEventNode, ref callStack));
}
return(true);
}
private static bool AddStopMethodToAggregatedCallTree(
ProfilerEvent?currentProfilerEvent,
ref AggregatedEventNode currentAggregatedEventNode,
ref Stack <ProfilerEvent> callStack)
{
if (currentAggregatedEventNode.Parent != null)
{
if (callStack.Count() == 0)
{
// Discard current tree
while (currentAggregatedEventNode.Parent != null)
{
currentAggregatedEventNode = currentAggregatedEventNode.Parent;
}
currentAggregatedEventNode.Children.Clear();
return(false);
}
ProfilerEvent startEvent = callStack.Peek();
if (currentProfilerEvent.Value.ObjectType != startEvent.ObjectType ||
currentProfilerEvent.Value.ObjectId != startEvent.ObjectId ||
currentProfilerEvent.Value.StatementName != startEvent.StatementName)
{
// Skip stop event from empty functions
return(false);
}
// We need to calculate duration for the previous statement and pop it from the statement call stack.
if (currentAggregatedEventNode.EvaluatedType == EventType.Statement ||
currentAggregatedEventNode.EvaluatedType == EventType.StopMethod ||
// Always close non events.
currentProfilerEvent.Value.IsNonAlEvent)
{
currentAggregatedEventNode = currentAggregatedEventNode.PopEventFromCallStackAndCalculateDuration(currentProfilerEvent.Value.TimeStampRelativeMSec);
if (currentProfilerEvent.Value.SubType == EventSubType.AlEvent &&
currentAggregatedEventNode.SubType == EventSubType.AlEvent &&
currentAggregatedEventNode.Parent != null &&
currentAggregatedEventNode.Parent.Parent == null)
{
// Also pop function node created for root functions
currentAggregatedEventNode = currentAggregatedEventNode.PopEventFromCallStackAndCalculateDuration(currentProfilerEvent.Value.TimeStampRelativeMSec);
}
}
currentAggregatedEventNode.EvaluatedType = EventType.StopMethod;
if (currentProfilerEvent.Value.IsAlEvent)
{
currentAggregatedEventNode.IsExecutingFunction = false;
}
callStack.Pop();
}
return(true);
}
/// <summary>
/// Traverses the call stack tree.
/// </summary>
/// <param name="aggregatedCallTree">Aggregated call tree to traverse.</param>
/// <returns>Flatten call tree.</returns>
private static IEnumerable <AggregatedEventNode> FlattenCallTree(AggregatedEventNode aggregatedCallTree)
{
yield return(aggregatedCallTree);
foreach (AggregatedEventNode node in aggregatedCallTree.Children)
{
foreach (AggregatedEventNode childNode in FlattenCallTree(node))
{
yield return(childNode);
}
}
}
private static void PopEventFromCallStackForPreviousAlStopMethodEvent(
ProfilerEvent?previousProfilerEvent,
ProfilerEvent?currentProfilerEvent,
ref AggregatedEventNode currentAggregatedEventNode,
ref Stack <ProfilerEvent> callStack)
{
if (previousProfilerEvent.HasValue && previousProfilerEvent.Value.Type == EventType.StopMethod &&
previousProfilerEvent.Value.SubType != EventSubType.SqlEvent)
{
// We have already calculated duration for the previous statement
// and pop it from the statement call stack.
// We should never pop root event. This can happen if we miss some events in the begining.
if (currentAggregatedEventNode.Parent != null)
{
if (!currentProfilerEvent.HasValue || // Previous event is the last one.
// The current event is none AL event. It comes after stop event. Need to pop the the current aggregated node. Only close AL events.
(currentProfilerEvent.Value.IsNonAlEvent && previousProfilerEvent.Value.IsAlEvent) ||
// Here we have statement after function call.
currentProfilerEvent.Value.Type == EventType.Statement ||
// Here we have funtion call in the end of other function.
currentProfilerEvent.Value.Type == EventType.StopMethod ||
// If we have two consecutive root method calls
(currentAggregatedEventNode.OriginalType == EventType.StartMethod &&
currentAggregatedEventNode.IsAlEvent))
{
if (currentProfilerEvent.HasValue && currentProfilerEvent.Value.IsNonAlEvent && previousProfilerEvent.Value.IsAlEvent)
{
return;
}
if (currentProfilerEvent.HasValue && currentProfilerEvent.Value.Type == EventType.StopMethod && currentProfilerEvent.Value.SubType == EventSubType.AlEvent && (
callStack.Count() == 0 ||
callStack.Peek().ObjectType != currentProfilerEvent.Value.ObjectType ||
callStack.Peek().ObjectId != currentProfilerEvent.Value.ObjectId ||
callStack.Peek().FunctionName != currentProfilerEvent.Value.StatementName))
{
return;
}
//AggregatedEventNode currentAggregatedEventNode2 = currentAggregatedEventNode;
//List<AggregatedEventNode> before = currentAggregatedEventNode.Parent.Children.TakeWhile(x => x != currentAggregatedEventNode2).ToList();
//if (currentAggregatedEventNode.OriginalType == EventType.StartMethod && currentAggregatedEventNode.IsAlEvent)
// if (before.Any(x => x.EvaluatedType == EventType.StartMethod) && !before.Any(x => x.OriginalType == EventType.Statement))
// return;
currentAggregatedEventNode = currentAggregatedEventNode.PopEventFromCallStackAndCalculateDuration(previousProfilerEvent.Value.TimeStampRelativeMSec);
}
}
}
}
/// <summary>
/// Initializes state of the <see cref="DynamicProfilerEventProcessor"/>
/// </summary>
public void Initialize()
{
// create the root node for the session
aggregatedCallTree = new AggregatedEventNode
{
StatementName = "Session: " + profilingSessionId + ";",
SessionId = profilingSessionId
};
currentAggregatedEventNode = aggregatedCallTree;
previousProfilerEvent = null;
}
private static bool AddStartMethodToAggregatedCallTree(ProfilerEvent?previousProfilerEvent, ProfilerEvent?currentProfilerEvent, ref AggregatedEventNode currentAggregatedEventNode)
{
// If it is the root method or if it is non AL event we also push start event into the stack.
if (currentAggregatedEventNode.Parent == null ||
currentProfilerEvent.Value.IsNonAlEvent ||
(previousProfilerEvent.HasValue && previousProfilerEvent.Value.IsNonAlEvent))
{
currentAggregatedEventNode = currentAggregatedEventNode.PushEventIntoCallStack(currentProfilerEvent.Value);
}
currentAggregatedEventNode.EvaluatedType = EventType.StartMethod;
return(true);
}
private static bool AddStatementToAggregatedCallTree(ProfilerEvent?currentProfilerEvent, ref AggregatedEventNode currentAggregatedEventNode)
{
// If there are two consecutive statements then first we need to calculate the duration for the previous
// one and pop it from the statement call stack.
// Then we push the current statement event into the stack
if (currentAggregatedEventNode.Parent != null && currentAggregatedEventNode.EvaluatedType == EventType.Statement)
{
currentAggregatedEventNode = currentAggregatedEventNode.PopEventFromCallStackAndCalculateDuration(currentProfilerEvent.Value.TimeStampRelativeMSec);
}
currentAggregatedEventNode = currentAggregatedEventNode.PushEventIntoCallStack(currentProfilerEvent.Value);
return(true);
}
/// <summary>
/// Initializes state of the <see cref="DynamicProfilerEventProcessor"/>
/// </summary>
public void Initialize()
{
// create the root node for the session
this.aggregatedCallTree = new AggregatedEventNode
{
StatementName = "Session: " + this.profilingSessionId + ";",
SessionId = this.profilingSessionId
};
this.currentAggregatedEventNode = aggregatedCallTree;
this.callStack = new Stack <ProfilerEvent>();
this.previousProfilerEvent = null;
}
private static bool AddStopMethodToAggregatedCallTree(ProfilerEvent?currentProfilerEvent, ref AggregatedEventNode currentAggregatedEventNode)
{
if (currentAggregatedEventNode.Parent != null)
{
// We need to calculate duration for the previous statement and pop it from the statement call stack.
if (currentAggregatedEventNode.EvaluatedType == EventType.Statement ||
// Always close non events.
currentProfilerEvent.Value.IsNonAlEvent)
{
currentAggregatedEventNode = currentAggregatedEventNode.PopEventFromCallStackAndCalculateDuration(currentProfilerEvent.Value.TimeStampRelativeMSec);
}
}
return(true);
}
/// <summary>
/// Pushes event into call stack. It might get or create aggregated event.
/// </summary>
/// <param name="profilerEvent">The profiler event.</param>
/// <returns>The aggregated event node.</returns>
internal AggregatedEventNode PushEventIntoCallStack(ProfilerEvent profilerEvent)
{
Debug.Assert(profilerEvent.Type == EventType.Statement || profilerEvent.Type == EventType.StartMethod);
AggregatedEventNode res = Children.Find(e =>
e.SessionId == profilerEvent.SessionId &&
e.ObjectType == profilerEvent.ObjectType &&
e.ObjectId == profilerEvent.ObjectId &&
e.LineNo == profilerEvent.LineNumber &&
e.StatementName == profilerEvent.StatementName);
if (res != null)
{
// We need to initialize state of the AggregatedEventNode.
// Otherwise duration will not be calculated correctly or we can get broken tree structure.
res.EvaluatedType = profilerEvent.Type;
res.TimeStampRelativeMSec = profilerEvent.TimeStampRelativeMSec;
++res.HitCount;
return(res);
}
res = new AggregatedEventNode(this)
{
SessionId = profilerEvent.SessionId,
Tenant = profilerEvent.Tenant,
UserName = profilerEvent.UserName,
AppId = profilerEvent.AppId,
AppInfo = profilerEvent.AppInfo,
ObjectType = profilerEvent.ObjectType,
ObjectId = profilerEvent.ObjectId,
LineNo = profilerEvent.LineNumber,
StatementName = profilerEvent.StatementName,
TimeStampRelativeMSec = profilerEvent.TimeStampRelativeMSec,
OriginalType = profilerEvent.Type,
EvaluatedType = profilerEvent.Type,
SubType = profilerEvent.SubType,
};
Children.Add(res);
++res.HitCount;
return(res);
}
/// <summary>
/// Traverses the call stack tree.
/// </summary>
/// <returns>reduces the tree by removing all nodes that are below the threshold call tree.</returns>
private void ReduceTree(AggregatedEventNode rootNode)
{
if (this.threshold <= 0)
{
return;
}
for (int index = 0; index < rootNode.Children.Count; index++)
{
AggregatedEventNode node = rootNode.Children[index];
if (node.DurationMSec < this.threshold)
{
node.Children.Clear();
rootNode.Children.Remove(node);
index--;
}
else
{
this.ReduceTree(node);
}
}
}
private static bool AddStartMethodToAggregatedCallTree(
ProfilerEvent?previousProfilerEvent,
ProfilerEvent?currentProfilerEvent,
ref AggregatedEventNode currentAggregatedEventNode,
ref Stack <ProfilerEvent> callStack)
{
// If it is the root method or if it is non AL event we also push start event into the stack.
if (currentAggregatedEventNode.Parent == null ||
currentProfilerEvent.Value.IsNonAlEvent)
{
currentAggregatedEventNode = currentAggregatedEventNode.PushEventIntoCallStack(currentProfilerEvent.Value);
}
currentAggregatedEventNode.EvaluatedType = EventType.StartMethod;
if (currentProfilerEvent.Value.IsAlEvent)
{
currentAggregatedEventNode.IsExecutingFunction = true;
}
callStack.Push(currentProfilerEvent.Value);
return(true);
}
/// <summary>
/// Initializes a new instance of the <see cref="AggregatedEventNode"/> class.
/// </summary>
/// <param name="parent">Parent <see cref="AggregatedEventNode"/>.</param>
internal AggregatedEventNode(AggregatedEventNode parent = null)
{
this.Children = new List <AggregatedEventNode>();
this.Parent = parent;
this.Depth = parent != null ? parent.Depth + 1 : 0;
}
private static bool PopEventFromCallStackIfSomeEventsWereMissing(
ProfilerEvent?previousProfilerEvent,
ProfilerEvent?currentProfilerEvent,
ref AggregatedEventNode currentAggregatedEventNode,
ref Stack <ProfilerEvent> callStack,
out bool skipCurrentEvent)
{
if (currentAggregatedEventNode.Parent != null &&
currentAggregatedEventNode.OriginalType == EventType.StartMethod &&
currentAggregatedEventNode.SubType == EventSubType.SqlEvent &&
currentProfilerEvent.HasValue && !(currentProfilerEvent.Value.Type == EventType.StopMethod && currentProfilerEvent.Value.SubType == EventSubType.SqlEvent))
{
// TODO: Here we have two consecutive start events. First event is of the SQL subtype. This should never happen because SQL queries cannot be nested.
// TODO: It could indicates an issue in evening.
// TODO: Need to pop previous event and push current.
ProfilerEvent missingProfilerEvent = new ProfilerEvent
{
SessionId = currentAggregatedEventNode.SessionId,
ObjectType = currentAggregatedEventNode.ObjectType,
ObjectId = currentAggregatedEventNode.ObjectId,
LineNo = currentAggregatedEventNode.LineNo,
Type = EventType.StartMethod,
StatementName = StopEventIsMissing + currentAggregatedEventNode.StatementName
};
currentAggregatedEventNode = currentAggregatedEventNode.PopEventFromCallStackAndCalculateDuration(previousProfilerEvent.Value.TimeStampRelativeMSec);
currentAggregatedEventNode = currentAggregatedEventNode.PushEventIntoCallStack(missingProfilerEvent);
currentAggregatedEventNode = currentAggregatedEventNode.PopEventFromCallStackAndCalculateDuration(missingProfilerEvent.TimeStampRelativeMSec);
if (currentProfilerEvent.Value.Type == EventType.StartMethod || currentProfilerEvent.Value.Type == EventType.Statement)
{
currentAggregatedEventNode = currentAggregatedEventNode.PushEventIntoCallStack(currentProfilerEvent.Value);
}
skipCurrentEvent = true;
return(true);
}
if (currentAggregatedEventNode.Parent != null &&
previousProfilerEvent.HasValue && previousProfilerEvent.Value.Type == EventType.StopMethod &&
currentProfilerEvent.HasValue && currentProfilerEvent.Value.Type == EventType.StopMethod &&
currentProfilerEvent.Value.IsAlEvent != currentAggregatedEventNode.IsAlEvent)
{
//TODO: We hit this block for example in the case if Codeunit 1 trigger is called and it does not have any code.
//TODO: We should consider if we want to fix it in the product.
// Skip this event. Should never happen. Indicates a issue in the event generation.
// Some events were missed.
// Create fake start event.
ProfilerEvent profilerEvent = currentProfilerEvent.Value;
profilerEvent.Type = EventType.StartMethod;
profilerEvent.StatementName = StartEventIsMissing + profilerEvent.StatementName;
currentAggregatedEventNode = currentAggregatedEventNode.PushEventIntoCallStack(profilerEvent);
currentAggregatedEventNode = currentAggregatedEventNode.PopEventFromCallStackAndCalculateDuration(currentProfilerEvent.Value.TimeStampRelativeMSec);
skipCurrentEvent = false;
return(true);
}
skipCurrentEvent = false;
return(false);
}