search

dabeaz / curio

Good Curio!
Other
4.01k stars 240 forks source link

performance problem --- a delay when task come to the curio.run func #270

Closed JmSeason closed 5 years ago

JmSeason commented 6 years ago

here is my code:

from curio import *
import time
from curio.debug import traptrace, schedtrace
import logging

logging.basicConfig(level=logging.DEBUG)

async def task1():
    while True:
        await sleep(0)

async def task2():
    while True:
        await sleep(0)

async def run_tasks():
    async with TaskGroup(wait=any) as g:
        t1 = await g.spawn(task1)
        t2 = await g.spawn(task2)

async def main():
    task = await spawn(run_tasks)
    while True:
        await sleep(0)
    await task.join()

run(main, debug=traptrace)

when i run this, i got console output below:

INFO:curio.debug:TRAP:1531291958.432000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.432000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.433000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.448000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.448000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.449000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.464000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.464000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.465000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.479000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.479000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.479000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.495000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.495000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.495000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.510000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.510000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.510000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.526000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.526000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.527000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.542000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.542000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.543000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.557000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.557000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.557000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.573000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.573000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.573000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.588000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.588000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.588000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.604000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.604000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.605000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.620000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.620000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.620000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.635000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.635000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.635000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.651000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.651000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.651000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.666000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.666000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.666000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.682000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.682000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.683000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.698000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.698000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.698000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.713000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.713000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.713000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.729000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.729000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.729000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.744000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.744000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.744000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.760000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.760000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.760000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.776000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.776000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.776000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.791000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.791000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.792000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.807000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.807000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.807000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.822000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.822000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.822000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.838000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.838000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.838000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.854000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.854000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.854000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.869000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.869000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.870000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.885000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.885000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.885000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.900000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.900000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.900000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.916000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.916000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.916000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.932000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.932000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.933000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.947000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.947000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.947000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.963000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.963000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.963000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.978000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.978000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.979000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.994000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.994000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291958.994000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291959.010000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291959.010000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291959.010000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291959.025000:Task(id=2, name='main'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291959.025000:Task(id=4, name='task1'):Traps._trap_sleep:(0, False) INFO:curio.debug:TRAP:1531291959.025000:Task(id=5, name='task2'):Traps._trap_sleep:(0, False) .........

my question is that why task turn to the 'main' task it would delay about 0.015 seconds, but my main or task1, task2 did nothing(just sleep)

dabeaz commented 6 years ago

What version of Curio? What operating system? What version of Python?

JmSeason commented 6 years ago

curio version :0.10 os : windows 7 python : 3.5.2

njsmith commented 6 years ago

It's probably because on Windows, time.monotonic only has ~15 ms resolution.

Imagine the clock only reported time to the nearest second. If it went to switch to the main task at time 10.9999, and then finished at time 11.0001, then the logs would just say "10.0000" and "11.0000", and you would think it had paused for a whole second, even though it was actually only 0.0002 seconds. So it's probably not a real pause.

There's a bit more discussion here: https://github.com/python-trio/trio/issues/33

JmSeason commented 6 years ago

o, i had tried trio in the same environment, it won delay when task switch

njsmith commented 6 years ago

Well, of course I do think trio is pretty cool, but... my point is that if you try to use time.monotonic to measure task switch latency on Windows then you probably won't get accurate measurements. So if that's what you're doing, then even if trio seemed to "win", it might be a coincidence or artifact rather than an actual difference between trio and curio.

JmSeason commented 6 years ago

i see, do you think it is a bug? because i use curio in my project on windows, because of the time.monotonic(you said, maybe), my project is slow, when i get the curio debug logs, it is also has the problem i said above, so i run a simple test code(above) to see if my code problem, so i found the problem in curio, but i did not try in linux, again, you think it is a bug?

dabeaz commented 6 years ago

Is this performance test a realistic representation of any actual code? I don't see how a bunch of rapidly switching tasks with sleep(0) would be anything like an actual application involving I/O.

JmSeason commented 6 years ago

my project use curio, i have many tasks, i tried curio.sleep(0) to schedule these tasks, when i print curio debug log, i found some delay(about 0.015 second) when a task turn to other task, so i write a simple test code(above) to see if my problem

dabeaz commented 6 years ago

Many tasks, yes, but aren't they doing some kind of I/O (reading on sockets, pipes, files, etc.)?

Regarding performance: every scheduling cycle of Curio also involves an I/O poll. That's not something I've measured on Windows however.

JmSeason commented 6 years ago

yes, i did not do I/O operation, i will try for some kind of I/O operation

JmSeason commented 6 years ago

i try to use trio replace curio in my project, than i won get this problem, when i use curio, my project finished in 2.5 seconds, when i use trio in my project, my project finished in 0.24 seconds, that is very different, i don't think curio would be that slow, maybe the problem is the windows time.monotonic, i don't have an idea about this now

imrn commented 6 years ago

Flooding an async framework with sleep(0)s may be a benchmark for kernel performance. Or it may be not.

I expect that an async framework does a good job on i/o performance and memory consumption when flooded with real tasks. If above timing numbers are a result of a deliberate design decision, I would be fine with it.

But if there is any further room for improvements for sleep(0)s, that would be an extra bonus too.

imrn commented 6 years ago

And did your account for os and cpu cache warm up period? Do you get same numbers for both frameforks when you run them 10-20 times in a row?

imrn commented 6 years ago

And are you planning to deploying someting real which is facing internet on a windows machine?

JmSeason commented 6 years ago

yes, i take many test times, every time result is the same, and my project is running on windows with python, my program is not facing internet, it is a desktop client program

dabeaz commented 6 years ago

There's really not much for me to work with on this bug report because the supplied code and described application is so vague. Curio is not large. The main kernel loop is not doing much. The only thing that comes to mind is perhaps some kind of Windows-specific thing related to I/O polling. Curio uses the Python default selector for I/O polling which is based (AFAIK) on select(). Maybe there's some kind of performance issue with that.

Alternatively, perhaps Trio is making an optimization to not poll for I/O if it knows that know tasks are actually waiting for any I/O.

njsmith commented 6 years ago

when i use curio, my project finished in 2.5 seconds, when i use trio in my project, my project finished in 0.24 seconds

The most helpful thing would be if you could show the scripts you measured this difference on.

The timings at the top of this thread are unfortunately not meaningful at all, because of how the Windows clock works. A 2.5 seconds vs 0.24 seconds difference sounds very meaningful, but none of us know what you were actually measuring so it's impossible to guess what might be causing the difference.

JmSeason commented 6 years ago

well, i have many tasks, i want to use sleep(0) to schedule tasks, i also take some test code below

import curio
import timeit

async def task():
    for i in range(1000):
        await curio.sleep(0)        

async def run_tasks():
    start = timeit.default_timer()
    async with curio.TaskGroup() as g:
        for i in range(3):
            await g.spawn(task)
    span = timeit.default_timer() - start
    print('span {} s'.format(span)) 

curio.run(run_tasks)

in curio, i got span about 15.6 seconds, there is another code below

import trio
import timeit

async def task():
    for i in range(1000):
        await trio.sleep(0)

async def run_tasks():
    start = timeit.default_timer()
    async with trio.open_nursery() as nursery:
        for i in range(3):
            nursery.start_soon(task)
    span = timeit.default_timer() - start
    print('span {} s'.format(span))

trio.run(run_tasks)

in trio, i got span about 0.26 seconds, there is a bit difference, is that i should not use sleep(0) to schedule tasks, if is yes, what ways should i do to schedule tasks

dabeaz commented 6 years ago

Did a bit of experimentation with this and on Windows, sure enough, about 15 seconds. On my Macbook, it ran in about 0.02 seconds. So, there is definitely some kind of platform-specific performance issue involved there. However, I also looked closely at the Curio code and found that sleep(0) makes a task go through the entire sleep cycle anyways. I modified it to special case 0 as a fast-reschedule and that made the problem go away. I pushed this change yesterday. Try it and see what happens in your application.

Might worth some amount of investigation to see what's causing that massive slowdown on Windows. There's really not much going on in the code other than calls to time_monotonic() and select(). I'll investigate further when I get a chance.

JmSeason commented 6 years ago

dabeaz, thanks a lot, i updated the new curio you committed, it work fast, it solve my problem

imrn commented 6 years ago

On 7/14/18, David Beazley notifications@github.com wrote:

I modified it to special case 0 as a fast-reschedule.

"sleep(0)" is a defacto alias for async yield/reschedule/ voluntary_context_switch/whatever_you_may_call. But I think is a bit awkward.

How about defining the concept and giving it a proper function name?

My suggestion:

await reschedule() await sleep(t) # is a noop for t <= 0

dabeaz commented 6 years ago

Curio already has await schedule() that does this. It's the same as sleep(0).