From debbugs-submit-bounces@debbugs.gnu.org Thu Apr 16 11:21:54 2020 Received: (at 40626) by debbugs.gnu.org; 16 Apr 2020 15:21:54 +0000 Received: from localhost ([127.0.0.1]:39129 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1jP6Kv-0002jZ-NK for submit@debbugs.gnu.org; Thu, 16 Apr 2020 11:21:54 -0400 Received: from eggs.gnu.org ([209.51.188.92]:34380) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1jP6Kt-0002jL-6n for 40626@debbugs.gnu.org; Thu, 16 Apr 2020 11:21:52 -0400 Received: from fencepost.gnu.org ([2001:470:142:3::e]:34020) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1jP6Ko-0002Cz-2g for 40626@debbugs.gnu.org; Thu, 16 Apr 2020 11:21:46 -0400 Received: from [2a01:e0a:1d:7270:af76:b9b:ca24:c465] (port=42240 helo=ribbon) by fencepost.gnu.org with esmtpsa (TLS1.2:RSA_AES_256_CBC_SHA1:256) (Exim 4.82) (envelope-from ) id 1jP6Kn-0007cx-NI for 40626@debbugs.gnu.org; Thu, 16 Apr 2020 11:21:45 -0400 From: =?utf-8?Q?Ludovic_Court=C3=A8s?= To: 40626@debbugs.gnu.org Subject: Re: bug#40626: Poor performance on low-end ARMv7 devices References: <87a73exj5v.fsf@inria.fr> Date: Thu, 16 Apr 2020 17:21:43 +0200 In-Reply-To: <87a73exj5v.fsf@inria.fr> ("Ludovic \=\?utf-8\?Q\?Court\=C3\=A8s\=22\?\= \=\?utf-8\?Q\?'s\?\= message of "Tue, 14 Apr 2020 15:59:24 +0200") Message-ID: <875zdzihh4.fsf@gnu.org> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.3 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic] X-Spam-Score: -1.5 (-) X-Debbugs-Envelope-To: 40626 X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -2.5 (--) Ludovic Court=C3=A8s skribis: > Most of it seems to go in loading .go files: On x86_64, I=E2=80=99ve run: ./pre-inst-env perf record guile -c '(use-modules (gnu packages libreoffi= ce))' which shows mostly GC activity, along with symbol interning activity: --8<---------------cut here---------------start------------->8--- 14.71% guile libgc.so.1.3.6 [.] GC_mark_from 7.49% guile libgc.so.1.3.6 [.] GC_header_cache_miss 5.56% guile libguile-3.0.so.1.1.1 [.] vm_regular_engine 5.42% guile libgc.so.1.3.6 [.] GC_add_to_black_list_normal 2.66% guile libpthread-2.29.so [.] __pthread_mutex_unlock_usercnt 2.63% guile libgc.so.1.3.6 [.] GC_find_header 2.09% guile ld-2.29.so [.] _dl_update_slotinfo 1.88% guile libguile-3.0.so.1.1.1 [.] scm_c_weak_set_lookup 1.68% guile libguile-3.0.so.1.1.1 [.] narrow_string_hash 1.64% guile libguile-3.0.so.1.1.1 [.] scm_i_is_narrow_string 1.55% guile libguile-3.0.so.1.1.1 [.] scm_ihashq 1.52% guile libguile-3.0.so.1.1.1 [.] scm_sloppy_assq 1.32% guile libgc.so.1.3.6 [.] GC_move_disappearing_link_inn= er 1.23% guile libgc.so.1.3.6 [.] GC_malloc_kind 1.23% guile libpthread-2.29.so [.] __pthread_mutex_lock 1.22% guile libguile-3.0.so.1.1.1 [.] scm_hash_fn_get_handle 1.19% guile libpthread-2.29.so [.] __pthread_mutex_trylock 1.12% guile libguile-3.0.so.1.1.1 [.] get_callee_vcode 1.12% guile libguile-3.0.so.1.1.1 [.] scm_equal_p --8<---------------cut here---------------end--------------->8--- Back on my A20 board, I get this (unhelpful) GC profile: --8<---------------cut here---------------start------------->8--- scheme@(guix-user)> ,use(statprof) scheme@(guix-user)> (gcprof (lambda () (resolve-module '(gnu packages base)= ))) % cumulative self time seconds seconds procedure 100.00 5.13 5.13 ice-9/boot-9.scm:2201:0:%load-announce 0.00 4081.53 0.00 ice-9/boot-9.scm:220:5:map1 0.00 621.21 0.00 ice-9/threads.scm:388:4 0.00 310.61 0.00 ice-9/boot-9.scm:2803:0:save-module-excursion 0.00 310.61 0.00 anon #x1b15600 0.00 310.61 0.00 ice-9/boot-9.scm:3211:7 0.00 310.61 0.00 ice-9/boot-9.scm:3500:5 0.00 310.61 0.00 ice-9/boot-9.scm:3508:21 0.00 305.47 0.00 ice-9/boot-9.scm:3256:0:resolve-interface 0.00 295.21 0.00 ice-9/boot-9.scm:3381:5 0.00 295.21 0.00 ice-9/boot-9.scm:3351:0:define-module* 0.00 5.13 0.00 anon #xb2d8d098 0.00 5.13 0.00 anon #xb32d0098 0.00 5.13 0.00 anon #xb2fca098 0.00 5.13 0.00 anon #xb32e2098 0.00 5.13 0.00 anon #xb3343098 0.00 5.13 0.00 ice-9/boot-9.scm:2557:0:call-with-deferred-obse= rvers [=E2=80=A6] --- Sample count: 2 Total time: 5.134 seconds (0.44 seconds in GC) --8<---------------cut here---------------end--------------->8--- and this profile: --8<---------------cut here---------------start------------->8--- scheme@(guix-user)> ,pr (resolve-module '(gnu packages base)) % cumulative self time seconds seconds procedure 17.86 1.38 1.38 ice-9/boot-9.scm:2201:0:%load-announce 5.36 0.41 0.41 ice-9/boot-9.scm:3545:0:autoload-done! 4.76 0.37 0.37 ice-9/boot-9.scm:3540:0:autoload-done-or-in-pro= gress? 4.76 0.37 0.37 anon #x1a671cc 4.17 0.32 0.32 ice-9/format.scm:113:2:format:format-work 3.57 0.28 0.28 ice-9/boot-9.scm:3552:0:autoload-in-progress! 2.98 0.55 0.23 ice-9/boot-9.scm:1396:0:symbol-append 2.98 0.23 0.23 anon #x1a65c28 1.79 0.32 0.14 ice-9/boot-9.scm:2729:0:module-make-local-var! 1.79 0.14 0.14 anon #x1a671a4 1.79 0.14 0.14 anon #x1a6c284 1.79 0.14 0.14 anon #x1a67644 1.79 0.14 0.14 ice-9/boot-9.scm:3209:4 1.19 6106.96 0.09 ice-9/boot-9.scm:220:5:map1 1.19 518.54 0.09 ice-9/boot-9.scm:3211:7 1.19 511.19 0.09 ice-9/boot-9.scm:3381:5 1.19 5.69 0.09 anon #xb13f9098 1.19 0.18 0.09 anon #xad994098 1.19 0.09 0.09 anon #x1a6848c 1.19 0.09 0.09 srfi/srfi-60.scm:57:0:bitwise-if 1.19 0.09 0.09 ice-9/boot-9.scm:2468:2 1.19 0.09 0.09 ice-9/boot-9.scm:2468:2 1.19 0.09 0.09 anon #x1a6e284 1.19 0.09 0.09 anon #x1a67cd4 1.19 0.09 0.09 anon #x1a6e87c [=E2=80=A6] --- Sample count: 168 Total time: 7.714 seconds (1.279 seconds in GC) --8<---------------cut here---------------end--------------->8--- What=E2=80=99s the deal with =E2=80=98%load-announce=E2=80=99? How many ti= mes is it called? --8<---------------cut here---------------start------------->8--- $ guix repl GNU Guile 3.0.2 Copyright (C) 1995-2020 Free Software Foundation, Inc. Guile comes with ABSOLUTELY NO WARRANTY; for details type `,show w'. This program is free software, and you are welcome to redistribute it under certain conditions; type `,show c' for details. Enter `,help' for help. scheme@(guix-user)> ,use(system vm vm) scheme@(guix-user)> (set-vm-engine! 'debug) scheme@(guix-user)> ,use(statprof) scheme@(guix-user)> (statprof (lambda () (resolve-module '(gnu packages bas= e))) #:count-calls? #t) % cumulative self time seconds seconds calls procedure 5.31 4.39 4.39 anon #x1ba81cc 3.84 98371.57 3.17 69196 ice-9/boot-9.scm:220:5:map1 3.32 2.75 2.75 57783 ice-9/boot-9.scm:2468:2 3.26 2.70 2.70 anon #x1ba81a4 3.01 2.49 2.49 60626 ice-9/boot-9.scm:1299:5 2.94 9.23 2.43 44668 ice-9/boot-9.scm:2757:0:module-add! 2.85 4.39 2.35 47021 ice-9/boot-9.scm:2549:0:module-modified 2.53 2.09 2.09 44668 ice-9/boot-9.scm:2652:0:module-obarray-= set! 2.33 1.93 1.93 anon #x1ba6c28 2.24 1.85 1.85 anon #x1baa1fc 2.21 1.83 1.83 anon #x1bad284 2.11 1.75 1.75 anon #x1ba8cd4 2.01 4.55 1.67 32603 ice-9/boot-9.scm:2790:0:module-ref-subm= odule 1.92 1.59 1.59 anon #x1ba8f34 1.89 1.56 1.56 21349 ice-9/boot-9.scm:806:0:and=3D> 1.76 1.46 1.46 32184 ice-9/boot-9.scm:2468:2 1.69 1.40 1.40 33343 ice-9/boot-9.scm:2468:2 1.69 1.40 1.40 anon #x1ba8080 1.50 15.24 1.24 19850 ice-9/boot-9.scm:3339:29 1.44 7457.26 1.19 7325 ice-9/boot-9.scm:3256:0:resolve-interfa= ce 1.44 1.19 1.19 19133 ice-9/boot-9.scm:3345:2 1.41 9.79 1.16 19217 ice-9/boot-9.scm:1396:0:symbol-append 1.37 1.14 1.14 20160 ice-9/boot-9.scm:2468:2 1.34 1.11 1.11 19850 ice-9/boot-9.scm:3303:48 1.34 1.11 1.11 14322 srfi/srfi-60.scm:57:0:bitwise-if 1.31 1.08 1.08 36200 anon #x1ba6c18 1.15 2.65 0.95 9672 ice-9/vlist.scm:544:0:vhash-assv 1.15 2.09 0.95 20671 ice-9/boot-9.scm:215:2:map 1.15 0.95 0.95 14210 ice-9/boot-9.scm:3209:4 1.12 7.09 0.93 12743 ice-9/boot-9.scm:2729:0:module-make-loc= al-var! 1.05 0.87 0.87 11594 guix/utils.scm:810:0:source-properties-= >location 0.99 1.35 0.82 11559 ice-9/boot-9.scm:2746:0:module-ensure-l= ocal-variable! 0.90 0.74 0.74 370 ice-9/boot-9.scm:2201:0:%load-announce [=E2=80=A6] --- Sample count: 3128 Total time: 82.752 seconds (16.401 seconds in GC) --8<---------------cut here---------------end--------------->8--- Only 370 times. Hmm could something be wrong with the mapping of instruction pointers to source code location? Ludo=E2=80=99.