[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
Re: list vs vector
|
From: |
Olivier Dion |
|
Subject: |
Re: list vs vector |
|
Date: |
Wed, 28 Dec 2022 15:23:07 -0500 |
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