list vs vector

list vs vector

[Sascha Ziemann]

I spent my Christmas vacation playing with XML and tree traversal. And
I have observed some strange timings, while measuring the execution
time of different algorithms. My test file is the XCB XML schema:

https://cgit.freedesktop.org/xcb/proto/plain/src/xcb.xsd

And my test program is this:

https://gist.github.com/ceving/6eb3792c64e505909f43858039ae18f8

I load the XSD file with "(sxml simple)" and traverse the XML tree in
order to remove all white-spaces. During the traversal of the tree I
visit each element and destructure each element with the following
procedure:

(define (sxml:call-with-element node proc)
  (if (sxml:element? node)
      (let ((name (car node))
            (rest (cdr node)))
        (if (pair? rest)
            (let ((maybe-attributes (car rest)))
              (if (sxml:attributes? maybe-attributes)
                  (proc name (cdr maybe-attributes) (cdr rest))
                  (proc name '() rest)))
            (proc name '() '())))
      node))

This is necessary, because in SXML the first child of an element may
be an attribute list of an actual child element. After I had written
the procedure, I had the impression that it might be faster to work
with vectors instead of lists, because the version with vectors looks
much simpler:

(define (vxml:call-with-element node proc)
  (if (vxml:element? node)
      (proc (vxml:element-name node)
            (vxml:element-attributes node)
            (vxml:element-children node))
      node))

But after I compared the two traversals, I had to realize that the
list-version is a bit faster than the vector-version. Although the
list-version does much testing, caring and cdring, the straight
forward vector-ref's are slower. Can anybody explain?

Re: list vs vector

[tomas]

[-- Attachment #1: Type: text/plain, Size: 549 bytes --]

On Wed, Dec 28, 2022 at 02:22:16PM +0100, Sascha Ziemann wrote:
> I spent my Christmas vacation playing with XML and tree traversal. And
> I have observed some strange timings, while measuring the execution
> time of different algorithms. My test file is the XCB XML schema:

[vector version slightly slower than lists]

This is interesting. Have you tried profiling? Sometimes it's as
easy as saying ,profile (my expression) at the Guile repl.

(I'm not looking into the code, since I try to avoid Github when
I can).

Cheers
-- 
t

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]

Re: list vs vector

[Damien Mattei]

i have no idea, at the opposite, in one of my program i experienced a
vector implementation faster than the list one.

Regards,

Damien

On Wed, Dec 28, 2022 at 2:23 PM Sascha Ziemann <ceving@gmail.com> wrote:

> I spent my Christmas vacation playing with XML and tree traversal. And
> I have observed some strange timings, while measuring the execution
> time of different algorithms. My test file is the XCB XML schema:
>
> https://cgit.freedesktop.org/xcb/proto/plain/src/xcb.xsd
>
> And my test program is this:
>
> https://gist.github.com/ceving/6eb3792c64e505909f43858039ae18f8
>
> I load the XSD file with "(sxml simple)" and traverse the XML tree in
> order to remove all white-spaces. During the traversal of the tree I
> visit each element and destructure each element with the following
> procedure:
>
> (define (sxml:call-with-element node proc)
>   (if (sxml:element? node)
>       (let ((name (car node))
>             (rest (cdr node)))
>         (if (pair? rest)
>             (let ((maybe-attributes (car rest)))
>               (if (sxml:attributes? maybe-attributes)
>                   (proc name (cdr maybe-attributes) (cdr rest))
>                   (proc name '() rest)))
>             (proc name '() '())))
>       node))
>
> This is necessary, because in SXML the first child of an element may
> be an attribute list of an actual child element. After I had written
> the procedure, I had the impression that it might be faster to work
> with vectors instead of lists, because the version with vectors looks
> much simpler:
>
> (define (vxml:call-with-element node proc)
>   (if (vxml:element? node)
>       (proc (vxml:element-name node)
>             (vxml:element-attributes node)
>             (vxml:element-children node))
>       node))
>
> But after I compared the two traversals, I had to realize that the
> list-version is a bit faster than the vector-version. Although the
> list-version does much testing, caring and cdring, the straight
> forward vector-ref's are slower. Can anybody explain?
>
>

Re: list vs vector

[Olivier Dion via General Guile related discussions]

On Wed, 28 Dec 2022, Sascha Ziemann <ceving@gmail.com> wrote:

Here are the profling informations:
--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> ,profile (vxml:traverse-pre (sxml->vxml xcb) remove-whitespace) #:loop 10000
%     cumulative   self
time   seconds     seconds  procedure
 39.38      1.62      1.62  char-whitespace?
 11.25      0.46      0.46  /home/old/test.scm:150:0:string:whitespace?
  5.63     99.73      0.23  srfi/srfi-1.scm:584:5:map1
  5.63      2.06      0.23  ice-9/boot-9.scm:340:2:string-every
  5.00      0.21      0.21  string-every-c-code
  4.38      0.18      0.18  /home/old/test.scm:84:4:traverse
  3.13      0.28      0.13  /home/old/test.scm:58:0:sxml:call-with-element
  3.13      0.21      0.13  srfi/srfi-1.scm:580:2:map
  3.13      0.13      0.13  /home/old/test.scm:97:0:vxml:element
  3.13      0.13      0.13  /home/old/test.scm:29:0:sxml:element?
  2.50     10.36      0.10  /home/old/test.scm:134:6
  2.50      2.75      0.10  /home/old/test.scm:85:6
  1.88      0.23      0.08  /home/old/test.scm:118:0:vxml:call-with-element
  1.88      0.08      0.08  remove
  1.25      0.05      0.05  /home/old/test.scm:133:4:traverse
  1.25      0.05      0.05  procedure?
  1.25      0.05      0.05  /home/old/test.scm:106:0:vxml:element-name
  1.25      0.05      0.05  /home/old/test.scm:112:0:vxml:element-children
  1.25      0.05      0.05  vector?
  0.63      0.03      0.03  list?
  0.63      0.03      0.03  /home/old/test.scm:34:0:sxml:attributes?
  0.00      3.14      0.00  /home/old/test.scm:134:6
  0.00      2.52      0.00  remove
  0.00      1.62      0.00  string-every-c-code
  0.00      0.98      0.00  <current input>:17:9
  0.00      0.95      0.00  /home/old/test.scm:85:6
---
Sample count: 160
Total time: 4.113558516 seconds (2.070575273 seconds in GC)
scheme@(guile-user)> ,profile (sxml->vxml (sxml:traverse-pre xcb remove-whitespace)) #:loop 10000
%     cumulative   self
time   seconds     seconds  procedure
 44.74      1.53      1.53  char-whitespace?
 15.13      0.52      0.52  /home/old/test.scm:150:0:string:whitespace?
  5.92      1.85      0.20  ice-9/boot-9.scm:340:2:string-every
  4.61      0.20      0.16  srfi/srfi-1.scm:580:2:map
  4.61      0.16      0.16  /home/old/test.scm:84:4:traverse
  3.95      0.14      0.14  string-every-c-code
  3.29      0.11      0.11  remove
  3.29      0.11      0.11  /home/old/test.scm:29:0:sxml:element?
  2.63     68.65      0.09  srfi/srfi-1.scm:584:5:map1
  2.63     12.34      0.09  /home/old/test.scm:85:6
  1.97      0.07      0.07  /home/old/test.scm:45:0:sxml:element
  1.97      0.07      0.07  /home/old/test.scm:34:0:sxml:attributes?
  1.32      0.23      0.05  /home/old/test.scm:58:0:sxml:call-with-element
  1.32      0.05      0.05  /home/old/test.scm:154:0:remove-whitespace
  1.32      0.05      0.05  list?
  0.66      0.02      0.02  procedure?
  0.66      0.02      0.02  /home/old/test.scm:97:0:vxml:element
  0.00      3.42      0.00  /home/old/test.scm:85:6
  0.00      3.06      0.00  <current input>:19:9
  0.00      2.41      0.00  remove
  0.00      1.49      0.00  string-every-c-code
---
Sample count: 152
Total time: 3.423245678 seconds (1.440664685 seconds in GC)
--8<---------------cut here---------------end--------------->8---

We see that the difference in total time (~ 0.69 second) is close to the
GC overhead (~ 0.63 second).


If we only focus on traversing instead ($1 = (sxml->vxml xcb)):
--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> ,profile (vxml:traverse-pre $1 remove-whitespace) #:loop 10000
%     cumulative   self
time   seconds     seconds  procedure
 53.42      1.54      1.54  char-whitespace?
 15.75      0.45      0.45  /home/old/test.scm:150:0:string:whitespace?
  8.90      0.26      0.26  string-every-c-code
  4.79      1.99      0.14  ice-9/boot-9.scm:340:2:string-every
  3.42      0.16      0.10  /home/old/test.scm:118:0:vxml:call-with-element
  2.74     54.01      0.08  srfi/srfi-1.scm:584:5:map1
  2.74      0.08      0.08  /home/old/test.scm:133:4:traverse
  2.05      0.06      0.06  procedure?
  1.37      0.06      0.04  srfi/srfi-1.scm:580:2:map
  0.68      9.25      0.02  /home/old/test.scm:134:6
  0.68      0.02      0.02  list?
  0.68      0.02      0.02  remove
  0.68      0.02      0.02  /home/old/test.scm:97:0:vxml:element
  0.68      0.02      0.02  /home/old/test.scm:106:0:vxml:element-name
  0.68      0.02      0.02  /home/old/test.scm:109:0:vxml:element-attributes
  0.68      0.02      0.02  vector?
  0.00      2.88      0.00  /home/old/test.scm:134:6
  0.00      2.45      0.00  remove
  0.00      1.54      0.00  string-every-c-code
---
Sample count: 146
Total time: 2.880217086 seconds (0.776929721 seconds in GC)
scheme@(guile-user)> ,profile (sxml:traverse-pre xcb remove-whitespace) #:loop 10000
%     cumulative   self
time   seconds     seconds  procedure
 51.97      1.57      1.57  char-whitespace?
 19.08      0.58      0.58  /home/old/test.scm:150:0:string:whitespace?
  4.61     59.19      0.14  srfi/srfi-1.scm:584:5:map1
  4.61      0.14      0.14  string-every-c-code
  3.95      0.16      0.12  /home/old/test.scm:45:0:sxml:element
  1.97      1.81      0.06  ice-9/boot-9.scm:340:2:string-every
  1.97      0.16      0.06  /home/old/test.scm:58:0:sxml:call-with-element
  1.97      0.06      0.06  /home/old/test.scm:29:0:sxml:element?
  1.97      0.06      0.06  procedure?
  1.32     10.18      0.04  /home/old/test.scm:85:6
  1.32      0.04      0.04  srfi/srfi-1.scm:580:2:map
  1.32      0.04      0.04  /home/old/test.scm:34:0:sxml:attributes?
  1.32      0.04      0.04  %after-gc-thunk
  0.66      0.02      0.02  /home/old/test.scm:154:0:remove-whitespace
  0.66      0.02      0.02  /home/old/test.scm:84:4:traverse
  0.66      0.02      0.02  /home/old/test.scm:82:0:sxml:traverse
  0.66      0.02      0.02  remove
  0.00      3.00      0.00  /home/old/test.scm:85:6
  0.00      2.41      0.00  remove
  0.00      1.55      0.00  string-every-c-code
  0.00      0.04      0.00  anon #x4e9530
---
Sample count: 152
Total time: 3.023158042 seconds (0.897702296 seconds in GC)
--8<---------------cut here---------------end--------------->8---

The vector version seems to be faster here.

Let's look at the allocation since the GC seems to be the culprit here.
--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> (use-modules (statprof))
scheme@(guile-user)> (gcprof (lambda () (vxml:traverse-pre (sxml->vxml xcb) remove-whitespace)) #:loop 100000)
%     cumulative   self
time   seconds     seconds  procedure
 28.58     11.31     11.31  /home/old/test.scm:133:4:traverse
 26.21     10.37     10.37  /home/old/test.scm:84:4:traverse
 19.08   1265.05      7.55  srfi/srfi-1.scm:584:5:map1
 13.10      5.18      5.18  /home/old/test.scm:150:0:string:whitespace?
 12.67      5.01      5.01  /home/old/test.scm:97:0:vxml:element
  0.29      0.11      0.11  /home/old/test.scm:82:0:sxml:traverse
  0.07      0.03      0.03  /home/old/test.scm:131:0:vxml:traverse
  0.00     65.27      0.00  /home/old/test.scm:134:6
  0.00     46.85      0.00  /home/old/test.scm:85:6
  0.00     21.33      0.00  /home/old/test.scm:134:6
  0.00     18.20      0.00  <current input>:3:8
  0.00     18.03      0.00  /home/old/test.scm:85:6
  0.00      5.18      0.00  remove
---
Sample count: 1389
Total time: 39.555044322 seconds (16.212054176 seconds in GC)
scheme@(guile-user)> (gcprof (lambda () (sxml->vxml (sxml:traverse-pre xcb remove-whitespace))) #:loop 100000)
%     cumulative   self
time   seconds     seconds  procedure
 58.37     19.56     19.56  /home/old/test.scm:84:4:traverse
 21.96      7.36      7.36  /home/old/test.scm:45:0:sxml:element
 10.87    516.55      3.64  srfi/srfi-1.scm:584:5:map1
  8.80      2.95      2.95  /home/old/test.scm:150:0:string:whitespace?
  0.00    103.89      0.00  /home/old/test.scm:85:6
  0.00     33.51      0.00  /home/old/test.scm:85:6
  0.00     33.26      0.00  <current input>:2:8
  0.00      2.95      0.00  remove
---
Sample count: 920
Total time: 33.514138568 seconds (10.50369987 seconds in GC)
--8<---------------cut here---------------end--------------->8---

Clearly we're spending way much time in the GC with the vxml variant.
Why?  I don't know :-(

-- 
Olivier Dion
oldiob.dev

Re: list vs vector

[Sascha Ziemann]

> Clearly we're spending way much time in the GC with the vxml variant.

Thanks a lot! This is a nice tutorial for statprof.

What you have found out, was already my guess but I had no proof. The
VXML version does not utilize the fact that the nodes are already
destructured. During each visit of a node, the vector gets converted
into an argument list and the result of the visit is that a new vector
gets created. This produces a lot of garbage. It would be better to
just pass the vector to the visiting function in order to return
itself, if no modification is necessary.