[racket-dev] Understanding the performance of raco make

I think you probably want to get information directly from
`compiler/cm`, probably `compiler/cm` doesn't provide the right
information right now, and probably some adjustments to `compiler/cm`
could get you useful information through the logging API. Also,
`parallel-compile-files` might need to change to propagate logging from
from a separate place to the original one.

Part of the reason that `compiler/cm` doesn't already provide good
information is that it has a `manager-trace-handler` parameter that
pre-dates the logging API. The default trace handler logs trace strings
as 'debug events, but it's easy to imagine that structured information
as 'info events would be more helpful for your purposes.

In other words, I'm suggesting that you change `compiler/cm` and
probably `parallel-compile-files` --- if that sounds reasonable to you.

Coincidentally, I'm right now adjusting the way that logging is used
for `compiler/cm-accomplice`, but I don't think those changes would
interfere with changes you might make.

At Tue, 28 Oct 2014 08:45:09 -0700, Eric Dobson wrote:
> I'm trying to improve the compilation speed of some modules, and to do that
> I need to understand how raco make is spending its time.
> 
> I decided to call parallel-compile-files myself with a handler that gets
> the time of start and done messages, and then turn those into a timeline
> plot.
> 
> I have a attached a screen shot of what that produces.​
>  Screen Shot 2014-10-28 at 8.07.42 AM.png
> <https://docs.google.com/file/d/0By8GtCCnLFX9WGgyWTRpbXdMQUU/edit?usp=drive_web>
> ​
> The problem I have found is that when one builder is building a module I
> don't get insight into what it is doing while compiling that modules
> dependencies that were not prefetched by a different builder. This causes
> two problems. The first is that compilation time for some modules looks
> very long, even though most of it is in compiling their dependencies. The
> second is that I cannot tell what is going on when only the original
> threads are doing processing, and so it isn't obvious why other threads
> start up again.
> 
> Is there a better way to instrument raco make?
> 
> Hacky code:
> 
> Instrumented compile:
> #lang racket/base
> 
> (require setup/parallel-build racket/match)
> (define times (make-hash))
> (parallel-compile-files (list
> 
> "/Users/endobson/proj/racket/plt/pkgs/typed-racket-pkgs/typed-racket-lib/typed-r
> acket/core.rkt")
>   #:handler
>     (λ (id type path-string msg out err)
>       (define time (current-inexact-milliseconds))
>       (define ps (if (path? path-string) (path->string path-string)
> path-string))
>       (cond
>         [(equal? type 'start)
>          (hash-set! times (list ps id) time)]
>         [(equal? type 'done)
>          (hash-set! times (list ps id) (list (hash-ref times (list ps id))
> time))])))
> (for ([(name time) times])
>   (match-define (list start stop) time)
>   (match-define (list file id) name)
>   (write (list id file start stop))
>   (newline))
> 
> 
> 
> Plotter:
> #lang racket/base
> 
> (require plot racket/match racket/list)
> (plot-new-window? #t)
> 
> (define work-units
>   (call-with-input-file* "data.rktd"
>     (lambda (port)
>       (let loop ([items empty])
>         (define item (read port))
>         (if (eof-object? item)
>             items
>             (loop (cons item items)))))))
> 
> (define converted-work-units
>   (for/list ([work-unit (in-list work-units)])
>     (match-define (list index file-name start stop) work-unit)
>     (list
>       (rectangles
>         #:alpha 0
>         (list (list (ivl start stop) (ivl (- index 1/3) (+ index 1/3)))))
>       #;
>       (point-label
>         (list (/ (+ start stop) 2) index)
>         file-name
>         #:anchor 'center
>         #:point-size 0))))
> 
> 
> (plot
>   #:width 1500
>   converted-work-units)
> _________________________
>   Racket Developers list:
>   http://lists.racket-lang.org/dev