Problem timing asynchronous delegate calls
akash
Posts: 8
In the example given below, the manual timings give similar times for using delegate.invoke and delegate.begininvoke. However, ANTS profiler reports the async calls as taking much longer. Any ideas what is going on?
Thanks
Akash
Module Module1
Public Delegate Function DoWork() As Double
Public SW As System.Diagnostics.Stopwatch
Sub Main()
SyncInvoke()
AsyncInvoke()
End Sub
Public Function SyncInvoke() As Double
Dim Del As New DoWork(AddressOf SyncCalc)
SW = New System.Diagnostics.Stopwatch
SW.Start()
Del.Invoke()
SW.Stop()
MsgBox("SyncInvoke : " & SW.ElapsedMilliseconds)
End Function
Public Function AsyncInvoke() As Double
Dim Del As New DoWork(AddressOf AsyncCalc)
SW = New System.Diagnostics.Stopwatch
SW.Start()
Dim Res As IAsyncResult = Del.BeginInvoke(Nothing, Nothing)
Del.EndInvoke(Res)
SW.Stop()
MsgBox("AsyncInvoke : " & SW.ElapsedMilliseconds)
End Function
Private Function SyncCalc() As Double
Dim Tot As Double = 0
For i As Integer = 1 To 100000000
Tot += System.Math.Sqrt(i)
Next
Return Tot
End Function
Private Function AsyncCalc() As Double
Dim Tot As Double = 0
For i As Integer = 1 To 100000000
Tot += System.Math.Sqrt(i)
Next
Return Tot
End Function
End Module
Thanks
Akash
Module Module1
Public Delegate Function DoWork() As Double
Public SW As System.Diagnostics.Stopwatch
Sub Main()
SyncInvoke()
AsyncInvoke()
End Sub
Public Function SyncInvoke() As Double
Dim Del As New DoWork(AddressOf SyncCalc)
SW = New System.Diagnostics.Stopwatch
SW.Start()
Del.Invoke()
SW.Stop()
MsgBox("SyncInvoke : " & SW.ElapsedMilliseconds)
End Function
Public Function AsyncInvoke() As Double
Dim Del As New DoWork(AddressOf AsyncCalc)
SW = New System.Diagnostics.Stopwatch
SW.Start()
Dim Res As IAsyncResult = Del.BeginInvoke(Nothing, Nothing)
Del.EndInvoke(Res)
SW.Stop()
MsgBox("AsyncInvoke : " & SW.ElapsedMilliseconds)
End Function
Private Function SyncCalc() As Double
Dim Tot As Double = 0
For i As Integer = 1 To 100000000
Tot += System.Math.Sqrt(i)
Next
Return Tot
End Function
Private Function AsyncCalc() As Double
Dim Tot As Double = 0
For i As Integer = 1 To 100000000
Tot += System.Math.Sqrt(i)
Next
Return Tot
End Function
End Module
Comments
I've been forced to download a trial of JetBrains dotTrace, which gives the correct timings for these calls.
Thanks
Akash
I agree that we do have problem with getting the times correct - I am looking into this right now. However, if you delete the pdb file ANTS Profiler will only time methods. In this case the timings for the methods are correct (in agreement with Jet Brains - a product that does not offer any line level timings).
Could I ask you to try out just profiling methods for now until we can sort out the line level bits?
Best regards,
Tom Harris
Red Gate Software
Removing the pdb file does mean that the method timings are correct - thanks. However, line-level timings are the main attraction of ANTS Profiler...also, I've started getting another problem when profiling, which I'll explain in a separate post (and again I don't get the problem with dotTrace).
Akash
We are going to address this problem by releasing an update to ANTS Profiler in the next two weeks.
I'm looking forward to the update!
I've just tried out your code on ANTS Profiler 3, and I see the effect you're reporting. However, after looking a bit closer, let me explain why it's there.
When profiling at line-level, we obviously introduce an amount of overhead into your application - this is necessary, as we need to record timing data when every sequence point (analogous to a debugger breakpoint) is hit. In order to try and give you the most realistic idea of how your application will perform outside the profiler, we subtract the amount of time we spend in our code from the amount of time your method spends executing. This means that methods may be reported as taking less time in the results than they actually did when executing in the profiler - this is entirely correct.
However, this approach can run into problems when there are multiple threads waiting on each other.
When you asynchronously invoke a method, it is queued for processing on a worker thread. Calling EndInvoke() then causes the current thread to block until the result of that invocation is ready.
Now, the problem here is that ANTS isn't directly introducing any overhead into that call to EndInvoke(), since it's effectively a Thread.Sleep, so we don't subtract any time from the wall clock time. However, the reason the EndInvoke takes longer than it would outside the profiler is of course that ANTS is introducing the overhead into the method being executed on the other thread.
You can probably see that it would be difficult to detect these cross-thread dependencies!
There is, however, something that can help: reduce the amount of overhead ANTS introduces. This is now easy to do in version 3 - profile in Fast Mode instead of Detailed Mode. This will only give you method level timings, but that is almost always sufficient to get you to the rough area of the problem, at which point I would recommend switching to detailed mode, and using a custom filter or the Visual Studio Add-in to profile only the methods or classes that you're most interested in.
I'd also recommend using the hierarchy view - and in particular, the "time with children" columns. This lets you quickly navigate down to the areas of code causing you the most pain - there will almost always be one or two methods taking the vast majority of the time (in my experience at least).
Note that any asynchronous invokes will "split" the hierarchy - in your example, AsyncInvoke() has no children, and AsyncCalc() has no parents, whereas SyncInvoke() shows SyncCalc() as a child. This is expected - we define method calls in the same way as the .NET runtime, which doesn't include cross-thread invocations (there's actually a lot of other stuff going on behind the scenes when you do that!).
I hope that goes some way to explaining the results you're getting.
Regards,
Robert
Red Gate