StackOverflow2013

Note that there are some explanatory texts on larger screens.

plurals

POBad Django / uwsgi performance
text
Body
copied!<p>I am running a django app with nginx & uwsgi. Here's how i run uwsgi:</p> <pre><code>sudo uwsgi -b 25000 --chdir=/www/python/apps/pyapp --module=wsgi:application --env DJANGO_SETTINGS_MODULE=settings --socket=/tmp/pyapp.socket --cheaper=8 --processes=16 --harakiri=10 --max-requests=5000 --vacuum --master --pidfile=/tmp/pyapp-master.pid --uid=220 --gid=499 </code></pre> <p>& nginx configurations:</p> <pre><code>server { listen 80; server_name test.com root /www/python/apps/pyapp/; access_log /var/log/nginx/test.com.access.log; error_log /var/log/nginx/test.com.error.log; # https://docs.djangoproject.com/en/dev/howto/static-files/#serving-static-files-in-production location /static/ { alias /www/python/apps/pyapp/static/; expires 30d; } location /media/ { alias /www/python/apps/pyapp/media/; expires 30d; } location / { uwsgi_pass unix:///tmp/pyapp.socket; include uwsgi_params; proxy_read_timeout 120; } # what to serve if upstream is not available or crashes #error_page 500 502 503 504 /media/50x.html; } </code></pre> <p>Here comes the problem. When doing "ab" (ApacheBenchmark) on the server i get the following results: </p> <p>nginx version: nginx version: nginx/1.2.6</p> <p>uwsgi version:1.4.5</p> <pre><code>Server Software: nginx/1.0.15 Server Hostname: pycms.com Server Port: 80 Document Path: /api/nodes/mostviewed/8/?format=json Document Length: 8696 bytes Concurrency Level: 100 Time taken for tests: 41.232 seconds Complete requests: 1000 Failed requests: 0 Write errors: 0 Total transferred: 8866000 bytes HTML transferred: 8696000 bytes Requests per second: 24.25 [#/sec] (mean) Time per request: 4123.216 [ms] (mean) Time per request: 41.232 [ms] (mean, across all concurrent requests) Transfer rate: 209.99 [Kbytes/sec] received </code></pre> <p>While running on 500 concurrency level</p> <pre><code>oncurrency Level: 500 Time taken for tests: 2.175 seconds Complete requests: 1000 Failed requests: 50 (Connect: 0, Receive: 0, Length: 50, Exceptions: 0) Write errors: 0 Non-2xx responses: 950 Total transferred: 629200 bytes HTML transferred: 476300 bytes Requests per second: 459.81 [#/sec] (mean) Time per request: 1087.416 [ms] (mean) Time per request: 2.175 [ms] (mean, across all concurrent requests) Transfer rate: 282.53 [Kbytes/sec] received </code></pre> <p>As you can see... all requests on the server fail with either timeout errors or "Client prematurely disconnected" or:</p> <pre><code>writev(): Broken pipe [proto/uwsgi.c line 124] during GET /api/nodes/mostviewed/9/?format=json </code></pre> <p>Here's a little bit more about my application: Basically, it's a collection of models that reflect MySQL tables which contain all the content. At the frontend, i have django-rest-framework which serves json content to the clients.</p> <p>I've installed django-profiling & django debug toolbar to see whats going on. On django-profiling here's what i get when running a single request:</p> <pre><code>Instance wide RAM usage Partition of a set of 147315 objects. Total size = 20779408 bytes. Index Count % Size % Cumulative % Kind (class / dict of class) 0 63960 43 5726288 28 5726288 28 str 1 36887 25 3131112 15 8857400 43 tuple 2 2495 2 1500392 7 10357792 50 dict (no owner) 3 615 0 1397160 7 11754952 57 dict of module 4 1371 1 1236432 6 12991384 63 type 5 9974 7 1196880 6 14188264 68 function 6 8974 6 1076880 5 15265144 73 types.CodeType 7 1371 1 1014408 5 16279552 78 dict of type 8 2684 2 340640 2 16620192 80 list 9 382 0 328912 2 16949104 82 dict of class <607 more rows. Type e.g. '_.more' to view.> CPU Time for this request 11068 function calls (10158 primitive calls) in 0.064 CPU seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.064 0.064 /usr/lib/python2.6/site-packages/django/views/generic/base.py:44(view) 1 0.000 0.000 0.064 0.064 /usr/lib/python2.6/site-packages/django/views/decorators/csrf.py:76(wrapped_view) 1 0.000 0.000 0.064 0.064 /usr/lib/python2.6/site-packages/rest_framework/views.py:359(dispatch) 1 0.000 0.000 0.064 0.064 /usr/lib/python2.6/site-packages/rest_framework/generics.py:144(get) 1 0.000 0.000 0.064 0.064 /usr/lib/python2.6/site-packages/rest_framework/mixins.py:46(list) 1 0.000 0.000 0.038 0.038 /usr/lib/python2.6/site-packages/rest_framework/serializers.py:348(data) 21/1 0.000 0.000 0.038 0.038 /usr/lib/python2.6/site-packages/rest_framework/serializers.py:273(to_native) 21/1 0.000 0.000 0.038 0.038 /usr/lib/python2.6/site-packages/rest_framework/serializers.py:190(convert_object) 11/1 0.000 0.000 0.036 0.036 /usr/lib/python2.6/site-packages/rest_framework/serializers.py:303(field_to_native) 13/11 0.000 0.000 0.033 0.003 /usr/lib/python2.6/site-packages/django/db/models/query.py:92(__iter__) 3/1 0.000 0.000 0.033 0.033 /usr/lib/python2.6/site-packages/django/db/models/query.py:77(__len__) 4 0.000 0.000 0.030 0.008 /usr/lib/python2.6/site-packages/django/db/models/sql/compiler.py:794(execute_sql) 1 0.000 0.000 0.021 0.021 /usr/lib/python2.6/site-packages/django/views/generic/list.py:33(paginate_queryset) 1 0.000 0.000 0.021 0.021 /usr/lib/python2.6/site-packages/django/core/paginator.py:35(page) 1 0.000 0.000 0.020 0.020 /usr/lib/python2.6/site-packages/django/core/paginator.py:20(validate_number) 3 0.000 0.000 0.020 0.007 /usr/lib/python2.6/site-packages/django/core/paginator.py:57(_get_num_pages) 4 0.000 0.000 0.020 0.005 /usr/lib/python2.6/site-packages/django/core/paginator.py:44(_get_count) 1 0.000 0.000 0.020 0.020 /usr/lib/python2.6/site-packages/django/db/models/query.py:340(count) 1 0.000 0.000 0.020 0.020 /usr/lib/python2.6/site-packages/django/db/models/sql/query.py:394(get_count) 1 0.000 0.000 0.020 0.020 /usr/lib/python2.6/site-packages/django/db/models/query.py:568(_prefetch_related_objects) 1 0.000 0.000 0.020 0.020 /usr/lib/python2.6/site-packages/django/db/models/query.py:1596(prefetch_related_objects) 4 0.000 0.000 0.020 0.005 /usr/lib/python2.6/site-packages/django/db/backends/util.py:36(execute) 1 0.000 0.000 0.020 0.020 /usr/lib/python2.6/site-packages/django/db/models/sql/query.py:340(get_aggregation) 5 0.000 0.000 0.020 0.004 /usr/lib64/python2.6/site-packages/MySQLdb/cursors.py:136(execute) 2 0.000 0.000 0.020 0.010 /usr/lib/python2.6/site-packages/django/db/models/query.py:1748(prefetch_one_level) 4 0.000 0.000 0.020 0.005 /usr/lib/python2.6/site-packages/django/db/backends/mysql/base.py:112(execute) 5 0.000 0.000 0.019 0.004 /usr/lib64/python2.6/site-packages/MySQLdb/cursors.py:316(_query) 60 0.000 0.000 0.018 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:231(iterator) 5 0.012 0.002 0.015 0.003 /usr/lib64/python2.6/site-packages/MySQLdb/cursors.py:278(_do_query) 60 0.000 0.000 0.013 0.000 /usr/lib/python2.6/site-packages/django/db/models/sql/compiler.py:751(results_iter) 30 0.000 0.000 0.010 0.000 /usr/lib/python2.6/site-packages/django/db/models/manager.py:115(all) 50 0.000 0.000 0.009 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:870(_clone) 51 0.001 0.000 0.009 0.000 /usr/lib/python2.6/site-packages/django/db/models/sql/query.py:235(clone) 4 0.000 0.000 0.009 0.002 /usr/lib/python2.6/site-packages/django/db/backends/__init__.py:302(cursor) 4 0.000 0.000 0.008 0.002 /usr/lib/python2.6/site-packages/django/db/backends/mysql/base.py:361(_cursor) 1 0.000 0.000 0.008 0.008 /usr/lib64/python2.6/site-packages/MySQLdb/__init__.py:78(Connect) 910/208 0.003 0.000 0.008 0.000 /usr/lib64/python2.6/copy.py:144(deepcopy) 22 0.000 0.000 0.007 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:619(filter) 22 0.000 0.000 0.007 0.000 /usr/lib/python2.6/site-packages/django/db/models/query.py:633(_filter_or_exclude) 20 0.000 0.000 0.005 0.000 /usr/lib/python2.6/site-packages/django/db/models/fields/related.py:560(get_query_set) 1 0.000 0.000 0.005 0.005 /usr/lib64/python2.6/site-packages/MySQLdb/connections.py:8() </code></pre> <p>..etc</p> <p>However, django-debug-toolbar shows the following:</p> <pre><code>Resource Usage Resource Value User CPU time 149.977 msec System CPU time 119.982 msec Total CPU time 269.959 msec Elapsed time 326.291 msec Context switches 11 voluntary, 40 involuntary and 5 queries in 27.1 ms </code></pre> <p>The problem is that "top" shows the load average rising quickly and apache benchmark which i ran both on the local server and from a remote machine within the network shows that i am not serving many requests / second. What is the problem? this is as far as i could reach when profiling the code so it would be appreciated if someone can point of what i am doing here.</p> <p><strong>Edit (23/02/2013): Adding more details based on Andrew Alcock's answer:</strong> The points that require my attention / answer are (3)(3) I've executed "show global variables" on MySQL and found out that MySQL configurations had 151 for max_connections setting which is more than enough to serve the workers i am starting for uwsgi.</p> <p>(3)(4)(2) The single request i am profiling is the heaviest one. It executes 4 queries according to django-debug-toolbar. What happens is that all queries run in: 3.71, 2.83, 0.88, 4.84 ms respectively.</p> <p>(4) Here you're referring to memory paging? if so, how could i tell? </p> <p>(5) On 16 workers, 100 concurrency rate, 1000 requests the load average goes up to ~ 12 I ran the tests on different number of workers (concurrency level is 100):</p> <ol> <li>1 worker, load average ~ 1.85, 19 reqs / second, Time per request: 5229.520, 0 non-2xx</li> <li>2 worker, load average ~ 1.5, 19 reqs / second, Time per request: 516.520, 0 non-2xx</li> <li>4 worker, load average ~ 3, 16 reqs / second, Time per request: 5929.921, 0 non-2xx</li> <li>8 worker, load average ~ 5, 18 reqs / second, Time per request: 5301.458, 0 non-2xx</li> <li>16 worker, load average ~ 19, 15 reqs / second, Time per request: 6384.720, 0 non-2xx</li> </ol> <p>AS you can see, the more workers we have, the more load we have on the system. I can see in uwsgi's daemon log that the response time in milliseconds increases when i increase the number of workers.</p> <p>On 16 workers, running 500 concurrency level requests uwsgi starts loggin the errors:</p> <pre><code> writev(): Broken pipe [proto/uwsgi.c line 124] </code></pre> <p>Load goes up to ~ 10 as well. and the tests don't take much time because non-2xx responses are 923 out of 1000 which is why the response here is quite fast as it's almost empty. Which is also a reply to your point #4 in the summary.</p> <p>Assuming that what i am facing here is an OS latency based on I/O and networking, what is the recommended action to scale this up? new hardware? bigger server?</p> <p>Thanks</p>

Querying!

Guidance

An individual column

Larger individual text columns get their own page to allow for proper reading.

SQuiL has stopped working due to an internal error.

If you are curious you may find further information in the browser console, which is accessible through the devtools (F12).

Reload