[IronPython] Bad performance calling .NET method

[Dino Viehland]

It looks like most of the perf problem here is actually the call to Unicode.Encoding.  There's an issue where we're not switching over from a sub-optimial (but quick to generate) code path to a more optimial (but slower to generate) code path when we're continually accessing members.  It's a trivial fix to make this work.  But I would suggest removing the call from the loop if it's perf sensitive anyway - you can store it in a global and access it there.

Moving Encoding.Unicode outside of the loop on my machine we were 14x slower than C#.  W/ a fix for the Unicode.Encoding issue, but leaving the get in, we are 23x slower.  W/o the fix we are ridiculously slower, I would guess it's like 5000x vs C# calling the empty method.  Your method probably does work though :)

At that point we're spending most of the time in the loop, iterating over the xrange, etc...  We'll eventually start optimizing that stuff away too but it's not a trivial fix.

From: users-bounces at lists.ironpython.com [mailto:users-bounces at lists.ironpython.com] On Behalf Of Laurion Burchall
Sent: Tuesday, April 20, 2010 1:46 PM
To: Discussion of IronPython
Subject: Re: [IronPython] Bad performance calling .NET method

In the case that affects me the code isn't global. The class looks like this:

class EseDBCursor(object):
    ...

    def __getitem__(self, key):
        with _EseTransaction(self._sesid):
            self._seekForKey(key)
            return self._retrieveCurrentRecordValue()

    def _makeKey(self, key):
       """Construct a key for the given value."""
       Api.MakeKey(self._sesid, self._tableid, str(key), Encoding.Unicode, MakeKeyGrbit.NewKey)

   def _seekForKey(self, key):
       """Seek for the specified key. A KeyError exception is raised if the key isn't found."""
       self._makeKey(key)
       if not Api.TrySeek(self._sesid, self._tableid, SeekGrbit.SeekEQ):
           raise KeyError('key \'%s\' was not found' % key)

I tried moving the call to Api.MakeKey into _seekForKey but that didn't improve things. It is definitely the call to Api.MakeKey that is slowing things down -- removing that one call speeds things up. The code that tests the performance looks like this:

def insertRetrieveTest():
    ...
    timer = Stopwatch.StartNew()
    for i in xrange(n):
        data = db[k]
    timer.Stop()
    ...

# Basic test first
insertRetrieveTest()
________________________________
From: users-bounces at lists.ironpython.com [users-bounces at lists.ironpython.com] on behalf of Dino Viehland [dinov at microsoft.com]
Sent: Tuesday, April 20, 2010 12:51 PM
To: Discussion of IronPython
Subject: Re: [IronPython]Bad performance calling .NET method
Is the perf problem only there when the code is global?  In general we don't try to optimize code which occurs at the top-level of a script - we assume the most significant work will occur inside of function definitions.  In this case the update to "i" through each loop iteration needs to update a global value in a dictionary rather than updating a local on the stack each time which is going to be much more expensive.  Also the reads from the globals instead of parameters will be much more expensive as well.  And while I doubt this is much of the perf problem you're also accessing the Unicode property on encoding each time through in the global case.  There's also the chance depending on what version of IronPython you're running on that we're staying in the interpreter.  I think on 2.6.1 we should compile the global loop eventually but it'll still be slower than the compiled function.

Is there a reason the top-level code needs to be efficient?

From: users-bounces at lists.ironpython.com [mailto:users-bounces at lists.ironpython.com] On Behalf Of Laurion Burchall
Sent: Tuesday, April 20, 2010 11:57 AM
To: Discussion of IronPython
Subject: Re: [IronPython] Bad performance calling .NET method

You were right about the structs. By creating a method with the same type of signature (struct, struct, string, Encoding, enumeration). I got the same slowdown in a trivial DLL. This is with the .NET 2.0 version of IP:

** First, the C# code:

namespace IronPythonInteropPerf
{
    using System.Text;

    public struct Struct1
    {
        internal int i;
    }

    public struct Struct2
    {
        internal int i;
    }

    public enum Enumeration
    {
        Foo,
    }

    public static class Interop
    {
        public static void A(Struct1 a, Struct2 b, string x, Encoding encoding, Enumeration e)
        {
        }
    }
}

** Now the IronPython test:

import System
import System.Diagnostics
import System.Text

from System.Diagnostics import Stopwatch
from System.Text import Encoding

import clr
clr.AddReferenceByPartialName('IronPythonInteropPerf')
from IronPythonInteropPerf import *

N = 1000000

a = Struct1()
b = Struct2()
c = 'hello'
d = Enumeration.Foo

stopwatch = Stopwatch.StartNew()
for i in xrange(N):
    Interop.A(a, b, c, Encoding.Unicode, d)
stopwatch.Stop()
print '    A: %s' % stopwatch.Elapsed

def foo(a1, a2, a3, a4, a5):
    stopwatch = Stopwatch.StartNew()
    for j in xrange(N):
        Interop.A(a1, a2, a3, a4, a5)
    stopwatch.Stop()
    print 'foo.A: %s' % stopwatch.Elapsed

foo(a, b, c, Encoding.Unicode, d)

** Note that I am calling Interop.A twice. This gives very different results -- the call from inside of function foo() is fast (11M calls/second) but the call from the script is slow (50K calls/second):

    A: 00:00:18.6063353
foo.A: 00:00:00.0894888

There isn't a caching effect at work either -- foo() is faster if I call it before the other code.
________________________________
From: users-bounces at lists.ironpython.com [users-bounces at lists.ironpython.com] on behalf of Dino Viehland [dinov at microsoft.com]
Sent: Tuesday, April 20, 2010 11:34 AM
To: Discussion of IronPython
Subject: Re: [IronPython]Bad performance calling .NET method
I assume something is going horribly wrong with our type checks.   Can you attach the repro?  Or at least are these just classes, or are any structs, or maybe weird classes like delegates?

And is this on .NET 2.0 or .NET 4.0?

From: users-bounces at lists.ironpython.com [mailto:users-bounces at lists.ironpython.com] On Behalf Of Laurion Burchall
Sent: Tuesday, April 20, 2010 2:11 AM
To: Discussion of IronPython
Subject: [IronPython] Bad performance calling .NET method

I am getting terrible performance invoking a C# method from IP. I have a static class called Api with this method:

  public static void MakeKey(JET_SESID sesid, JET_TABLEID tableid, string data, Encoding encoding, MakeKeyGrbit grbit)

When I call it directly from C# I get about 3M calls/second. In IronPython I get only 50,000 calls/second -- a 60X slowdown!

The method is overloaded. When I call these overloads I get good performance (~ 1M calls/second):
  public static void MakeKey(JET_SESID sesid, JET_TABLEID tableid, int data, MakeKeyGrbit grbit)
  public static void MakeKey(JET_SESID sesid, JET_TABLEID tableid, float data, MakeKeyGrbit grbit)
  public static void MakeKey(JET_SESID sesid, JET_TABLEID tableid, byte[] data, MakeKeyGrbit grbit)
(for the last overload I passed in the string turned into a byte array with Encoding.GetBytes())

Things I have tried that didn't help:
 - Changing the name of the method so it was unique.
 - Calling the method using Api.MakeKey.Overloads[...]
 - Calling other methods I have that take string arguments. They were fast.

When I profile the code the time shows up in mscorwks.dll (56%) and mscorlib.ni.dll (17%). IronPython is only 8% and my code is 6%.

Can anyone help me work out what is going wrong? I have a short, turn-key repro of this. MakeKey is a very commonly used method so having it be so slow is crippling.

thanks,
--Laurion


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.python.org/pipermail/ironpython-users/attachments/20100422/bec4d40b/attachment.html>