{"action":"created","issue":{"url":"https://api.github.com/repos/saghul/uvwsgi/issues/4","repository_url":"https://api.github.com/repos/saghul/uvwsgi","labels_url":"https://api.github.com/repos/saghul/uvwsgi/issues/4/labels{/name}","comments_url":"https://api.github.com/repos/saghul/uvwsgi/issues/4/comments","events_url":"https://api.github.com/repos/saghul/uvwsgi/issues/4/events","html_url":"https://github.com/saghul/uvwsgi/issues/4","id":154868674,"number":4,"title":"High latency for second request","user":{"login":"peterdemin","id":1448666,"avatar_url":"https://avatars.githubusercontent.com/u/1448666?v=3","gravatar_id":"","url":"https://api.github.com/users/peterdemin","html_url":"https://github.com/peterdemin","followers_url":"https://api.github.com/users/peterdemin/followers","following_url":"https://api.github.com/users/peterdemin/following{/other_user}","gists_url":"https://api.github.com/users/peterdemin/gists{/gist_id}","starred_url":"https://api.github.com/users/peterdemin/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/peterdemin/subscriptions","organizations_url":"https://api.github.com/users/peterdemin/orgs","repos_url":"https://api.github.com/users/peterdemin/repos","events_url":"https://api.github.com/users/peterdemin/events{/privacy}","received_events_url":"https://api.github.com/users/peterdemin/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":3,"created_at":"2016-05-14T18:30:04Z","updated_at":"2016-06-23T10:44:52Z","closed_at":null,"body":"I copied example flask \"hello world\" app with uvwsgi:\r\n```python\r\nfrom flask import Flask\r\n\r\napp = Flask(__name__)\r\n\r\n@app.route('/')\r\ndef index():\r\n    return 'hello world!'\r\n```\r\nand launched it with `uvwsgi echo:app --port 11111`.\r\n\r\nOn the same host I started IPython and called profiler.\r\nFor single request service responds in 4 ms, which is acceptable for python.\r\n```\r\nIn [1]: %prun -s cumulative s.get(\"http://127.0.0.1:11111\")\r\n         1421 function calls (1417 primitive calls) in 0.004 seconds\r\n\r\n   Ordered by: cumulative time\r\n\r\n   ncalls  tottime  percall  cumtime  percall filename:lineno(function)\r\n        1    0.000    0.000    0.004    0.004 <string>:1(<module>)\r\n        1    0.000    0.000    0.004    0.004 sessions.py:479(get)\r\n        1    0.000    0.000    0.004    0.004 sessions.py:398(request)\r\n        1    0.000    0.000    0.002    0.002 sessions.py:549(send)\r\n        1    0.000    0.000    0.002    0.002 adapters.py:356(send)\r\n        1    0.000    0.000    0.002    0.002 sessions.py:358(prepare_request)\r\n        1    0.000    0.000    0.002    0.002 connectionpool.py:444(urlopen)\r\n        1    0.000    0.000    0.001    0.001 connectionpool.py:327(_make_request)\r\n        1    0.000    0.000    0.001    0.001 httplib.py:1099(getresponse)\r\n        1    0.000    0.000    0.001    0.001 httplib.py:446(begin)\r\n        1    0.000    0.000    0.001    0.001 utils.py:96(get_netrc_auth)\r\n        6    0.000    0.000    0.001    0.000 socket.py:410(readline)\r\n        1    0.000    0.000    0.001    0.001 httplib.py:407(_read_status)\r\n        2    0.001    0.000    0.001    0.000 {method 'recv' of '_socket.socket' objects}\r\n```\r\n\r\nBut for second and all subsequent requests I observe degradation to ~40 ms:\r\n```\r\nIn [2]: %prun -s cumulative s.get(\"http://127.0.0.1:11111\"), s.get(\"http://127.0.0.1:11111\")\r\n\r\n         2842 function calls (2834 primitive calls) in 0.047 seconds\r\n\r\n   Ordered by: cumulative time\r\n\r\n   ncalls  tottime  percall  cumtime  percall filename:lineno(function)\r\n        1    0.000    0.000    0.047    0.047 <string>:1(<module>)\r\n        2    0.000    0.000    0.047    0.023 sessions.py:479(get)\r\n        2    0.000    0.000    0.047    0.023 sessions.py:398(request)\r\n        2    0.000    0.000    0.044    0.022 sessions.py:549(send)\r\n        3    0.041    0.014    0.041    0.014 {method 'recv' of '_socket.socket' objects}\r\n        2    0.000    0.000    0.039    0.020 models.py:727(content)\r\n       34    0.000    0.000    0.039    0.001 {method 'join' of 'str' objects}\r\n        4    0.000    0.000    0.039    0.010 models.py:660(generate)\r\n        4    0.000    0.000    0.039    0.010 response.py:332(stream)\r\n        2    0.000    0.000    0.039    0.020 response.py:272(read)\r\n        2    0.000    0.000    0.039    0.019 httplib.py:579(read)\r\n        2    0.000    0.000    0.039    0.019 socket.py:340(read)\r\n        2    0.000    0.000    0.004    0.002 adapters.py:356(send)\r\n        2    0.000    0.000    0.003    0.002 connectionpool.py:444(urlopen)\r\n        2    0.000    0.000    0.003    0.001 connectionpool.py:327(_make_request)\r\n        2    0.000    0.000    0.003    0.001 sessions.py:358(prepare_request)\r\n```\r\n\r\nThe bottleneck is in `socket.py:340(read)` indicating the problem on the service side.\r\nTo prove this I launched the same test against built-in HTTP server:\r\n```python\r\n#!/usr/bin/env python\r\nfrom BaseHTTPServer import HTTPServer, BaseHTTPRequestHandler\r\n\r\nclass RequestHandler(BaseHTTPRequestHandler):\r\n    def do_GET(self):\r\n        self.send_response(200)\r\n\r\nif __name__ == '__main__':\r\n    HTTPServer(('0.0.0.0', 11111), RequestHandler).serve_forever()\r\n```\r\nand got time for subsequent requests equal to the first."},"comment":{"url":"https://api.github.com/repos/saghul/uvwsgi/issues/comments/228013567","html_url":"https://github.com/saghul/uvwsgi/issues/4#issuecomment-228013567","issue_url":"https://api.github.com/repos/saghul/uvwsgi/issues/4","id":228013567,"user":{"login":"saghul","id":317464,"avatar_url":"https://avatars.githubusercontent.com/u/317464?v=3","gravatar_id":"","url":"https://api.github.com/users/saghul","html_url":"https://github.com/saghul","followers_url":"https://api.github.com/users/saghul/followers","following_url":"https://api.github.com/users/saghul/following{/other_user}","gists_url":"https://api.github.com/users/saghul/gists{/gist_id}","starred_url":"https://api.github.com/users/saghul/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/saghul/subscriptions","organizations_url":"https://api.github.com/users/saghul/orgs","repos_url":"https://api.github.com/users/saghul/repos","events_url":"https://api.github.com/users/saghul/events{/privacy}","received_events_url":"https://api.github.com/users/saghul/received_events","type":"User","site_admin":false},"created_at":"2016-06-23T10:44:52Z","updated_at":"2016-06-23T10:44:52Z","body":"Thanks @catroot! ❤️ "}}
{"actor":{"display_login":"saghul"}}