[GHC] #15333: Weird cachegrind results for binary-trees

[GHC]

#15333: Weird cachegrind results for binary-trees
-------------------------------------+-------------------------------------
        Reporter:  sgraf             |                Owner:  (none)
            Type:  bug               |               Status:  new
        Priority:  normal            |            Milestone:  Research
       Component:  NoFib benchmark   |  needed
  suite                              |              Version:  8.5
      Resolution:                    |             Keywords:
Operating System:  Unknown/Multiple  |         Architecture:
                                     |  Unknown/Multiple
 Type of failure:  None/Unknown      |            Test Case:
      Blocked By:                    |             Blocking:
 Related Tickets:                    |  Differential Rev(s):
       Wiki Page:                    |
-------------------------------------+-------------------------------------
Description changed by sgraf:

Old description:

> I'm currently investigating an alleged regression in my branch of the
> late lambda lift and hit a confusing data point. Note that I'm very much
> relying on cachegrinds counted instructions/memory accesses for my
> findings.
>
> Check out the most recent version of `nofib` and run the following
> script:
>
> {{{#!sh
> #! /usr/bin/env zsh
> sed -i 's/import Debug.Trace//g' Main.hs # Make the following line
> idempotent
> echo "import Debug.Trace" | cat - Main.hs > Main.tmp && mv Main.tmp
> Main.hs # add the import for trace
> sed -i 's/trace "" \$ bit/bit/g' Main.hs # strip `trace $ ` prefixes in
> the call to `bit`
> ghc -O2 -XBangPatterns Main.hs -o bt1
> sed -i 's/bit/trace "" $ bit/g' Main.hs # prepend `trace $ ` to the call
> to `bit`
> ghc -O2 -XBangPatterns Main.hs -o bt2
> valgrind --tool=cachegrind ./bt1 12 2>&1 > /dev/null # without trace
> valgrind --tool=cachegrind ./bt2 12 2>&1 > /dev/null # with trace
> }}}
>
> This will compile two versions of `binary-trees`, one with an extra
> `trace "" $` call before the only call to the `bit` function. One would
> expect the version with the `trace` call (`bt1`) to allocate more than
> the version without (`bt2`). Indeed, the output of `+RTS -s` suggests
> that:
>
> {{{
> $ ./bt1 12 +RTS -s
> ...
> 43,107,560 bytes allocated in the heap
> ...
> $ ./bt2 12 +RTS -s
> ...
> 43,116,888 bytes allocated in the heap
> ...
> }}}
>
> That's fine. A few benchmark runs by hand also suggested the tracing
> version is a little slower (probably due to IO).
>
> Compare that to the output of the above cachegrind calls:
>
> {{{
> $ valgrind --tool=cachegrind ./bt1 12 > /dev/null
> ...
> I   refs:      118,697,583
> ...
> D   refs:       43,475,212
> ...
> $ valgrind --tool=cachegrind ./bt2 12 > /dev/null
> ...
> I   refs:      116,340,710
> ...
> D   refs:       42,523,369
> ...
> }}}
>
> It's the other way round here! How's that possible?
>
> Even if this isn't strictly a bug in GHC or NoFib, it's relevant
> nonetheless, as our benchmark infrastructure currently relies on
> instruction counts. I couldn't reproduce this by writing my own no-op
> `trace _ a = a; {-# NOINLINE trace #-}`, btw.
>
> I checked this on GHC 8.2.2 and a semi-recent HEAD commit
> (bb539cfe335eeec7989332b859b1f3162c5e105a).

New description:

 I'm currently investigating an alleged regression in my branch of the late
 lambda lift and hit a confusing data point. Note that I'm very much
 relying on cachegrinds counted instructions/memory accesses for my
 findings.

 Check out the most recent version of `nofib` and run the following script:

 {{{#!sh
 #! /bin/sh
 sed -i 's/import Debug.Trace//g' Main.hs # Make the following line
 idempotent
 echo "import Debug.Trace" | cat - Main.hs > Main.tmp && mv Main.tmp
 Main.hs # add the import for trace
 sed -i 's/trace "" \$ bit/bit/g' Main.hs # strip `trace $ ` prefixes in
 the call to `bit`
 ghc -O2 -XBangPatterns Main.hs -o bt1
 sed -i 's/bit/trace "" $ bit/g' Main.hs # prepend `trace $ ` to the call
 to `bit`
 ghc -O2 -XBangPatterns Main.hs -o bt2
 valgrind --tool=cachegrind ./bt1 12 2>&1 > /dev/null # without trace
 valgrind --tool=cachegrind ./bt2 12 2>&1 > /dev/null # with trace
 }}}

 This will compile two versions of `binary-trees`, one with an extra `trace
 "" $` call before the only call to the `bit` function. One would expect
 the version with the `trace` call (`bt1`) to allocate more than the
 version without (`bt2`). Indeed, the output of `+RTS -s` suggests that:

 {{{
 $ ./bt1 12 +RTS -s
 ...
 43,107,560 bytes allocated in the heap
 ...
 $ ./bt2 12 +RTS -s
 ...
 43,116,888 bytes allocated in the heap
 ...
 }}}

 That's fine. A few benchmark runs by hand also suggested the tracing
 version is a little slower (probably due to IO).

 Compare that to the output of the above cachegrind calls:

 {{{
 $ valgrind --tool=cachegrind ./bt1 12 > /dev/null
 ...
 I   refs:      118,697,583
 ...
 D   refs:       43,475,212
 ...
 $ valgrind --tool=cachegrind ./bt2 12 > /dev/null
 ...
 I   refs:      116,340,710
 ...
 D   refs:       42,523,369
 ...
 }}}

 It's the other way round here! How's that possible?

 Even if this isn't strictly a bug in GHC or NoFib, it's relevant
 nonetheless, as our benchmark infrastructure currently relies on
 instruction counts. I couldn't reproduce this by writing my own no-op
 `trace _ a = a; {-# NOINLINE trace #-}`, btw.

 I checked this on GHC 8.2.2 and a semi-recent HEAD commit
 (bb539cfe335eeec7989332b859b1f3162c5e105a).

--

-- 
Ticket URL: <http://ghc.haskell.org/trac/ghc/ticket/15333#comment:1>
GHC <http://www.haskell.org/ghc/>
The Glasgow Haskell Compiler