Heap profiling - hp2ps: samples out of sequence

changed weight to 5

Trac metadata

Trac field	Value
Test case	- → libraries/hpc/tests/fork/hpc_fork

mentioned in commit 90fa8cf2

mentioned in commit 13a801af

The problem is that the profiler doesn't work with forkProcess (e.g., see #8862). In this particular case, the issue is that the elapsed per-process time is being reported for each sample. Since the parent spends more time performing the forks than each child does executing threadDelay, its elapsed time is the largest. But the parent outputs its sample before either child, and so the samples appear out of order.

The reason this behavior does not cause a problem when using 7.10.3 is that the sample times used to only be reported in hundredths of a second (and so were all 0.00). As of 1da3bbd2, they are being reported with full precision.

One possible way to work around this is to simply increase the threadDelay intervals for each child (400000 for the first and 800000 for the second worked for me).

mentioned in issue #14006 (closed)

I'm still seeing this with a profiling ghc. The ghc-stage2.prof can't be read.

David also reported seeing this while profiling GHC (#14006 (closed)). However, I think we should keep this ticket to describe the incompatibility with forkProcess. Perhaps comment on #14006 (closed) instead. It might be helpful if you could include the hp file as well.

I don't have the .hp anymore :( It's been basically a prof stage2, compiling a module e.g. Dynflags with -fllvmng. Due to the time building ghc takes, I won't be able to reproduce this right away. Eventually I'll probably have to again, when testing the llvmng backend.

mentioned in issue #14257 (closed)

I hit this today on 8.2.1. This is on a proprietary project so I am unable to provide any substantial code to aid debugging this. Below is a highly inefficient program which re-sequences .hp so that you can at least use the data.

{-# LANGUAGE LambdaCase #-}
{-# LANGUAGE OverloadedStrings #-}
module Main (main) where

import           Control.Monad (guard)
import           Data.Attoparsec.Combinator as P
import           Data.Attoparsec.Text as P
import           Data.List (sort)
import           Data.Monoid ((<>))
import           Data.Text as T
import qualified Data.Text.IO as T
import           System.Environment (getArgs)
import           System.Exit (exitFailure)
import           System.IO (hPutStrLn, stderr)

data Sample = Sample !Double ![Text]
  deriving (Eq)

instance Ord Sample where
  compare (Sample x _) (Sample y _) = compare x y

data F = F ![Text] ![Sample]

parseF :: Parser F
parseF = do
  ls <- P.manyTill (P.takeTill isEndOfLine <* endOfLine) (P.lookAhead "BEGIN_SAMPLE")
  s <- P.many' parseSample
  pure $! F ls s

parseSample :: Parser Sample
parseSample = do
  s <- "BEGIN_SAMPLE " *> double <* endOfLine
  let endSample = do
        es <- "END_SAMPLE " *> double <* endOfLine
        guard (es == s)
      l = P.takeTill isEndOfLine <* endOfLine
  ls <- P.manyTill l endSample
  pure $! Sample s ls

renderSample :: Sample -> Text
renderSample (Sample d ls) = T.unlines $
  ("BEGIN_SAMPLE " <> T.pack (show d))
  : ls
  ++ [ "END_SAMPLE " <> T.pack (show d) ]

main :: IO ()
main = getArgs >>= \case
  [input, output] -> do
    c <- T.readFile input
    case parseOnly parseF c of
      Left err -> do
        hPutStrLn stderr ("Parse failed: " <> err)
        exitFailure
      Right (F startLines samples) -> do
        let s' = T.concat . Prelude.map renderSample $ sort samples
        T.writeFile output (T.unlines startLines <> s')
  _ -> do
    hPutStrLn stderr "usage: fix-hp inputFile outputFile"
    exitFailure

Ohh, i'm super sorry, not to have attached my reorder script.

{-# LANGUAGE LambdaCase #-}

import System.Environment (getArgs)

import Data.List (mapAccumL, isPrefixOf)
import GHC.Exts (sortWith)

main :: IO ()
main = getArgs >>= \case
  [f] -> readFile f >>= pure . unlines . reorder . lines >>= putStr
  _   -> putStrLn $ "only one input"

reorder :: [String] -> [String]
reorder = map snd . sortWith fst . snd . mapAccumL f (-1.0)
  where
    g :: (Double, String) -> (Double, (Double, String))
    g (x,y) = (x,(x,y))
    f :: Double -> String -> (Double, (Double, String))
    f acc line
      | "BEGIN_SAMPLE " `isPrefixOf` line = g (read $ drop 13 line, line)
      | "END_SAMPLE " `isPrefixOf` line && (read $ drop 11 line) /= acc = error "BEING/END missmatch"
      | otherwise                         = g (acc, line)

Could have saved someone else some time :(

However, the generated output still looks rather garbled. [[Image(https://dl.dropbox.com/s/yz5d5ug656mziun/Screenshot%202017-10-03%2017.15.58.png)]]

did you observe the same Fuuzetsu?

I was looking at a similar issue, #14257 (closed), and thought I had a theory. Unfortunately it fell apart. I'll try to get back to this soon.

Trac metadata

Trac field	Value
Related	#664 (closed) → #664 (closed), #14257 (closed)

mentioned in issue #14445 (closed)

closed

changed milestone to %8.4.1

I believe this is another manifestation of #14257 (closed). I have verified that this can no longer be reproduced on master.

Trac metadata

Trac field	Value
Resolution	Unresolved → ResolvedFixed

added Pnormal label

mentioned in commit d79162ec

mentioned in commit bff802b8

mentioned in commit c748399c

mentioned in commit 6fa040e5

mentioned in commit 8757f427

mentioned in commit ac0f0c86

mentioned in commit 787db34d

mentioned in commit b81c2952

mentioned in commit b3df1efb

Trac field	Value
Version	8.0.1-rc2
Type	Bug
TypeOfFailure	OtherFailure
Priority	normal
Resolution	Unresolved
Component	Profiling
Test case
Differential revisions
BlockedBy
Related	#664 (closed)
Blocking
CC
Operating system
Architecture

Heap profiling - hp2ps: samples out of sequence

Child items ...

Activity

Heap profiling - hp2ps: samples out of sequence

Relates to

Activity