[Python-Dev] New branch for r23c2 work (original) (raw)

Skip Montanaro skip@pobox.com
Mon, 21 Jul 2003 21:48:09 -0500 

Skip> It looks like the Mac OS X implementation of getaddrinfo is just
Skip> dog slow.  I instrumented setipaddr with calls to gettimeofday()
Skip> to see how long different sections took.  It turns out that
Skip> getaddrinfo() is hideously slow:

Stuart> This would be hideously slow by design - Python is sitting idle
Stuart> while the lookupd directory is queried (you can tell as lookupd
Stuart> process is chewing CPU).

Yes, thanks for reminding me of that. I had forgotten that an external process is involved in name resolution.

Stuart> I don't think this should affect an Apple release - Python 2.2.0
Stuart> as shipped with OS X 10.2 has the same behavior.

I think we've concluded that it's okay to ship 2.3 with this problem unresolved, however I'm completely befuddled at the moment. I wrote this simple program:

#include <sys/time.h>
#include <sys/types.h>
#include <sys/socket.h>
#include <netdb.h>
#include <stdio.h>

int
main(int argc, char **argv) {
        int i;
        struct addrinfo hints, *res;
        int error;
        struct timeval t, u;

        hints.ai_family = AF_INET;
        hints.ai_socktype = SOCK_DGRAM;     /*dummy*/
        hints.ai_flags = AI_PASSIVE;

        printf("start\n");
        for (i=0; i<100; i++) {
                gettimeofday(&t, NULL);
                error = getaddrinfo(0, "0", &hints, &res);
                gettimeofday(&u, NULL);
                fprintf(stderr, "gtod: %.6f\n",
                        u.tv_sec-t.tv_sec+(u.tv_usec-t.tv_usec)*1e-6);
                freeaddrinfo(res);
        }
        printf("finish\n");
}

When run on my Mac, it takes between 2 and 7 microseconds per getaddrinfo call. The exact same instrumented call inside socketmodule.c:setipaddr at line 700 takes about 150 milliseconds per call. I tried eliminating the Py_{BEGIN,END}_ALLOW_THREADS calls as well as the ACQUIRE and RELEASE of the getaddrinfo lock. That had no effect on the call.

I also tweaked the compile like to run just the C preprocessor (gcc -E instead of gcc -g) and checked the output:

            ...
            hints.ai_family = af;
            hints.ai_socktype = 2;
            hints.ai_flags = 0x00000001;
            { PyThreadState *_save; _save = PyEval_SaveThread();
            PyThread_acquire_lock(netdb_lock, 1);
            gettimeofday(&t, 0);
            error = getaddrinfo(0, "0", &hints, &res);
            gettimeofday(&u, 0);
            fprintf((&__sF[2]), "gtod: %.6f\n",
                    u.tv_sec-t.tv_sec+(u.tv_usec-t.tv_usec)*1e-6);
            PyEval_RestoreThread(_save); }
            ...

otool -L run against both the test program and _socket.so indicate that both refer to just one shared library (/usr/lib/libSystem.B.dylib), so both should be calling the same routine.

Another little observation. I ran the getaddr program (with the loop cranked up to 10 million iterations) while the top command was running. The lookupd process didn't show on the radar at all. While running the Python script however, lookupd consumed about 50% of the cpu.

I've added this information to the tracker item.

Skip