Quicklisp takes 3 seconds to load on SBCL

[samuel-hunter]

This is likely false memory, but I don't remember Quicklisp having this performance issue a few months ago, before I reinstalled all my dev tools.

I measured how long it takes with and without Quicklisp on SBCL 2.2.3.debian and a Quicklisp system, both fresh-installed today:

~$ time sbcl --load ~/quicklisp/setup.lisp --eval '(quit)' >/dev/null

real	0m2.870s
user	0m2.010s
sys	0m0.847s
~$ time sbcl --eval '(quit)' >/dev/null

real	0m0.010s
user	0m0.005s
sys	0m0.005s

That's nearly a 3 second startup when SBCL usually takes no time at alll, backed after running it multiple times.

Roswell helps me reproduce it with various impl's, so it's not SBCL-specific:

~$ ros use sbcl-bin
~$ time ros run --no-quicklisp --quit

real	0m0.072s
user	0m0.041s
sys	0m0.031s
~$ time ros run --quicklisp --quit

real	0m3.064s
user	0m2.166s
sys	0m0.895s
~$ ros use ccl-bin
~$ time ros run --no-quicklisp --quit

real	0m0.051s
user	0m0.047s
sys	0m0.004s
~$ time ros run --quicklisp --quit

real	0m6.187s
user	0m5.398s
sys	0m0.805s
~$ # etc...

I find it a little surprising that a dependency manager needs this much time to load, though maybe the internals are more complex than I give it credit for. Is this expected performance?

[quicklisp]

It shouldn't take that long. What do you see in a backtrace?

…

On Thu, Jun 30, 2022 at 11:49 AM Samuel Hunter ***@***.***> wrote: This is likely false memory, but I don't remember Quicklisp having this performance issue a few months ago, before I reinstalled all my dev tools. I measured how long it takes with and without Quicklisp on SBCL 2.2.3.debian and a Quicklisp system, both fresh-installed today: ~$ time sbcl --load ~/quicklisp/setup.lisp --eval '(quit)' >/dev/null real 0m2.870s user 0m2.010s sys 0m0.847s~$ time sbcl --eval '(quit)' >/dev/null real 0m0.010s user 0m0.005s sys 0m0.005s That's nearly a 3 second startup when SBCL usually takes no time at alll, backed after running it multiple times. Roswell helps me reproduce it with various impl's, so it's not SBCL-specific: ~$ ros use sbcl-bin~$ time ros run --no-quicklisp --quit real 0m0.072s user 0m0.041s sys 0m0.031s~$ time ros run --quicklisp --quit real 0m3.064s user 0m2.166s sys 0m0.895s~$ ros use ccl-bin~$ time ros run --no-quicklisp --quit real 0m0.051s user 0m0.047s sys 0m0.004s~$ time ros run --quicklisp --quit real 0m6.187s user 0m5.398s sys 0m0.805s~$ # etc... I find it a little surprising that a dependency manager needs this much time to load, though maybe the internals are more complex than I give it credit for. Is this expected performance? — Reply to this email directly, view it on GitHub <#217>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AACPNLOC6W2PLU6FYV3QW6TVRW6X3ANCNFSM52J2YAXA> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[samuel-hunter]

I'm not sure under what frame or from where you want the backtrace. Is this what you are looking for?

~$ ros use sbcl-bin
~$ ros run
* (print-backtrace)
Backtrace for: #<SB-THREAD:THREAD "main thread" RUNNING {1001B80073}>
0: (SB-INT:SIMPLE-EVAL-IN-LEXENV (PRINT-BACKTRACE) #<NULL-LEXENV>)
1: (EVAL (PRINT-BACKTRACE))
2: (INTERACTIVE-EVAL (PRINT-BACKTRACE) :EVAL NIL)
3: (SB-IMPL::REPL-FUN NIL)
4: ((LAMBDA NIL :IN SB-IMPL::TOPLEVEL-REPL))
5: (SB-IMPL::%WITH-REBOUND-IO-SYNTAX #<FUNCTION (LAMBDA NIL :IN SB-IMPL::TOPLEVEL-REPL) {1002C2252B}>)
6: (SB-IMPL::TOPLEVEL-REPL NIL)
7: (SB-IMPL::TOPLEVEL-INIT)
8: ((FLET SB-UNIX::BODY :IN SB-IMPL::START-LISP))
9: ((FLET "WITHOUT-INTERRUPTS-BODY-3" :IN SB-IMPL::START-LISP))
10: (SB-IMPL::%START-LISP)

What else can I give to help with this issue?

[quicklisp]

Interrupt it while it’s loading slowly to see where it’s spending time.

…

On Jul 6, 2022, at 22:15, Samuel Hunter ***@***.***> wrote:  I'm not sure under what frame or from where you want the backtrace. Is this what you are looking for? ~$ ros use sbcl-bin ~$ ros run * (print-backtrace) Backtrace for: #<SB-THREAD:THREAD "main thread" RUNNING {1001B80073}> 0: (SB-INT:SIMPLE-EVAL-IN-LEXENV (PRINT-BACKTRACE) #<NULL-LEXENV>) 1: (EVAL (PRINT-BACKTRACE)) 2: (INTERACTIVE-EVAL (PRINT-BACKTRACE) :EVAL NIL) 3: (SB-IMPL::REPL-FUN NIL) 4: ((LAMBDA NIL :IN SB-IMPL::TOPLEVEL-REPL)) 5: (SB-IMPL::%WITH-REBOUND-IO-SYNTAX #<FUNCTION (LAMBDA NIL :IN SB-IMPL::TOPLEVEL-REPL) {1002C2252B}>) 6: (SB-IMPL::TOPLEVEL-REPL NIL) 7: (SB-IMPL::TOPLEVEL-INIT) 8: ((FLET SB-UNIX::BODY :IN SB-IMPL::START-LISP)) 9: ((FLET "WITHOUT-INTERRUPTS-BODY-3" :IN SB-IMPL::START-LISP)) 10: (SB-IMPL::%START-LISP) What else can I give to help with this issue? — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you commented.

[samuel-hunter]

Thanks! I printed the backtrace and found the issue was from walking through an extremely dense directory tree:

~$ ros use sbcl-bin
~$ ros run
^CWhile evaluating the form starting at line 129, column 0
  of #P"/home/shunter/.local/share/roswell/lisp/quicklisp/setup.lisp":

debugger invoked on a SB-SYS:INTERACTIVE-INTERRUPT @7F9408EB3136 in thread
#<THREAD "main thread" RUNNING {1001680073}>:
  Interactive interrupt at #x7F9408EB3136.

Type HELP for debugger help, or (SB-EXT:EXIT) to exit from SBCL.

restarts (invokable by number or by possibly-abbreviated name):
  0: [CONTINUE                     ] Return from SB-UNIX:SIGINT.
  1: [RETRY                        ] Retry ASDF operation.
  2: [CLEAR-CONFIGURATION-AND-RETRY] Retry ASDF operation after resetting the
                                     configuration.
  3: [RETRY                        ] Retry EVAL of current toplevel form.
  4:                                 Ignore error and continue loading file "/home/shunter/.local/share/roswell/lisp/quicklisp/setup.lisp".
  5: [ABORT                        ] Abort loading file "/home/shunter/.local/share/roswell/lisp/quicklisp/setup.lisp".
  6:                                 Ignore runtime option --eval "(ros:run '((:eval\"(ros:quicklisp)\")))".
  7:                                 Skip rest of --eval and --load options.
  8:                                 Skip to toplevel READ/EVAL/PRINT loop.
  9: [EXIT                         ] Exit SBCL (calling #'EXIT, killing the process).

("bogus stack frame")
0] backtrace

Backtrace for: #<SB-THREAD:THREAD "main thread" RUNNING {1001680073}>
0: ("bogus stack frame")
1: (SB-UNIX:UNIX-LSTAT #<(SIMPLE-ARRAY CHARACTER (202)) /home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/html/group__group__scb__i2c__macros.... {10024B727F}>)
2: (SB-IMPL::NATIVE-FILE-KIND #<(SIMPLE-ARRAY CHARACTER (202)) /home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/html/group__group__scb__i2c__macros.... {10024B727F}> NIL)
3: ((FLET SB-IMPL::ITERATE :IN SB-EXT:MAP-DIRECTORY) #<FUNCTION (FLET SB-IMPL::ONE-ITER :IN SB-IMPL::CALL-WITH-NATIVE-DIRECTORY-ITERATOR) {7F94089FDBCB}>)
4: (SB-IMPL::CALL-WITH-NATIVE-DIRECTORY-ITERATOR #<FUNCTION (FLET SB-IMPL::ITERATE :IN SB-EXT:MAP-DIRECTORY) {7F94089FDC5B}> "/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/html/" NIL)
5: (SB-EXT:MAP-DIRECTORY #<FUNCTION (LAMBDA (SB-IMPL::FILE) :IN SB-IMPL::MAP-MATCHING-ENTRIES) {10023205AB}> #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/html/" :FILES T :DIRECTORIES :AS-FILES :CLASSIFY-SYMLINKS T :ERRORP NIL)
6: (SB-IMPL::MAP-MATCHING-DIRECTORIES #<FUNCTION (LAMBDA (DIRECTORY) :IN DIRECTORY) {100232057B}> #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/html/*.asd")
7: (DIRECTORY #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/html/*.asd" :RESOLVE-SYMLINKS NIL)
8: (UIOP/FILESYSTEM:DIRECTORY-FILES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/html/" #P"*.asd")
9: (ASDF/SOURCE-REGISTRY:COLLECT-ASDS-IN-DIRECTORY #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/html/" #<FUNCTION (LAMBDA (ASDF/SOURCE-REGISTRY::ASD) :IN ASDF/SOURCE-REGISTRY:COMPUTE-SOURCE-REGISTRY) {10016CAE7B}>)
10: ((FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/html/")
11: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/html/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
12: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/pdl_api_reference_manual/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
13: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/docs/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
14: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/mtb-pdl-cat1/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
15: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/libs/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
16: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/psoc64/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
17: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/cypress/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
18: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/target/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
19: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/ext/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
20: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/platform/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
21: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/trusted-firmware-m/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
22: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/ARM/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
23: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/Middleware/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
24: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/hello-world-iot/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
25: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/git/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
26: (UIOP/FILESYSTEM:COLLECT-SUB*DIRECTORIES #P"/home/shunter/Documents/src/" #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::COLLECTP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D000B}> #<FUNCTION (FLET ASDF/SOURCE-REGISTRY::RECURSEP :IN ASDF/SOURCE-REGISTRY:COLLECT-SUB*DIRECTORIES-ASD-FILES) {10028D003B}> #<FUNCTION (LAMBDA (&REST REST) :IN "/tmp/sbcl/contrib/asdf/asdf.lisp") {534EF3EB}>)
27: (ASDF/SOURCE-REGISTRY:COMPUTE-SOURCE-REGISTRY NIL #<HASH-TABLE :TEST EQUAL :COUNT 32 {10020DC2D3}>)
28: (ASDF/SOURCE-REGISTRY:ENSURE-SOURCE-REGISTRY NIL)
29: (ASDF/SYSTEM-REGISTRY:SYSDEF-SOURCE-REGISTRY-SEARCH "asdf")
30: ((FLET ASDF/SYSTEM-REGISTRY::TRY :IN ASDF/SYSTEM-REGISTRY:SEARCH-FOR-SYSTEM-DEFINITION) ASDF/SYSTEM-REGISTRY:SYSDEF-SOURCE-REGISTRY-SEARCH)
31: (SB-KERNEL:%MAP-FOR-EFFECT-ARITY-1 #<FUNCTION (FLET ASDF/SYSTEM-REGISTRY::TRY :IN ASDF/SYSTEM-REGISTRY:SEARCH-FOR-SYSTEM-DEFINITION) {10020DBF2B}> (ASDF/PACKAGE-INFERRED-SYSTEM:SYSDEF-PACKAGE-INFERRED-SYSTEM-SEARCH ASDF/SYSTEM-REGISTRY:SYSDEF-CENTRAL-REGISTRY-SEARCH ASDF/SYSTEM-REGISTRY:SYSDEF-SOURCE-REGISTRY-SEARCH))
32: (ASDF/SYSTEM-REGISTRY:SEARCH-FOR-SYSTEM-DEFINITION "asdf")
33: ((LAMBDA NIL :IN ASDF/FIND-SYSTEM:LOCATE-SYSTEM))
34: ((LAMBDA NIL :IN ASDF/SYSTEM:FIND-SYSTEM))
35: (ASDF/SESSION:CONSULT-ASDF-CACHE (ASDF/SYSTEM:FIND-SYSTEM "asdf") #<FUNCTION (LAMBDA NIL :IN ASDF/SYSTEM:FIND-SYSTEM) {10020BEC3B}>)
36: ((:METHOD ASDF/COMPONENT:FIND-COMPONENT (STRING T)) "asdf" NIL :REGISTERED NIL) [fast-method]
37: ((:METHOD ASDF/OPERATE:OPERATE (SYMBOL T)) ASDF/LISP-ACTION:LOAD-OP :ASDF :VERBOSE NIL) [fast-method]
38: ((SB-PCL::EMF ASDF/OPERATE:OPERATE) #<unused argument> #<unused argument> ASDF/LISP-ACTION:LOAD-OP :ASDF :VERBOSE NIL)
39: ((LAMBDA NIL :IN ASDF/OPERATE:OPERATE))
40: ((:METHOD ASDF/OPERATE:OPERATE :AROUND (T T)) ASDF/LISP-ACTION:LOAD-OP :ASDF :VERBOSE NIL) [fast-method]
41: (ASDF/OPERATE:LOAD-SYSTEM :ASDF :VERBOSE NIL)
42: (ASDF/UPGRADE:UPGRADE-ASDF)
43: ((LAMBDA NIL :IN ASDF/OPERATE:OPERATE))
44: (ASDF/SESSION:CALL-WITH-ASDF-SESSION #<FUNCTION (LAMBDA NIL :IN ASDF/OPERATE:OPERATE) {1001E5BCAB}> :OVERRIDE NIL :KEY NIL :OVERRIDE-CACHE NIL :OVERRIDE-FORCING NIL)
45: ((:METHOD ASDF/OPERATE:OPERATE :AROUND (T T)) ASDF/LISP-ACTION:LOAD-OP "quicklisp" :VERBOSE NIL) [fast-method]
46: ((LAMBDA NIL :IN "/home/shunter/.local/share/roswell/lisp/quicklisp/setup.lisp"))
47: (SB-INT:SIMPLE-EVAL-IN-LEXENV (LET ((*COMPILE-PRINT* NIL) (*COMPILE-VERBOSE* NIL) (*LOAD-VERBOSE* NIL) (*LOAD-PRINT* NIL)) (ASDF/OPERATE:OOS (QUOTE ASDF/LISP-ACTION:LOAD-OP) "quicklisp" :VERBOSE NIL)) #<NULL-LEXENV>)
48: (SB-EXT:EVAL-TLF (LET ((*COMPILE-PRINT* NIL) (*COMPILE-VERBOSE* NIL) (*LOAD-VERBOSE* NIL) (*LOAD-PRINT* NIL)) (ASDF/OPERATE:OOS (QUOTE ASDF/LISP-ACTION:LOAD-OP) "quicklisp" :VERBOSE NIL)) 14 NIL)
49: ((LABELS SB-FASL::EVAL-FORM :IN SB-INT:LOAD-AS-SOURCE) (LET ((*COMPILE-PRINT* NIL) (*COMPILE-VERBOSE* NIL) (*LOAD-VERBOSE* NIL) (*LOAD-PRINT* NIL)) (ASDF/OPERATE:OOS (QUOTE ASDF/LISP-ACTION:LOAD-OP) "quicklisp" :VERBOSE NIL)) 14)
50: ((LAMBDA (SB-KERNEL:FORM &KEY :CURRENT-INDEX &ALLOW-OTHER-KEYS) :IN SB-INT:LOAD-AS-SOURCE) (LET ((*COMPILE-PRINT* NIL) (*COMPILE-VERBOSE* NIL) (*LOAD-VERBOSE* NIL) (*LOAD-PRINT* NIL)) (ASDF/OPERATE:OOS (QUOTE ASDF/LISP-ACTION:LOAD-OP) "quicklisp" :VERBOSE NIL)) :CURRENT-INDEX 14)
51: (SB-C::%DO-FORMS-FROM-INFO #<FUNCTION (LAMBDA (SB-KERNEL:FORM &KEY :CURRENT-INDEX &ALLOW-OTHER-KEYS) :IN SB-INT:LOAD-AS-SOURCE) {100322F56B}> #<SB-C::SOURCE-INFO {100322F533}> SB-C::INPUT-ERROR-IN-LOAD)
52: (SB-INT:LOAD-AS-SOURCE #<SB-INT:FORM-TRACKING-STREAM for "file /home/shunter/.local/share/roswell/lisp/quicklisp/setup.lisp" {100322DB13}> :VERBOSE NIL :PRINT NIL :CONTEXT "loading")
53: ((LABELS SB-FASL::LOAD-STREAM-1 :IN LOAD) #<SB-INT:FORM-TRACKING-STREAM for "file /home/shunter/.local/share/roswell/lisp/quicklisp/setup.lisp" {100322DB13}> NIL)
54: (SB-FASL::CALL-WITH-LOAD-BINDINGS #<FUNCTION (LABELS SB-FASL::LOAD-STREAM-1 :IN LOAD) {7F94089FF62B}> #<SB-INT:FORM-TRACKING-STREAM for "file /home/shunter/.local/share/roswell/lisp/quicklisp/setup.lisp" {100322DB13}> NIL #<SB-INT:FORM-TRACKING-STREAM for "file /home/shunter/.local/share/roswell/lisp/quicklisp/setup.lisp" {100322DB13}>)
55: (LOAD #P"/home/shunter/.local/share/roswell/lisp/quicklisp/setup.lisp" :VERBOSE NIL :PRINT NIL :IF-DOES-NOT-EXIST :ERROR :EXTERNAL-FORMAT :DEFAULT)
56: (ROSWELL:QUICKLISP :PATH NIL :ENVIRONMENT "QUICKLISP_HOME")
57: (SB-INT:SIMPLE-EVAL-IN-LEXENV (ROSWELL:QUICKLISP) #<NULL-LEXENV>)
58: (EVAL (ROSWELL:QUICKLISP))
59: (ROSWELL::EVAL "(ros:quicklisp)")
60: (ROSWELL:RUN ((:EVAL "(ros:quicklisp)")))
61: (SB-INT:SIMPLE-EVAL-IN-LEXENV (ROSWELL:RUN (QUOTE ((:EVAL "(ros:quicklisp)")))) #<NULL-LEXENV>)
62: (EVAL (ROSWELL:RUN (QUOTE ((:EVAL "(ros:quicklisp)")))))
63: (SB-IMPL::PROCESS-EVAL/LOAD-OPTIONS ((:EVAL . "(progn #-ros.init(cl:load \"/usr/local/etc/roswell/init.lisp\"))") (:EVAL . "(ros:run '((:eval\"(ros:quicklisp)\")))")))
64: (SB-IMPL::TOPLEVEL-INIT)
65: ((FLET SB-UNIX::BODY :IN SB-IMPL::START-LISP))
66: ((FLET "WITHOUT-INTERRUPTS-BODY-3" :IN SB-IMPL::START-LISP))
67: (SB-IMPL::%START-LISP)

I've installed a terribly massive repo over a quarter-year ago, and I see that Quicklisp (though, not ASDF alone?) searches the whole tree for ASDF system files ahead-of-time. Although I prefer flatter folders to store my source code, a special directory for lisp systems only solves the issue.

Thanks!

[quicklisp]

This looks entirely like an asdf issue to me. Maybe it’s a config issue. Quicklisp usually caches big tree scans from session to session but asdf does not.

[samuel-hunter]

That's what I thought at first two, so I decided to load both ASDF and Quicklisp individually. Loading ASDF doesn't trigger the many-second tree-walk, but loading Quicklisp right after does:

~$ sbcl
This is SBCL 2.2.6.debian, an implementation of ANSI Common Lisp.
More information about SBCL is available at <http://www.sbcl.org/>.

SBCL is free software, provided as is, with absolutely no warranty.
It is mostly in the public domain; some portions are provided under
BSD-style licenses.  See the CREDITS and COPYING files in the
distribution for more information.
* (member :asdf *features*)
NIL
* (time (require :asdf))
Evaluation took:
  0.064 seconds of real time
  0.063112 seconds of total run time (0.059517 user, 0.003595 system)
  98.44% CPU
  88 lambdas converted
  177,433,937 processor cycles
  23,133,904 bytes consed
  
("ASDF" "asdf" "UIOP" "uiop")
* (member :asdf *features*)
(:ASDF :OS-UNIX :NON-BASE-CHARS-EXIST-P :ASDF-UNICODE :X86-64 :GENCGC :64-BIT
 :ANSI-CL :COMMON-LISP :ELF :IEEE-FLOATING-POINT :LINUX :LITTLE-ENDIAN
 :PACKAGE-LOCAL-NICKNAMES :SB-CORE-COMPRESSION :SB-LDB :SB-PACKAGE-LOCKS
 :SB-THREAD :SB-UNICODE :SBCL :UNIX)
* (time (load "quicklisp/setup"))
Evaluation took:
  2.204 seconds of real time
  2.201832 seconds of total run time (1.554370 user, 0.647462 system)
  [ Run times consist of 0.074 seconds GC time, and 2.128 seconds non-GC time. ]
  99.91% CPU
  125 forms interpreted
  912 lambdas converted
  6,172,970,809 processor cycles
  1,123,653,824 bytes consed
  
T

I don't know how ASDF nor Quicklisp works behind the scenes. If Quicklisp is caching the tree scan, is it possible that a part of ASDF is not loaded?

[quicklisp]

It's possible that your asdf config points to a big tree that it must scan.

[samuel-hunter]

Yes, I believe I've mentioned that earlier:

I've installed a terribly massive repo over a quarter-year ago, and I see that Quicklisp (though, not ASDF alone?) searches the whole tree for ASDF system files ahead-of-time.

I do wonder why this happens after ASDF has already loaded, while loading Quicklisp -- since you said that Quicklisp usually caches big tree scans from session to session -- though since you helped me solve the primary issue a couple months ago, I'll close this issue

Thanks!