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

[Jacob Ilsø Christensen]

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?

* 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?

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

/Jacob
-------------- next part --------------
Total time spent compiling 0 methods (sec): 0
Time(ms) Count   P/call(ms) Method name
########################
 1504.086       1  1504.086   .C::Main()
  Callers (with count) that contribute at least for 1%:
           1  100 % System.Object::runtime_invoke_void(object,intptr,intptr,intptr)
########################
 1504.091       1  1504.091   System.Object::runtime_invoke_void(object,intptr,intptr,intptr)
  Callers (with count) that contribute at least for 1%:
########################
 1502.971       2  751.486   System.Threading.Thread::Sleep_internal(int)
  Callers (with count) that contribute at least for 1%:
           2  100 % System.Threading.Thread::Sleep(int)
########################
 1503.045       2  751.523   System.Threading.Thread::Sleep(int)
  Callers (with count) that contribute at least for 1%:
           1  50 % .C::AMethod()
           1  50 % .C::BMethod()
########################
 1002.073       1  1002.073   .C::AMethod()
  Callers (with count) that contribute at least for 1%:
           1  100 % .C::Main()
########################
 501.762       1  501.762   .C::BMethod()
  Callers (with count) that contribute at least for 1%:
           1  100 % .C::Main()
########################
   2.885       1    2.885   System.Runtime.Remoting.Contexts.Context::.cctor()
  Callers (with count) that contribute at least for 1%:
           1  100 % System.Object::runtime_invoke_void(object,intptr,intptr,intptr)
########################
   3.409       3    1.136   System.Object::runtime_invoke_void(object,intptr,intptr,intptr)
  Callers (with count) that contribute at least for 1%:
           1  50 % .C::AMethod()
           1  50 % System.Runtime.Remoting.Contexts.Context::.cctor()
########################
   1.359       1    1.359   System.Collections.Hashtable::.ctor()
  Callers (with count) that contribute at least for 1%:
           1  100 % System.Runtime.Remoting.Contexts.Context::.cctor()
########################
   1.293       1    1.293   System.Collections.Hashtable::.ctor(int,single)
  Callers (with count) that contribute at least for 1%:
           1  100 % System.Collections.Hashtable::.ctor()
Total number of calls: 59

Allocation profiler
Total mem Method
Total memory allocated: 0 KB