too many futex syscalls

[Martin Pool]

strace on bzr reveals we do many futex syscalls during typical operations.

It's believed, but not certain, that this is due to non-top-level import statements, for which Python uses an 'import lock' separate from the GIL. Moving them to top-level imports, or lazy imports, or at least into less-hot functions may help, and may reduce overhead in other ways.

It's also surprising that we're seeing futex calls at all, since they are documented (futex(7)) to be entirely in userspace when uncontested. This may mean that there actually is contention on the lock from some other thread, or that there is a bug in how Python is using the futex.

[Martin Pool (mbp)]

A simple invocation of python shows them apparently being hit at startup and on imports:

mbp@hope% strace -e trace=futex python -c import\ pdb -c import\ pdb
futex(0x816a048, FUTEX_WAKE, 1) = 0
futex(0x816a048, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x818bd00, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0xb7e98a6c, FUTEX_WAKE, 2147483647) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0xb7ec9070, FUTEX_WAKE, 2147483647) = 0
futex(0x8171df8, FUTEX_WAKE, 1) = 0
futex(0x818bd00, FUTEX_WAKE, 1) = 0
futex(0x816a048, FUTEX_WAKE, 1) = 0
futex(0x816a048, FUTEX_WAKE, 1) = 0
futex(0x816a048, FUTEX_WAKE, 1) = 0

mbp@hope% strace -e trace=futex python
futex(0x816a038, FUTEX_WAKE, 1) = 0
futex(0x816a038, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0x818bcf0, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0xb7f76a6c, FUTEX_WAKE, 2147483647) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
Python 2.5.1 (r251:54863, Sep 11 2007, 23:45:37)
[GCC 4.1.3 20070831 (prerelease) (Ubuntu 4.1.2-16ubuntu1)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
futex(0x8171de8, FUTEX_WAKE, 1) = 0
futex(0xb7fa7070, FUTEX_WAKE, 2147483647) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
>>> import pdb
futex(0x81cbb98, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
>>> import pdb
futex(0x81cbb98, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
>>> import pdb
futex(0x81cbb98, FUTEX_WAKE, 1) = 0
futex(0x8171de8, FUTEX_WAKE, 1) = 0
>>> futex(0x81cbb98, FUTEX_WAKE, 1) = 0

futex(0x818bcf0, FUTEX_WAKE, 1) = 0
futex(0x816a038, FUTEX_WAKE, 1) = 0
futex(0x816a038, FUTEX_WAKE, 1) = 0
futex(0x816a038, FUTEX_WAKE, 1) = 0
Process 7104 detached

note that in the second case we can't be 100% sure this is due to the import rather than some consequence of the interactive session.

[Martin Pool (mbp)]

During python startup, pthread mutex locks and unlocks are called several times from a stack like this:
(gdb) bt
#0 0xb7f3e536 in pthread_mutex_lock () from /lib/tls/i686/cmov/libpthread.so.0
#1 0xb7f685ed in _dl_lookup_symbol_x () from /lib/ld-linux.so.2
#2 0xb7f69710 in _dl_relocate_object () from /lib/ld-linux.so.2
#3 0xb7f700bb in dl_open_worker () from /lib/ld-linux.so.2
#4 0xb7f6c016 in _dl_catch_error () from /lib/ld-linux.so.2
#5 0xb7f6f99e in _dl_open () from /lib/ld-linux.so.2
#6 0xb7f33c19 in ?? () from /lib/tls/i686/cmov/libdl.so.2
#7 0xbf999f97 in ?? ()
#8 0x80000002 in ?? ()
#9 0x080f101c in _PyImport_GetDynLoadFunc (
    fqname=0xbf999c30 "\227\237\231¿\002", shortname=0x0,
    pathname=0xb7c3b630 "U\211åS\203ì\004è", fp=0xb7c33b22)
    at ../Python/dynload_shlib.c:134
#10 0xb7f6c016 in _dl_catch_error () from /lib/ld-linux.so.2
#11 0xb7f342bc in ?? () from /lib/tls/i686/cmov/libdl.so.2
#12 0xb7f33b80 in ?? () from /lib/tls/i686/cmov/libdl.so.2
#13 0xbf999c30 in ?? ()
#14 0xb7f33b80 in ?? () from /lib/tls/i686/cmov/libdl.so.2
#15 0xb7f35ff4 in ?? () from /lib/tls/i686/cmov/libdl.so.2

then while loading pdb:

Breakpoint 4, 0xb7f3e536 in pthread_mutex_lock ()
   from /lib/tls/i686/cmov/libpthread.so.0
(gdb) bt
#0 0xb7f3e536 in pthread_mutex_lock () from /lib/tls/i686/cmov/libpthread.so.0
#1 0xb7f33d65 in dlsym () from /lib/tls/i686/cmov/libdl.so.2
#2 0x080f104d in _PyImport_GetDynLoadFunc (fqname=0xbf991097 "strop",
    shortname=0xbf991097 "strop",
    pathname=0xbf990027 "/usr/lib/python2.5/lib-dynload/strop.so",
    fp=0x81d6e08) at ../Python/dynload_shlib.c:145
#3 0x080e1a0a in _PyImport_LoadDynamicModule (name=0xbf991097 "strop",
    pathname=0xbf990027 "/usr/lib/python2.5/lib-dynload/strop.so",
    fp=0x81d6e08) at ../Python/importdl.c:42
#4 0x080df6d5 in load_module (name=0xbf991097 "strop", fp=0xbf98fe72,
    buf=0xbf990027 "/usr/lib/python2.5/lib-dynload/strop.so", type=3,
    loader=0x81e91a0) at ../Python/import.c:1758
#5 0x080df98b in import_submodule (mod=0x8146678, subname=0xbf991097 "strop",
    fullname=0xbf991097 "strop") at ../Python/import.c:2400
#6 0x080dfe3e in load_next (mod=0x8146678, altmod=0x8146678,
    p_name=<value optimized out>, buf=0xbf991097 "strop", p_buflen=0xbf991090)
    at ../Python/import.c:2220
#7 0x080e0068 in import_module_level (name=0x0, globals=0xb7d662b4,
    locals=<value optimized out>, fromlist=0xb7d64e64, level=-1)
    at ../Python/import.c:2001
#8 0x080e04f7 in PyImport_ImportModuleLevel (name=0xb7d66274 "strop",
    globals=0xb7d4edfc, locals=0xb7d4edfc, fromlist=0xb7d64e64, level=-1)
    at ../Python/import.c:2072
#9 0x080c1db4 in builtin___import__ (self=0x0, args=0xb7d67144, kwds=0x0)
    at ../Python/bltinmodule.c:47
#10 0x0805c9e7 in PyObject_Call (func=0x81e91a0, arg=0xb7d67144, kw=0x0)
    at ../Objects/abstract.c:1860
#11 0x080c232c in PyEval_CallObjectWithKeywords (func=0xb7d86e6c,
    arg=0xb7d67144, kw=0x0) at ../Python/ceval.c:3433
#12 0x080c4a9d in PyEval_EvalFrameEx (f=0x81d4d74, throwflag=0)
    at ../Python/ceval.c:2063
#13 0x080ca115 in PyEval_EvalCodeEx (co=0xb7d654e8, globals=0xb7d4edfc,
    locals=0xb7d4edfc, args=0x0, argcou...

[Martin Pool (mbp)]

To pound this just a little more:

>>> print timeit.Timer('import bzrlib; bzrlib.__version__').repeat()
[1.7602419853210449, 1.6976041793823242, 1.6759340763092041]
>>> print timeit.Timer('bzrlib.__version__', 'import bzrlib;').repeat()
[0.21311306953430176, 0.21236085891723633, 0.22443580627441406]
>>> print timeit.Timer('import bzrlib').repeat()
[1.5148138999938965, 1.4960010051727295, 1.4763419628143311]

so the import statement, when the module is already loaded, seems to take 1.5ms; it'd be worth eliminating them from anything like an inner loop. Running each of these under strace shows that there is indeed a futex syscall per import and for these benchmarks they take 100.00% of the system time.

[Robert Collins (lifeless)]

I think we should close this bug: its a general 'stuff is slow' bug, but very outdated. General profiling can show these things from time to time, and we've already changed our coding style to avoid inner loop imports.

[Martin Pool (mbp)]

I don't know if we'll fix this soon but I'd only consider it fixed when we
properly understand why.

On Sep 28, 2009 10:20 AM, "Robert Collins" <email address hidden>
wrote:

I think we should close this bug: its a general 'stuff is slow' bug, but
very outdated. General profiling can show these things from time to
time, and we've already changed our coding style to avoid inner loop
imports.

-- too many futex syscalls https://bugs.launchpad.net/bugs/140834
You received this bug notification because you are a member of bzr-core,
which is subscribed to Bazaar.