[Ironpython-users] clr.GetProfileData() exclusive time bug?

[Kuno Meyer]

Hi all,

 

I guess that the profiling framework built into IronPyhton as described in http://blogs.msdn.com/b/curth/archive/2009/03/29/an-ironpython-profiler.aspx does not any more work correcty. Consider the following code:

import clr
from System.Threading import Thread

def foo(): Thread.Sleep(1000)
def bar(): foo(); Thread.Sleep(1000)

if __name__ == '__main__':
    bar()

    # don't forget '-X:EnableProfiler'
    for i in clr.GetProfilerData():
        if not ('foo' in i.Name or 'bar' in i.Name or 'Sleep' in i.Name or 'module testProf' in i.Name):
            continue

        print i.Name, i.Calls, i.InclusiveTime, i.ExclusiveTime

 

It produces this output:

module testProfPy 1 20366333 20119848

def foo() 1 10106225 10103305
def bar() 1 20110991 20110649
type Thread: method: Sleep(Int32) 2 19990812 19990812

 

To my understanding, the exclusive times are not correct: Since neider foo() nor bar() do any work but just call Thread.Sleep(), their exclusive times should be close to 0. Or am I wrong?

 

The C# counterpart behaves different, but still a bit weird to me:

    class Program
    {
        static void Foo() { Thread.Sleep(1000); }
        static void Bar() { Foo(); Thread.Sleep(1000); }
        static void Main(string[] args) { Bar(); }
    }

 

It produces:

Function Name	Number of Calls	Elapsed Inclusive Time %	Elapsed Exclusive Time %	Avg Elapsed Inclusive Time	Avg Elapsed Exclusive Time	Module Name
System.Threading.Thread.Sleep(int32)	1	50.00	50.00	1'000.37	1'000.37	mscorlib.dll
testProf.Program.Bar()	1	99.99	49.99	2'000.61	1'000.25	testProf.exe
testProf.Program.Main(string[])	1	100.00	0.01	2'000.83	0.22	testProf.exe

The weird part is that Therad.Sleep() is only called once, and that Foo() never shows up (maybe we see here call inlining?), but other than that, it is clearly visible that the Main() method does not have any significant exclusive time.

 

Therefore, my assumption is that the Profiler class (in the IronPython codebase) is somewhat out of sync to the way IronPython handles function calls nowadays.

 

Regards,

Kuno

 

_______________________________________________
Ironpython-users mailing list
Ironpython-users@python.org
https://mail.python.org/mailman/listinfo/ironpython-users