On Wed, 28 Dec 2022, Sascha Ziemann <cev...@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