Find threading.Lock's futex id

Question

I want to instrument a large Python project to be able to debug production issues that look like this:

23321 07:49:57.925037 futex(0x23b2c20, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
23321 07:50:12.435793 <... futex resumed> ) = 0

Here, a thread waited 14.4 seconds on some lock (or condition variable).

I don't know for sure if that lock was created in Python code or in some 3rd party C extension, but Python is statistically a good guess.

By the time I attached strace, this futex was already created. I suspect it was created during application start-up.

I'd like to poke threading.Lock() and threading.Condition() objects and find out their underlying futex id's.

At the very least I'd log these id's, so that later, if I have to strace a running application, I can resolve futex calls I see to something logical.

Instead of `strace` you can use [sysdig](http://www.sysdig.org/) - it's much more convenient tool for monitoring — AndreyT, Jun 15 '16 at 13:03
That's a good point, I should use better tools. Can you elaborate on the core question however --- how can I track futex or lock contention back to creation of that lock or it's logical function in source code? — Dima Tisnek, Jun 16 '16 at 09:10

score 2 · Answer 1 · answered Jun 15 '16 at 11:40

2

You can record program execution via rr, and then you may set conditional breakpoint like this:

b futex if $rdi==0x23b2c20

answered Jun 15 '16 at 11:40

AndreyT

1,449
1
15
28

Nice idea, but an overkill for me. The bug I'm after doesn't manifest itself immediately. If I were run the application under `rr`, I'm afraid sheer amount of IO `rr` would have to record would be beyond what I can handle. I doubt I can run this in production. Anyway if I can't find a better way, I may go with this. – Dima Tisnek Jun 15 '16 at 11:52
2

Also, you can use dynamic instrumentation tools such as: [frida](http://www.frida.re), [pin](https://software.intel.com/en-us/articles/pin-a-dynamic-binary-instrumentation-tool), [dyninst](http://www.dyninst.org/dyninst). Or you may override `futex` via `LD_PRELOAD`: [article1](http://samanbarghi.com/blog/2014/09/05/how-to-wrap-a-system-call-libc-function-in-linux), [article2](https://rafalcieslak.wordpress.com/2013/04/02/dynamic-linker-tricks-using-ld_preload-to-cheat-inject-features-and-investigate-programs/) – AndreyT Jun 15 '16 at 13:36

score 0 · Answer 2 · answered Jun 16 '16 at 12:31

I managed to hack something for Python2, here's a demo:

$ strace -T -e signal=none -e futex python2 test.py
futex(0x7f6da47be0a8, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000006>
('futex address', '0x55de8d1105b0')
futex(0x55de8d123a30, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, ffffffff) = 0 <0.000038>
futex(0x55de8d074bf0, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, ffffffff) = 0 <0.000032>
futex(0x55de8d074bf0, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, ffffffff) = 0 <0.000036>
before
futex(0x55de8d1105b0, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, ffffffff) = 0 <5.017658>
inside
+++ exited with 0 +++

Note that both Python and strace report same futex address, 0x55de8d1105b0

Code:

import threading
import time
import sys
import ctypes

l = threading.Lock()

if sys.getsizeof(l) == 48:
    OFFSET = 4  # debug build: next, prev, refcnt, type, payload(lock_lock, ...)
elif sys.getsizeof(l) == 32:
    OFFSET = 2  # normal build: refcnt, type, payload(lock_lock, ...)
else:
    assert 0, "Don't do this shit to me"

lp = ctypes.cast(id(l), ctypes.POINTER(ctypes.POINTER(ctypes.c_ubyte)))[OFFSET]

print("futex address", hex(ctypes.addressof(lp.contents)))


class holder(threading.Thread):
    def run(self):
        with l:
            time.sleep(5)


holder().start()

print("before")
with l:
    print("inside")

Find threading.Lock's futex id

2 Answers2