Uploaded image for project: 'WiredTiger'
  1. WiredTiger
  2. WT-1539

Seeing Poor Performance with test_async01.py

XMLWordPrintableJSON

    • Type: Icon: Task Task
    • Resolution: Done
    • None
    • Affects Version/s: None
    • Component/s: None
    • Labels:

      Mark Benvenuto and Jonathan Reams reported:

      We are running test_async01.py on Ubuntu 14.04 (Python 2.7.6), and Oracle Solaris 11.2 (2.7.9) but seeing these test cases take multiple minutes or even hours.

      The test completes but the stack traces make it look like a deadlock is going on. I looks like Thread 1 is holding the Python GIL while waiting for a free async operation. Thread 2 is waiting on the GIL while try to execute its ready async operation.

      If I change

      -    async_ops = nentries / 2
+    async_ops = nentries * 2

      the performance issues go away since the code never has to wait for an async operation to free up.

      I need your help in trying to understand why the test is performing so poorly, and any suggestions in how to improve things.

      See https://mci.10gen.com/version/wiredtiger_94e83e02d5a26a53f37c698b4dda862cfc5930f4

      mark

      Here are two of the 12 threads that are in the process on Solaris 11.2 with Python 2.7.9
Thread 2 (LWP    6        ):
#0  0xffff80ffbf4854b7 in __lwp_park () from /lib/64/libc.so.1
WT-1  0xffff80ffbf4780e6 in sema_wait_impl () from /lib/64/libc.so.1
WT-2  0xffff80ffbf47826c in sema_wait () from /lib/64/libc.so.1
WT-3  0xffff80ffbf46cc1c in sem_wait () from /lib/64/libc.so.1
WT-4  0x0000000000534c78 in PyThread_acquire_lock (lock=0x60e9a0, waitflag=waitflag@entry=1) at Python/thread_pthread.h:324
WT-5  0x00000000004ebb84 in PyEval_RestoreThread (tstate=tstate@entry=0x9ce690) at Python/ceval.c:357
WT-6  0x000000000051f148 in PyGILState_Ensure () at Python/pystate.c:611
WT-7  0xffff80ffbc54b59b in pythonAsyncCallback (cb=<optimized out>, asyncop=0x963580, opret=0, flags=0) at wiredtiger_wrap.c:3768
WT-8  0xffff80ffbc2e5853 in __async_worker_op (session=0x93b760, op=0x963580, worker=0xffff80ffbd64ef50) at src/async/async_worker.c:255
WT-9  0xffff80ffbc2e5a31 in __wt_async_worker (arg=0x93b760) at src/async/async_worker.c:310
WT-10 0xffff80ffbf4851cd in _thrp_setup () from /lib/64/libc.so.1
WT-11 0xffff80ffbf485470 in ?? () from /lib/64/libc.so.1
WT-12 0x0000000000000000 in ?? ()

Thread 1 (LWP    1        ):
#0  0xffff80ffbf48e30a in __pollsys () from /lib/64/libc.so.1
WT-1  0xffff80ffbf476f79 in _pollsys () from /lib/64/libc.so.1
WT-2  0xffff80ffbf4343f9 in pselect () from /lib/64/libc.so.1
WT-3  0xffff80ffbf434878 in select () from /lib/64/libc.so.1
WT-4  0xffff80ffbc3812db in __wt_sleep (seconds=0, micro_seconds=10000) at src/os_posix/os_sleep.c:23
WT-5  0xffff80ffbc54eb56 in _wrap_Connection_async_new_op (self=<optimized out>, args=<optimized out>) at wiredtiger_wrap.c:7295
WT-6  0x00000000004f2aa1 in do_call (nk=<optimized out>, na=<optimized out>, pp_stack=0xffff80ffbfffe310, func=0xffff80ffbe472518) at Python/ceval.c:4248
WT-7  call_function (oparg=<optimized out>, pp_stack=0xffff80ffbfffe310) at Python/ceval.c:4056
WT-8  PyEval_EvalFrameEx (f=f@entry=0x92fe60, throwflag=throwflag@entry=0) at Python/ceval.c:2679
WT-9  0x00000000004f2758 in fast_function (nk=<optimized out>, na=1, n=<optimized out>, pp_stack=0xffff80ffbfffe470, func=0xffff80ffbe338488) at Python/ceval.c                                                                                :4119

            Assignee:
            donald.anderson@mongodb.com Donald Anderson
            Reporter:
            donald.anderson@mongodb.com Donald Anderson
            Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

              Created:
              Updated:
              Resolved: