[racket-dev] Why is current-module-name-resolver taking so much time?

From: Sam Tobin-Hochstadt (samth at cs.indiana.edu)
Date: Fri Sep 20 15:48:39 EDT 2013

I decided to look at why 'make' with a fully-built install takes a
long time, and got a surprising result.  First, the 'link-all.rkt'
script takes about 17 seconds on my machine, almost all of it in
`pkg-install`. I then profiled this, and got the surprising result
that the majority of the time is spent resolving module names:

----------------------------------------------------------------------------
                                 [traversing imports] [68]              0.3%
                                 standard-module-name-resolver [49]     0.3%
                                 temp37 [43]                            0.9%
                                 run [5]                                3.9%
                                 ??? [29]                              20.2%
                                 parse-loop88 [36]                     29.1%
                                 for-loop [21]                         45.2%
 [49] 11872(63.2%) 6006(32.0%) standard-module-name-resolver (unknown source)
                                 [traversing imports] [51]             31.9%
                                 find-col-file [52]                     3.5%
                                 show-collection-err [54]               2.0%
                                 ??? [55]                               1.8%
                                 [traversing imports] [56]              1.1%
                                 ??? [57]                               1.0%
                                 [traversing imports] [53]              0.9%
                                 [traversing imports] [58]              0.8%
                                 ??? [59]                               0.7%
                                 ??? [60]                               0.5%
                                 split-relative-string [61]             0.5%
                                 ??? [63]                               0.5%
                                 lang:read-syntax [62]                  0.5%
                                 go [64]                                0.5%
                                 standard-module-name-resolver [49]     0.3%
----------------------------------------------------------------------------

If you're unused to reading `profile` output, it says that 63.2% of
the time is spent in `standard-module-name-resolver`, with about half
that in the function itself, and half in the functions it calls in
turn.

I've never seen a profile where this turned up so high, and I'm trying
to figure out if there's some way it can be made faster.  The only
call to (current-module-name-resolver) in the pkg system is on line
1333 of pkg/lib.rkt, which according to the profiler is responsible
for fewer than half of this time.

Sam

Posted on the dev mailing list.