On Dec 30, 2007 12:22 AM, Edi Weitz edi@agharta.de wrote:
On Wed, 26 Dec 2007 22:27:40 +0600, Ivan Boldyrev boldyrev+nospam@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í