<div dir="ltr">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.<div><br></div><div>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.</div><div><br></div><div>I have a attached a screen shot of what that produces.​<br><div class="gmail_chip gmail_drive_chip" style="width:396px;height:18px;max-height:18px;background-color:#f5f5f5;padding:5px;color:#222;font-family:arial;font-style:normal;font-weight:bold;font-size:13px;border:1px solid #ddd;line-height:1"><a href="https://docs.google.com/file/d/0By8GtCCnLFX9WGgyWTRpbXdMQUU/edit?usp=drive_web" target="_blank" style="display:inline-block;overflow:hidden;text-overflow:ellipsis;white-space:nowrap;text-decoration:none;padding:1px 0px;border:none;width:100%"><img style="vertical-align: bottom; border: none;" src="https://ssl.gstatic.com/docs/doclist/images/icon_11_image_list.png"> <span dir="ltr" style="color:#15c;text-decoration:none;vertical-align:bottom">Screen Shot 2014-10-28 at 8.07.42 AM.png</span></a></div>​<br></div><div>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.</div><div><br></div><div>Is there a better way to instrument raco make?</div><div><br></div><div>Hacky code:</div><div><br></div><div>Instrumented compile:</div><div><div>#lang racket/base</div><div><br></div><div>(require setup/parallel-build racket/match)</div><div>(define times (make-hash))<br></div><div>(parallel-compile-files (list</div><div>  "/Users/endobson/proj/racket/plt/pkgs/typed-racket-pkgs/typed-racket-lib/typed-racket/core.rkt")</div><div>  #:handler</div><div>    (λ (id type path-string msg out err)</div><div>      (define time (current-inexact-milliseconds))</div><div>      (define ps (if (path? path-string) (path->string path-string) path-string))</div><div>      (cond</div><div>        [(equal? type 'start)</div><div>         (hash-set! times (list ps id) time)]</div><div>        [(equal? type 'done)</div><div>         (hash-set! times (list ps id) (list (hash-ref times (list ps id)) time))])))</div><div>(for ([(name time) times])</div><div>  (match-define (list start stop) time)</div><div>  (match-define (list file id) name)</div><div>  (write (list id file start stop))</div><div>  (newline))</div></div><div><br></div><div><br></div><div><br></div><div>Plotter:</div><div><div>#lang racket/base</div><div><br></div><div>(require plot racket/match racket/list)</div><div>(plot-new-window? #t)</div><div><br></div><div>(define work-units<br></div><div>  (call-with-input-file* "data.rktd"</div><div>    (lambda (port)</div><div>      (let loop ([items empty])</div><div>        (define item (read port))</div><div>        (if (eof-object? item)</div><div>            items</div><div>            (loop (cons item items)))))))</div><div><br></div><div>(define converted-work-units</div><div>  (for/list ([work-unit (in-list work-units)])</div><div>    (match-define (list index file-name start stop) work-unit)</div><div>    (list</div><div>      (rectangles</div><div>        #:alpha 0</div><div>        (list (list (ivl start stop) (ivl (- index 1/3) (+ index 1/3)))))</div><div>      #;</div><div>      (point-label</div><div>        (list (/ (+ start stop) 2) index)</div><div>        file-name</div><div>        #:anchor 'center</div><div>        #:point-size 0))))</div><div><br></div><div><br></div><div>(plot</div><div>  #:width 1500<br></div><div>  converted-work-units)</div></div><div><br></div></div>