Problem/Bug with Time summaries in ANTS 4!

Hello!

I have been a User of ANTS 3 the last years and just recently switched to lates version of ANTS 4 now. So far ANTS 4 is awesome because it is really much faster in profiling. However there is a significant change which makes it very hard to judge results in ANTS 4 for us.

In ANTS 3 we mostly used the Time(s) column (not the Time With Children column) to find out about the methods which consume the most time within the program.

In ANTS 4 I now wanted to do the same but I get very different results and the Time(s) column is not usable at all. I am not sure if there is a problem in calculations but it doesnt seem to be right.

Example: I have a method when I look in the code viewer at the following line, it looks like this:

21.493 seconds, 205 Hit Count, 0.105 Avg Time - DataRow[] adr = _dtWList.Select(sSQLWhere, "No");

If I now look at the summary above in the "Show method grids" the method is listed there with a Time (s) of 0,001s but with a Time With Children (s) of 21,494s.

So why does it count DataRow[] adr = _dtWList.Select(sSQLWhere, "No"); in ANTS 4 as a children function, while in ANTS 3 it was included in the Time (s) of the method - which would be correct in my eyes?

Due to this problem the whole Time (s) calculations for individual methods are totally wrong, and I can't really judge the longest mehtods anymore in ANTS 4? All Time (s) values in ANTS 4 are below 0.080s, which is not possible because I am having many methods that consume far more time without any children's?

Shouldn't the Time (s) column show the actual total time of the method excluding any child functions?

Is this a known problem? Or is it intentional to calculate e.g. DataTable.Selects as Childs in Methods?

Hope you can help, kind regards,
Oliver

Comments

  • The intended behaviour hasn't really changed between the two versions, but ANTS 4 is very much faster than ANTS 3 and we took advantage of that to capture much more detail about the application being profiled.

    The Time measurement is intended to be the time spent exclusively in a certain method, excluding any methods that it calls (framework or otherwise). However, ANTS 3 did not measure the time spent in methods without source by default, so these would be measured as part of the method that made the call: this made the Time measurement inaccurate in the older version of the profiler.

    Time with children is the actual overall amount of time spent running a method. It's the best indication of which methods 'feel slow'. You may want to play with the CPU/wallclock time setting depending on what your application is doing to get the best view of the results. ANTS 3 didn't have this option and always showed wallclock time.

    ANTS 4 does have a similar feature, you can set it to profile only methods with source, and it will show timings in the same way as before if you choose this option. However, as there is much less detail, there will be no indication of why a particular method is slower, and ANTS 4 doesn't have line-level timing support in this mode.

    We've added a much better way of exploring how functions relate to each other, though, in the form of the call graph. If you've found that the Select method is taking a lot of time, but want to relate it to your code, you can click the call graph icon next to the call and expand it upwards to find your methods: if it's called from many different places, you will see all of them drawn out as a tree and how much time each of your methods is spending in the Select call.
    Andrew Hunter
    Software Developer
    Red Gate Software Ltd.
  • I see but with the old version I just pin pointed big bottlenecks in a matter of seconds, just by sorting the methods by Time (s). Surely for more detailed optimisations the new way is much better...

    However since we are using many DataSet, XML functions from the framework ANTS 3 showed us all the the bottlenecks in the DataSet.Select statements etc. in a very easy way.

    So how could I change ANTS 4 to perform the same? So when I sort by time (s) it actually shows me how long a specific method performs including all code (especially all my dataset/framework calls) except child functions - thats how ANTS 3 did it... but I cant find any setting to make it same in ANTS 4 :(

    Thanks alot for the quick answer, kind regards,
    Oliver
  • We did some heavy benchmarking today and I have to say we always got back to ANTS 3, simply because finding the longest performing methods was a pain in ANTS 4.

    We don't need to optimize deep into the code (thus we dont need the call graphs as of yet), we just seek out the core functions and improved them through caching etc. With that we could reduce the time of the program code greatly.

    I really hope you can add this features for the time (s) back into ANTS 4... because at the moment the time(s) is not useful in any way, since it cuts all the time used for the framework functions away...

    Even though we love the speed of the new ANTS and everythig else... for us the upgrade was not worth it yet :(
  • Any news on this?
  • Hi Oliver,

    There’s not really any news as such because the timings are as they are supposed to be. I would like to clarify some things. Can I ask what you meant by “ANTS cuts all the time used for the framework functions away”. This isn't true - the profiler records all time taken for methods if you are profiling with the default option.

    The default profiling mode of ANTS 4 profiles all methods but the default display aims to reduce the amount of initial information by collapsing groups of methods without source in the Tree View (see text indicating collapsed node) and also hides them in the Methods grid by default. However, you can very easily see the time spent in all methods executed by changing the combo box display options on either view to ‘All Methods’.

    As Andrew previously mentioned, the time in self of a method is returned correctly in ANTS 4 as the SELECT method in itself takes no time to execute – it’s the time with children which is taking the time due to all the child framework methods being executed as a result of SELECT being called.

    A really easy way to see this in ANTS 4 is to select the region of time on the timeline you are most interested in i.e. the period of time where the SELECT command was executed and then returned and examining the performance data in the Tree View.

    You can easily see which methods are spending a great deal of time in themselves as well as the time with children. Simply toggling between showing Top Down (methods with source) and Top Down (any method) will help demonstrate where exactly the time is going even more precisely. You would also want to make sure that you are looking at ‘Wall Clock’ time rather than the default ‘CPU Time’ which ANTS 3 didn’t have and is the default in ANTS 4.

    Also note that if you have collapsed the methods in the Tree View without source (by having Top Down, methods with source) then it will give you the total Time in self of all the resulting child methods as a single value which sounds like it may be of interest to you combined with the SELECT time in self.

    We are planning to introduce another profiling mode in V5 which will be making an appearance relatively soon and will be akin to the default profiling mode of ANTS 3. This profiling mode will only profile methods with source at the line level and include any time spent in any resulting methods without source (e.g. framework, 3rd party methods; which won’t actually be profiled) in the initial calling methods time and time with children values as appropriate.

    I will post here when the V5 Early Access Program starts which will also provide some basic support for Windows 7.

    Kind Regards,

    Stephen
  • There’s not really any news as such because the timings are as they are supposed to be. I would like to clarify some things. Can I ask what you meant by “ANTS cuts all the time used for the framework functions away”. This isn't true - the profiler records all time taken for methods if you are profiling with the default option.
    Well it is true if you look at the Time(s) column (not the Times with childs column!). In Ants 3 the Time(s) column showed the complete execution time of a method including framework calls but excluding your own child functions (that is exactly what we are interested in - how long takes the longest method and how can I optimize them).

    Surely you can now use the "Time with childs column" but there is a big problem associated with it -> first I have to walk down the whole tree to find the functions which only has framework calls left and no other child functions - thats very time consuming in our case.

    In ANTS 3 I simply sorted by Time(s) and got the longest performing methods without having to worry about any child functions.
    But since ANTS 4 sees all the internal framework calls as child functions you really don't see how long a specific method takes you in the Time(s) column... so thats why the Time(s) is mostly below 0.001s anyway and not of any use at all...

    I hope you understand what we need and why for that Ants3 is much better now to use .

    Hopefully you can bring an option back in Version 5 to also calculate the framework functions in the Time(s) column again, because as of yet we don't use Ants 4, even though its much faster and better overall.
Sign In or Register to comment.