[Mono-dev] Questions about --profile=default:time

[Rafael Teixeira]

Hi Jacob,

On 3/24/06, Jacob Ilsø Christensen <jacobilsoe at gmail.com> wrote:
> Hi.
>
> I have a few questions about the --profile=default:time in mono. I
> have this program:
>
> ----
> using System.Threading;
>
> public class C
> {
>         public static void Main()
>         {
>                 AMethod();
>                 BMethod();
>         }
>
>         public static void AMethod()
>         {
>                 Thread.Sleep(1000);
>         }
>
>         public static void BMethod()
>         {
>                 Thread.Sleep(500);
>         }
> }
> ----
>
> This gives the attached profiler output. Among others these things puzzle me:
>
> * In:  "3.409       3    1.136   System.Object::runtime_invoke..." why
> does the profiler output a count of 3 when the lines below show 2
> calls? Is this due to the extra invocation show further up in the
> file?

Sure, a profiler counts a method each time it enters it, on any
instance or statically.

> * In: "1503.045       2  751.523
> System.Threading.Thread::Sleep(int)" AMethod actually spends around
> 1000 ms and BMethod 500 ms. What is the purpose of outputting 751.523
> as an average when the two methods do not share the time but just the
> number of calls?

Well most profilers just agregate results, as that consumes less
memory and time and is generally more useful for optimization
purposes. A profiler I wrote on for VB6,  in another life, collected
the raw data and post-processed to give chained averages, like how was
the average of the Sleep call inside AMethod and inside BMethod, but
that took a lot of post-processing and yielded a much larger set of
results to try to figure out where the bottlenecks are.

See that in that case, it is easier to simply use our minds and deduce
that if the mean time of AMethod is a little over 1000ms and BMethod a
little over 500ms, and both call Sleep, both are contributing equally
for the Sleep average. This is a constructed example, and profiling it
has little to add to what reading the code already tell us.

Profiling is really useful when trying to identify bottlenecks on
complex code heavily affected by the data it receives or the
interactions with the user or other pieces of the system. In that
case, averages and standard deviation are good guides to find the
culprits.

Profile MD launch for instance and you'll see how many threads do lots
of things, but some dependencies can't be avoided and thus force
sequential execution. Also some bottlenecks are beyond MD code into
the depths of GTK+ for instance, what makes them harder to overcome.

> Have I just misunderstood something, or is some information missing
> from the profiler output?

As I said, I think you are underestimating the poser of average times,
and the costs of having more detailed data both on producing and on
analizing it.

> /Jacob
>
>
> _______________________________________________
> Mono-devel-list mailing list
> Mono-devel-list at lists.ximian.com
> http://lists.ximian.com/mailman/listinfo/mono-devel-list
>
>
>
>


--
Rafael "Monoman" Teixeira
---------------------------------------
As I'm currently working a lot with Java and even fixing Java VMs
(JamVM/Kaffe) and GNU Classpath code, I think I may partly borrow the
title (Javaman) from my friend Bruno Souza and become the
MonoNJavaMan. Yeah, I may currently be crazier than usual...