Opened 3 years ago

Closed 11 months ago

#10007 closed bug (fixed)

Fix misattribution of Cost Centre profiles to lintAnnots

Reported by: thoughtpolice Owned by: simonmar
Priority: high Milestone: 8.2.1
Component: Profiling Version: 7.10.1-rc1
Keywords: Cc: bgamari
Operating System: Unknown/Multiple Architecture: Unknown/Multiple
Type of failure: Incorrect result at runtime Test Case:
Blocked By: Blocking:
Related Tickets: #9961,#5654 Differential Rev(s): Phab:D616 Phab:D636
Wiki Page:

Description

Split off from #9961 - the profiling results while debugging erroneously reported that most cost centre profiles were a result of lintAnnots, as opposed to CSE. This is a bug.

Change History (21)

comment:1 Changed 3 years ago by simonmar

Differential Rev(s): Phab:D616Phab:D616 Phab:D636

comment:2 Changed 3 years ago by Simon Marlow <marlowsd@…>

In daed18c35cda114d8a5303bcb645195e1fd397e3/ghc:

Fix a profiling bug

Summary:
We were erroneously discarding SCCs on function-typed variables.
These can affect the call stack, so we have to retain them.  The bug
was introduced during the recent SourceNote refactoring.

This is an alternative to the fix proposed in D616.  I also added the
scc005 test from that diff, which works with this change.

While I was here, I also fixed up the other profiling tests, marking a
few as expect_broken_for(10037) where the opt/unopt output differs in
non-fatal ways.

Test Plan: profiling tests

Reviewers: scpmw, ezyang, austin

Subscribers: thomie

Differential Revision: https://phabricator.haskell.org/D636

GHC Trac Issues: #10007

comment:3 Changed 3 years ago by hvr

Status: newmerge

...I assume this is to be merged to 7.10?

comment:4 Changed 3 years ago by scpmw

Well, it's the wrong fix, as far as I'm concerned. Yes, it fixes the erroneous attribution to lintAnnots, but only because we change the program's (RTS) cost semantics twice during optimisations, with both instances un-doing each other. This is not guaranteed, see the new test case for D616.

I also didn't feel it would help the discussion to mention this - but this also doesn't fix rather silly double-annotations on parameters, which (I think) only don't appear because we automatically eliminate repeating cost centres in stacks. If needed, I could produce another test case that demonstrates that.

Short version: This is only a band-aid. And as far as those go, I would still prefer D616. At least until I have figured out how to *actually* implement Eval2, which would fix the whole situation from the RTS end.

comment:5 Changed 3 years ago by simonmar

I respectfully disagree that is is a band-aid. It is not a complete fix, but it does fix a regression since 7.8, so it should definitely go into 7.10. I'll continue to discuss the larger issue on D616.

comment:6 Changed 3 years ago by thoughtpolice

Resolution: fixed
Status: mergeclosed

Merged to ghc-7.10 (via 1d401b4384b5f9c7429140320e1d0bc120172b8b).

comment:7 Changed 2 years ago by simonpj

Owner: scpmw deleted
Resolution: fixed
Status: closednew

Lots of cost is still attributed to lintAnnots, so the original problem doesn't seem to be fixed. So I'll re-open.

Simon

comment:8 Changed 2 years ago by scpmw

Yes - I investigated this again a month ago, and found that SM's fix didn't correct the whole problem. In fact, if I remember correctly what we end up with is something like

case scctick<SpecConstr> specConstrProgram of ...

In this situation the tick will fail to actually capture any cost in specConstrProgram, which will instead end up in the cost-centre next in the hierarchy, which happens to be lintAnnots (Core2Core before).

As explained in D616 and #5654, this is a fairly fundamental problem: GHC simply doesn't implement the cost-centre semantics for function values correctly. Correcting this isn't exactly easy - I have been experimenting in the past weeks, and the best solution I can come up with (still?) involves a new closure type that wraps function values when they escape cost-centre scopes.

Two possible solutions here: We could attempt another stopgap measure. For example, the above code should probably in-line as it is only used once. Building the full solution will still need a bit more tinkering, but I might be able to make a proposal soon-ish (... just need to get it to stop crashing. Seems getting register saving right can be surprisingly tricky).

comment:9 Changed 2 years ago by bgamari

Cc: bgamari added
Milestone: 7.10.17.10.3
Owner: set to scpmw

Thanks for the update!

comment:10 Changed 2 years ago by simonpj

Try the effect of changing (in SimplCore):

            ; guts' <- lintAnnots (ppr pass) (doCorePass pass) guts

to

            ; guts' <- lintAnnots (ppr pass) (\p -> doCorePass pass p) guts

Simon M speculates that this might work around the problem.

comment:11 Changed 2 years ago by scpmw

Unfortunately, I am pretty sure I tested that - and it doesn't work. The easiest workaround is updating all doCorePass equations as follows:

doCorePass pass@(CoreDoSimplify {}) guts = {-# SCC "Simplify" #-}
                                           simplifyPgm pass guts

Which avoids this problem by not putting the SCC on a function-type expression.

Last edited 2 years ago by scpmw (previous) (diff)

comment:12 Changed 2 years ago by bgamari

scpmw, I've tested Simon's suggestion on master and it appears to work for me. Costs are correctly attributed to cost-centers beneath lintAnnots. I'll be merging this to master.

comment:13 Changed 2 years ago by scpmw

Interesting. I checked, and the code I used to reproduce the problem was exactly what simonpj suggested, but with an extra SCC on the doCorePass call. That way, I could catch exactly the "leaking" costs. Maybe that annotation also changed the compiler behaviour sufficiently to stop this from working.

Anyway, all the better. Maybe we should close this ticket then, and continue the discussion of the larger issue in #5654?

comment:14 Changed 2 years ago by bgamari

Hmm, actually it seems that master is now doing the right thing even without my patch. I am quite confused. I'll return to this after the release.

comment:15 Changed 2 years ago by bgamari

This may be related to #5654.

comment:16 Changed 2 years ago by bgamari

Milestone: 7.10.38.2.1

comment:17 Changed 12 months ago by bgamari

Milestone: 8.2.18.4.1

This won't be happening for 8.2 either, sadly.

comment:18 Changed 12 months ago by simonmar

Milestone: 8.4.18.2.1

As it happens, I was just working on this!

comment:19 Changed 12 months ago by simonmar

Owner: changed from scpmw to simonmar

comment:20 Changed 11 months ago by Ben Gamari <ben@…>

In 394231b3/ghc:

Fix cost-centre-stacks bug (#5654)

This fixes some cases of wrong stacks being generated by the profiler.
For background and details on the fix see
`Note [Evaluating functions with profiling]` in `rts/Apply.cmm`.

This does have an impact on allocations for some programs when
profiling.  nofib results:

```
   k-nucleotide          +0.0%     +8.8%    +11.0%    +11.0%      0.0%
         puzzle          +0.0%    +12.5%     0.244     0.246      0.0%
      typecheck           0.0%     +8.7%    +16.1%    +16.2%      0.0%
------------------------------------------------------------------------
--------
            Min          -0.0%     -0.0%    -34.4%    -35.5%    -25.0%
            Max          +0.0%    +12.5%    +48.9%    +49.4%    +10.6%
 Geometric Mean          +0.0%     +0.6%     +2.0%     +1.8%     -0.3%

```

But runtimes don't seem to be affected much, and the examples I looked
at were completely legitimate.  For example, in puzzle we have this:

```
position :: ItemType -> StateType ->  BankType
position Bono = bonoPos
position Edge = edgePos
position Larry = larryPos
position Adam = adamPos
```

where the identifiers on the rhs are all record selectors.  Previously
the profiler gave a stack that looked like

```
  position
  bonoPos
  ...
```

i.e. `bonoPos` was at the same level of the call stack as `position`,
but now it looks like

```
  position
   bonoPos
   ...
```

I used the normaliser from the testsuite to diff the profiling output
from other nofib programs and they all looked better.

Test Plan:
* the broken test passes
* validate
* compiled and ran all of nofib, measured perf, diff'd several .prof
files

Reviewers: niteria, erikd, austin, scpmw, bgamari

Reviewed By: bgamari

Subscribers: thomie

Differential Revision: https://phabricator.haskell.org/D2804

GHC Trac Issues: #5654, #10007

comment:21 Changed 11 months ago by simonmar

Resolution: fixed
Status: newclosed

Optimistically closing as fixed.

Note: See TracTickets for help on using tickets.