On Mon, 6 Sep 2021 21:25:48 +0100 Mark Fisher <[email protected]> wrote:
> The compilation options enable instrumentation-based profiling. There's > statistical profiling available when running executables with -:p which > might give you more useful data (see > https://www.more-magic.net/posts/statistical-profiling.html for more > infomation). Could you please try that one as well? > > I had found that article, didn't realise it was as easy as adding the switch > when running. > > Here's the output for windows: > reading `PROFILE.15844' ... > > procedure > calls seconds average percent > ----------------------------------------------------------------------------------------------------------------------- > ../advents/2015/aoc2015day04.scm:35: > message-digest-byte-vector#message-digest-string 149 8.269 0.055 > 69.671 > ../advents/2015/aoc2015day04.scm:35: chicken.string#conc > 112 1.320 0.011 11.120 > ##sys#substring=? > 72 1.050 0.014 8.845 > ../advents/aoc-files.scm:43: streams.primitive#$make-stream-eager$ > 10 0.140 0.014 1.179 > ##sys#profile-exit > 11 0.120 0.010 1.010 > ../advents/2015/aoc2015day04.scm:35: loop240 > 9 0.090 0.010 0.758 > comparators/default.scm:115: make-comparator > 9 0.090 0.010 0.758 > comparators/default.scm:111: object-type > 8 0.090 0.011 0.758 > ../advents/aoc-files.scm:47: streams.utils#stream-fold-right > 2 0.060 0.030 0.505 > ../advents/2015/aoc2015day03.scm:110: streams.primitive#stream-null? > 5 0.050 0.010 0.421 > ../advents/aoc-files.scm:44: streams.primitive#stream-cdr > 4 0.040 0.010 0.336 > ../advents/2015/aoc2015day03.scm:110: streams.primitive#$make-stream-eager$ > 3 0.040 0.013 0.336 > comparators/comparators-impl.scm:235: acc > 3 0.030 0.010 0.252 > ../advents/2015/aoc2015day03.scm:113: streams.primitive#stream-null? > 3 0.030 0.010 0.252 > comparators/comparators-impl.scm:236: acc > 3 0.030 0.010 0.252 > ../advents/aoc-files.scm:43: streams.primitive#stream-car > 3 0.030 0.010 0.252 > ../advents/2015/aoc2015day01.scm:70: streams.derived#stream-fold > 1 0.030 0.030 0.252 > ../advents/2015/aoc2015day01.scm:95: streams.utils#stream-find > 1 0.030 0.030 0.252 > ##sys#profile-entry > 2 0.020 0.010 0.168 > ../advents/aoc-files.scm:41: streams.derived#stream-append > 2 0.020 0.010 0.168 > comparators/comparators-impl.scm:234: acc > 2 0.020 0.010 0.168 > ../advents/2015/aoc2015day03.scm:72: srfi-113#set-adjoin! > 2 0.020 0.010 0.168 > comparators/default.scm:87: object-type > 2 0.020 0.010 0.168 > comparators/default.scm:110: object-type > 2 0.020 0.010 0.168 > comparators/comparators-impl.scm:200: %salt% > 2 0.020 0.010 0.168 > ../advents/2015/aoc2015day03.scm:113: streams.primitive#$make-stream-eager$ > 2 0.020 0.010 0.168 > ../advents/2015/aoc2015day03.scm:113: streams.primitive#stream-car > 1 0.020 0.020 0.168 > ../advents/aoc-files.scm:40: streams.derived#stream-append > 1 0.010 0.010 0.084 > comparators/comparators-impl.scm:166: exact > 1 0.010 0.010 0.084 > ../advents/2015/advent2015.scm:38: scheme#display > 1 0.010 0.010 0.084 > ../advents/2015/aoc2015day03.scm:110: streams.primitive#$make-stream-lazy$ > 1 0.010 0.010 0.084 > ../advents/2015/aoc2015day02.scm:86: g194 > 1 0.010 0.010 0.084 > ../advents/2015/aoc2015day03.scm:71: streams.derived#stream-fold > 1 0.010 0.010 0.084 > comparators/comparators-impl.scm:95: g307 > 1 0.010 0.010 0.084 > comparators/comparators-impl.scm:222: g450 > 1 0.010 0.010 0.084 > comparators/default.scm:56: g721 > 1 0.010 0.010 0.084 > ../advents/2015/aoc2015day04.scm:8: chicken.load#load-extension > 1 0.010 0.010 0.084 > comparators/comparators-impl.scm:166: scheme#round > 1 0.010 0.010 0.084 > ../advents/2015/advent2015.scm:26: format#format > 1 0.010 0.010 0.084 > ../advents/2015/aoc2015day03.scm:110: streams.primitive#stream-cdr > 1 0.010 0.010 0.084 > ../advents/2015/aoc2015day03.scm:110: streams.primitive#stream-car > 1 0.010 0.010 0.084 > ../advents/2015/aoc2015day01.scm:46: chicken.load#load-extension > 1 0.010 0.010 0.084 > > Under linux: > reading `PROFILE.220771' ... > > procedure > calls seconds average percent > ----------------------------------------------------------------------------------------------------------------------- > ../advents/2015/aoc2015day04.scm:35: > message-digest-byte-vector#message-digest-string 35 2.020 0.057 > 73.722 > ../advents/2015/aoc2015day04.scm:35: chicken.string#conc > 30 0.320 0.010 11.678 > ##sys#substring=? > 9 0.090 0.010 3.284 > ../advents/2015/aoc2015day04.scm:35: loop240 > 2 0.060 0.030 2.189 > comparators/default.scm:115: make-comparator > 2 0.030 0.014 1.094 > ../advents/aoc-files.scm:43: streams.primitive#$make-stream-eager$ > 2 0.030 0.014 1.094 > comparators/default.scm:111: object-type > 2 0.020 0.010 0.729 > ##sys#profile-exit > 2 0.020 0.010 0.729 > ../advents/2015/aoc2015day03.scm:72: srfi-113#set-adjoin! > 2 0.020 0.010 0.729 > ../advents/2015/aoc2015day01.scm:95: streams.utils#stream-find > 1 0.020 0.020 0.729 > ../advents/2015/aoc2015day03.scm:110: streams.primitive#$make-stream-lazy$ > 1 0.010 0.010 0.364 > comparators/default.scm:110: object-type > 1 0.010 0.010 0.364 > ##sys#list->string > 1 0.010 0.010 0.364 > comparators/comparators-impl.scm:236: acc > 1 0.010 0.010 0.364 > ../advents/2015/aoc2015day03.scm:110: streams.primitive#stream-car > 1 0.010 0.010 0.364 > ../advents/2015/advent2015.scm:25: format#format > 1 0.010 0.010 0.364 > ../advents/2015/aoc2015day03.scm:113: streams.primitive#stream-null? > 1 0.010 0.010 0.364 > ../advents/aoc-files.scm:38: streams.primitive#$make-stream-lazy$ > 1 0.010 0.010 0.364 > ##sys#profile-entry > 1 0.010 0.010 0.364 > ##sys#dynamic-wind > 1 0.010 0.010 0.364 > ../advents/2015/aoc2015day03.scm:113: streams.primitive#$make-stream-lazy$ > 1 0.010 0.010 0.364 > > which does show a lot more calls in windows. Thanks for sharing your results. Some [potentially wrong/misleading/stupid] notes and questions: * I believe in this particular case the profiler based on instrumentation can provide more reliable results. The statistical profiler relies on signal handling -- I think that itself can be a source of discrepancies when it comes to comparing results obtained from different systems. * Do you observe the same behavior with other programs? For example, you said that GCC is the same version on both Linux and Windows. If you compile the same C file on both systems, is gcc ~4 times slower on Windows too? I mean gcc's execution time (i.e., time to compile a file). * I wonder if the CHICKEN runtime/eggs is going through some slow path in Windows' libc that is not affecting the entire virtualized Linux system running your CHICKEN program. If the virtualization software manages to avoid that slow path, that could explain the performance difference. * Is it possible that Windows is doing something funny to the execution of your binaries? Like some runtime analysis to detect malicious behavior? Sounds a bit crazy, but who knows. I'm sorry. I don't really understand why things are slower on Windows. At this point I have more questions than answers. :-) All the best. Mario -- http://parenteses.org/mario
