still confused - Githubissues

simonmichael commented 5 years ago

I love this tool for clarifying profiles - thanks!

Today I'm trying to understand a profile in more detail, and I'm just confused. Would it be possible to make these explanations clearer ?

TOT is the total time spent in any item under this code, what GHC calls inherited time. INH is the total time spent in the items that Profiterole did not move out to the top level. IND is the individual time, just like GHC profiles.

I've attached the profile in question for the sake of discussion. hledger.profiterole.txt hledger.prof.txt

simonmichael commented 5 years ago

PS that was a -p profile. Now I see -P recommended, I'll try that next.

Some questions I was asking myself:

where do the hyperlinks lead ? (to the broken-out sections ?)
what determines when a section is broken out from the main section ?
do the main + broken-out sections add up to 100%, or do the broken-out sections show some of the main section's time in more detail ?
why do some items, taking up significant time, show a (0) call count ?
can it be made to show space, or is it always time ?
why does it stop at some costly functions and show no detail below ? (because I was using -p not -P I think)

simonmichael commented 5 years ago

wouldn't it be nice if it included the same heading info as the regular profile (date, title, command, total time and allocation) or better, the same info as in a +RTS -s report (GC info, max residency etc.) for an all-in-one report ?

simonmichael commented 5 years ago

Here are the profiles made with -P: hledger.P.profiterole.txt hledger.P.prof.txt

What determines the order of broken-out sections ? They don't seem to be time-ordered in the above.

simonmichael commented 5 years ago

And here's one made with -Pa ("Give information about *all* cost centres"): hledger.Pa.profiterole.txt

I tried that because I was still asking myself:

why don't I see more detail under amountValue.ps' and commodityValue in this profile ?

This might be confusion on my part. Ignore this if too much detail, but just in case it helps answer that, here is their code:

-- | Find the market value of this amount on the given date, in it's
-- default valuation commodity, using the given market prices which
-- should be in date then parse order.
-- If no default valuation commodity can be found, the amount is left
-- unchanged.
amountValue :: MarketPricesDateAndParseOrdered -> Day -> Amount -> Amount
amountValue ps d a@Amount{acommodity=c} =
  let ps' = filter ((c==).mpcommodity) ps
  in
    case commodityValue ps' d c of
      Just v  -> v{aquantity=aquantity v * aquantity a}
      Nothing -> a

-- | Find the market value, if known, of one unit of the given
-- commodity (A), on the given valuation date, in the commodity (B)
-- mentioned in the latest applicable market price.
--
-- The applicable price is obtained from the given market prices,
-- which should be for commodity A only, and in date then parse order.
-- It is the price with the latest date on or before the valuation
-- date; or if there are multiple prices on that date, the last one
-- parsed.
commodityValue :: CommodityPricesDateAndParseOrdered -> Day -> CommoditySymbol -> Maybe Amount
commodityValue ps valuationdate c =
  case filter ((<=valuationdate).mpdate) ps of
    []  -> dbg Nothing
    ps' -> dbg $ Just $ mpamount $ last ps'
  where
    dbg = dbg8 ("using market price for "++T.unpack c)

ndmitchell commented 5 years ago

I suggest I answer here, and after we've figured out your confusion, flip this to documentation.

As another way of describing it:

TOT = cost of this, everything under this, including following hyperlinks
INH = cost of this, everything under this, not following hyperlinks
IND = cost of this only
where do the hyperlinks lead ? (to the broken-out sections ?) Yes.
what determines when a section is broken out from the main section ? Has two roots - if there are two paths to the same function, it gets broken out.
do the main + broken-out sections add up to 100%, or do the broken-out sections show some of the main section's time in more detail ? IND throughout adds up to 100%. INH of the top of each broken out chunk adds up to 100%. Subject to rounding errors - which can be fairly large with -p and are usually pretty small with -P. That's the thing that -P controls.
why do some items, taking up significant time, show a (0) call count ? That's how GHC produces it - a GHC "issue".
can it be made to show space, or is it always time ? Always time. My experience is that space in this view is mostly useless. If you want space, use one of the heap profiling features.
why does it stop at some costly functions and show no detail below ? (because I was using -p not -P I think) Probably because GHC shows nothing below.
wouldn't it be nice if it included the same heading info as the regular profile (date, title, command, total time and allocation) or better, the same info as in a +RTS -s report (GC info, max residency etc.) for an all-in-one report ? A reasonable feature request. Patch welcome! Or a separate ticket to leave it for someone else.
why don't I see more detail under amountValue.ps' and commodityValue in this profile ? Because you are calling base, which tends to truncate the profile. If you care about seeing inside, best thing to do is define local functions that split it up how you want to see it. This is entirely due to GHC's profiling output.

simonmichael commented 5 years ago

Apologies for the very slow conversation. I've just had a chance to do some more profiling. Thanks for your helpful notes.

I'll pick on one issue right now: the headings TOT, INH, IND. With your help I understand what they mean but I'm still finding the names non-mnemonic, or at least the INH column. It's new to profiterole (and I guess useful since you added it), and presumably INH stands for inherited, but it's actually TOT that corresponds to the "inherited" column in GHC's standard profiles.

simonmichael commented 5 years ago

Another question:

What do the (...)'s mean ?

simonmichael commented 5 years ago

I think the meaning of that middle column is something like: "inherited time in this execution branch alone, excluding parts also used by others". (I'm wondering if there's any other heading that could improve on INH).

ndmitchell commented 5 years ago

I think the (...) is coming from the GHC profile and just copied over (can you check the original .prof). If so, no idea.

I think your intuition is right for the middle column. I do find it handy as it tells me if this block is the right one. If TOT is much bigger than INH then I know to keep diving. If not, I know everything is here. Happy to change names if we can come up with something better. If no one else uses INH it may be better to drop entirely - less numbers makes it more usable.

jberryman commented 5 years ago

I wish I could be helpful and offer improvements to the docs, but I've stared at the examples and read through this thread but I'm still at a loss as to what the IND and INH columns represent, sorry...

For instance I really don't know what "cost of this only" means.

It might help me to read a short example of the thought process you'd take interpreting e.g. https://gist.github.com/ndmitchell/ab790bbfa482a70fa2db020fda623309#file-hlint-profiterole-txt

ndmitchell commented 5 years ago

Taking line 30 of that file:

TOT  INH  IND
48.1  46.1  10.5    Hint.Match findIdeas (903)

The function call findIdeas and all functions it calls are responsible for 48.1% of the program execution. The function findIdeas itself takes 10.5% of the program, namely the code inside findIdeas, ignoring any time spent in calls that it makes. Looking only at the block from lines 29 to 70, there findIdeas and its function calls is responsible for 46.1% of the program.

From that I can know that findIdeas is expensive (about half the program), 10% of the time goes in findIdeas itself which is high, and that if I want to know what it calls, this block is the one to look at - I don't need to look anywhere else, e.g. HSE.Util fromParen on line 53 has more time pulled out as a separate block (since its called from multiple places), but it's not relevant enough here.

simonmichael commented 5 years ago

These are all helpful clues, thanks. I think much of this stuff is confusing until you have spent a lot of time reading profiles.

Yes the (...) is coming from the GHC profile. It turns out to correspond to a sub-definition; sometimes GHC shows names for these and sometimes it doesn't. Inquiring on #ghc. For (...)'s which happen to be mentioned in the top list in the original GHC profile, you can use the source location info (not available in the profiterole profile) to find out which definition they represent.

simonmichael commented 5 years ago

(A quick example of the above, though it's not profiterole's issue: showamt is shown by name but declaredprices is not.) [See ghc#17006]

ndmitchell commented 5 years ago

I suspect adding in source locations isn't too hard

jberryman commented 5 years ago

Thanks a lot, and I missed this helpful comment before I posted.

I'll try restating differently. Can you tell me if I have this right?:

51.0  47.4   -  Hint.Match readMatch (53)
48.1 46.1 10.5     Hint.Match findIdeas (903)

Here findIdeas called from readMatch takes up 46.1% of the execution time of the program. 2% of the program execution time are from callers other than readMatch. 10.5% of program execution comes from stuff within the body of findIdeas which isn't accounted for in the calls findIdeas makes in the tree below (lines 31 - 70) .

...hm, but then what do TOT and INH mean for readMatch on line 29?

Have I got it mostly right? I'm still not quite sure how to express IND although I think I understand it; after all (thinking out loud...) shouldn't a function's cost always be just the sum of the costs of the functions it calls? I guess IND is the mostly arbitrary leftover cost after we subtract the cost of calls which are accounted for elsewhere in the tree?

I think this data is super useful in the tree view (starting https://gist.github.com/ndmitchell/ab790bbfa482a70fa2db020fda623309#file-hlint-profiterole-txt-L29), and should be left in. I think the data is pretty easy to scan, might augment it with some background color in the html version to sort of highlight the process of scanning down until TOT and INH differ significantly.

But I'm now wondering if the three columns aren't the most useful, or are a little misleading, in the first overview section (lines 1 - 26)...

Totally OT: wondering if a normalized view of pct_cost / calls_count might also be useful, the hypothesis being that functions with a high cost-per-call are lower hanging fruit.

jberryman commented 5 years ago

@ndmitchell

can it be made to show space, or is it always time ? Always time. My experience is that space in this view is mostly useless. If you want space, use one of the heap profiling features.

This is OT as well but I've just been thinking about it: in a -hc profile I'm looking at I see half a dozen separate bands, and the .hp file has corresponding entries like these (note I had to run with a very large -L value to even see these):

(129414)decodeEventASN1Repr.loop/decodeEventASN1Repr/                                                                                                                                                                   decodeASN1Repr/decodeASN1Repr'/decodeSignedObject/decodeSignedCertificate/readCertificates.getCert/readCertificates/readCertificateStore.makeDirStore/readCertificateStore/getSystemCertificateStore/initConnectionContext/getTlsConnection/mkManagerSettingsContext'/mkManagerSettingsContext/mkManagerSettings/tlsManagerSettings/managerTlsConnection/mkCreateConnection/newManager/main        79784
(129360)>>=.\.ks'/>>=.\/>>=/getWord8/fmap.\/fmap/getHeader/runParseState.runGetHeader.\/runParseState.runGetHeader/runParseState.go/runParseState.loop/runParseState/parseLBS.process/parseLBS.foldrEither/parseLBS/    decodeASN1Repr/decodeASN1Repr'/decodeSignedObject/decodeSignedCertificate/readCertificates.getCert/readCertificates/readCertificateStore.makeDirStore/readCertificateStore/getSystemCertificateStore/initConnectionContext/getTlsConnection/mkManagerSettingsContext'/mkManagerSettingsContext/mkManagerSettings/tlsManagerSettings/managerTlsConnection/mkCreateConnection/newManager/main 59560
(129428)getOID/decodePrimitive/decodeEventASN1Repr.loop/decodeEventASN1Repr/                                                                                                                                            decodeASN1Repr/decodeASN1Repr'/decodeSignedObject/decodeSignedCertificate/readCertificates.getCert/readCertificates/readCertificateStore.makeDirStore/readCertificateStore/getSystemCertificateStore/initConnectionContext/getTlsConnection/mkManagerSettingsContext'/mkManagerSettingsContext/mkManagerSettings/tlsManagerSettings/managerTlsConnection/mkCreateConnection/newManager/main 330448
(129466)getConstructedEndRepr.getEnd/getConstructedEndRepr.g.(...)/getConstructedEndRepr.g/getConstructedEndRepr/decodeSignedObject.parseSigned.\.(...)/decodeSignedObject.parseSigned.\/decodeSignedObject.onContainer/decodeSignedObject.parseSigned/decodeSignedObject/decodeSignedCertificate/readCertificates.getCert/readCertificates/readCertificateStore.makeDirStore/readCertificateStore/getSystemCertificateStore/initConnectionContext/getTlsConnection/mkManagerSettingsContext'/mkManagerSettingsContext/mkManagerSettings/tlsManagerSettings/managerTlsConnection/mkCreateConnection/newManager/main     324336
(129415)decodeSignedObject.onContainer/decodeSignedObject.parseSigned/decodeSignedObject/decodeSignedCertificate/readCertificates.getCert/readCertificates/readCertificateStore.makeDirStore/readCertificateStore/getSystemCertificateStore/initConnectionContext/getTlsConnection/mkManagerSettingsContext'/mkManagerSettingsContext/mkManagerSettings/tlsManagerSettings/managerTlsConnection/mkCreateConnection/newManager/main      309960
(129345)runParseState.go/runParseState.loop/runParseState/parseLBS.process/parseLBS.foldrEither/parseLBS/                                                                                                               decodeASN1Repr/decodeASN1Repr'/decodeSignedObject/decodeSignedCertificate/readCertificates.getCert/readCertificates/readCertificateStore.makeDirStore/readCertificateStore/getSystemCertificateStore/initConnectionContext/getTlsConnection/mkManagerSettingsContext'/mkManagerSettingsContext/mkManagerSettings/tlsManagerSettings/managerTlsConnection/mkCreateConnection/newManager/main    224816
(129401)getBytes.(...)/>>=.\.ks'/>>=.\/>>=/getBytes/runParseState.runGetPrimitive.\/runParseState.runGetPrimitive/runParseState.go/runParseState.loop/runParseState/parseLBS.process/parseLBS.foldrEither/parseLBS/     decodeASN1Repr/decodeASN1Repr'/decodeSignedObject/decodeSignedCertificate/readCertificates.getCert/readCertificates/readCertificateStore.makeDirStore/readCertificateStore/getSystemCertificateStore/initConnectionContext/getTlsConnection/mkManagerSettingsContext'/mkManagerSettingsContext/mkManagerSettings/tlsManagerSettings/managerTlsConnection/mkCreateConnection/newManager/main  195040

^ scroll to the right to observe how I've manually aligned the call stacks a little. I think these are all more or less the same leak or that I'll solve them altogether, but it's not at all obvious when only looking at the top of the call-centre stack (i.e. the part that GHC doesn't truncate).

So I think the approach you take here is basically what I want, i.e. something like your tree view that I can scan, or a trie data structure

...I think the real trouble here would be getting GHC to not truncate while ensuring the heap profile doesn't grow to too many GB. Relevant: https://gitlab.haskell.org/ghc/ghc/issues/17009

ndmitchell commented 5 years ago

Dividing cost by calls is dubious since my experience is that call counts are often wildly off, and costs for some things are sufficiently off that I would put little faith in any sum involving both. If the data was spot on it might be a good idea.

TOT is this function and every function it calls. INH is this function and every function it calls in this block, so excluding any functions that profiterole hoisted to the top level elsewhere. IND is this function and not those it called.

As a consequence the missing 2% is not other callers to findIdeas (if there were two distinct callers then findIdeas would have been a root itself) but calls that findIdeas makes to functions called by other places - eg fromParen.

As to the space data, getting it from the heap profile and displaying it in a similar manner to profiterole might be cool. I know Matthew Pickering is working on improving the heap profile a lot.

ndmitchell / profiterole

still confused #4