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

[Jacob Ilsø Christensen]

Hi.

Thanks for the detailed answer. I will give these issues a bit more thought.

/Jacob

On 3/26/06, Rafael Teixeira <monoman at gmail.com> wrote:
> 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...
>