Re: [racket-dev] weirdness with racket or typed racket module requiring startup time?
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. You think you could be taking a small GC hit then? PLTSTDERR=debug environment variable might show GC info. Or add debugging printfs that dump (current-gc-milliseconds) at each step in program. Possibly. Here's what I see on one of my older machines when I invoke one of the entry-point modules into Whalesong. dyoo@kfisler-ra1:~/work/whalesong$ PLTSTDERR=debug time racket whalesong-helpers.rkt GC [0:minor] at 1,713K(+238K)[+152K]; freed 857K(-4,953K) in 4 msec GC [0:minor] at 1,965K(+4,082K)[+156K]; freed 558K(-1,854K) in 4 msec GC [0:minor] at 3,454K(+4,993K)[+172K]; freed 877K(-877K) in 8 msec GC [0:minor] at 5,504K(+3,471K)[+172K]; freed 1,250K(-2,546K) in 8 msec GC [0:minor] at 7,311K(+3,312K)[+188K]; freed 1,196K(-6,588K) in 16 msec GC [0:minor] at 10,370K(+6,253K)[+192K]; freed 2,064K(-7,456K) in 16 msec GC [0:minor] at 13,768K(+8,679K)[+328K]; freed 2,947K(-4,243K) in 28 msec GC [0:minor] at 17,891K(+6,716K)[+580K]; freed 3,724K(-14,508K) in 44 msec GC [0:minor] at 22,335K(+13,536K)[+736K]; freed 3,952K(-6,544K) in 40 msec GC [0:minor] at 28,611K(+11,564K)[+816K]; freed 4,591K(-16,671K) in 48 msec GC [0:minor] at 38,072K(+17,831K)[+1,196K]; freed 8,097K(-28,369K) in 44 msec GC [0:minor] at 46,609K(+29,566K)[+1,696K]; freed 12,936K(-13,960K) in 112 msec GC [0:minor] at 51,924K(+25,275K)[+2,932K]; freed 11,081K(-16,265K) in 92 msec GC [0:minor] at 65,100K(+18,835K)[+3,616K]; freed 16,881K(-22,065K) in 96 msec GC [0:MAJOR] at 75,231K(+16,560K)[+4,568K]; freed 23,374K(-53,342K) in 296 msec GC [0:minor] at 79,301K(+42,458K)[+4,752K]; freed 23,269K(-25,861K) in 40 msec 3.10user 0.28system 0:04.85elapsed 70%CPU (0avgtext+0avgdata 463504maxresident)k 0inputs+0outputs (0major+47826minor)pagefaults 0swaps As an experiment, I have a branch in my repository where I try to switch over all uses of #lang typed/racket/base to typed/racket/base/no-check to measure performance differences. See: https://github.com/dyoo/whalesong/tree/no-check Unfortunately, this is failing unexpectedly. # dyoo@kfisler-ra1:~/work/whalesong$ raco make whalesong-helpers.rkt time racket whalesong-helpers.rkt procedure application: expected procedure, given: #f; arguments were: 2 === context === /home/dyoo/work/whalesong/compiler/compiler.rkt:1305:0: compile-statically-known-lam-application /home/dyoo/work/whalesong/compiler/compiler.rkt:904:0: compile-lambda-bodies /home/dyoo/work/whalesong/compiler/compiler.rkt:34:0: -compile /home/dyoo/work/whalesong/compiler/bootstrapped-primitives.rkt:89:4: make-bootstrapped-primitive-code /home/dyoo/work/whalesong/compiler/bootstrapped-primitives.rkt:145:0: get-bootstrapping-code /home/dyoo/work/whalesong/make/make-structs.rkt: [running body] /home/dyoo/work/whalesong/js-assembler/package.rkt: [traversing imports] /home/dyoo/work/whalesong/whalesong-helpers.rkt: [traversing imports] real0m2.274s user0m1.940s sys 0m0.248s # I'm seeing a runtime error by switching over to #lang typed/racket/base/no-check, with the error highlight over my definition of arity-matches?. The definition for atomic-arity-list? seems to not be bound, nor is natural?, both of which I define using define-predicate. Even when I try to hack in definitions for these, I'm still receiving other error messages. I'll send a bug report about no-check. _ For list-related administrative tasks: http://lists.racket-lang.org/listinfo/dev
[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] real0m1.872s user0m1.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@thunderclap:~/work/whalesong$ raco make load.rkt dyoo@thunderclap:~/work/whalesong$ time racket load.rkt real0m1.856s user0m1.608s sys 0m0.140s ## I then uncomment the require in my load.rkt, recompile, and measure again. ## dyoo@thunderclap:~/work/whalesong$ raco make load.rkt dyoo@thunderclap:~/work/whalesong$ time racket load.rkt real0m2.028s user0m1.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@thunderclap:~/work/whalesong$ cat load.rkt #lang racket/base (require (planet dyoo/whalesong/whalesong-helpers) (planet dyoo/whalesong/js-assembler/package)) dyoo@thunderclap:~/work/whalesong$ raco make load.rkt dyoo@thunderclap:~/work/whalesong$ time racket load.rkt real0m1.792s user0m1.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. _ For list-related administrative tasks: http://lists.racket-lang.org/listinfo/dev
Re: [racket-dev] weirdness with racket or typed racket module requiring startup time?
On Sun, Sep 25, 2011 at 9:24 PM, Danny Yoo d...@cs.wpi.edu wrote: [snip TR taking a long time to load] 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. This looks a little worse than I expected, but in general, modules in Typed Racket incur some startup time overhead. Right now, this is inherent in the architecture of how Typed Racket modules communicate with each other, and the semantics of `require' in Racket. The plan is that adding facets or sub-modules will allow this time to be reduced or eliminated, but right now you can't avoid it. -- sam th sa...@ccs.neu.edu _ For list-related administrative tasks: http://lists.racket-lang.org/listinfo/dev
Re: [racket-dev] weirdness with racket or typed racket module requiring startup time?
Danny Yoo wrote at 09/25/2011 09:24 PM: 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. You think you could be taking a small GC hit then? PLTSTDERR=debug environment variable might show GC info. Or add debugging printfs that dump (current-gc-milliseconds) at each step in program. -- http://www.neilvandyke.org/ _ For list-related administrative tasks: http://lists.racket-lang.org/listinfo/dev
