bug#12033: format should be faster

bug#12033: format should be faster

[nalaginrut]

Our "format" is rather slow, can we make it faster?
I can only output strings with display if I need an faster program,
which is not so elegant.

bug#12033: format should be faster

[Ludovic Courtès]

Hi!

nalaginrut <nalaginrut@gmail.com> skribis:

> Our "format" is rather slow,

What makes you say so?

Did you make sure that the output port you’re writing to is buffered
(this is not the case by default!)?  See ‘setvbuf’.

> can we make it faster?  I can only output strings with display if I
> need an faster program, which is not so elegant.

Until (ice-9 format) is loaded, ‘format’ is an alias for
‘simple-format’, which is implemented in C, less capable but faster than
(ice-9 format).  Perhaps that’s usable for your use case?

Thanks,
Ludo’.

bug#12033: format should be faster

[nalaginrut]

On Sun, 2012-08-19 at 00:19 +0200, Ludovic Courtès wrote: 
> Hi!
> 
> nalaginrut <nalaginrut@gmail.com> skribis:
> 
> > Our "format" is rather slow,
> 
> What makes you say so?
> 
> Did you make sure that the output port you’re writing to is buffered
> (this is not the case by default!)?  See ‘setvbuf’.
> 

OK, yes, I assumed the port will be buffered in default.
Should I set stdin/stdout(current-input-port/current-output-port) as
buffered each time?
But in my case, there's only current-output-port. And I set it as
buffered, the result is the same.

> > can we make it faster?  I can only output strings with display if I
> > need an faster program, which is not so elegant.
> 
> Until (ice-9 format) is loaded, ‘format’ is an alias for
> ‘simple-format’, which is implemented in C, less capable but faster than
> (ice-9 format).  Perhaps that’s usable for your use case?
> 


But I never use (ice-9 format).
There's ~15s difference between "display" and "format" in my laptop.
---------------code-1------------------
(define (main . args)
  (let* ((ll ((@ (srfi srfi-1) iota) (read) 1)) (len (length ll)) (m (1-
(/ len 2))))
    (display len)(newline)
    (let lp((a (list-head ll (1+ m))) (b (list-tail ll (1+ m))) (n 1))
      (and (< n len) 
   (for-each (lambda (x y) (display x)(display " ")(display y)(display "
")) a b)(newline)
   (lp (append (list 1 (car b)) (cdr a)) (append (cdr b) (list (list-ref
a m))) (1+ n))))))
-----------------end-------------------

--------------code-2-------------------
(define (main . args)
  (let* ((ll ((@ (srfi srfi-1) iota) (read) 1)) (len (length ll)) (m (1-
(/ len 2))))
    (display len)(newline)
    (let lp((a (list-head ll (1+ m))) (b (list-tail ll (1+ m))) (n 1))
      (and (< n len) 
   (for-each (lambda (x y) (format #t "~a ~a~%"  x y)) a b)
   (lp (append (list 1 (car b)) (cdr a)) (append (cdr b) (list (list-ref
a m))) (1+ n))))))
---------------end---------------------

time { echo 6000 | ./test 1>/dev/null ;} 

Code-1 is 0m30.326s
Code-2 is 0m45.310s

PS: Please use 6000 at least, or it's size is not representative.

> Thanks,
> Ludo’.

bug#12033: format should be faster

[Ludovic Courtès]

Hi,

Here’s slightly modified code:

--8<---------------cut here---------------start------------->8---
(use-modules (ice-9 time))

(define (d len)
  (let* ((ll ((@ (srfi srfi-1) iota) len 1)) (m (1- (/ len 2))))
    (time
     (with-output-to-port (%make-void-port "w")
       (lambda ()
        (let lp ((a (list-head ll (1+ m))) (b (list-tail ll (1+ m))) (n 1))
          (and (< n len)
               (for-each (lambda (x y)
                           (display x)(display " ")(display y)
                           (display " "))
                         a b)
               (newline)
               (lp (append (list 1 (car b)) (cdr a))
                   (append (cdr b) (list (list-ref a m)))
                   (1+ n)))))))))

(define (f len)
  (let* ((ll ((@ (srfi srfi-1) iota) len 1)) (m (1- (/ len 2))))
    (time
     (with-output-to-port (%make-void-port "w")
       (lambda ()
        (let lp ((a (list-head ll (1+ m))) (b (list-tail ll (1+ m))) (n 1))
          (and (< n len)
               (for-each (lambda (x y)
                           (simple-format #t "~a ~a~%" x y))
                         a b)
               (lp (append (list 1 (car b)) (cdr a))
                   (append (cdr b) (list (list-ref a m)))
                   (1+ n)))))))))
--8<---------------cut here---------------end--------------->8---

Here’s the difference I have:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> (f 4000)
clock utime stime cutime cstime gctime
 8.37  8.35  0.00   0.00   0.00   0.56
$9 = #f
scheme@(guile-user)> (d 4000)
clock utime stime cutime cstime gctime
 6.37  6.35  0.00   0.00   0.00   0.05
$10 = #f
--8<---------------cut here---------------end--------------->8---

So ‘simple-format’ is 30% slower than the series of ‘display’
etc. calls.

A profile from Callgrind shows that ~22% of the program with ‘f’ is
spent in ‘scm_c_substring’ and the allocations it entails.

Commit b908768a7ec79f78def344c464186a51f55b69e8 in stable-2.0 changes
the situation like this:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> (d 4000)
clock utime stime cutime cstime gctime
 6.46  6.45  0.00   0.00   0.00   0.08
$3 = #f
scheme@(guile-user)> (f 4000)
clock utime stime cutime cstime gctime
 5.47  5.44  0.01   0.00   0.00   0.25
$4 = #f
--8<---------------cut here---------------end--------------->8---

Now, ‘simple-format’ is 15% faster than ‘display’.  Hurray!  ;-)

So, I’m closing this bug.

Note that (ice-9 format) is an order of magnitude slower, though:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> (f 4000)
clock utime stime cutime cstime gctime
260.14 258.94  0.51   0.00   0.00  63.19
$1 = #f
--8<---------------cut here---------------end--------------->8---

Admittedly, this should be fixed, but that’s another story...

Thanks,
Ludo’.

bug#12033: closed (Re: bug#12033: format should be faster)

[Ludovic Courtès]

I wrote:

> Note that (ice-9 format) is an order of magnitude slower, though:
>
> scheme@(guile-user)> (f 4000)
> clock utime stime cutime cstime gctime
> 260.14 258.94  0.51   0.00   0.00  63.19
> $1 = #f
>
> Admittedly, this should be fixed, but that’s another story...

A bit of profiling shows this:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> ,pr (with-output-to-port (%make-void-port "w") (lambda () (let loop ((i 40000)) (or (zero? i) (begin (format #t "~a ~a~%" 'foo 'bar) (loop (1- i)))))))
%     cumulative   self             
time   seconds     seconds      name
 15.70      2.13      0.34  format
 10.74      1.39      0.23  tilde-dispatch
 10.74      0.96      0.23  call-with-output-string
  7.44      0.20      0.16  #<procedure b042600 at ice-9/r4rs.scm:236:3 (p)>
[...]
Sample count: 121
Total time: 2.183744831 seconds (0.77482795 seconds in GC)
--8<---------------cut here---------------end--------------->8---

Procedure #4 is ‘with-output-to-string’, so we can easily improve that
by using ‘call-with-output-string’ directly instead:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> ,pr (with-output-to-port (%make-void-port "w") (lambda () (let loop ((i 40000)) (or (zero? i) (begin (format #t "~a ~a~%" 'foo 'bar) (loop (1- i)))))))
%     cumulative   self             
time   seconds     seconds      name
 17.39      0.56      0.28  call-with-output-string
 14.13      0.24      0.23  #<procedure 11e5a1a0 at /home/ludo/src/guile/module/ice-9/format.scm:782:46 (p)>
 13.04      1.58      0.21  format
  9.78      1.27      0.16  format:format-work
[...]
Sample count: 92
Total time: 1.597127172 seconds (0.513423265 seconds in GC)
--8<---------------cut here---------------end--------------->8---

Commit 6c9220064d987deee813cfd933d50353d14d4c0f.

To be continued...

Ludo’.

bug#12033: closed (Re: bug#12033: format should be faster)

[nalaginrut]

On Tue, 2012-08-21 at 00:37 +0200, Ludovic Courtès wrote: 
> I wrote:
> 
> > Note that (ice-9 format) is an order of magnitude slower, though:
> >
> > scheme@(guile-user)> (f 4000)
> > clock utime stime cutime cstime gctime
> > 260.14 258.94  0.51   0.00   0.00  63.19
> > $1 = #f
> >
> > Admittedly, this should be fixed, but that’s another story...
> 
> A bit of profiling shows this:
> 
> --8<---------------cut here---------------start------------->8---
> scheme@(guile-user)> ,pr (with-output-to-port (%make-void-port "w") (lambda () (let loop ((i 40000)) (or (zero? i) (begin (format #t "~a ~a~%" 'foo 'bar) (loop (1- i)))))))
> %     cumulative   self             
> time   seconds     seconds      name
>  15.70      2.13      0.34  format
>  10.74      1.39      0.23  tilde-dispatch
>  10.74      0.96      0.23  call-with-output-string
>   7.44      0.20      0.16  #<procedure b042600 at ice-9/r4rs.scm:236:3 (p)>
> [...]


hi Ludo!
I recall something about tilde-displatch since you mentioned it.
A guy discussed the efficiency of format with me years ago, I talked
with Andy, but then I forgot it:

--------------------code-------------------
scheme@(guile-user)> ,profile (let lp ((i 10000)) (if (> i 0) (begin
(format #f "0x~2'0x, 0x~2'0x, 0x~2'0x" i i i) (lp (1- i)))))
%     cumulative   self             
time   seconds     seconds      name
22.58      0.56      0.23  tilde-dispatch
12.90      1.00      0.13  format
12.90      0.13      0.13  number->string
  8.06      0.13      0.08  format:out-char
  4.84      0.80      0.05  format:format-work
--------------------end------------------- 

In this case, we tried "0x~2'0x" and it's so slow that we can't bare it.
i=10000 is fast, but we need (* 600 80000)
And we found that "tilde-dispatch" cost too much. Is there any possible
to optimize it? 

> Sample count: 121
> Total time: 2.183744831 seconds (0.77482795 seconds in GC)
> --8<---------------cut here---------------end--------------->8---
> 
> Procedure #4 is ‘with-output-to-string’, so we can easily improve that
> by using ‘call-with-output-string’ directly instead:
> 
> --8<---------------cut here---------------start------------->8---
> scheme@(guile-user)> ,pr (with-output-to-port (%make-void-port "w") (lambda () (let loop ((i 40000)) (or (zero? i) (begin (format #t "~a ~a~%" 'foo 'bar) (loop (1- i)))))))
> %     cumulative   self             
> time   seconds     seconds      name
>  17.39      0.56      0.28  call-with-output-string
>  14.13      0.24      0.23  #<procedure 11e5a1a0 at /home/ludo/src/guile/module/ice-9/format.scm:782:46 (p)>
>  13.04      1.58      0.21  format
>   9.78      1.27      0.16  format:format-work
> [...]
> Sample count: 92
> Total time: 1.597127172 seconds (0.513423265 seconds in GC)
> --8<---------------cut here---------------end--------------->8---
> 
> Commit 6c9220064d987deee813cfd933d50353d14d4c0f.
> 
> To be continued...
> 
> Ludo’.

bug#12033: closed (Re: bug#12033: format should be faster)

[Noah Lavine]

Hello,

> --------------------code-------------------
> scheme@(guile-user)> ,profile (let lp ((i 10000)) (if (> i 0) (begin
> (format #f "0x~2'0x, 0x~2'0x, 0x~2'0x" i i i) (lp (1- i)))))
> %     cumulative   self
> time   seconds     seconds      name
> 22.58      0.56      0.23  tilde-dispatch
> 12.90      1.00      0.13  format
> 12.90      0.13      0.13  number->string
>   8.06      0.13      0.08  format:out-char
>   4.84      0.80      0.05  format:format-work
> --------------------end-------------------
>
> In this case, we tried "0x~2'0x" and it's so slow that we can't bare it.
> i=10000 is fast, but we need (* 600 80000)
> And we found that "tilde-dispatch" cost too much. Is there any possible
> to optimize it?

It seems clear that in this case, Guile "should" know how to dispatch
on the format string just once, outside of the loop, instead of doing
it in every iteration. What do people think of declaring format as a
macro? That wouldn't help instances of format that have a variable
format string, but I bet that's a lot less common than this case.

Noah

bug#12033: closed (Re: bug#12033: format should be faster)

[Ian Price]

Noah Lavine <noah.b.lavine@gmail.com> writes:

> It seems clear that in this case, Guile "should" know how to dispatch
> on the format string just once, outside of the loop, instead of doing
> it in every iteration. What do people think of declaring format as a
> macro? That wouldn't help instances of format that have a variable
> format string, but I bet that's a lot less common than this case.

Makes sense to me, though I'm not quite sure how that plays with (ice-9
format)'s side-effecting of the existing format binding. Though it was
meant as a toy, I wrote https://gist.github.com/3167775 ages ago, along
similar lines to this.

-- 
Ian Price -- shift-reset.com

"Programming is like pinball. The reward for doing it well is
the opportunity to do it again" - from "The Wizardy Compiled"

bug#12033: closed (Re: bug#12033: format should be faster)

[Ludovic Courtès]

Hi,

Noah Lavine <noah.b.lavine@gmail.com> skribis:

>> --------------------code-------------------
>> scheme@(guile-user)> ,profile (let lp ((i 10000)) (if (> i 0) (begin
>> (format #f "0x~2'0x, 0x~2'0x, 0x~2'0x" i i i) (lp (1- i)))))
>> %     cumulative   self
>> time   seconds     seconds      name
>> 22.58      0.56      0.23  tilde-dispatch
>> 12.90      1.00      0.13  format
>> 12.90      0.13      0.13  number->string
>>   8.06      0.13      0.08  format:out-char
>>   4.84      0.80      0.05  format:format-work
>> --------------------end-------------------
>>
>> In this case, we tried "0x~2'0x" and it's so slow that we can't bare it.
>> i=10000 is fast, but we need (* 600 80000)
>> And we found that "tilde-dispatch" cost too much. Is there any possible
>> to optimize it?
>
> It seems clear that in this case, Guile "should" know how to dispatch
> on the format string just once, outside of the loop, instead of doing
> it in every iteration.

I think Andy would say: “inline cache!”.  :-)

> What do people think of declaring format as a macro?

That’s tempting, but it breaks the ABI (so not for 2.0), and it breaks
for users who do ((@ (ice-9 format) format) #t "foo"), for instance.

Maybe we could have a ‘format*’ macro that does as much as possible of
the dispatch at compile-time?  The difficulty would be to factorize
dispatch code with the ‘format’ procedure.

Another (IMO less elegant) option would be to have an optional compiler
optimization pass that would do something similar.

Thanks,
Ludo’.

bug#12033: closed (Re: bug#12033: format should be faster)

[Noah Lavine]

Hi,

On Tue, Aug 21, 2012 at 7:37 AM, Ludovic Courtès <ludo@gnu.org> wrote:
> Hi,
>
> Noah Lavine <noah.b.lavine@gmail.com> skribis:
>
>>> --------------------code-------------------
>>> scheme@(guile-user)> ,profile (let lp ((i 10000)) (if (> i 0) (begin
>>> (format #f "0x~2'0x, 0x~2'0x, 0x~2'0x" i i i) (lp (1- i)))))
>>> %     cumulative   self
>>> time   seconds     seconds      name
>>> 22.58      0.56      0.23  tilde-dispatch
>>> 12.90      1.00      0.13  format
>>> 12.90      0.13      0.13  number->string
>>>   8.06      0.13      0.08  format:out-char
>>>   4.84      0.80      0.05  format:format-work
>>> --------------------end-------------------
>>>
>>> In this case, we tried "0x~2'0x" and it's so slow that we can't bare it.
>>> i=10000 is fast, but we need (* 600 80000)
>>> And we found that "tilde-dispatch" cost too much. Is there any possible
>>> to optimize it?
>>
>> It seems clear that in this case, Guile "should" know how to dispatch
>> on the format string just once, outside of the loop, instead of doing
>> it in every iteration.
>
> I think Andy would say: “inline cache!”.  :-)
>
>> What do people think of declaring format as a macro?
>
> That’s tempting, but it breaks the ABI (so not for 2.0), and it breaks
> for users who do ((@ (ice-9 format) format) #t "foo"), for instance.
>
> Maybe we could have a ‘format*’ macro that does as much as possible of
> the dispatch at compile-time?  The difficulty would be to factorize
> dispatch code with the ‘format’ procedure.

What I was hoping to do is have a macro that is also
identifier-syntax, so if format is used in a way that can't be
macroexpanded, it falls back to the procedure. I think I've seen an
example of this before, but I'm not sure where.

> Another (IMO less elegant) option would be to have an optional compiler
> optimization pass that would do something similar.

Yes, but I agree it's less elegant, because it splits the format logic
across two pieces of code, and puts some of it in the compiler, which
shouldn't really have to know about it. This is a problem that I'd
like to solve more generally, by letting functions tell the compiler
how to optimize themselves, but that's a big project, and using a
macro seemed like a much simpler way to get the same effect here.

However, I wonder if the partial evaluator would actually solve this
problem if it knew how to do cross-module inlining. That's another big
project, but it could be a way to solve this problem and keep format
as a function.

> Thanks,
> Ludo’.

Thanks,
Noah

bug#12033: closed (Re: bug#12033: format should be faster)

[Ludovic Courtès]

Hi,

Noah Lavine <noah.b.lavine@gmail.com> skribis:

> What I was hoping to do is have a macro that is also
> identifier-syntax, so if format is used in a way that can't be
> macroexpanded, it falls back to the procedure. I think I've seen an
> example of this before, but I'm not sure where.

Yes, ‘define-inlinable’ does that, for instance.

[...]

> However, I wonder if the partial evaluator would actually solve this
> problem if it knew how to do cross-module inlining. That's another big
> project, but it could be a way to solve this problem and keep format
> as a function.

If ‘format’ were defined with ‘define-inlinable’ (which it cannot
currently, because rest arguments aren’t supported–which should be
fixed), then peval could specialize the ‘format’ code at the call site.
I wonder how far it’d go, though.

Ludo’.

bug#12033: closed (Re: bug#12033: format should be faster)

[Andy Wingo]

On Tue 21 Aug 2012 13:37, ludo@gnu.org (Ludovic Courtès) writes:

>> It seems clear that in this case, Guile "should" know how to dispatch
>> on the format string just once, outside of the loop, instead of doing
>> it in every iteration.
>
> I think Andy would say: “inline cache!”.  :-)

:-)

There are lots of possibilities here.  You could "compile" a format
string into a closure, and save it in a hash table.  You could compile
it to Scheme and then compile that procedure.  You could recognize some
common degenerate cases.

Dunno!  In this case I would compile the string into a closure.  Seems
pretty cheap and it would kill the dispatch overhead.

Andy
-- 
http://wingolog.org/

bug#12033: closed (Re: bug#12033: format should be faster)

[nalaginrut]

hey guys! Any conclusion?

On Tue, 2012-08-21 at 21:35 +0200, Andy Wingo wrote: 
> On Tue 21 Aug 2012 13:37, ludo@gnu.org (Ludovic Courtès) writes:
> 
> >> It seems clear that in this case, Guile "should" know how to dispatch
> >> on the format string just once, outside of the loop, instead of doing
> >> it in every iteration.
> >
> > I think Andy would say: “inline cache!”.  :-)
> 
> :-)
> 
> There are lots of possibilities here.  You could "compile" a format
> string into a closure, and save it in a hash table.  You could compile
> it to Scheme and then compile that procedure.  You could recognize some
> common degenerate cases.
> 
> Dunno!  In this case I would compile the string into a closure.  Seems
> pretty cheap and it would kill the dispatch overhead.
> 
> Andy

bug#12033: closed (Re: bug#12033: format should be faster)

[Ludovic Courtès]

Hi,

nalaginrut <nalaginrut@gmail.com> skribis:

> hey guys! Any conclusion?

I think there’s no simpler answer, so no conclusion.  We’d have to
experiment with the various possibilities (‘define-inlinable’ for
‘format’, a ‘format*’ macro, or compiler support).

Of course, you’re welcome to give it a go and let guile-devel know!  :-)

Ludo’.