For the sake of profiling ASGI apps, it would be really helpful if there was a way to

Hi <a class="user-mention notranslate" data-hovercard-type="user" data-hovercard-url="

using <a class="user-mention notranslate" data-hovercard-type="user" data

<a class="user-mention notranslate" data-hovercard-type="user" data-hovercard-url="/us

Coroutine-aware wall-time profiling ,about sumerc/yappi

Comments (46)

sumerc commented on September 24, 2024 7

Hi @dmontagu,
I have been able to run your test case successfully! (I have renamed the test file to be test_asyncio_context_vars.py and added it to the coroutine-profiling branch.). A new API has been written and first tests indicate it is stable. I am extensively writing test cases, it would be nice if you can also get a look at it. The only change I needed to do is to change set_context_id_callback to the new API: set_tag_callback. So, with the new version of Yappi you can simply tag any function regardless of thread or coroutine. I hope you can start using it in FastAPI and tell me about the progress.

from yappi.

sumerc commented on September 24, 2024 5

Ok. This will hopefully be my final update:
I have done few changes related to get_func_stats() again: implemented filtering on C side and moved same tags into same hashtables. With these improvements, now 1000 concurrent requests is being done in ~3.7 secs! which seems to indicate 10x improvement. I think we no more need filtering on clear_stats() as the number of tags does not affect performance anymore while filtering on tag.(as we use a hashtable underneath.)

Anyway, I will be finalizing the tests and hopefully will be releasing a new version which includes lots of new, exciting stuff. Looking forward to your latest feedback and use cases in FastAPI, too, of course.

from yappi.

dmontagu commented on September 24, 2024 3

I am not sure if 2 has any benefits when 3 is available. Do you really think it is possible to have a low 2 and high 3? or high 2 and low 3?

It should never be possible to have a high 2 and low 3.

However, the difference between low-2-high-3 and high-2-high-3 can be significant.

You can confirm low-2-high-3 and high-2-high-3 is possible by converting the function in my example above:

async def func_to_profile(context_id: int) -> float:
    yappi_request_id.set(context_id)

    start = time.time()
    await asyncio.sleep(1)
    end = time.time()

    assert yappi_request_id.get() == context_id

    return end - start

async def func_to_profile(context_id: int) -> float:
    yappi_request_id.set(context_id)

    start = time.time()
    time.sleep(1)  # <-------------
    end = time.time()

    assert yappi_request_id.get() == context_id

    return end - start

Before the change, you get low-2-high-3; after the change you get high-2-high-3.

While this is one of the most basic possible examples, this specific issue has been brought up in multiple FastAPI issues. There are also plenty of other situations (especially when depending on libraries written without asyncio in mind) where this can become a problem, but be harder to identify.

High-2-high-3 means there are calls blocking your event loop, and potentially massively reducing your ability to handle concurrent requests.

A common example of a mistake that could lead to this would be making use of the requests library to perform a webhook action inside an async def endpoint. If you did this, your server process would be entirely non-responsive while waiting for the response from the webhook. This could easily take your maximum requests-handled-per-second from 10,000 down to 10(!). (And could easily be fixed, once identified, by using an async alternative such as httpx.)

Detecting this is especially important because even "small" amounts of blocking IO (to the tune of 10+ms per request) will have a catastrophic impact on the maximum number of requests you can handle per second.

Typically, a low-1-high-2-high-3 situation means the problem is in the python code you've written.

Low-2-high-3 means that you aren't wasting compute resources waiting on a blocked call, but you are still taking a long time to return a response. For example, maybe you are asynchronously executing a database query which could benefit from a (missing) index. Your python server may not be wasting any time or compute, but you would still be getting a response to your users slower than you may like. How important this is would depend on the context and magnitude of the delay, but without an async-friendly profiler it may be difficult to discover precisely which call is causing the delay.

Typically, a low-1-low-2-high-3 situation means the problem is NOT in the python code you've written, but in something you are asynchronously accessing.

from yappi.

sumerc commented on September 24, 2024 2

Relevant PR merged to master. Closing this gigantic issue...

from yappi.

dmontagu commented on September 24, 2024 1

Yes, multiple threads in a single event loop is relatively common in an ASGI context -- it is basically the only way you can perform blocking IO (e.g., using blocking libraries, such as a non-async elasticsearch client or similar) inside an async def function without blocking the server's event loop.

Starlette, one of the more popular async frameworks has a built in function that allows you to basically convert a blocking, non-async function into a non-blocking call by running it in a threadpool: run_in_threadpool. It is defined here: https://github.com/encode/starlette/blob/824cede0dbb10c5851460649687f0ed3e338a41f/starlette/concurrency.py#L14

(For context, FastAPI (the project where the issue was initially raised) is basically a framework built on top of starlette oriented around high-speed development and OpenAPI compatibility. So all of the examples related to Starlette are basically directly relevant to FastAPI too.)

While the run_in_threadpool can be used anywhere to basically make a blocking IO call non-blcoking, on a more fundamental level, Starlette actually uses the run_in_threadpool function to automatically convert endpoint functions that are not defined as coroutines (i.e., using async def) into coroutines by use of a function called request_response: https://github.com/encode/starlette/blob/824cede0dbb10c5851460649687f0ed3e338a41f/starlette/routing.py#L31. In particular, since sqlalchemy is non-async, basically any ASGI server relying on sqlalchemy for ORM needs to make use of this approach to prevent the server from blocking. (This is probably the most common reason I've seen for wanting to use threading in an ASGI context, but in general, even if it isn't a fundamental part of your server architecture, it is not uncommon that you'd have some handful of endpoints with blocking IO that need to be executed in separate threads.)

Another common example I've seen is performing password hashing/checking for login in a threadpool, since most cryptography libraries will release the GIL while hashing a password; this is critical to prevent the server from becoming non-responsive while someone is logging in (since, for security reasons, password hashing should take a macroscopic amount of time). In this case, you'd use the run_in_threadpool function directly in "user" code, inside your password-checking logic.

More rarely, it can be helpful to actually use a ProcessPoolExecutor, rather than a ThreadPoolExecutor (specifically when CPU bound), but I would imagine that would be harder/impossible for yappi to profile properly. Fortunately, given how much rarer that is, I think it is fine to require such situations to be handled in a more manual way.

That said, at least in the context of profiling a web application, I don't think one needs to be very directly concerned about the thread ID; typically more important would just be tracking the request ID (what I'm storing in the ContextVar above). But you would frequently want to be able to merge the results from multiple threads, if they all shared a request-based context id.

(Obviously it would also be fine if you could track both the async context id and the thread id. And maybe this is possible already since it looks like the _ctx struct has fields for both the callback-based id and the actual os thread id.)

from yappi.

sumerc commented on September 24, 2024 1

using @dmontagu snippet from here and coroutine-profiling branch (installed with pipenv install git+https://github.com/sumerc/yappi.git@coroutine-profiling#egg=yappi)

I get
Task 1:
    Actual wall time: 1001.941ms
     Yappi wall time:    0.068ms
Task 2:
    Actual wall time: 1001.953ms
     Yappi wall time:    0.050ms
Task 3:
    Actual wall time: 1001.936ms
     Yappi wall time:    0.036ms

Yes. I have not tested it I will share my tests here for you to verify in a next comment. But I know the problem here. The problem is when you set the context_id in the func_to_profile it becomes too late because yappi already implicitly calls get_context_id and gets a value and then you set the context id. I am not sure if this has practical problems on your side. We can talk about that too but here is a working version with the current branch:

import asyncio
import time
from contextvars import ContextVar

import yappi

yappi_request_id = ContextVar('yappi_request_id')
yappi_request_id.set(-1)


def get_context_id() -> int:
    try:
        return yappi_request_id.get()
    except LookupError:
        return -2


yappi.set_context_id_callback(get_context_id)


async def _wrapper(context_id: int) -> float:
    yappi_request_id.set(context_id)

    assert yappi_request_id.get() == context_id

    return await func_to_profile()


async def func_to_profile() -> float:

    start = time.time()
    await asyncio.sleep(1)
    end = time.time()

    return end - start


yappi.set_clock_type("wall")
yappi.start()


async def main():
    context_ids = [1, 2, 3]
    tasks = [_wrapper(i) for i in context_ids]
    actual_durations = await asyncio.gather(*tasks)
    yappi_durations = [
        yappi.get_func_stats({
            "name": "func_to_profile",
            "ctx_id": i
        }).pop().ttot for i in context_ids
    ]
    for context_id, actual_duration, yappi_duration in zip(
        context_ids, actual_durations, yappi_durations
    ):
        print(f"Task {context_id}:")
        print(f"    Actual wall time: {actual_duration * 1000:>8.3f}ms")
        print(f"     Yappi wall time: {yappi_duration * 1000:>8.3f}ms")


if __name__ == '__main__':
    asyncio.run(main())
'''
Task 1:
    Actual wall time: 1001.781ms
     Yappi wall time: 1001.787ms
Task 2:
    Actual wall time: 1001.832ms
     Yappi wall time: 1001.835ms
Task 3:
    Actual wall time: 1001.859ms
     Yappi wall time: 1001.862ms
'''

So I have just added a wrapper() function that sets the callback and calls the real function. If this will be an issue on your side, we need to think about it but I don't have any quick solution to this problem.

from yappi.

dmontagu commented on September 24, 2024 1

@sumerc Awesome! This is not a problem at all; we'd be setting the contextvar's value (and therefore the context id) in a cheap middleware which wouldn't need to be profiled. Basically equivalent to the wrapper you've written, but integrated neatly with the server.

from yappi.

sm-Fifteen commented on September 24, 2024 1

Yes yes. The issue is not related with context vars anymore. So, you can already use set_ctx_callback_id API to arrange your context. The issue we are trying to solve is: correct wall-time profiling of coroutines: currently whenever a context switch happens, the profiler receives call_leave event which makes the profiler thinks that the coroutine has ended, the test branch aims to fix that.

Shouldn't the issue be renamed into something like "Accurate wall-time for coroutines" or something along those lines?

from yappi.

belm0 commented on September 24, 2024 1

For what it's worth, here is a performance timer I made for Trio tasks. It measures wall time while the task is executing (i.e. excluding trio.sleep(), async I/O, etc.).

def trio_perf_counter():
    """Trio task-local equivalent of time.perf_counter().

    For the current Trio task, return the value (in fractional seconds) of a
    performance counter, i.e. a clock with the highest available resolution to
    measure a short duration.  It includes time elapsed during time.sleep,
    but not trio.sleep.  The reference point of the returned value is
    undefined, so that only the difference between the results of consecutive
    calls is valid.
    ...

(see https://github.com/belm0/perf-timer#trio_perf_counter and source)

The implementation uses time.perf_counter() under the hood, but in theory could use other counters from the time module like process_time() or thread_time(). There's significantly more overhead in using anything other than perf_counter(), and since async Python programs are ideally single-thread and not running on a system with high CPU contention (this applies doubly if you are trying to profile a program), perf_counter() has been good enough for my use cases.

This wasn't too hard to implement for Trio, which has an instrumentation API. If you're able to implement something equivalent for asyncio, I'd like to add it to my PerfTimer package. I'm aware of one attempt which no longer works with recent Python versions.

from yappi.

sumerc commented on September 24, 2024 1

edit I thought it was pycharm but I got the same running directly the script in a terminal.
now should I run it in pycharm debugger I got this
edit2: reading the below, I thought pydedvd breakpoints might cause this but I have no breakpoints set

Please do not use set_context_id_callback instead use set_tag_callback. I have puit this internal error 15 as an assert, now you hit that I changed it to an actual assert:)

The other problem regarding importing sys is related with having yappi still running while the module is being unloaded. I will fix that but it is mostly cosmetic. To fix that: simply call yappi.stop(). Here is a fully working code for you to play with:

import asyncio
import time
from contextvars import ContextVar

import sys
import yappi

yappi_request_id = ContextVar('yappi_request_id')
yappi_request_id.set(-1)


def get_context_id() -> int:
    try:
        return yappi_request_id.get()
    except LookupError:
        return -2


yappi.set_tag_callback(get_context_id)


async def _wrapper(context_id: int) -> float:
    yappi_request_id.set(context_id)

    assert yappi_request_id.get() == context_id

    return await func_to_profile()


async def func_to_profile() -> float:

    start = time.time()
    await asyncio.sleep(1)
    end = time.time()

    return end - start


yappi.set_clock_type("wall")
yappi.start()


async def main():
    context_ids = [1, 2, 3]
    tasks = [_wrapper(i) for i in context_ids]
    actual_durations = await asyncio.gather(*tasks)
    yappi_durations = [
        yappi.get_func_stats({
            "name": "func_to_profile",
            "tag": i
        }).pop().ttot for i in context_ids
    ]
    for context_id, actual_duration, yappi_duration in zip(
        context_ids, actual_durations, yappi_durations
    ):
        print(f"Task {context_id}:")
        print(f"    Actual wall time: {actual_duration * 1000:>8.3f}ms")
        print(f"     Yappi wall time: {yappi_duration * 1000:>8.3f}ms")


if __name__ == '__main__':
    asyncio.run(main())
    yappi.stop()

from yappi.

euri10 commented on September 24, 2024 1

using the snippet above I got it working in a terminal, however should I run it in pycharm I got this huge wall of warnings, sorry if I'm doing (again) something silly !

edit sorry I got the same warnings in pycharm or terminal, was trying another script
edit2 ok silly me the message is quite explicit, change to yappi_request_id.set(-10) solves the warning

from debugger in pycharm

/home/lotso/.local/share/virtualenvs/rapidFastAPItest-eKoLkZ3A/bin/python /home/lotso/PycharmProjects/rapidFastAPItest/fastapi_q/701_profiling_wall.py
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
Task 1:
    Actual wall time: 1009.331ms
     Yappi wall time: 1009.465ms
Task 2:
    Actual wall time: 1009.300ms
     Yappi wall time: 1009.380ms
Task 3:
    Actual wall time: 1011.008ms
     Yappi wall time: 1011.088ms
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.
[+] [yappi-info] -1 cannot be set as a tag. it is reserved and will not have any effect.

Process finished with exit code 0

from yappi.

dmontagu commented on September 24, 2024

Actually, I think we've got this working now using the set_context_id_callback, but the biggest outstanding issue is how to track time spent awaiting async calls.

Any ideas about how to handle this? Setting yappi.set_clock_type("wall") doesn't seem to work in the intended way. I'm not sure how hard it would be to get it to work properly though, given the complexities associated with the asyncio event loop.

from yappi.

sumerc commented on September 24, 2024

Hi,

First of all, profiling async. code was on top of my todo list. So, I am a bit lucky to have you guys trying to solve similar issue with practical needs:) . I would happily accept any PRs and try my best helping any kind of issue regarding profiling async. code.

Actually what I would be suggesting: set_context_id_cbk() like you have already figured out. We have previously solved similar problem in greenlet-profiler. See here: https://emptysqua.re/blog/greenletprofiler/

Now, you seem to have lots of background on the issue and I am pretty new to this contextvars. Could you elaborate the problem more? I remember we have done similar things in the past by simply shifting some time values back and forth but I really do not remember. Could you explain the problem in a simple example?

from yappi.

sumerc commented on September 24, 2024

I think I remember the code: I mentioned it here: fastapi/fastapi#701 (comment).

I might have misunderstood the problem, let's verify.

from yappi.

dmontagu commented on September 24, 2024

@sumerc
Here's a self contained example that should work in python 3.7:

import asyncio
import time
from contextvars import ContextVar

import yappi

yappi_request_id = ContextVar('yappi_request_id')
yappi_request_id.set(-1)


def get_context_id() -> int:
    try:
        return yappi_request_id.get()
    except LookupError:
        return -2


yappi.set_context_id_callback(get_context_id)


async def func_to_profile(context_id: int) -> float:
    yappi_request_id.set(context_id)

    start = time.time()
    await asyncio.sleep(1)
    end = time.time()

    assert yappi_request_id.get() == context_id

    return end - start


yappi.set_clock_type("wall")
yappi.start()


async def main():
    context_ids = [1, 2, 3]
    tasks = [func_to_profile(i) for i in context_ids]
    actual_durations = await asyncio.gather(*tasks)
    yappi_durations = [yappi.get_func_stats({"name": "func_to_profile", "ctx_id": i}).pop().ttot for i in context_ids]
    for context_id, actual_duration, yappi_duration in zip(context_ids, actual_durations, yappi_durations):
        print(f"Task {context_id}:")
        print(f"    Actual wall time: {actual_duration * 1000:>8.3f}ms")
        print(f"     Yappi wall time: {yappi_duration * 1000:>8.3f}ms")


if __name__ == '__main__':
    asyncio.run(main())

"""
Task 1:
    Actual wall time: 1005.207ms
     Yappi wall time:    0.059ms
Task 2:
    Actual wall time: 1005.039ms
     Yappi wall time:    0.034ms
Task 3:
    Actual wall time: 1004.950ms
     Yappi wall time:    0.090ms
"""

If I understand correctly, if things were behaving properly, "Yappi wall time" should be larger than "Actual wall time".

from yappi.

dmontagu commented on September 24, 2024

I'm trying to read through how you got things working with greenlet, but I'm having a hard time figuring out how to get it to work with asyncio. I'll update if/when I make more progress; please let me know though if you think you see how to make it work.

from yappi.

dmontagu commented on September 24, 2024

@sumerc Oh, I think I see what's going on -- the point is that the greenlet profiler has a slightly modified version of yappi that does the pausing. (I didn't realize you had linked me to a different repo!) Am I understanding that correctly?

Is your proposal that we do something similar to handle asyncio calls? Do you have any ideas about an API for this? It would be great if we could get it upstreamed into the main yappi, e.g., as a different clock option or similar (not sure what you have in mind though).

But even if it requires essentially replicating _yappi.c I guess we could make that work!

from yappi.

dmontagu commented on September 24, 2024

Also, I noticed in the greenlet modification of yappi, it only does the context pausing/resuming if the clock type is "cpu". So I'm a little worried something else might be going on here? In particular, I don't fully understand why the wall clock times are off in the example above. (I'll dig into this more eventually, I'll have to take a break on this for at least a few hours though.)

(Or maybe the point is that we just need to make use of different versions of the _pause_ctx and _resume_ctx functions?)

Edit: I definitely feel out of my depth trying to figure out what is going on here.

Some potentially relevant info:

When working with asyncio, threads may still be involved since you can run functions in threads via an executor for the event loop. I guess that may need to be accounted for.
In the following, I'm not sure how prev_ctx / current_ctx will be set when asyncio calls are being made and/or awaits are happening:
```
// _yapp_callback
current_ctx = _thread2ctx(PyThreadState_GET());

// From greenlet profiler
if (prev_ctx != current_ctx) {
    current_ctx->sched_cnt++;
    if (context_id_callback && get_timing_clock_type() == CPU_CLOCK) {		
        _pause_ctx(prev_ctx);		
        _resume_ctx(current_ctx);		
    }		
}
```
It looks like for the greenlet profiler, the ctx tracks too much time by default, but in our case, it tracks too little. Maybe this is due to other changes in the greenlet profiler? At this point, I'm not really sure where to begin looking more deeply.

from yappi.

sumerc commented on September 24, 2024

@dmontagu, I think your initial investigation is pretty useful and you are correct for we will need to think about different threads in an event loop. I will be looking into this in more depth, now I understand and also remembered:) the problem fully. I am currently not sure why wall time is not working for async. functions, I will start looking into that.

BTW, Let me ask you this: is using multiple threads for a single event loop a common use case? Could you also provide an example or maybe just explain(without code) where it makes sense?

from yappi.

sumerc commented on September 24, 2024

Thanks for the very detailed answer. Now, I will probably be thinking about these in my head for days:) The problem with threads is more about thinking about the shared vars/global structures rather than functionality. While designing the solution, I need to think all the time that this might be called from another thread ..etc...

For the wall-time problem, I think I understand the problem: the issue is (it is interesting that we have not seen it before), the profiler CALL/RETURN events are called for every context switch occurring. Normally these events are generated when a functions ends but in async. case, they are called whenever a task switch occurs. So, that is why we cannot calculate the wall time correctly becasue whenever you call sleep(..), profiler thinks it left the function.

BTW, this same behaviour is also present in cProfile. It also does not calculate wall-time correctly. I mean correct might be a wrong word here as at the end of the day, when you call sleep, in fact there is nothing happening in single thread case, and for multiple threads, cProfile already says it does not support that.

So, I need to think about this more. I still feel that this is solvable somehow but might require some careful work. I am thinking about an API like set_context_backend("asyncio") which sets the context id callback and enables the correct profiling for the backend. And do the same for set_ctx_backend("gevent"). I initially did not like the idea of integrating yappi to different frameworks but given the fact that there are lots of libs/use cases for these frameworks we should add support for these, IMHO.

from yappi.

sumerc commented on September 24, 2024

BTW, one of the good side effect of this behavior (calling CALL/LEAVE in context switches) is that you get correct CPU time per-task for free which we have struggled for Greenlet:)

from yappi.

dmontagu commented on September 24, 2024

Yeah, that makes sense to me. I think since asyncio is part of the standard library, it is worth handling in a first class way (I may be biased though.. 🙂).

I think supporting this properly would definitely be a big value proposition over alternative profilers.

Another question to consider: should we make it possible to track each of the following?

CPU time (presumably what is currently reported as CPU time)
Wall time, but only within a context (not sure, but maybe this is what is currently reported as wall time?)
Wall time, including context switches (what we're trying to get)

I think (but am not 100% sure) that each of these are distinct, and potentially useful. (For example, having a low 1, high 2, and high 3 probably means you have blocking IO that should be refactored; having a low 1, low 2, and high 3 probably means you just have slow IO).

Perhaps there is nothing to do to enable tracking 1 and 2 (if that's how things currently work?) -- just don't make a set_context_backend call -- but I think whatever solution we come up with should probably make it possible to access each of those measurements.

from yappi.

sumerc commented on September 24, 2024

Yes. I assume 1 and 2 is already covered.(I will also check on that too.) I am also OK call_count being incremented per context-switch, it also makes some kind of sense.

I am not sure if 2 has any benefits when 3 is available. Do you really think it is possible to have a low 2 and high 3? or high 2 and low 3?

from yappi.

sm-Fifteen commented on September 24, 2024

For the wall-time problem, I think I understand the problem: the issue is (it is interesting that we have not seen it before), the profiler CALL/RETURN events are called for every context switch occurring. Normally these events are generated when a functions ends but in async. case, they are called whenever a task switch occurs. So, that is why we cannot calculate the wall time correctly becasue whenever you call sleep(..), profiler thinks it left the function.

https://github.com/python/cpython/blob/138ccbb02216ca086047c3139857fb44f3dab1f9/Python/ceval.c#L3793-L3807

So whenever a generator yields, it's considered as exiting the function by profilers? That's going to be an issue... I get why they'd do this for profiling, since it ensures the time being measured is strictly limited to the time being spent in the function, but it also makes proper timing of asyncio functions a lot harder to acheive, since whenever an await breaks the callstack, the profiler won't know it.

We would need a different way to figure out the callstack of running tasks, then. After looking around, it looks like Tasks are aware of their own stacks as part of a cr_frame/gr_frame attribute internal to coroutines which might be accessible from C code (if I'm reading this properly, I'm not too familiar with CPython's C API).

So, I need to think about this more. I still feel that this is solvable somehow but might require some careful work. I am thinking about an API like set_context_backend("asyncio") which sets the context id callback and enables the correct profiling for the backend. And do the same for set_ctx_backend("gevent"). I initially did not like the idea of integrating yappi to different frameworks but given the fact that there are lots of libs/use cases for these frameworks we should add support for these, IMHO.

Not neccessarily. A solution to allow profiling ~~async functions~~ coroutines would benefit a lot of async libraries besides just asyncio (like Curio/Trio) without having to tie yappi to a specific implementation of it.

from yappi.

sumerc commented on September 24, 2024

We would need a different way to figure out the callstack of running tasks, then. After looking around, it looks like Tasks are aware of their own stacks as part of a cr_frame/gr_frame attribute internal to coroutines which might be accessible from C code (if I'm reading this properly, I'm not too familiar with CPython's C API).

That is exactly what I will be looking into. We need to differentiate between a real coroutine exit vs couroutine task switch. But coming to the first question @dmontagu asked, is this really what we want to achieve? You guys know async. world better than me, do you think implementing 3 over 2 has practical benefits?

Not neccessarily. A solution to allow profiling async functions coroutines would benefit a lot of async libraries besides just asyncio (like Curio/Trio) without having to tie yappi to a specific implementation of it.

Yeah, but the problem is you see gevent does run until the end of coroutine and does not call profiler events for context switch, that is something we have simulated in the past. But asyncio does that. I am pretty sure all these libraries will have one way or another subtle differences like this which will probably make implementation different.

First thing is first: let's focus on asyncio first. It is currently the most widely used one, am I right?

from yappi.

sm-Fifteen commented on September 24, 2024

That is exactly what I will be looking into. We need to differentiate between a real coroutine exit vs couroutine task switch. But coming to the first question @dmontagu asked, is this really what we want to achieve? You guys know async. world better than me, do you think implementing 3 over 2 has practical benefits?

I would personally be fine with just 1 and 3 (tracking actual CPU time spent in the function + total time that function has spent in the callstack). 2 would be nice, I suppose, and it's the current behavior so implementing it wouldn't cost any effort, but considering one needs to be picked between 2 and 3 if we don't want to alter the YStats objects, I'd prefer 3.

Yeah, but the problem is you see gevent does run until the end of coroutine and does not call profiler events for context switch, that is something we have simulated in the past. But asyncio does that. I am pretty sure all these libraries will have one way or another subtle differences like this which will probably make implementation different.

From the way you're describing this, I'd consider this more of a "gevent quirk" (compared to native coroutines, anyway) than a framework difference that needs to be accounted for with various modes. I'm saying this having never used gevent before, though.

First thing is first: let's focus on asyncio first. It is currently the most widely used one, am I right?

Asyncio is mainly just a series of I/O systems built on top of the Python 3.5+ coroutines (which mostly are just generators with special syntax to make sure they don't interfere with real generators), and I don't believe a profiler like yappi really needs to account for anything beyond that. But I do believe that asyncio has pretty much conquered the async space in Python (I haven't heard of Twisted or Tornado in quite some time, and Trio is still fairly niche for the time being, even though it shows a lot of promise). Limiting support to asyncio only if that choice ends up having to be made would probably work just fine for the vast majority of users (myself included). I was just saying this to point out that it might not actually be needed.

from yappi.

sumerc commented on September 24, 2024

Thanks for the detailed explanation again. I will be reading the comment from time to time for reference.

So, for the next step I think at least we all agree is having these metrics are very useful:

a. CPU time per-coroutine
b. Wall time per-coroutine

let's defer the discussion of having wall-time per-coroutine ONLY when running to the end.

Now, as I said before a) is already available as function exit events happen for every await.
For b), I might have found a way, I will be testing it in a different branch and inform you in few days. But I really need your help on verifying/testing this as I will probably use weird ways to differentiate coroutine end and coroutine context switch. So, it would be great if you can help me testing.

PLEASE: bundle your tests as unittest.TestCase because I will be adding them to unit tests later on. I will be testing the behaviour for all Python versions starting from 3.5, this is something I would be doing but if you have any chance testing on those versions too, that would be great!

from yappi.

sumerc commented on September 24, 2024

@dmontagu @sm-Fifteen The test branch name is coroutine-profiling. It is in very alpha stage but seems to work on couple of cases I had thrown. It seems to to profile wall time correctly in py3.7.5.

Please send your valuable feedback.

Thanks!

from yappi.

euri10 commented on September 24, 2024

I will be testing the behaviour for all Python versions starting from 3.5, this is something I would be doing but if you have any chance testing on those versions too, that would be great!

iirc contextvars appears in 3.7

from yappi.

sumerc commented on September 24, 2024

iirc contextvars appears in 3.7

Yes yes. The issue is not related with context vars anymore. So, you can already use set_ctx_callback_id API to arrange your context. The issue we are trying to solve is: correct wall-time profiling of coroutines: currently whenever a context switch happens, the profiler receives call_leave event which makes the profiler thinks that the coroutine has ended, the test branch aims to fix that.

from yappi.

euri10 commented on September 24, 2024

iirc contextvars appears in 3.7

Yes yes. The issue is not related with context vars anymore. So, you can already use set_ctx_callback_id API to arrange your context. The issue we are trying to solve is: correct wall-time profiling of coroutines: currently whenever a context switch happens, the profiler receives call_leave event which makes the profiler thinks that the coroutine has ended, the test branch aims to fix that.

my bad I thought you wanted to test it on 3.5

from yappi.

euri10 commented on September 24, 2024

using @dmontagu snippet from here and coroutine-profiling branch (installed with pipenv install git+https://github.com/sumerc/yappi.git@coroutine-profiling#egg=yappi)

I get

Task 1:
    Actual wall time: 1001.941ms
     Yappi wall time:    0.068ms
Task 2:
    Actual wall time: 1001.953ms
     Yappi wall time:    0.050ms
Task 3:
    Actual wall time: 1001.936ms
     Yappi wall time:    0.036ms

from yappi.

dmontagu commented on September 24, 2024

Yes, I'll write a couple unittest.TestCase examples tonight. I really appreciate the prompt responses and progress!

from yappi.

sumerc commented on September 24, 2024

Below is one of the test files I have used. I have tried to think corner cases(at least it is corner to me:) ) like async generators and recursive async files, old style coroutines...etc. I am counting on you guys to find more of these:)

import asyncio
import yappi
import time


def mygenerator(n):
    while (n):
        yield n
        n -= 1


# async generator
async def ticker(n):
    for i in range(n):
        yield i
        await asyncio.sleep(1.0)


@asyncio.coroutine
def old_style_coroutine():
    yield from asyncio.sleep(1)


async def myasyncfunc(n=2):
    if not n:
        return
    await asyncio.sleep(1.0)
    time.sleep(1.0)
    await old_style_coroutine()

    async for i in ticker(2):
        print("giter", i)

    await myasyncfunc(n - 1)


yappi.set_clock_type("wall")
yappi.start()
for i in mygenerator(5):
    print(i)
asyncio.run(myasyncfunc())
yappi.stop()
yappi.get_func_stats().print_all()

from yappi.

dmontagu commented on September 24, 2024

@sumerc ~~Have you thought about recursive async functions? Not sure if that would cause weird edge cases.~~ I see it above now 🤦‍♂️.

Another thing to think about -- async context managers. Probably doesn't add new edge cases (and may ultimately be basically equivalent to async generators), but worth ensuring it behaves properly.

~~Also, async for.~~ I see that too 🤦‍♂️🤦‍♂️.

from yappi.

sumerc commented on September 24, 2024

@sumerc Have you thought about recursive async functions? Not sure if that would cause weird edge cases.

Yes. As yappi already has support for recursive functions I think it will not be too much problem. But of course, in this case it is new and needs to be tested. It seems to be working at least for simple cases.

Another thing to think about -- async context managers. Probably doesn't add new edge cases (and may ultimately be basically equivalent to async generators), but worth ensuring it behaves properly.

Nice catch. Would be nice to test.

from yappi.

sumerc commented on September 24, 2024

Update: There is an issue related with time calculation of concurrent coroutines on same function, but I think it is close to finish, I am still testing. ~~There will hopefully no change to the underlying API, only calling set_context_id_callback() will be enough.~~ There might a new API to support aggregating different profile data by tagging. I am still thinking about the details, but it seems very promising.

from yappi.

sumerc commented on September 24, 2024

This wasn't too hard to implement for Trio, which has an instrumentation API. If you're able to implement something equivalent for asyncio, I'd like to add it to my [PerfTimer]

Nice to know. I will be notifying when the work is finished.

from yappi.

euri10 commented on September 24, 2024

thanks a lot @sumerc that looks amazing.
running this I got some weird stuff happening, ths is the output, am I doing something silly, I recreated entirely my venv thinking maybe it was that but I still have those NameError: name 'sys' is not defined at the end ?

Task 1:
    Actual wall time: 1005.084ms
     Yappi wall time: 1005.192ms
Task 2:
    Actual wall time: 1004.938ms
     Yappi wall time: 1005.016ms
Task 3:
    Actual wall time: 1006.451ms
     Yappi wall time: 1006.527ms
Traceback (most recent call last):
  File "<string>", line 1, in <module>
NameError: name 'sys' is not defined
Traceback (most recent call last):
  File "<string>", line 1, in <module>
NameError: name 'sys' is not defined
Traceback (most recent call last):
  File "<string>", line 1, in <module>
NameError: name 'sys' is not defined
Traceback (most recent call last):
  File "<string>", line 1, in <module>
NameError: name 'sys' is not defined

Process finished with exit code 0

edit I thought it was pycharm but I got the same running directly the script in a terminal.
now should I run it in pycharm debugger I got this
edit2: reading the below, I thought pydedvd breakpoints might cause this but I have no breakpoints set

from debugger in pycharm

Connected to pydev debugger (build 192.7142.56)
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
Task 1:
    Actual wall time: 1011.178ms
     Yappi wall time: 1011.338ms
Task 2:
    Actual wall time: 1011.864ms
     Yappi wall time: 1012.022ms
Task 3:
    Actual wall time: 1015.012ms
[*]	[yappi-err]	Internal Error. [15]
[*]	[yappi-err]	Internal Error. [15]
     Yappi wall time: 1015.126ms
Error in sys.excepthook:
Traceback (most recent call last):
  File "/home/lotso/pycharm-2018.3.2/helpers/pydev/_pydevd_bundle/pydevd_breakpoints.py", line 166, in _fallback_excepthook
TypeError: 'NoneType' object is not callable

Original exception was:
Traceback (most recent call last):
  File "<string>", line 1, in <module>
NameError: name 'sys' is not defined
Error in sys.excepthook:
Traceback (most recent call last):
  File "/home/lotso/pycharm-2018.3.2/helpers/pydev/_pydevd_bundle/pydevd_breakpoints.py", line 166, in _fallback_excepthook
TypeError: 'NoneType' object is not callable

Original exception was:
Traceback (most recent call last):
  File "<string>", line 1, in <module>
NameError: name 'sys' is not defined
Error in sys.excepthook:
Traceback (most recent call last):
  File "/home/lotso/pycharm-2018.3.2/helpers/pydev/_pydevd_bundle/pydevd_breakpoints.py", line 166, in _fallback_excepthook
TypeError: 'NoneType' object is not callable

Original exception was:
Traceback (most recent call last):
  File "<string>", line 1, in <module>
NameError: name 'sys' is not defined
Error in sys.excepthook:
Traceback (most recent call last):
  File "/home/lotso/pycharm-2018.3.2/helpers/pydev/_pydevd_bundle/pydevd_breakpoints.py", line 166, in _fallback_excepthook
TypeError: 'NoneType' object is not callable

Original exception was:
Traceback (most recent call last):
  File "<string>", line 1, in <module>
NameError: name 'sys' is not defined

Process finished with exit code 0

from yappi.

dmontagu commented on September 24, 2024

This is great! I'll try it out when I get a chance (hopefully some time this week) and give you feedback. Thanks so much for all of your effort!

from yappi.

sumerc commented on September 24, 2024

No need for sorry! These are valuable User experience issues and should be taken care of. I should be using a more uncommon default tag id.

edit: I have fixed the problem with import sys error on interpreter shutdown.

from yappi.

sm-Fifteen commented on September 24, 2024

Having had some time to try this in the wild, I will say that this is extremely useful, although there's a few things that tend to throw off profiling results in async contexts:

If a task is holding the thread by running sync operations, it will stall any tasks that are ready to resume, much like the GIL does with Python threads. For CPU time, that's usually what you want, but for wall time, it may trick you into thinking a task took much longer to execute than it actually did because it's not considered as finished until it can resume. I don't know what can be done about this given we can't know when a task or thread is ready to resume until it actually does so, but it could be interesting to have an extra metric that says, maybe, for how much of that duration was the GIL held by another thread or the asyncio thread actually running code (which would show as CPU time) instead of waiting on I/O.
If multiple tasks are running in parallel, I believe their execution time is added together in the final runtime, which can lead to some operations seeming to take much longer than thery actually did. I personally have no idea how a profiler like yappi should handle this, but I figure I should point it out.

Both of these affect threads as well as coroutines (and threads are often used to run sync code without blocking the asyncio thread, so there's also that), and might be worth looking into as potential improvements.

Also, it's really interesting to see the extra attention this project has been seeing now that the word has gotten out that there's a Python profiler with coroutine support! :)

from yappi.

sumerc commented on September 24, 2024

If a task is holding the thread by running sync operations, it will stall any tasks that are ready to resume, much like the GIL does with Python threads. For CPU time, that's usually what you want, but for wall time, it may trick you into thinking a task took much longer to execute than it actually did because it's not considered as finished until it can resume. I don't know what can be done about this given we can't know when a task or thread is ready to resume until it actually does so, but it could be interesting to have an extra metric that says, maybe, for how much of that duration was the GIL held by another thread or the asyncio thread actually running code (which would show as CPU time) instead of waiting on I/O.

For asyncio, I do not know any way to differentiate between a task that is ready to run and still working in I/O. Maybe there is a way, tough. For GIL: again AFAIK, there is no way of knowing if a thread is waiting on GIL or I/O. I know some profilers like py-spy show you the statistically how much time spent in functions related to C extensions, maybe you can use that to retrieve GIL related information.... Not sure.

Having said that, I believe these ideas are worth digging and I will be thinking in my head but I am not sure they can be incorporated into Yappi as solving these problems might require different set of tools/approaches. (walking the real stack trace of the application or instrumenting user-level functions...)

If multiple tasks are running in parallel, I believe their execution time is added together in the final runtime, which can lead to some operations seeming to take much longer than thery actually did. I personally have no idea how a profiler like yappi should handle this, but I figure I should point it out.

I could not quite understand this one. Could you please provide a simple example?

Also, it's really interesting to see the extra attention this project has been seeing now that the word has gotten out that there's a Python profiler with coroutine support! :)

Yes :) Thanks to you and the other guys at FastAPI.

from yappi.

sm-Fifteen commented on September 24, 2024

If a task is holding the thread by running sync operations, it will stall any tasks that are ready to resume, much like the GIL does with Python threads. For CPU time, that's usually what you want, but for wall time, it may trick you into thinking a task took much longer to execute than it actually did because it's not considered as finished until it can resume. I don't know what can be done about this given we can't know when a task or thread is ready to resume until it actually does so, but it could be interesting to have an extra metric that says, maybe, for how much of that duration was the GIL held by another thread or the asyncio thread actually running code (which would show as CPU time) instead of waiting on I/O.

For asyncio, I do not know any way to differentiate between a task that is ready to run and still working in I/O. Maybe there is a way, tough. For GIL: again AFAIK, there is no way of knowing if a thread is waiting on GIL or I/O. I know some profilers like py-spy show you the statistically how much time spent in functions related to C extensions, maybe you can use that to retrieve GIL related information.... Not sure.

Having said that, I believe these ideas are worth digging and I will be thinking in my head but I am not sure they can be incorporated into Yappi as solving these problems might require different set of tools/approaches. (walking the real stack trace of the application or instrumenting user-level functions...)

Well, the way I'm thinking of would require always collecting stats for both wall and cpu time. You could get a pretty rough idea of the "time window to resume" or the "percentage of time blocked" or however such a metric would be named by just adding together the CPU time for all the other frames that ran during the lifetime of that function. This obviously wouldn't hold in the case of C extensions that are able to release the GIL on their thread, but it's a metric I'm sure a lot of people would appreciate having in a multithreaded context.

If multiple tasks are running in parallel, I believe their execution time is added together in the final runtime, which can lead to some operations seeming to take much longer than thery actually did. I personally have no idea how a profiler like yappi should handle this, but I figure I should point it out.

I could not quite understand this one. Could you please provide a simple example?

>>> import yappi
>>> import asyncio
>>> async def test_coro():
...     await asyncio.sleep(5)
...
>>> async def amain():
...     coro1 = test_coro()
...     coro2 = test_coro()
...     await asyncio.gather(coro1, coro2)
...
>>> def do_profile():
...     yappi.set_clock_type("wall")
...     yappi.start()
...     asyncio.run(amain())
...     yappi.stop()
...     yappi.get_func_stats(filter={'name':'test_coro'}).print_all()
...
>>> yappi.clear_stats()
>>> do_profile()

Clock type: WALL
Ordered by: totaltime, desc

name                                  ncall  tsub      ttot      tavg
<stdin>:1 test_coro                   2      0.000012  10.01328  5.006642

asyncio.gather waits for both tasks to complete in parallel, so the pause only lasts 5 seconds, but 10 seconds is measured. I'm pointing it out because I noticed it could happen and it makes the results incorrect (I think?), but I'm not entirely sure how that could be fixed. The same thing would probably affect threads.

Also, it's really interesting to see the extra attention this project has been seeing now that the word has gotten out that there's a Python profiler with coroutine support! :)

Yes :) Thanks to you and the other guys at FastAPI.

cProfile had better watch out!

from yappi.

sumerc commented on September 24, 2024

Well, the way I'm thinking of would require always collecting stats for both wall and cpu time. You could get a pretty rough idea of the "time window to resume" or the "percentage of time blocked" or however such a metric would be named by just adding together the CPU time for all the other frames that ran during the lifetime of that function. This obviously wouldn't hold in the case of C extensions that are able to release the GIL on their thread, but it's a metric I'm sure a lot of people would appreciate having in a multithreaded context.

OK then I might have misunderstood. We call I/O time=Wall time - CPU time and yes, this can be done with having a clock_type of both wall/cpu at the same time. It is quite possible. I had assumed you were asking for to differentiate a the wait for different objects in I/O. Like how much we waited for GIL, and how much we actually waited for the I/O operation to complete.

asyncio.gather waits for both tasks to complete in parallel, so the pause only lasts 5 seconds, but 10 seconds is measured. I'm pointing it out because I noticed it could happen and it makes the results incorrect (I think?), but I'm not entirely sure how that could be fixed. The same thing would probably affect threads.

We can filter on ctx_id and tag fields to get per-coroutine/thread info on any result. I am really not sure on how to improve this more, honestly. The way yappi looks at this dimension is like: when it measures walltime for example, it measures it from the perspective of the thread/coroutine, thus that is why we always see the aggregated time. That is also probably why we need to have good filtering support...

from yappi.

sm-Fifteen commented on September 24, 2024

OK then I might have misunderstood. We call I/O time=Wall time - CPU time and yes, this can be done with having a clock_type of both wall/cpu at the same time. It is quite possible. I had assumed you were asking for to differentiate a the wait for different objects in I/O. Like how much we waited for GIL, and how much we actually waited for the I/O operation to complete.

Well, that would definitely be the ideal case, but I understand that those are all things that turn out to be very hard to test for at the moment, so a wall_time - cpu_time_of_anything_that_ran_for_the_duration_of_wall_time is the most obvious estimate I can think of (though you might want to tweak it depending on whether the current frame is async or not, because coroutines are blocked from resuming by any sync function running on the event loop thread, even if it's time.sleep(), whereas threads can be switched whenever the CPU is idle).

We can filter on ctx_id and tag fields to get per-coroutine/thread info on any result. I am really not sure on how to improve this more, honestly. The way yappi looks at this dimension is like: when it measures walltime for example, it measures it from the perspective of the thread/coroutine, thus that is why we always see the aggregated time. That is also probably why we need to have good filtering support...

Yeah, things like asyncio.gather() and whatever the threading equivalent is are somewhat of an edge-case, here. The problem is that code that is unaware of the profiler could be using asyncio.gather to execute tasks in parallel like this, so I don't know if there would really be an occasion to change the context/tag ID. You just end up having a walltime for a subtask that was executed multiple times in parallel (like test_coro above with a walltime of 10 seconds) being potentially longer than the walltime of its parent frame (like amain above with a walltime of 5 seconds).

from yappi.

Coroutine-aware wall-time profiling about yappi HOT 46 CLOSED

Comments (46)

Related Issues (20)

Recommend Projects

React

Vue.js

Typescript

TensorFlow

Django

Laravel

D3

Recommend Topics

javascript

web

server

Machine learning

Visualization

Game

Recommend Org

Facebook

Microsoft

Google

Alibaba

D3

Tencent