Timings reported do not make sense

leerjet

I am using v3.1.0.20, having used versions of the profiler since its inception. The timings I am getting cannot be correct. In particular, I run an application and check the Output window to see that the before/after the "AddRange" line before is about 5 seconds different. However, Profiler is reporting the "Time" shown below.

0.0049 Console.WriteLine(DateTime.Now.ToLongTimeString());
0.730 leerGridView1.Items.AddRange(algi);
0.0000 Console.WriteLine(DateTime.Now.ToLongTimeString());

In addition, the summary page shows the above routine (event handler for a button press) as taking 0.7305 seconds when I know (and can see from the UI of the program as well as the VS Output window) takes about 5 seconds.

What is going on??

I am using a desktop, Windows XP Pro and an Intel 6850 Quad core.

Brian Donahue

Hello,

I believe that you are showing us the line-level times in your example. If I understand you correctly, you want to see the total time taken to execute an event handler, in that case you'd want to be looking at the all methods tab, looking at 'buttonx_click' and examining the time with children statistic. Provided the event only executed once (ANTS adds up all the times for the method), you should see 5 seconds or possibly slightly less, because ANTS Profiler is meant to compensate for its' own overhead.

Please let me know if you think I'm mistaken about anything.

leerjet

Yes, you are mistaken. Perhaps I wasn't clear. Please be aware that I am quite experienced with your product and what is being reported is just wrong. In the "All methods" screen, the line for this event hander is:

Method Time(sec.) Time w/childeren Hit Cnt
FormTooltipTest2.btnAdd300Rows_Click 0.0071 0.7725 1

Brian Donahue

Maybe there are async delegates in the event handler or work happening in a background thread?

leerjet

Brian:

I do not understand what you are asking. The entire event handler attached to this button click is:

private void btnAdd100Rows_Click(object sender, EventArgs e)
{
LeerGridItem[] algi = new LeerGridItem[300];
LeerGridItem lgi;
for(int i = 0; i < 300; ++i)
{
lgi = new LeerGridItem(new Object[] { "Line " + n.ToString(), "Two", DateTime.Now, 7, DateTime.Now });
algi = lgi;
++n;
}
Console.WriteLine(DateTime.Now.ToLongTimeString());
leerGridView1.Items.AddRange(algi);
Console.WriteLine(DateTime.Now.ToLongTimeString());
}

If I run under debug and breakpoint at the "AddRange" line and single step over that line, the debugger comes back in about 5 seconds. From a standpoint of the profiler, why should it matter what code is doing in that AddRange method? Most of the code behind the AddRange I wrote myself and I am not using multiple threads. I am, however, using a third party grid control contained in another dll. Again, I don't see why that should matter. Please explain if I am mistaken. However, it seems like if a single statement does not return for 5 seconds, that the profiler should say that statement took 5 seconds.

Brian Donahue

Doesn't it take some time to step through code with the debugger? The way I understand, the debugger needs to stop the application, get a stack frame, retrieve the values of all variables referenced on the stack, etc. Wouldn't it be more realistic to set a timer before the method and check the timer after the method?

leerjet

Brian:

Please take the time to understand the information I am giving you before responding. Let me try and organize the facts for you:

1. When I run at full speed with no breakpoints, the Console.WriteLine statements before and after the "...AddRange" statement clearly indicate a before/after time difference of 5 seconds.

2. Now, to prove that the AddRange statement actually takes about five seconds, I place a breakpoint at the AddRange line. I then run the program under debug allowing it to break at the AddRange statement. Pressing the "Step Over" debug toolbar button once will force another breakpoint at the statement directly after the current line within the same method. Therefore, pressing that button will cause another breakpoint at the 2nd Console.WriteLine. When I press the StepOver toolbar icon I use my watch to time how long it takes. The result is still approximately 5 seconds. That proves without question that the AddRange statement is slow.The time it takes the debugger to start and stop is largely insignificant. compared to the 5 seconds observed.

3. Now I run my project under ANTS Profiler 3. I press the applications button that causes the above event handler to be invoked and immediately after the results of the AddRange are displayed (it fills a list view) I force ANTS to take a snapshot. I then press the "All methods" tab to see detailed information. No matter whether I look at the "time with children" data for the "btnAdd100Rows_Click" statement or the actual "AddRange" routine being called in the "Source code" section at the button of the ANTS window and look at line timings for the button event handler, it shows that the AddRange line took 0.771 seconds. All cases show exactly 1 Hit count.

The question then remains, what would cause ANTS to report one eighth of the time it actually takes for that single statement?

leerjet

Brian:

Let me go a step further. I just changed my routine so the the code between the two Console.WriteLine's did nothing:

Console.WriteLine(DateTime.Now.ToLongTimeString());
for(int i = 0; i < 160000000; ++i)
{
}
Console.WriteLine(DateTime.Now.ToLongTimeString());

When run under debug, the Console.WriteLine show the same hh:mm:ss. In other words, the loop takes almost no time. (it's actually about 0.4 seconds). However, when run under ANTS, it reports that the event handler takes over 50 seconds. That's over 100 times too big. The reported results just don't make sense.

Brian Donahue

This is something a bit different -- we do acknowledge that 'tight code loops' are a problem for the line-level timing because the overhead compensation often takes longer than the line itself. I don't believe you would encounter a loop with one line of code in it all too often, but we are looking at ways of solving the problem even though it's been a challenge almost from the start.

leerjet

I think I have come across the potential source of this problem, which looks like a serious deficiency in ANTS. I will write it up here as it might be useful to your engineers.

Look at the two segements of code below:

public void test()
{
Console.WriteLine("Before try/catch loop: " + DateTime.Now.ToLongTimeString());
for(int j = 0;j < 1000;++j)
{
try
{
int k = Int32.Parse("123");
}
catch
{
}
}
Console.WriteLine("After try/catch loop: " + DateTime.Now.ToLongTimeString());
}


public void test()
{
Console.WriteLine("Before try/catch loop: " + DateTime.Now.ToLongTimeString());
for(int j = 0;j < 1000;++j)
{
try
{
int k = Int32.Parse("abc");
}
catch
{
}
}
Console.WriteLine("After try/catch loop: " + DateTime.Now.ToLongTimeString());
}


When run under the normal debugger, the first code segment shows that the times before and after loop are the same, essentially meaning that it took less than a second. (Int32.Parse coverts the number string to an integer).
Then second code segment, which will generate an exception that is "caught" (because "abc" is not a number), shows the time before and after difference as about 5 seconds.

When run under ANTS, both segments report about 0.7 seconds. It seems that the time wasted by .Net for the exception is not taken into account. If this can be duplicated by you, I would consider it serious problem as code like this could potentially be the source of a slowdown in an application under test if a block like that happens to execute too many times.

Robert C

Hi,

You say "when running in the normal debugger" - that's something worth watching out for. Throwing exceptions whilst the VS debugger is attached has a serious performance penalty.

I changed your code slightly to use Environment.TickCount rather than DateTime.Now, which gave me millisecond timing nice and easily.

Running inside the debugger, I got results of 0ms for the first case, and 3120ms for the second. Outside the debugger, that second reading went down to 60ms!

Running inside ANTS Profiler, I got results of 100ms and 350ms reported by ANTS for the two tests, and 47ms and 359ms reported on the console. Admittedly it's not perfect, but it is in the right order of magnitude. This isn't too surprising, given the still small amount of work actually being done in the loop.

Hope that helps,
Robert

leerjet

Robert:

I appreciate you trying to look at this, however, there is absolutely something strange with what is happening when running under ANTS. Having code that generates exceptions that are caught is a normal programming practice. Using a profiler should not yield wildly different results. I changed my test segment to use ticks and ran 3 tests. The results prove to me that ANTS is "interfering" with the normal flow of the code:

int n1 = Environment.TickCount;
for(int j = 0;j < 1000;++j)
{
try
{
int k = Int32.Parse("adf");
}
catch
{
}
}
int n2 = Environment.TickCount;
MessageBox.Show("Before/After: " + n1.ToString() + " / " + n2.ToString());

Test 1: Debug release, press "Start debugging" toolbar button:
Message box shows about 4000 ticks difference

Test 2: Release build, press "Start debugging". Message box shows about 3000 ticks difference.

Test 3: Profile Debug build under ANTS. Message box shows about 150 ticks difference.

From this it appears that ANTS is actually causing the timing or execution of the code segment to change. IMHO, that's awful.

Lee

Robert C

Hi,

It's not whether it's a release or debug build that makes the difference - it's that you're running it inside a debugger (perfectly possible on a release build, you just get less useful information :-p).

Try running it completely outside of Visual Studio, or else use the Debug -> "Start Without Debugging" option in VS.

I think you'll find it's not ANTS interfering, it's the VS debugger :-). (This only applies to exceptions - in code flow that isn't heavy on exceptions, the VS debugger has a much lower impact)

Robert