New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add AsyncWrite option for writing stats #9

Merged
merged 2 commits into from Aug 23, 2018

Conversation

Projects
None yet
2 participants
@denzow
Copy link
Contributor

denzow commented Aug 18, 2018

Hi.
I add async_write option for writing stats.

I use wsgi_lineprof for ISUCON, and write stats to log file.
But, writing log file is too slow for ISUCON. I wanna reduce writing overhead.
if async_write is true, main thread do not wait writing stats. Writing thread write stats asynchronously.

I look forward to hearing from you.

@denzow denzow force-pushed the denzow:master branch from 58629ea to 21fad8e Aug 19, 2018

@ymyzk

This comment has been minimized.

Copy link
Owner

ymyzk commented Aug 19, 2018

The idea sounds interesting. Could you show me some data which shows using this new option reduces overhead? Thanks.

@denzow

This comment has been minimized.

Copy link
Contributor

denzow commented Aug 19, 2018

Thanks for your reply.

It is testcase.

import time
from wsgiref.util import setup_testing_defaults
from wsgiref.simple_server import make_server
from wsgi_lineprof.filters import FilenameFilter
from wsgi_lineprof.middleware import LineProfilerMiddleware


class SlowFileLikeObject(object):

    def write(self, content, *args, **kwargs):
        time.sleep(0.1)
        # print(content, end='')


# Simple WSGI application
def app(environ, start_response):
    setup_testing_defaults(environ)

    status = '200 OK'
    headers = [('Content-type', 'text/plain; charset=utf-8')]

    start_response(status, headers)
    return [b'HELLO WORLD']


# Set up profiler
filters = [
    FilenameFilter("sample_for_async.py"),
]
app = LineProfilerMiddleware(app, filters=filters, async_write=False, stream=SlowFileLikeObject())

if __name__ == '__main__':
    server = make_server('127.0.0.1', 8000, app)
    print("Serving on 127.0.0.1:8000...")
    server.serve_forever()

no profiling(avg 0 msecs)

[pid: 62897|app: 0|req: 1/1] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:44:53 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (1 switches on core 0)
[pid: 62897|app: 0|req: 2/2] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:44:53 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 62897|app: 0|req: 3/3] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:44:54 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 62897|app: 0|req: 4/4] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:44:54 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 62897|app: 0|req: 5/5] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:44:55 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)

async_write=False(over 1700 msecs)

[pid: 62631|app: 0|req: 1/1] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:39:47 2018] GET / => generated 11 bytes in 1730 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 62631|app: 0|req: 2/2] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:39:49 2018] GET / => generated 11 bytes in 1716 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 62631|app: 0|req: 3/3] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:39:53 2018] GET / => generated 11 bytes in 1712 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 62631|app: 0|req: 4/4] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:39:55 2018] GET / => generated 11 bytes in 1714 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 62631|app: 0|req: 5/5] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:39:56 2018] GET / => generated 11 bytes in 1714 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)

async_write=True(avg 0 msecs)

[pid: 62365|app: 0|req: 1/1] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:39:24 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (1 switches on core 0)
[pid: 62365|app: 0|req: 2/2] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:39:24 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 62365|app: 0|req: 3/3] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:39:25 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (1 switches on core 0)
[pid: 62365|app: 0|req: 4/4] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:39:25 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 62365|app: 0|req: 5/5] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 15:39:25 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)

Of Course. real file is faster than SlowFileLikeObject. But there are a few overhead.

@ymyzk

This comment has been minimized.

Copy link
Owner

ymyzk commented Aug 19, 2018

Thank you for sharing a sample code.

Assuming 100ms overhead seems extreme for me. Do you have more convincing data with real disk access?

@denzow

This comment has been minimized.

Copy link
Contributor

denzow commented Aug 19, 2018

Sorry for the not convincing data.

sample code (add dummy lines for stats.)

from wsgiref.util import setup_testing_defaults
from wsgiref.simple_server import make_server
from wsgi_lineprof.filters import FilenameFilter
from wsgi_lineprof.middleware import LineProfilerMiddleware


# Simple WSGI application
def app(environ, start_response):
    setup_testing_defaults(environ)

    status = '200 OK'
    headers = [('Content-type', 'text/plain; charset=utf-8')]
    dummy_line = 1
    dummy_line = 2
    dummy_line = 3
    dummy_line = 4
    dummy_line = 5
    dummy_line = 6
    dummy_line = 7
    dummy_line = 8
    dummy_line = 9
    dummy_line = 10
    dummy_line = 11
    dummy_line = 12
    dummy_line = 13
    dummy_line = 14
    dummy_line = 15
    dummy_line = 16
    dummy_line = 17
    dummy_line = 18
    dummy_line = 19
    dummy_line = 20
    start_response(status, headers)
    return [b'HELLO WORLD']


# Set up profiler
filters = [
    FilenameFilter("sample_for_async.py"),
]
app = LineProfilerMiddleware(app, filters=filters, async_write=False, stream=open('./test.log', 'w'))

if __name__ == '__main__':
    server = make_server('127.0.0.1', 8000, app)
    print("Serving on 127.0.0.1:8000...")
    server.serve_forever()

uwsgi.ini

[uwsgi]
module = sample_for_async
callable = app
http = :8000
master = true
processes = 1
enable-threads = true
lazy-apps = true

no profiling

[pid: 64542|app: 0|req: 1/1] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:51:10 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (1 switches on core 0)
[pid: 64542|app: 0|req: 2/2] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:51:11 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64542|app: 0|req: 3/3] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:51:11 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64542|app: 0|req: 4/4] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:51:11 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64542|app: 0|req: 5/5] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:51:11 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64542|app: 0|req: 6/6] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:51:11 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (1 switches on core 0)
[pid: 64542|app: 0|req: 7/7] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:51:11 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (1 switches on core 0)
[pid: 64542|app: 0|req: 8/8] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:51:11 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64542|app: 0|req: 9/9] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:51:11 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64542|app: 0|req: 10/10] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:51:11 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (1 switches on core 0)

async write(False)

[pid: 64763|app: 0|req: 1/1] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:56:03 2018] GET / => generated 11 bytes in 7 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64763|app: 0|req: 2/2] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:56:03 2018] GET / => generated 11 bytes in 1 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64763|app: 0|req: 3/3] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:56:03 2018] GET / => generated 11 bytes in 1 msecs (HTTP/1.1 200) 1 headers in 60 bytes (1 switches on core 0)
[pid: 64763|app: 0|req: 4/4] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:56:03 2018] GET / => generated 11 bytes in 1 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64763|app: 0|req: 5/5] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:56:03 2018] GET / => generated 11 bytes in 1 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64763|app: 0|req: 6/6] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:56:03 2018] GET / => generated 11 bytes in 1 msecs (HTTP/1.1 200) 1 headers in 60 bytes (1 switches on core 0)
[pid: 64763|app: 0|req: 7/7] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:56:03 2018] GET / => generated 11 bytes in 1 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64763|app: 0|req: 8/8] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:56:03 2018] GET / => generated 11 bytes in 1 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64763|app: 0|req: 9/9] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:56:03 2018] GET / => generated 11 bytes in 1 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64763|app: 0|req: 10/10] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:56:03 2018] GET / => generated 11 bytes in 2 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)

async write(True)

[pid: 64972|app: 0|req: 1/1] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:58:02 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64972|app: 0|req: 2/2] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:58:02 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64972|app: 0|req: 3/3] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:58:02 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64972|app: 0|req: 4/4] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:58:02 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64972|app: 0|req: 5/5] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:58:02 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64972|app: 0|req: 6/6] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:58:02 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (1 switches on core 0)
[pid: 64972|app: 0|req: 7/7] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:58:02 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64972|app: 0|req: 8/8] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:58:02 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64972|app: 0|req: 9/9] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:58:02 2018] GET / => generated 11 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)
[pid: 64972|app: 0|req: 10/10] 127.0.0.1 () {28 vars in 307 bytes} [Sun Aug 19 17:58:02 2018] GET / => generated 11 bytes in 1 msecs (HTTP/1.1 200) 1 headers in 60 bytes (2 switches on core 0)

async_write=True is faster than async_write=False avg 1ms.

is this data convinicing?

@ymyzk

This comment has been minimized.

Copy link
Owner

ymyzk commented Aug 19, 2018

I think latency of 1ms/req is worth dealing with. Thanks for sharing data!

Some clean up seems to be required before this branch is got merged. I'll work on it later.

@denzow denzow force-pushed the denzow:master branch from febbae1 to aa8cc2a Aug 19, 2018

@ymyzk ymyzk changed the base branch from master to async-stream Aug 23, 2018

@ymyzk ymyzk merged commit df8ae09 into ymyzk:async-stream Aug 23, 2018

1 check failed

continuous-integration/travis-ci/pr The Travis CI build failed
Details

@ymyzk ymyzk referenced this pull request Aug 23, 2018

Merged

Add async stream support #12

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment