[hunchentoot-devel] Hunchentoot performance

[vseguip at gmail.com]

On Dec 30, 2007 12:22 AM, Edi Weitz <edi at agharta.de> wrote:
> On Wed, 26 Dec 2007 22:27:40 +0600, Ivan Boldyrev <boldyrev+nospam at cgitftp.uiggm.nsc.ru> wrote:
>
> > For example, such low-level method as flexi-streams::unread-char%
> > calls flexi-streams:translate-char that uses
> > with-output-to-sequence.
>
> Can you check with the latest release (0.14.0) of FLEXI-STREAMS and
> see if it makes a difference for you?
>

Hi Edi,
 It definitely makes a difference, get-request-data certainly is not
on the top list anymore but write-header-line still tops right there
(flexi-streams 0.14) using sendfile system call:

ab -n 1000 -k  -c 1 http://localhost:8000/test2.jpg


  seconds  |    consed   |   calls   |  sec/call  |  name
-------------------------------------------------------------
     0.475 | 199,787,592 |     6,006 |   0.000079 | WRITE-HEADER-LINE
     0.276 |  59,215,472 |     1,001 |   0.000276 | LOG-MESSAGE
     0.140 |           0 |     1,001 |   0.000139 | SENDTHEFILE


It looks like write-header-line still takes an inordinate amount of
time for no good reason so I changed it to first build a string and
the output it to the stream:

(defmethod write-header-line ((mod-lisp-p (eql nil)) key value)
  "Accepts strings KEY and VALUE and writes them directly to the
client as an HTTP header line."
  (let ((header-lines  (with-output-to-string (str)
                         (write-string key str)
                         (write-string ": "  str)
                         ;; remove line breaks
                         (write-string (regex-replace-all "[\\r\\n]"
value " ")  str)
                         (write-string +crlf+  str))))
    (write-sequence header-lines *hunchentoot-stream*)))

This seemed to work very well, and now write-header-line is down to
tens of millisecond range, (maybe using write-string on the
*hunchentoot-stream* was causing a flush on the socket each time?):

  seconds  |    consed   |   calls   |  sec/call  |  name
-------------------------------------------------------------
     0.256 |  57,464,072 |     1,001 |   0.000256 | LOG-MESSAGE
     0.176 |           0 |     1,001 |   0.000175 | SENDTHEFILE
     0.089 |  11,123,696 |   277,277 |  0.0000003 |
FLEXI-STREAMS::CHAR-TO-OCTETS
     0.084 |  16,824,960 |     1,001 |   0.000083 | RFC-1123-DATE
     0.080 |  14,609,960 |     1,001 |   0.000079 | ISO-TIME
     0.071 |     818,104 |     2,005 |   0.000035 | FLEXI-STREAMS::SET-CLASS
     0.047 |      12,264 |     1,002 |   0.000047 | FORCE-OUTPUT*
     0.046 |           0 |   277,277 |  0.0000002 | FLEXI-STREAMS::WRITE-BYTE*
     0.035 |           0 |   130,130 |  0.0000003 | (SETF
FLEXI-STREAMS::FLEXI-STREAM-LAST-CHAR-CODE)
     0.032 |   1,514,000 |     1,001 |   0.000031 | SERVER-NAME-HEADER

 Just for the sake of it, I redefined log-messsage to a "do-nothing"
function and  this is what I got:

  seconds  |    consed   |   calls   |  sec/call  |  name
-------------------------------------------------------------
     0.192 |           0 |     1,001 |   0.000191 | SENDTHEFILE
     0.139 |  12,404,872 |     1,001 |   0.000139 | HANDLE-STATIC-SENDFILE
     0.103 |   4,741,480 |     2,005 |   0.000051 | FLEXI-STREAMS::SET-CLASS
     0.100 |  16,327,208 |     1,001 |   0.000099 | RFC-1123-DATE
     0.097 |  18,786,488 |   126,127 |   0.000001 | FLEXI-STREAMS::READ-BYTE*
     0.074 |           0 |   182,182 |  0.0000004 | FLEXI-STREAMS::WRITE-BYTE*
     0.063 |           0 |   130,132 |  0.0000005 | (SETF FLEXI-STREAM-POSITION)
     0.055 |     750,888 |     1,002 |   0.000055 | FORCE-OUTPUT*
     0.053 |  50,860,872 |     6,006 |   0.000009 | WRITE-HEADER-LINE

Now it seems like rfc-1123-date could do with some optimization, but
all in all I'm getting 465 req/sec wich is a very nice performance
improvement.
Cheers,
   V. Seguí