From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.io!.POSTED.blaine.gmane.org!not-for-mail From: Olivier Dion via General Guile related discussions Newsgroups: gmane.lisp.guile.user Subject: Re: list vs vector Date: Wed, 28 Dec 2022 15:23:07 -0500 Message-ID: <874jtfqnv8.fsf@laura> References: Reply-To: Olivier Dion Mime-Version: 1.0 Content-Type: text/plain Injection-Info: ciao.gmane.io; posting-host="blaine.gmane.org:116.202.254.214"; logging-data="15734"; mail-complaints-to="usenet@ciao.gmane.io" To: Sascha Ziemann , guile-user@gnu.org Original-X-From: guile-user-bounces+guile-user=m.gmane-mx.org@gnu.org Wed Dec 28 21:24:06 2022 Return-path: Envelope-to: guile-user@m.gmane-mx.org Original-Received: from lists.gnu.org ([209.51.188.17]) by ciao.gmane.io with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1pAcy5-0003yl-UQ for guile-user@m.gmane-mx.org; Wed, 28 Dec 2022 21:24:06 +0100 Original-Received: from localhost ([::1] helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1pAcxV-00075J-OB; Wed, 28 Dec 2022 15:23:30 -0500 Original-Received: from eggs.gnu.org ([2001:470:142:3::10]) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1pAcxO-00074z-JS for guile-user@gnu.org; Wed, 28 Dec 2022 15:23:23 -0500 Original-Received: from smtp.polymtl.ca ([132.207.4.11]) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1pAcxL-0004Jb-JE for guile-user@gnu.org; Wed, 28 Dec 2022 15:23:22 -0500 Original-Received: from localhost (modemcable094.169-200-24.mc.videotron.ca [24.200.169.94]) by smtp.polymtl.ca (8.14.7/8.14.7) with ESMTP id 2BSKN7Ye023740; Wed, 28 Dec 2022 15:23:11 -0500 DKIM-Filter: OpenDKIM Filter v2.11.0 smtp.polymtl.ca 2BSKN7Ye023740 In-Reply-To: X-Poly-FromMTA: (modemcable094.169-200-24.mc.videotron.ca [24.200.169.94]) at Wed, 28 Dec 2022 20:23:07 +0000 Received-SPF: pass client-ip=132.207.4.11; envelope-from=olivier.dion@polymtl.ca; helo=smtp.polymtl.ca X-Spam_score_int: -41 X-Spam_score: -4.2 X-Spam_bar: ---- X-Spam_report: (-4.2 / 5.0 requ) BAYES_00=-1.9, RCVD_IN_DNSWL_MED=-2.3, RCVD_IN_MSPIKE_H3=0.001, RCVD_IN_MSPIKE_WL=0.001, SPF_HELO_PASS=-0.001, SPF_PASS=-0.001 autolearn=ham autolearn_force=no X-Spam_action: no action X-BeenThere: guile-user@gnu.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: General Guile related discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: guile-user-bounces+guile-user=m.gmane-mx.org@gnu.org Original-Sender: guile-user-bounces+guile-user=m.gmane-mx.org@gnu.org Xref: news.gmane.io gmane.lisp.guile.user:18803 Archived-At: On Wed, 28 Dec 2022, Sascha Ziemann 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 :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 :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 :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 :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