[s-xml-rpc-devel] significant speed increase in SBCL

[Sven Van Caekenberghe]

Will,

On 17 Feb 2008, at 02:35, William Halliburton wrote:

> Hello all.  Using s-xml-rpc with SBCL 1.0.14 and was seeing a lot of  
> consing.
> Just attempted to hit some low hanging fruit and got lucky.
>
> Please excuse any wierd table cut-and-paste formatting below.
>
> I am using hunchentoot as the front end and was calling as such:
>
> (handle-xml-rpc-call (raw-post-data :want-stream t) id)
>
> Profiling gave: (note that the lisp test system was calling itself  
> so both the call and answer are shown,
> but I really only care about the answer.)
>
> ;;   seconds  |    consed   |  calls |  sec/call  |  name
> ;; ----------------------------------------------------------
> ;;     10.430 | 107,109,496 |     32 |   0.325942 | S-XML-RPC:XML- 
> RPC-CALL
> ;;      5.583 |  57,897,032 |  1,670 |   0.003343 | S-XML::PARSE- 
> IDENTIFIER
> ;;      1.179 |  12,740,176 |    835 |   0.001412 | S-XML::PARSE-XML- 
> ELEMENT
> ;;      1.073 |   9,625,512 |  1,845 |   0.000582 | S-XML::PARSE- 
> WHITESPACE
> ;;      0.988 |   8,591,704 |    239 |   0.004132 | S-XML::PARSE-TEXT
> ;;      0.425 |   4,491,216 |    899 |   0.000472 | S-XML::SKIP- 
> WHITESPACE
> ;;      0.111 |      53,968 |  1,670 |   0.000067 | S-XML:RESOLVE- 
> IDENTIFIER
> ;;      0.041 |           0 | 11,810 |   0.000003 | S- 
> XML::IDENTIFIER-CHAR-P
> ;;      0.028 |     516,088 |     64 |   0.000436 | S-XML- 
> RPC::FORMAT-HEADER
> ;;      0.021 |         720 |  1,670 |   0.000013 | S-XML::FIND- 
> NAMESPACE-BINDING
> ;;      0.021 |           0 |  1,845 |   0.000011 | S-XML::GET-BUFFER
> ;;      0.013 |           0 |  1,670 |   0.000008 | S-XML:SPLIT- 
> IDENTIFIER
> ;;      0.011 |           0 |    835 |   0.000013 | S-XML- 
> RPC::DECODE-XML-RPC-FINISH-ELEMENT
>
>
> When I changed handle-xml-rpc-call to take a string as make its own  
> stream as such:
>
> (handle-xml-rpc-call-string (raw-post-data) id)
>
>
> (defun handle-xml-rpc-call-string (string id)
>     (with-input-from-string (in string)
>       (let ((call (decode-xml-rpc in)))
>         (let ((result (apply *xml-rpc-call-hook*
>                              (first call)
>                              (rest call))))
>           (encode-xml-rpc-result result))))))
>
> I now profile:
>
>   seconds  |   consed   |  calls |  sec/call  |  name
> ---------------------------------------------------------
>      0.985 | 15,135,160 |     32 |   0.030786 | S-XML-RPC:XML-RPC-CALL
>      0.023 |    118,296 |  1,670 |   0.000014 | S-XML:RESOLVE- 
> IDENTIFIER
>      0.021 |          0 | 11,810 |   0.000002 | S-XML::IDENTIFIER- 
> CHAR-P
>      0.019 |    769,856 |     32 |   0.000593 | RPC-HANDLER
>      0.016 |    459,688 |     64 |   0.000248 | S-XML-RPC::FORMAT- 
> HEADER
>      0.013 |     11,128 |    899 |   0.000014 | S-XML::SKIP-WHITESPACE
>      0.010 |     12,536 |  1,670 |   0.000006 | S-XML::PARSE- 
> IDENTIFIER
>      0.009 |          0 |  1,670 |   0.000006 | S-XML::GET-MINI-BUFFER
>      0.009 |          0 |  1,670 |   0.000006 | S-XML:SPLIT-IDENTIFIER
>      0.004 |          0 |      8 |   0.000498 | UPDATE-SEARCH-STRING
>      0.004 |      7,944 |     32 |   0.000118 | S-XML-RPC::ENCODE- 
> XML-RPC-RESULT
>
> For a 10 fold speed increase.
>
> I just thought this might be of use to someone down the line.
>
> Will

Thanks for trying to optimize s-xml-rpc, a 10-fold speed-increase  
would be nice indeed.

However, could you please specify your change/patch against the latest  
version of xml-rpc.lisp version 1.11 from cvs head ? That function is  
considerably larger. But the key point of your change would be the  
same. Having said that, I feel that the speed increase and/or orginal  
slowness has something to do with the differences between (raw-post- 
data :want-stream t) and (raw-post-data) rather than with the s-xml- 
rpc code. The stream delivered by hunchentoot is either slow or slow  
as used by the xml parser (char by char). This is some kind of network  
stream so maybe there is some logic to this.

Anyway, you could use

(with-input-from-string (in (raw-post-data))
   (handle-xml-rpc-call-string in id))

to get your optimization and without touching the original code.

Still, the tip of consuming the post data all at once and then feeding  
it to s-xml-rpc as a string-stream still stands.

What do you think ?

Sven