Skip to content

Perform memory measurement on SIGUSR1 #761

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 7 commits into from
Jan 2, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 5 additions & 1 deletion ghcide/docs/opentelemetry.md
Original file line number Diff line number Diff line change
Expand Up @@ -19,14 +19,18 @@ Then, you can run `ghcide`, giving it a file to dump eventlog information into.
ghcide +RTS -l -ol ghcide.eventlog -RTS
```

You can also optionally enable reporting detailed memory data with `--ot-memory-profiling`
# Profiling the Shake cache

The flag `--ot-memory-profiling` profiles the values map repeatedly with 1s pauses in between.

```sh
ghcide --ot-memory-profiling +RTS -A4G -l -ol ghcide.eventlog -RTS
```

*Note:* This option, while functional, is extremely slow. You will notice this because the memory graph in the output will have datapoints spaced apart by a couple of minutes. The nursery must be big enough (-A1G or larger) or the measurements will self-abort.

Another way to profile the heap is by sending a USR1 signal (`kill -s USR1`) to the process.

## Viewing with tracy

After installing `opentelemetry-extra` and `tracy`, you can view the opentelementry output:
Expand Down
3 changes: 1 addition & 2 deletions ghcide/src/Development/IDE/Core/Shake.hs
Original file line number Diff line number Diff line change
Expand Up @@ -406,8 +406,7 @@ shakeOpen getLspId eventer withProgress withIndefiniteProgress clientCapabilitie
let ideState = IdeState{..}

IdeOptions{ optOTMemoryProfiling = IdeOTMemoryProfiling otProfilingEnabled } <- getIdeOptionsIO shakeExtras
when otProfilingEnabled $
startTelemetry logger $ state shakeExtras
startTelemetry otProfilingEnabled logger $ state shakeExtras

return ideState
where
Expand Down
58 changes: 35 additions & 23 deletions ghcide/src/Development/IDE/Core/Tracing.hs
Original file line number Diff line number Diff line change
Expand Up @@ -13,7 +13,7 @@ import Control.Concurrent.Extra (Var, modifyVar_, newVar,
readVar, threadDelay)
import Control.Exception (evaluate)
import Control.Exception.Safe (catch, SomeException)
import Control.Monad (unless, forM_, forever, (>=>))
import Control.Monad (void, when, unless, forM_, forever, (>=>))
import Control.Monad.Extra (whenJust)
import Control.Seq (r0, seqList, seqTuple2, using)
import Data.Dynamic (Dynamic)
Expand All @@ -28,12 +28,13 @@ import Development.IDE.Core.RuleTypes (GhcSession (GhcSession),
import Development.IDE.Types.Logger (logInfo, Logger, logDebug)
import Development.IDE.Types.Shake (Key (..), Value, Values)
import Development.Shake (Action, actionBracket, liftIO)
import Ide.PluginUtils (installSigUsr1Handler)
import Foreign.Storable (Storable (sizeOf))
import HeapSize (recursiveSize, runHeapsize)
import Language.Haskell.LSP.Types (NormalizedFilePath,
fromNormalizedFilePath)
import Numeric.Natural (Natural)
import OpenTelemetry.Eventlog (addEvent, beginSpan, endSpan,
import OpenTelemetry.Eventlog (Synchronicity(Asynchronous), Instrument, addEvent, beginSpan, endSpan,
mkValueObserver, observe,
setTag, withSpan, withSpan_)

Expand Down Expand Up @@ -71,36 +72,47 @@ otTracedAction key file success act = actionBracket
unless (success res) $ setTag sp "error" "1"
return res)

startTelemetry :: Logger -> Var Values -> IO ()
startTelemetry logger stateRef = do
startTelemetry :: Bool -> Logger -> Var Values -> IO ()
startTelemetry allTheTime logger stateRef = do
instrumentFor <- getInstrumentCached
mapCountInstrument <- mkValueObserver "values map count"

_ <- regularly (1 * seconds) $
withSpan_ "Measure length" $
readVar stateRef
>>= observe mapCountInstrument . length

_ <- regularly (1 * seconds) $ do
values <- readVar stateRef
let keys = nub
$ Key GhcSession : Key GhcSessionDeps
: [ k | (_,k) <- HMap.keys values
-- do GhcSessionIO last since it closes over stateRef itself
, k /= Key GhcSessionIO]
++ [Key GhcSessionIO]
!groupedForSharing <- evaluate (keys `using` seqList r0)
measureMemory logger [groupedForSharing] instrumentFor stateRef
`catch` \(e::SomeException) ->
logInfo logger ("MEMORY PROFILING ERROR: " <> fromString (show e))
return ()
installSigUsr1Handler $ do
logInfo logger "SIGUSR1 received: performing memory measurement"
performMeasurement logger stateRef instrumentFor mapCountInstrument

when allTheTime $ void $ regularly (1 * seconds) $
performMeasurement logger stateRef instrumentFor mapCountInstrument
where
seconds = 1000000

regularly :: Int -> IO () -> IO (Async ())
regularly delay act = async $ forever (act >> threadDelay delay)

{-# ANN startTelemetry ("HLint: ignore Use nubOrd" :: String) #-}

performMeasurement ::
Logger ->
Var (HMap.HashMap (NormalizedFilePath, Key) (Value Dynamic)) ->
(Maybe Key -> IO OurValueObserver) ->
Instrument 'Asynchronous a m' ->
IO ()
performMeasurement logger stateRef instrumentFor mapCountInstrument = do
withSpan_ "Measure length" $ readVar stateRef >>= observe mapCountInstrument . length

values <- readVar stateRef
let keys = Key GhcSession
: Key GhcSessionDeps
: [ k | (_,k) <- HMap.keys values
-- do GhcSessionIO last since it closes over stateRef itself
, k /= Key GhcSession
, k /= Key GhcSessionDeps
, k /= Key GhcSessionIO
] ++ [Key GhcSessionIO]
groupedForSharing <- evaluate (keys `using` seqList r0)
measureMemory logger [groupedForSharing] instrumentFor stateRef
`catch` \(e::SomeException) ->
logInfo logger ("MEMORY PROFILING ERROR: " <> fromString (show e))


type OurValueObserver = Int -> IO ()

Expand Down
10 changes: 9 additions & 1 deletion hls-plugin-api/src/Ide/PluginUtils.hs
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,7 @@ module Ide.PluginUtils
fullRange,
mkLspCommand,
mkLspCmdId,
allLspCmdIds,allLspCmdIds')
allLspCmdIds,allLspCmdIds',installSigUsr1Handler)
where


Expand All @@ -35,13 +35,15 @@ import Language.Haskell.LSP.Types.Capabilities
#ifdef mingw32_HOST_OS
import qualified System.Win32.Process as P (getCurrentProcessId)
#else
import System.Posix.Signals
import qualified System.Posix.Process as P (getProcessID)
#endif
import qualified Data.Aeson as J
import qualified Data.Default
import qualified Data.Map.Strict as Map
import Ide.Plugin.Config
import qualified Language.Haskell.LSP.Core as LSP
import Control.Monad (void)

-- ---------------------------------------------------------------------

Expand Down Expand Up @@ -246,8 +248,14 @@ getPid :: IO T.Text
getPid = T.pack . show <$> getProcessID

getProcessID :: IO Int
installSigUsr1Handler :: IO () -> IO ()

#ifdef mingw32_HOST_OS
getProcessID = fromIntegral <$> P.getCurrentProcessId
installSigUsr1Handler _ = return ()

#else
getProcessID = fromIntegral <$> P.getProcessID

installSigUsr1Handler h = void $ installHandler sigUSR1 (Catch h) Nothing
#endif