I’m experimenting with different versions of the same function and testing timing with a native executable. It runs three functions, plus Core.Command.run to parse a command line parameter. I time individual functions with this sort of thing:
let time3 f x y z =
let t = Sys.time() in
let result = f x y z in
Printf.printf "%fs\n" (Sys.time() -. t);
result
The total time in the three functions is a little more than 4 seconds, which is also what my time function reports for Command.run, which is what I’d expect.
However, the entire execution time, as reported by /usr/bin/time and by running date before and after is about 55 seconds.
What could the program doing for those extra 50 seconds? If I run the same code on a larger data structure, I get an even longer run time beyond the function times, so I don’t think it’s only normal start up and shut down that every program undergoes. e.g. with larger data structures the function times total 10 seconds and total run time of the program is 2 minutes and 50 seconds.
Garbage collection between function calls, maybe?
EDIT: Or with a larger parameter (1000 rather than 300 0r 400–not worth explaining what that means), the functions take 2 minutes and 20 seconds, but the whole program takes 50 minutes.
(Why did I use date? The program forks multiple processes inside one of the functions using a Parmap function that exits inside that function. I wanted to make sure time wasn’t confused by that. It’s not, but user and sys time are more than real time, as you might expect.)
Ah, the answer may be here: Sys.time measures CPU time, not wall time. Sys.time might not capture garbage collection or time spent in system calls, for all I know, and wouldn’t record time waiting to get into a CPU. Maybe Sys.time only records the time before and after the call to a Parmap function.
Unix.gettimeofday reports wall time an gives function execution times that do add up to about the whole program time.
Do not use gettimeofday to measure time, it is sensitive to operating system calendar time adjustements (e.g. via ntp); it can even go back in time. Use a monotonic time source for that (one is available in mtime).
In general, usr/bin/time is a pretty good indication of how much time is really used up. Not benchmarking accurate, but ‘good enough’ for most purposes.
Yeah, I’m finding that when I add up the gettimeofday times for function calls, they’re about equal to the Unix time report.
(Haven’t yet tested with mtime, and I will, but for long run times, at least, it sounds like getttimeofday will usually be close to accurate as long as one doesn’t test while going over a time zone border. )
@dbuenzli, I’m having trouble figuring out how to get access to Mtime_clock within the Mtime package, where some core functions such as elapsed live. I think I’m missing something obvious.
Thanks @hcarty, @dbuenzli–for some reason when I tried to compile min_os.ml yesterday, I got an error. I worked on it for a few minutes and gave up for the time being. Just now when I tried it, both the bytecode and native compile commands worked instantly. I’m not sure what I was doing wrong.
In utop, I can #load "<path>/lib/mtime/os/mtime_clock.cma" (is that what I should do?) but I have not yet figured out how to get to the Mtime_clock module. My current need isn’t for bytecode timing, but utop is great for learning how to use a new module.
(One drawback of tools like oasis and jbuilder working so well, is that people like me can get a lot done without really understanding or knowing how to user the underlying compiler tools. The compiler command lines given in min_os.ml are very useful up to a point, but then I actually don’t know how to translate it into a jbuild file. Thanks for the link to basus’s issue; I hadn’t looked in the issues. That discussion tells me what I need to put in a jbuild file, and min_os.ml tells me how to use mtime. I can work on it now.)
)