Repository: sumerc/yappi (language: python)

Issue:
Overlapping task and coroutine can confuse `yappi`
It seems `yappi` gets confused when a coroutine is scheduled as a task and awaited from the same function and the task returns first. If the task returns first the timings from the explicit await on the coroutine get lost (still contributes to the call count):
```python
from asyncio import create_task, run, sleep
import yappi
yappi.set_clock_type('wall')

async def test(d=0):
    t = create_task(sleep(5+d))
    await sleep(5)
    await t

for d in [-2, 0, 2]:
    with yappi.run():
        run(test(d))
    print(f'#### d={d} (expect tsub ~ ttot ~ 2*5+d={2*5+d}):')  # but we get 5-d if d < 0
    yappi.get_func_stats(filter_callback=lambda x: yappi.func_matches(x, [sleep])).print_all()
    yappi.clear_stats()
```


Discussion / hints:

Fix patch:
diff --git a/yappi/_yappi.c b/yappi/_yappi.c
index 343130d..cceadd8 100644
--- a/yappi/_yappi.c
+++ b/yappi/_yappi.c
@@ -859,6 +859,18 @@ _get_frame_elapsed(void)
     return result;
 }
 
+static void
+_print_coros(_pit *cp)
+{
+    _coro *coro;
+
+    printf("Printing coroutines on %s...\n", PyStr_AS_CSTRING(cp->name));
+    coro = cp->coroutines;
+    while(coro) {
+        printf("CORO %s %p %lld\n", PyStr_AS_CSTRING(cp->name), coro->frame, coro->t0);
+        coro = (_coro *)coro->next;
+    }
+}
 
 static int 
 _coro_enter(_pit *cp, PyFrameObject *frame)
@@ -879,7 +891,7 @@ _coro_enter(_pit *cp, PyFrameObject *frame)
         coro = (_coro *)coro->next;
     }
 
-    //printf("CORO ENTER %s %p\n", PyStr_AS_CSTRING(cp->name), frame);
+    //printf("CORO ENTER %s %p %lld\n", PyStr_AS_CSTRING(cp->name), frame, tickcount());
 
     coro = ymalloc(sizeof(_coro));
     if (!coro) {
@@ -909,7 +921,7 @@ _coro_exit(_pit *cp, PyFrameObject *frame)
             return 0;
     }
 
-    //printf("CORO EXIT %s %p\n", PyStr_AS_CSTRING(cp->name), frame);
+    //printf("CORO EXIT %s %p %lld\n", PyStr_AS_CSTRING(cp->name), frame, tickcount());
 
     prev = NULL;
     coro = cp->coroutines;
@@ -919,9 +931,10 @@ _coro_exit(_pit *cp, PyFrameObject *frame)
             if (prev) {
                 prev->next = coro->next;
             } else {
-                cp->coroutines = NULL;
+                cp->coroutines = (_coro *)coro->next;
             }
             yfree(coro);
+            //printf("CORO EXIT(elapsed) %s %p %lld\n", PyStr_AS_CSTRING(cp->name), frame, tickcount()-_t0);
             return tickcount() - _t0;
         }
         prev = coro;
@@ -2179,6 +2192,7 @@ init_yappi(void)
     test_timings = NULL;
 
     SUPPRESS_WARNING(_DebugPrintObjects);
+    SUPPRESS_WARNING(_print_coros);
 
     if (!_init_profiler()) {
         PyErr_SetString(YappiProfileError, "profiler cannot be initialized.");


Test patch:
diff --git a/tests/test_asyncio.py b/tests/test_asyncio.py
index 4ac4c5f..b547674 100644
--- a/tests/test_asyncio.py
+++ b/tests/test_asyncio.py
@@ -12,6 +12,33 @@ def async_sleep(sec):
 
 class SingleThreadTests(YappiUnitTestCase):
 
+    def test_issue58(self):
+
+        @asyncio.coroutine
+        def mt(d):
+            t = asyncio.Task(async_sleep(3 + d))
+            yield from async_sleep(3)
+            yield from t
+
+        yappi.set_clock_type('wall')
+
+        with yappi.run():
+            asyncio.get_event_loop().run_until_complete(mt(-2))
+        r1 = '''
+        async_sleep 2      0  4.005451  2.002725
+        '''
+        stats = yappi.get_func_stats()
+        self.assert_traces_almost_equal(r1, stats)
+        yappi.clear_stats()
+
+        with yappi.run():
+            asyncio.get_event_loop().run_until_complete(mt(1))
+        r1 = '''
+        async_sleep 2      0  7.006886  3.503443
+        '''
+        stats = yappi.get_func_stats()
+        self.assert_traces_almost_equal(r1, stats)
+
     def test_recursive_coroutine(self):
 
         @asyncio.coroutine