paste.httpserver والتباطؤ مع http/1.1 keep-alive ؛ تم اختباره مع HTTPERF و AB

Question

لدي خادم ويب يعتمد على paste.httpserver باعتباره adapater بين HTTP و WSGI. عندما أقوم بإجراء قياسات للأداء مع HTTPERF ، يمكنني القيام بأكثر من 1000 طلب في الثانية إذا بدأت طلبًا جديدًا في كل مرة باستخدام--Num-Conn. إذا قمت بدلاً من ذلك بإعادة استخدام الاتصال باستخدام-Num-Call ، فستحصل على حوالي 11 طلبًا في الثانية ، 1/100 من السرعة.

إذا جربت ab أحصل على مهلة.

اختباراتي

% ./httperf --server localhost --port 8080 --num-conn 100
...
Request rate: 1320.4 req/s (0.8 ms/req)
...

و

% ./httperf --server localhost --port 8080 --num-call 100
...
Request rate: 11.2 req/s (89.4 ms/req)
...

إليك خادمًا بسيطًا مستنسخًا

from paste import httpserver

def echo_app(environ, start_response):
    n = 10000
    start_response("200 Ok", [("Content-Type", "text/plain"),
                              ("Content-Length", str(n))])
    return ["*" * n]

httpserver.serve(echo_app, protocol_version="HTTP/1.1")

إنه خادم متعدد الخيوط ، وهو أمر صعب. إليك تباينًا واحدًا مترابدًا:

from paste import httpserver

class MyHandler(httpserver.WSGIHandler):
    sys_version = None
    server_version = "MyServer/0.0"
    protocol_version = "HTTP/1.1"

    def log_request(self, *args, **kwargs):
        pass


def echo_app(environ, start_response):
    n = 10000
    start_response("200 Ok", [("Content-Type", "text/plain"),
                              ("Content-Length", str(n))])
    return ["*" * n]

# WSGIServerBase is single-threaded
server = httpserver.WSGIServerBase(echo_app, ("localhost", 8080), MyHandler)
server.handle_request()

التنميط مع

% python2.6 -m cProfile -o paste.prof paste_slowdown.py

وضربها مع

%httperf --client=0/1 --server=localhost --port=8080 --uri=/ \ 
   --send-buffer=4096 --recv-buffer=16384 --num-conns=1 --num-calls=500

أحصل على ملف تعريف مثل

>>> p=pstats.Stats("paste.prof")
>>> p.strip_dirs().sort_stats("cumulative").print_stats()
Sun Nov 22 21:31:57 2009    paste.prof

         109749 function calls in 46.570 CPU seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   46.571   46.571 {execfile}
        1    0.001    0.001   46.570   46.570 paste_slowdown.py:2(<module>)
        1    0.000    0.000   46.115   46.115 SocketServer.py:250(handle_request)
        1    0.000    0.000   44.675   44.675 SocketServer.py:268(_handle_request_noblock)
        1    0.000    0.000   44.675   44.675 SocketServer.py:301(process_request)
        1    0.000    0.000   44.675   44.675 SocketServer.py:318(finish_request)
        1    0.000    0.000   44.675   44.675 SocketServer.py:609(__init__)
        1    0.000    0.000   44.675   44.675 httpserver.py:456(handle)
        1    0.001    0.001   44.675   44.675 BaseHTTPServer.py:325(handle)
      501    0.006    0.000   44.674    0.089 httpserver.py:440(handle_one_request)
     2001    0.020    0.000   44.383    0.022 socket.py:373(readline)
      501   44.354    0.089   44.354    0.089 {method 'recv' of '_socket.socket' objects}
        1    1.440    1.440    1.440    1.440 {select.select}
         ....

يمكنك أن ترى أن كل الوقت تقريبًا في RECV.

قررت أن تنقذ httpref وكتابة طلب http/1.1 مع الحفاظ على الحافة وإرساله باستخدام netcat:

GET / HTTP/1.1
Location: localhost
Connection: Keep-Alive
Content-Length: 0

GET / HTTP/1.1
Location: localhost
Connection: Keep-Alive
Content-Length: 0

 ... repeat 97 more times, to have 99 keep-alives in total ...

GET / HTTP/1.1
Location: localhost
Connection: Close
Content-Length: 0

الذي أرسلته مع

nc localhost 8080 < ~/src/send_to_paste.txt

كان إجمالي الوقت لـ 100 طلب هو 0.03 ثانية ، لذا فهو أداء جيد جدًا.

هذا يشير إلى أن httperf يرتكب شيئًا خاطئًا (لكنه جزء من التعليمات البرمجية المستخدمة على نطاق واسع) ، لذلك حاولت "AB"

% ab -n 100 -k localhost:8080/
This is ApacheBench, Version 1.3d <$Revision: 1.73 $> apache-1.3
Copyright (c) 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Copyright (c) 2006 The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)...
Server timed out

: Operation now in progress

صياغة الخادم ، فإنه يتعامل مع طلب واحد وينتظر الثانية.

أي فكرة عما يحدث؟

Answer 1

بعد بعض الجهد ، يبدو أنه أيضًا خوارزمية ناجل أو تأخر ACK ، أو التفاعلات بينهما. يختفي إذا فعلت شيئًا مثل

server.socket.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)

كيف قمت بتتبعها؟ أولاً ، قمت بتكوين كل "RECV" في Socket.py ، لذلك يمكنني معرفة أي RECV كان ينتظر. كنت أرى حوالي 5 RECV من أصل 11 كان تأخير ما يقرب من 200 مللي ثانية. لم أستطع معرفة سبب وجود أي تأخير. بعد ذلك ، استخدمت Wireshark لمشاهدة الرسائل ولاحظت أن الإرسال من الخادم إلى العميل الذي كان له التأخير. هذا يعني شيئًا في طبقة TCP في الرسائل الصادرة من موكلي.

اقترح أحد الأصدقاء ما هو واضح ، وبحثت عن "تأخير مقبس 200 مللي ثانية" ووجدت أوصافًا لهذه المشكلة.

تقرير لصق TRAC هو في http://trac.pythonpaste.org/pythonpaste/ticket/392 جنبا إلى جنب مع التصحيح الذي يتيح TCP_NODELAY عندما يستخدم المعالج HTTP/1.1.