[racket-dev] weirdness with racket or typed racket module requiring startup time?

In Whalesong, I've been watching where the compile-time is going,
because I want to make it more pleasant to use.  When I compile hello
world, it takes about three seconds to complete the compile on my
machine.

Out of a lark, I wanted to see what the base-line was for just loading
up the modules and not doing any work at all:

#############################################
$ time whalesong
[command line usage output cut]

real	0m1.872s
user	0m1.592s
sys	0m0.152s
#############################################

Oh dear.  Ok, so I must be doing something terribly wrong, because it
looks like the majority of the time is simply from loading Whalesong's
modules in the first place.

Is there something built into Racket that lets me see how long it
takes for modules to invoke?  If not, I guess I can just annotate each
of my modules to see where the time's taking.



In any event, I'm definitely doing raco make, so something else is
accounting for the time.  While trying to trace it, I saw something
unusual.  Here's a reduced test case.  Let's say that I have the
following test file that I'm calling "load.rkt":

;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
#lang racket/base
(require (planet dyoo/whalesong/whalesong-helpers)
         #;(planet dyoo/whalesong/make/make-structs))
;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;

To note: whalesong-helpers.rkt itself does a require of make-structs.
I first have load.rkt where the require to make-structs is commented
out.

I measure the time it takes to run load.rkt:

######################################################
dyoo at thunderclap:~/work/whalesong$ raco make load.rkt
dyoo at thunderclap:~/work/whalesong$ time racket load.rkt

real	0m1.856s
user	0m1.608s
sys	0m0.140s
######################################################

I then uncomment the require in my load.rkt, recompile, and measure again.



######################################################
dyoo at thunderclap:~/work/whalesong$ raco make load.rkt
dyoo at thunderclap:~/work/whalesong$ time racket load.rkt

real	0m2.028s
user	0m1.808s
sys	0m0.104s
######################################################

I'm observing about a 100ms cost here for something that I expected to
be a no-op, because the module has already been required.


The reason I think Typed Racket might be involved is because
make-structs is written in #lang typed/racket/base.  When I do a
similar experiment, replacing the require to make-structs with a
module in #lang racket/base, I don't see the introduced delay:

;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
dyoo at thunderclap:~/work/whalesong$ cat load.rkt
#lang racket/base

(require (planet dyoo/whalesong/whalesong-helpers)
         (planet dyoo/whalesong/js-assembler/package))
dyoo at thunderclap:~/work/whalesong$ raco make load.rkt
dyoo at thunderclap:~/work/whalesong$ time racket load.rkt

real	0m1.792s
user	0m1.548s
sys	0m0.152s
;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;


Is that something that's supposed to happen?  I guess I'm just trying
to understand the repercussions of requiring a module from Typed
Racket into regular Racket.