I’m trying to understand the output of racket-mode’s racket-profile. Here’s an example of my program profiled at three different points: CALLS MSEC NAME FILE 54 46 for-loop src/widgets.rkt 1 6 init-new-tab src/tab.rkt 1 1 go method in browser-text% src/widgets.rkt 7 1 parse-dir-entity src/gopher.rkt 1 1 src/gopher.rkt 355 1 loop-mls src/gopher.rkt

108 46 for-loop src/widgets.rkt 1 6 init-new-tab src/tab.rkt 37 4 parse-dir-entity src/gopher.rkt 3 3 go method in browser-text% src/widgets.rkt 3 3 src/gopher.rkt 2384 3 loop-mls src/gopher.rkt

1051 51 parse-dir-entity src/gopher.rkt 1123 46 for-loop src/widgets.rkt 101686 25 loop-mls src/gopher.rkt 1 6 init-new-tab src/tab.rkt 4 4 go method in browser-text% src/widgets.rkt 4 4 src/gopher.rkt 4 4 gopher-fetch src/gopher.rkt 1051 3 menu-line-split src/gopher.rkt

I originally assumed that the msec time was per call since for most calls it remains relatively static as the number of calls increases. However, that isn’t the case for loop-mls. loop-mls can’t be taking 25 msec for each of 101,686 calls.

I also wonder if garbage collection time is counted. Basically my code runs quickly until it starts handling more data. At that point the execution appears to slow, but the amount of work done per function call should remain pretty consistent.

IIRC it is the total time spent.

I added this to Racket Mode some years ago, but, the spirit is to provide a way to use the errortrace-lib based profiling and give the results in an Emacs buffer that makes it easier to jump to the locations.

https://docs.racket-lang.org/errortrace/stacktrace.html#%28sig-val._%28%28lib._errortrace%2Fstacktrace..rkt%29._stacktrace-imports~5e._initialize-profile-point%29%29

It basically just accumulates current-inexact-milliseconds between the register-profile-start and register-profile-stop calls from the errortrace instrumentation.

I would expect it to include GC time.

Note that any profiling using something like Racket Mode or DrRacket is probably not as trustworthy as doing it via command-line Racket. There is some risk of other things happening, complicating the results.

To the extent I’ve used this in Racket Mode, for myself — eating my own dog food — I’ve focused more on “CALLS”, taken “MSEC” with a big grain of salt, and used it mostly to challenge my intuition about roughly where the time is spent. Like, to help find a starting point, or candidate that might not have occurred to me.

^ @jjsimpso I hope that helps? Or at least, helps set expectations realistically?

See also raco profile https://docs.racket-lang.org/profile/index.html

Maybe see also Optimization Coach.

Thanks. So is raco profile implemented differently then? That is one thing I wasn’t sure about.

I just enabled the GC logs and I do see about 20ms of GC time, but that doesn’t account for the delay I’m seeing.

I’ll try raco profile next to get a clean run without possible interference. Thanks for your help.