From 088db2a62787257fbdd78c75143e1ab3d0177eb3 Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Fri, 8 Oct 2021 19:45:42 +0100 Subject: [PATCH 01/15] Collect metrics and expose an EKG server --- cabal.project | 14 ++++++++ docs/contributing/contributing.md | 29 +++++++++++++++ ghcide/ghcide.cabal | 2 ++ ghcide/src/Development/IDE/Core/Service.hs | 7 ++-- ghcide/src/Development/IDE/Core/Shake.hs | 41 ++++++++++++++++++++-- ghcide/src/Development/IDE/Main.hs | 35 ++++++++++++++---- 6 files changed, 117 insertions(+), 11 deletions(-) diff --git a/cabal.project b/cabal.project index 78ceb8e2ff..122d60eaf1 100644 --- a/cabal.project +++ b/cabal.project @@ -53,6 +53,12 @@ constraints: ghc-lib-parser-ex -auto, stylish-haskell +ghc-lib + source-repository-package + type:git + location: https://github.com/vshabanov/ekg-json + tag: 00ebe7211c981686e65730b7144fbf5350462608 + -- https://github.com/tibbe/ekg-json/pull/12 + allow-newer: -- ghc-9.2 ---------- @@ -70,3 +76,11 @@ allow-newer: -- for shake-bench Chart:lens, Chart-diagrams:lens, + + -- for ekg + ekg-core:base, + ekg-wai:base, + + -- for shake-bench + Chart-diagrams:diagrams-core, + SVGFonts:diagrams-core diff --git a/docs/contributing/contributing.md b/docs/contributing/contributing.md index 2dde423b74..20762ccbd1 100644 --- a/docs/contributing/contributing.md +++ b/docs/contributing/contributing.md @@ -225,6 +225,35 @@ If you don't want to use [nix](https://nixos.org/guides/install-nix.html), you c See the [tutorial](./plugin-tutorial.md) on writing a plugin in HLS. +## Measuring, benchmarking and tracing + +### Metrics + +HLS opens a metrics server on port 8000 exposing GC and ghcide metrics. The ghcide metrics currently exposed are: + +- `ghcide.values_count`- count of build results in the store +- `ghcide.database_count` - count of build keys in the store (these two would be the same in the absence of GC) +- `ghcide.build_count` - build count. A key is GC'ed if it is dirty and older than 100 builds +- `ghcide.dirty_keys_count` - non transitive count of dirty build keys +- `ghcide.indexing_pending_count` - count of items in the indexing queue +- `ghcide.exports_map_count` - count of identifiers in the exports map. + +### Benchmarks + +If you are touching performance sensitive code, take the time to run a differential +benchmark between HEAD and master using the benchHist script. This assumes that +"master" points to the upstream master. + +Run the benchmarks with `cabal bench ghcide`. + +It should take around 25 minutes and the results will be stored in the `ghcide/bench-results` folder. To interpret the results, see the comments in the `ghcide/bench/hist/Main.hs` module. + +More details in [bench/README](../../ghcide/bench/README.md) + +### Tracing + +HLS records opentelemetry eventlog traces via [opentelemetry](https://hackage.haskell.org/package/opentelemetry). To generate the traces, build with `-eventlog` and run with `+RTS -l`. To visualize the traces, install [Tracy](https://github.com/wolfpld/tracy) and use [eventlog-to-tracy](https://hackage.haskell.org/package/opentelemetry-extra) to open the generated eventlog. + ## Adding support for a new editor Adding support for new editors is fairly easy if the editor already has good support for generic LSP-based extensions. diff --git a/ghcide/ghcide.cabal b/ghcide/ghcide.cabal index 93bd51a950..acf6e068ad 100644 --- a/ghcide/ghcide.cabal +++ b/ghcide/ghcide.cabal @@ -48,6 +48,8 @@ library dependent-map, dependent-sum, dlist, + ekg-wai, + ekg-core, exceptions, extra >= 1.7.4, enummapset, diff --git a/ghcide/src/Development/IDE/Core/Service.hs b/ghcide/src/Development/IDE/Core/Service.hs index 0dd04a2cd7..efca483663 100644 --- a/ghcide/src/Development/IDE/Core/Service.hs +++ b/ghcide/src/Development/IDE/Core/Service.hs @@ -38,10 +38,11 @@ import Control.Monad import qualified Development.IDE.Core.FileExists as FileExists import qualified Development.IDE.Core.OfInterest as OfInterest import Development.IDE.Core.Shake hiding (Log) +import Development.IDE.Core.Shake import qualified Development.IDE.Core.Shake as Shake import Development.IDE.Types.Shake (WithHieDb) import System.Environment (lookupEnv) - +import System.Metrics data Log = LogShake Shake.Log @@ -68,8 +69,9 @@ initialise :: Recorder (WithPriority Log) -> IdeOptions -> WithHieDb -> IndexQueue + -> Maybe Store -> IO IdeState -initialise recorder defaultConfig mainRule lspEnv logger debouncer options withHieDb hiedbChan = do +initialise recorder defaultConfig mainRule lspEnv logger debouncer options withHieDb hiedbChan metrics = do shakeProfiling <- do let fromConf = optShakeProfiling options fromEnv <- lookupEnv "GHCIDE_BUILD_PROFILING" @@ -86,6 +88,7 @@ initialise recorder defaultConfig mainRule lspEnv logger debouncer options withH withHieDb hiedbChan (optShakeOptions options) + metrics $ do addIdeGlobal $ GlobalIdeOptions options ofInterestRules (cmapWithPrio LogOfInterest recorder) diff --git a/ghcide/src/Development/IDE/Core/Shake.hs b/ghcide/src/Development/IDE/Core/Shake.hs index 808de1d1a6..28e3ab2ff5 100644 --- a/ghcide/src/Development/IDE/Core/Shake.hs +++ b/ghcide/src/Development/IDE/Core/Shake.hs @@ -136,6 +136,7 @@ import Development.IDE.Graph hiding (ShakeValue) import qualified Development.IDE.Graph as Shake import Development.IDE.Graph.Database (ShakeDatabase, shakeGetBuildStep, + shakeGetDatabaseKeys, shakeNewDatabase, shakeProfileDatabase, shakeRunDatabaseForKeys) @@ -152,6 +153,23 @@ import Development.IDE.Types.Options import Development.IDE.Types.Shake import qualified Focus import GHC.Fingerprint +import Language.LSP.Types.Capabilities +import OpenTelemetry.Eventlog + +import Control.Exception.Extra hiding (bracket_) +import Data.Aeson (toJSON) +import qualified Data.ByteString.Char8 as BS8 +import Data.Coerce (coerce) +import Data.Default +import Data.Foldable (for_, toList) +import Data.HashSet (HashSet) +import qualified Data.HashSet as HSet +import Data.IORef.Extra (atomicModifyIORef'_, + atomicModifyIORef_) +import Data.String (fromString) +import Data.Text (pack) +import Debug.Trace.Flags (userTracingEnabled) +import qualified Development.IDE.Types.Exports as ExportsMap import HieDb.Types import Ide.Plugin.Config import qualified Ide.PluginUtils as HLS @@ -167,6 +185,7 @@ import OpenTelemetry.Eventlog import qualified StmContainers.Map as STM import System.FilePath hiding (makeRelative) import System.IO.Unsafe (unsafePerformIO) +import System.Metrics (Store, registerCounter, registerGauge) import System.Time.Extra data Log @@ -388,7 +407,7 @@ lastValueIO s@ShakeExtras{positionMapping,persistentKeys,state} k file = do | otherwise = do pmap <- readTVarIO persistentKeys mv <- runMaybeT $ do - liftIO $ Logger.logDebug (logger s) $ T.pack $ "LOOKUP UP PERSISTENT FOR: " ++ show k + liftIO $ Logger.logDebug (logger s) $ T.pack $ "LOOKUP PERSISTENT FOR: " ++ show k f <- MaybeT $ pure $ HMap.lookup (Key k) pmap (dv,del,ver) <- MaybeT $ runIdeAction "lastValueIO" s $ f file MaybeT $ pure $ (,del,ver) <$> fromDynamic dv @@ -557,10 +576,11 @@ shakeOpen :: Recorder (WithPriority Log) -> WithHieDb -> IndexQueue -> ShakeOptions + -> Maybe Store -> Rules () -> IO IdeState shakeOpen recorder lspEnv defaultConfig logger debouncer - shakeProfileDir (IdeReportProgress reportProgress) ideTesting@(IdeTesting testing) withHieDb indexQueue opts rules = mdo + shakeProfileDir (IdeReportProgress reportProgress) ideTesting@(IdeTesting testing) withHieDb indexQueue opts metrics rules = mdo let log :: Logger.Priority -> Log -> IO () log = logWith recorder @@ -613,11 +633,28 @@ shakeOpen recorder lspEnv defaultConfig logger debouncer IdeOptions { optOTMemoryProfiling = IdeOTMemoryProfiling otProfilingEnabled , optProgressStyle + , optCheckParents } <- getIdeOptionsIO shakeExtras void $ startTelemetry shakeDb shakeExtras startProfilingTelemetry otProfilingEnabled logger $ state shakeExtras + checkParents <- optCheckParents + for_ metrics $ \store -> do + let readValuesCounter = fromIntegral . countRelevantKeys checkParents . HMap.keys <$> readVar (state shakeExtras) + readDirtyKeys = fromIntegral . countRelevantKeys checkParents . HSet.toList <$> readIORef (dirtyKeys shakeExtras) + readIndexPending = fromIntegral . HMap.size <$> readTVarIO (indexPending $ hiedbWriter shakeExtras) + readExportsMap = fromIntegral . HMap.size . getExportsMap <$> readVar (exportsMap shakeExtras) + readDatabaseCount = fromIntegral . countRelevantKeys checkParents . map fst <$> shakeGetDatabaseKeys shakeDb + readDatabaseStep = fromIntegral <$> shakeGetBuildStep shakeDb + + registerGauge "ghcide.values_count" readValuesCounter store + registerGauge "ghcide.dirty_keys_count" readDirtyKeys store + registerGauge "ghcide.indexing_pending_count" readIndexPending store + registerGauge "ghcide.exports_map_count" readExportsMap store + registerGauge "ghcide.database_count" readDatabaseCount store + registerCounter "ghcide.num_builds" readDatabaseStep store + return ideState startTelemetry :: ShakeDatabase -> ShakeExtras -> IO (Async ()) diff --git a/ghcide/src/Development/IDE/Main.hs b/ghcide/src/Development/IDE/Main.hs index 43e9827c8b..55c411887d 100644 --- a/ghcide/src/Development/IDE/Main.hs +++ b/ghcide/src/Development/IDE/Main.hs @@ -29,6 +29,7 @@ import Data.Maybe (catMaybes, isJust) import qualified Data.Text as T import Data.Text.Lazy.Encoding (decodeUtf8) import qualified Data.Text.Lazy.IO as LT +import Data.Traversable (for) import Data.Typeable (typeOf) import Development.IDE (Action, GhcVersion (..), Priority (Debug, Error), Rules, @@ -126,6 +127,9 @@ import System.IO (BufferMode (LineBufferin hSetEncoding, stderr, stdin, stdout, utf8) import System.Random (newStdGen) +import qualified System.Metrics as Monitoring +import System.Remote.Monitoring.Wai +import qualified System.Remote.Monitoring.Wai as Monitoring import System.Time.Extra (Seconds, offsetTime, showDuration) import Text.Printf (printf) @@ -231,6 +235,7 @@ data Arguments = Arguments , argsHandleIn :: IO Handle , argsHandleOut :: IO Handle , argsThreads :: Maybe Natural + , argsMonitoringPort :: Maybe Natural } @@ -268,6 +273,7 @@ defaultArguments recorder logger = Arguments -- the language server tests without the redirection. putStr " " >> hFlush stdout return newStdout + , argsMonitoringPort = Just 8000 } @@ -355,6 +361,23 @@ defaultMain recorder Arguments{..} = withHeapStats (cmapWithPrio LogHeapStats re -- FIXME: Remove this after GHC 9 gets fully supported when (ghcVersion == GHC90) $ log Warning LogOnlyPartialGhc9Support + server <- fmap join $ for argsMonitoringPort $ \p -> do + store <- Monitoring.newStore + let startServer = Monitoring.forkServerWith store "localhost" (fromIntegral p) + -- this can fail if the port is busy, throwing an async exception back to us + -- to handle that, wrap the server thread in an async + mb_server <- async startServer >>= waitCatch + case mb_server of + Right s -> do + logInfo logger $ T.pack $ + "Started monitoring server on port " <> show p + return $ Just s + Left e -> do + logInfo logger $ T.pack $ + "Unable to bind monitoring server on port " + <> show p <> ":" <> show e + return Nothing + initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig @@ -365,6 +388,9 @@ defaultMain recorder Arguments{..} = withHeapStats (cmapWithPrio LogHeapStats re options withHieDb hieChan + (Monitoring.serverMetricStore <$> server) + `onException` + traverse_ (killThread . serverThreadId) server dumpSTMStats Check argFiles -> do dir <- maybe IO.getCurrentDirectory return argsProjectRoot @@ -397,7 +423,7 @@ defaultMain recorder Arguments{..} = withHeapStats (cmapWithPrio LogHeapStats re , optCheckProject = pure False , optModifyDynFlags = optModifyDynFlags def_options <> pluginModifyDynflags plugins } - ide <- initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig rules Nothing logger debouncer options hiedb hieChan + ide <- initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig rules Nothing logger debouncer options hiedb hieChan Nothing shakeSessionInit (cmapWithPrio LogShake recorder) ide registerIdeConfiguration (shakeExtras ide) $ IdeConfiguration mempty (hashed Nothing) @@ -450,13 +476,8 @@ defaultMain recorder Arguments{..} = withHeapStats (cmapWithPrio LogHeapStats re , optCheckProject = pure False , optModifyDynFlags = optModifyDynFlags def_options <> pluginModifyDynflags plugins } - ide <- initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig rules Nothing logger debouncer options hiedb hieChan + ide <- initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig rules Nothing logger debouncer options hiedb hieChan Nothing shakeSessionInit (cmapWithPrio LogShake recorder) ide - registerIdeConfiguration (shakeExtras ide) $ IdeConfiguration mempty (hashed Nothing) - c ide - -{-# ANN defaultMain ("HLint: ignore Use nubOrd" :: String) #-} - expandFiles :: [FilePath] -> IO [FilePath] expandFiles = concatMapM $ \x -> do From ad1fb0d37fe0b877aae9ad9bd92df5be378db92d Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Tue, 12 Oct 2021 20:23:44 +0100 Subject: [PATCH 02/15] register gc metrics locally --- ghcide/src/Development/IDE/Main.hs | 1 + 1 file changed, 1 insertion(+) diff --git a/ghcide/src/Development/IDE/Main.hs b/ghcide/src/Development/IDE/Main.hs index 55c411887d..7ea8b82f85 100644 --- a/ghcide/src/Development/IDE/Main.hs +++ b/ghcide/src/Development/IDE/Main.hs @@ -363,6 +363,7 @@ defaultMain recorder Arguments{..} = withHeapStats (cmapWithPrio LogHeapStats re log Warning LogOnlyPartialGhc9Support server <- fmap join $ for argsMonitoringPort $ \p -> do store <- Monitoring.newStore + Monitoring.registerGcMetrics store let startServer = Monitoring.forkServerWith store "localhost" (fromIntegral p) -- this can fail if the port is busy, throwing an async exception back to us -- to handle that, wrap the server thread in an async From 816043c0de0cd5a2a416379d1c3eaf667021b63b Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Sat, 30 Apr 2022 08:07:27 +0100 Subject: [PATCH 03/15] getDatabaseKeys --- hls-graph/src/Development/IDE/Graph/Database.hs | 6 ++++++ hls-graph/src/Development/IDE/Graph/Internal/Database.hs | 2 +- 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/hls-graph/src/Development/IDE/Graph/Database.hs b/hls-graph/src/Development/IDE/Graph/Database.hs index 53406bc3dd..1d5aab3789 100644 --- a/hls-graph/src/Development/IDE/Graph/Database.hs +++ b/hls-graph/src/Development/IDE/Graph/Database.hs @@ -9,6 +9,7 @@ module Development.IDE.Graph.Database( shakeRunDatabaseForKeys, shakeProfileDatabase, shakeGetBuildStep, + shakeGetDatabaseKeys, shakeGetDirtySet, shakeGetCleanKeys ,shakeGetBuildEdges) where @@ -79,3 +80,8 @@ shakeGetBuildEdges (ShakeDatabase _ _ db) = do keys <- getDatabaseValues db let ress = mapMaybe (getResult . snd) keys return $ sum $ map (length . getResultDepsDefault [] . resultDeps) ress + +-- | Returns an approximation of the database keys, +-- annotated with how long ago (in # builds) they were visited +shakeGetDatabaseKeys :: ShakeDatabase -> IO [(Key, Int)] +shakeGetDatabaseKeys (ShakeDatabase _ _ db) = getKeysAndVisitAge db diff --git a/hls-graph/src/Development/IDE/Graph/Internal/Database.hs b/hls-graph/src/Development/IDE/Graph/Internal/Database.hs index a6282a05eb..0ed2ccbb64 100644 --- a/hls-graph/src/Development/IDE/Graph/Internal/Database.hs +++ b/hls-graph/src/Development/IDE/Graph/Internal/Database.hs @@ -199,7 +199,7 @@ getDirtySet db = do calcAgeStatus _ = Nothing return $ mapMaybe (secondM calcAgeStatus) dbContents --- | Returns ann approximation of the database keys, +-- | Returns an approximation of the database keys, -- annotated with how long ago (in # builds) they were visited getKeysAndVisitAge :: Database -> IO [(Key, Int)] getKeysAndVisitAge db = do From ab13cfe81e24005cde195bb6332953cf65746bcf Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Sat, 30 Apr 2022 08:17:58 +0100 Subject: [PATCH 04/15] fixups --- ghcide/src/Development/IDE/Core/Service.hs | 1 - ghcide/src/Development/IDE/Core/Shake.hs | 27 +++++----------------- ghcide/src/Development/IDE/Main.hs | 13 +++++++---- 3 files changed, 15 insertions(+), 26 deletions(-) diff --git a/ghcide/src/Development/IDE/Core/Service.hs b/ghcide/src/Development/IDE/Core/Service.hs index efca483663..28183651f9 100644 --- a/ghcide/src/Development/IDE/Core/Service.hs +++ b/ghcide/src/Development/IDE/Core/Service.hs @@ -38,7 +38,6 @@ import Control.Monad import qualified Development.IDE.Core.FileExists as FileExists import qualified Development.IDE.Core.OfInterest as OfInterest import Development.IDE.Core.Shake hiding (Log) -import Development.IDE.Core.Shake import qualified Development.IDE.Core.Shake as Shake import Development.IDE.Types.Shake (WithHieDb) import System.Environment (lookupEnv) diff --git a/ghcide/src/Development/IDE/Core/Shake.hs b/ghcide/src/Development/IDE/Core/Shake.hs index 28e3ab2ff5..a461d82bc1 100644 --- a/ghcide/src/Development/IDE/Core/Shake.hs +++ b/ghcide/src/Development/IDE/Core/Shake.hs @@ -155,21 +155,6 @@ import qualified Focus import GHC.Fingerprint import Language.LSP.Types.Capabilities import OpenTelemetry.Eventlog - -import Control.Exception.Extra hiding (bracket_) -import Data.Aeson (toJSON) -import qualified Data.ByteString.Char8 as BS8 -import Data.Coerce (coerce) -import Data.Default -import Data.Foldable (for_, toList) -import Data.HashSet (HashSet) -import qualified Data.HashSet as HSet -import Data.IORef.Extra (atomicModifyIORef'_, - atomicModifyIORef_) -import Data.String (fromString) -import Data.Text (pack) -import Debug.Trace.Flags (userTracingEnabled) -import qualified Development.IDE.Types.Exports as ExportsMap import HieDb.Types import Ide.Plugin.Config import qualified Ide.PluginUtils as HLS @@ -178,10 +163,8 @@ import Language.LSP.Diagnostics import qualified Language.LSP.Server as LSP import Language.LSP.Types import qualified Language.LSP.Types as LSP -import Language.LSP.Types.Capabilities import Language.LSP.VFS import qualified "list-t" ListT -import OpenTelemetry.Eventlog import qualified StmContainers.Map as STM import System.FilePath hiding (makeRelative) import System.IO.Unsafe (unsafePerformIO) @@ -641,10 +624,10 @@ shakeOpen recorder lspEnv defaultConfig logger debouncer checkParents <- optCheckParents for_ metrics $ \store -> do - let readValuesCounter = fromIntegral . countRelevantKeys checkParents . HMap.keys <$> readVar (state shakeExtras) - readDirtyKeys = fromIntegral . countRelevantKeys checkParents . HSet.toList <$> readIORef (dirtyKeys shakeExtras) + let readValuesCounter = fromIntegral . countRelevantKeys checkParents <$> getStateKeys shakeExtras + readDirtyKeys = fromIntegral . countRelevantKeys checkParents . HSet.toList <$> readTVarIO(dirtyKeys shakeExtras) readIndexPending = fromIntegral . HMap.size <$> readTVarIO (indexPending $ hiedbWriter shakeExtras) - readExportsMap = fromIntegral . HMap.size . getExportsMap <$> readVar (exportsMap shakeExtras) + readExportsMap = fromIntegral . HMap.size . getExportsMap <$> readTVarIO (exportsMap shakeExtras) readDatabaseCount = fromIntegral . countRelevantKeys checkParents . map fst <$> shakeGetDatabaseKeys shakeDb readDatabaseStep = fromIntegral <$> shakeGetBuildStep shakeDb @@ -666,7 +649,7 @@ startTelemetry db extras@ShakeExtras{..} IdeOptions{optCheckParents} <- getIdeOptionsIO extras checkParents <- optCheckParents regularly 1 $ do - observe countKeys . countRelevantKeys checkParents . map fst =<< (atomically . ListT.toList . STM.listT) state + observe countKeys . countRelevantKeys checkParents =<< getStateKeys extras readTVarIO dirtyKeys >>= observe countDirty . countRelevantKeys checkParents . HSet.toList shakeGetBuildStep db >>= observe countBuilds @@ -675,6 +658,8 @@ startTelemetry db extras@ShakeExtras{..} regularly :: Seconds -> IO () -> IO (Async ()) regularly delay act = async $ forever (act >> sleep delay) +getStateKeys :: ShakeExtras -> IO [Key] +getStateKeys = (fmap.fmap) fst . atomically . ListT.toList . STM.listT . state -- | Must be called in the 'Initialized' handler and only once shakeSessionInit :: Recorder (WithPriority Log) -> IdeState -> IO () diff --git a/ghcide/src/Development/IDE/Main.hs b/ghcide/src/Development/IDE/Main.hs index 7ea8b82f85..1180b00afc 100644 --- a/ghcide/src/Development/IDE/Main.hs +++ b/ghcide/src/Development/IDE/Main.hs @@ -11,12 +11,14 @@ module Development.IDE.Main ,testing ,Log(..) ) where -import Control.Concurrent.Extra (withNumCapabilities) +import Control.Concurrent.Async (async, waitCatch) +import Control.Concurrent.Extra (killThread, withNumCapabilities) import Control.Concurrent.STM.Stats (atomically, dumpSTMStats) import Control.Exception.Safe (SomeException, catchAny, - displayException) -import Control.Monad.Extra (concatMapM, unless, + displayException, + onException) +import Control.Monad.Extra (concatMapM, join, unless, when) import qualified Data.Aeson.Encode.Pretty as A import Data.Default (Default (def)) @@ -34,7 +36,8 @@ import Data.Typeable (typeOf) import Development.IDE (Action, GhcVersion (..), Priority (Debug, Error), Rules, ghcVersion, - hDuplicateTo') + hDuplicateTo', + logInfo) import Development.IDE.Core.Debouncer (Debouncer, newAsyncDebouncer) import Development.IDE.Core.FileStore (isWatchSupported) @@ -479,6 +482,8 @@ defaultMain recorder Arguments{..} = withHeapStats (cmapWithPrio LogHeapStats re } ide <- initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig rules Nothing logger debouncer options hiedb hieChan Nothing shakeSessionInit (cmapWithPrio LogShake recorder) ide + registerIdeConfiguration (shakeExtras ide) $ IdeConfiguration mempty (hashed Nothing) + c ide expandFiles :: [FilePath] -> IO [FilePath] expandFiles = concatMapM $ \x -> do From c6319d396bf6375c7651d3ff383ad28ff76a4412 Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Sat, 30 Apr 2022 12:04:51 +0100 Subject: [PATCH 05/15] Abstract monitoring and put EKG behind a Cabal flag --- docs/contributing/contributing.md | 2 +- ghcide/exe/Arguments.hs | 7 +++ ghcide/exe/Main.hs | 13 +++- ghcide/ghcide.cabal | 22 ++++++- ghcide/src/Development/IDE/Core/Service.hs | 40 ++++++------ ghcide/src/Development/IDE/Core/Shake.hs | 62 ++++++++----------- ghcide/src/Development/IDE/Main.hs | 57 ++++++----------- ghcide/src/Development/IDE/Monitoring/EKG.hs | 34 ++++++++++ .../IDE/Monitoring/OpenTelemetry.hs | 31 ++++++++++ .../src/Development/IDE/Types/Monitoring.hs | 30 +++++++++ 10 files changed, 200 insertions(+), 98 deletions(-) create mode 100644 ghcide/src/Development/IDE/Monitoring/EKG.hs create mode 100644 ghcide/src/Development/IDE/Monitoring/OpenTelemetry.hs create mode 100644 ghcide/src/Development/IDE/Types/Monitoring.hs diff --git a/docs/contributing/contributing.md b/docs/contributing/contributing.md index 20762ccbd1..b885aa12c6 100644 --- a/docs/contributing/contributing.md +++ b/docs/contributing/contributing.md @@ -229,7 +229,7 @@ See the [tutorial](./plugin-tutorial.md) on writing a plugin in HLS. ### Metrics -HLS opens a metrics server on port 8000 exposing GC and ghcide metrics. The ghcide metrics currently exposed are: +When ghcide is built with the `ekg` flag, HLS opens a metrics server on port 8999 exposing GC and ghcide metrics. The ghcide metrics currently exposed are: - `ghcide.values_count`- count of build results in the store - `ghcide.database_count` - count of build keys in the store (these two would be the same in the absence of GC) diff --git a/ghcide/exe/Arguments.hs b/ghcide/exe/Arguments.hs index 4b5e8ae0fa..5a9c443bc6 100644 --- a/ghcide/exe/Arguments.hs +++ b/ghcide/exe/Arguments.hs @@ -1,6 +1,7 @@ -- Copyright (c) 2019 The DAML Authors. All rights reserved. -- SPDX-License-Identifier: Apache-2.0 +{-# LANGUAGE CPP #-} module Arguments(Arguments(..), getArguments) where import Development.IDE (IdeState) @@ -19,6 +20,9 @@ data Arguments = Arguments ,argsVerbose :: Bool ,argsCommand :: Command ,argsConservativeChangeTracking :: Bool +#ifdef MONITORING_EKG + ,argsMonitoringPort :: Int +#endif } getArguments :: IdePlugins IdeState -> IO Arguments @@ -40,6 +44,9 @@ arguments plugins = Arguments <*> switch (short 'd' <> long "verbose" <> help "Include internal events in logging output") <*> (commandP plugins <|> lspCommand <|> checkCommand) <*> switch (long "conservative-change-tracking" <> help "disable reactive change tracking (for testing/debugging)") +#ifdef MONITORING_EKG + <*> option auto (long "monitoring-port" <> metavar "PORT" <> value 8999 <> showDefault <> help "Port to use for monitoring") +#endif where checkCommand = Check <$> many (argument str (metavar "FILES/DIRS...")) lspCommand = LSP <$ flag' True (long "lsp" <> help "Start talking to an LSP client") diff --git a/ghcide/exe/Main.hs b/ghcide/exe/Main.hs index 37bab4d72e..ff7e554b5a 100644 --- a/ghcide/exe/Main.hs +++ b/ghcide/exe/Main.hs @@ -1,6 +1,7 @@ -- Copyright (c) 2019 The DAML Authors. All rights reserved. -- SPDX-License-Identifier: Apache-2.0 {-# OPTIONS_GHC -Wno-dodgy-imports #-} -- GHC no longer exports def in GHC 8.6 and above +{-# LANGUAGE CPP #-} {-# LANGUAGE TemplateHaskell #-} module Main(main) where @@ -24,7 +25,6 @@ import Development.IDE.Types.Logger (Logger (Logger), LoggingColumn (DataColumn, PriorityColumn), Pretty (pretty), Priority (Debug, Info, Error), - Recorder (Recorder), WithPriority (WithPriority, priority), cfilter, cmapWithPrio, makeDefaultStderrRecorder, layoutPretty, renderStrict, defaultLayoutOptions) @@ -43,6 +43,11 @@ import System.Exit (exitSuccess) import System.IO (hPutStrLn, stderr) import System.Info (compilerVersion) +#ifdef MONITORING_EKG +import qualified Development.IDE.Monitoring.OpenTelemetry as OpenTelemetry +import qualified Development.IDE.Monitoring.EKG as EKG +#endif + data Log = LogIDEMain IDEMain.Log | LogRules Rules.Log @@ -142,4 +147,10 @@ main = withTelemetryLogger $ \telemetryLogger -> do , optCheckProject = pure $ checkProject config , optRunSubset = not argsConservativeChangeTracking } +#ifdef MONITORING_EKG + , IDEMain.argsMonitoring = OpenTelemetry.monitoring <> EKG.monitoring logger argsMonitoringPort +#ifdef MONITORING_EKG +#endif +#endif + } diff --git a/ghcide/ghcide.cabal b/ghcide/ghcide.cabal index acf6e068ad..4a6109bcc9 100644 --- a/ghcide/ghcide.cabal +++ b/ghcide/ghcide.cabal @@ -30,6 +30,11 @@ flag ghc-patched-unboxed-bytecode default: False manual: True +flag ekg + description: Enable EKG monitoring of the build graph and other metrics on port 8999 + default: False + manual: True + library default-language: Haskell2010 build-depends: @@ -48,8 +53,6 @@ library dependent-map, dependent-sum, dlist, - ekg-wai, - ekg-core, exceptions, extra >= 1.7.4, enummapset, @@ -200,6 +203,8 @@ library Development.IDE.Types.KnownTargets Development.IDE.Types.Location Development.IDE.Types.Logger + Development.IDE.Types.Monitoring + Development.IDE.Monitoring.OpenTelemetry Development.IDE.Types.Options Development.IDE.Types.Shake Development.IDE.Plugin @@ -238,6 +243,14 @@ library exposed-modules: Development.IDE.GHC.Compat.CPP + if flag(ekg) + build-depends: + ekg-wai, + ekg-core, + cpp-options: -DMONITORING_EKG + exposed-modules: + Development.IDE.Monitoring.EKG + flag test-exe description: Build the ghcide-test-preprocessor executable default: True @@ -358,6 +371,11 @@ executable ghcide if !flag(executable) buildable: False + if flag(ekg) + build-depends: + ekg-wai, + ekg-core, + cpp-options: -DMONITORING_EKG test-suite ghcide-tests type: exitcode-stdio-1.0 diff --git a/ghcide/src/Development/IDE/Core/Service.hs b/ghcide/src/Development/IDE/Core/Service.hs index 28183651f9..8ef090e84e 100644 --- a/ghcide/src/Development/IDE/Core/Service.hs +++ b/ghcide/src/Development/IDE/Core/Service.hs @@ -18,30 +18,30 @@ module Development.IDE.Core.Service( Log(..), ) where -import Control.Applicative ((<|>)) +import Control.Applicative ((<|>)) import Development.IDE.Core.Debouncer -import Development.IDE.Core.FileExists (fileExistsRules) -import Development.IDE.Core.OfInterest hiding (Log, LogShake) +import Development.IDE.Core.FileExists (fileExistsRules) +import Development.IDE.Core.OfInterest hiding (Log, LogShake) import Development.IDE.Graph -import Development.IDE.Types.Logger as Logger (Logger, - Pretty (pretty), - Priority (Debug), - Recorder, - WithPriority, - cmapWithPrio) -import Development.IDE.Types.Options (IdeOptions (..)) +import Development.IDE.Types.Logger as Logger (Logger, + Pretty (pretty), + Priority (Debug), + Recorder, + WithPriority, + cmapWithPrio) +import Development.IDE.Types.Options (IdeOptions (..)) import Ide.Plugin.Config -import qualified Language.LSP.Server as LSP -import qualified Language.LSP.Types as LSP +import qualified Language.LSP.Server as LSP +import qualified Language.LSP.Types as LSP import Control.Monad -import qualified Development.IDE.Core.FileExists as FileExists -import qualified Development.IDE.Core.OfInterest as OfInterest -import Development.IDE.Core.Shake hiding (Log) -import qualified Development.IDE.Core.Shake as Shake -import Development.IDE.Types.Shake (WithHieDb) -import System.Environment (lookupEnv) -import System.Metrics +import qualified Development.IDE.Core.FileExists as FileExists +import qualified Development.IDE.Core.OfInterest as OfInterest +import Development.IDE.Core.Shake hiding (Log) +import qualified Development.IDE.Core.Shake as Shake +import Development.IDE.Types.Monitoring (Monitoring) +import Development.IDE.Types.Shake (WithHieDb) +import System.Environment (lookupEnv) data Log = LogShake Shake.Log @@ -68,7 +68,7 @@ initialise :: Recorder (WithPriority Log) -> IdeOptions -> WithHieDb -> IndexQueue - -> Maybe Store + -> Monitoring -> IO IdeState initialise recorder defaultConfig mainRule lspEnv logger debouncer options withHieDb hiedbChan metrics = do shakeProfiling <- do diff --git a/ghcide/src/Development/IDE/Core/Shake.hs b/ghcide/src/Development/IDE/Core/Shake.hs index a461d82bc1..fbd7c3795f 100644 --- a/ghcide/src/Development/IDE/Core/Shake.hs +++ b/ghcide/src/Development/IDE/Core/Shake.hs @@ -118,7 +118,6 @@ import Data.Typeable import Data.Unique import Data.Vector (Vector) import qualified Data.Vector as Vector -import Debug.Trace.Flags (userTracingEnabled) import Development.IDE.Core.Debouncer import Development.IDE.Core.FileUtils (getModTime) import Development.IDE.Core.PositionMapping @@ -168,8 +167,8 @@ import qualified "list-t" ListT import qualified StmContainers.Map as STM import System.FilePath hiding (makeRelative) import System.IO.Unsafe (unsafePerformIO) -import System.Metrics (Store, registerCounter, registerGauge) import System.Time.Extra +import Development.IDE.Types.Monitoring (Monitoring(..)) data Log = LogCreateHieDbExportsMapStart @@ -464,6 +463,7 @@ data IdeState = IdeState ,shakeSession :: MVar ShakeSession ,shakeExtras :: ShakeExtras ,shakeDatabaseProfile :: ShakeDatabase -> IO (Maybe FilePath) + ,stopMonitoring :: IO () } @@ -559,11 +559,13 @@ shakeOpen :: Recorder (WithPriority Log) -> WithHieDb -> IndexQueue -> ShakeOptions - -> Maybe Store + -> Monitoring -> Rules () -> IO IdeState shakeOpen recorder lspEnv defaultConfig logger debouncer - shakeProfileDir (IdeReportProgress reportProgress) ideTesting@(IdeTesting testing) withHieDb indexQueue opts metrics rules = mdo + shakeProfileDir (IdeReportProgress reportProgress) + ideTesting@(IdeTesting testing) + withHieDb indexQueue opts monitoring rules = mdo let log :: Logger.Priority -> Log -> IO () log = logWith recorder @@ -611,7 +613,6 @@ shakeOpen recorder lspEnv defaultConfig logger debouncer rules shakeSession <- newEmptyMVar shakeDatabaseProfile <- shakeDatabaseProfileIO shakeProfileDir - let ideState = IdeState{..} IdeOptions { optOTMemoryProfiling = IdeOTMemoryProfiling otProfilingEnabled @@ -619,44 +620,30 @@ shakeOpen recorder lspEnv defaultConfig logger debouncer , optCheckParents } <- getIdeOptionsIO shakeExtras - void $ startTelemetry shakeDb shakeExtras startProfilingTelemetry otProfilingEnabled logger $ state shakeExtras checkParents <- optCheckParents - for_ metrics $ \store -> do - let readValuesCounter = fromIntegral . countRelevantKeys checkParents <$> getStateKeys shakeExtras - readDirtyKeys = fromIntegral . countRelevantKeys checkParents . HSet.toList <$> readTVarIO(dirtyKeys shakeExtras) - readIndexPending = fromIntegral . HMap.size <$> readTVarIO (indexPending $ hiedbWriter shakeExtras) - readExportsMap = fromIntegral . HMap.size . getExportsMap <$> readTVarIO (exportsMap shakeExtras) - readDatabaseCount = fromIntegral . countRelevantKeys checkParents . map fst <$> shakeGetDatabaseKeys shakeDb - readDatabaseStep = fromIntegral <$> shakeGetBuildStep shakeDb - - registerGauge "ghcide.values_count" readValuesCounter store - registerGauge "ghcide.dirty_keys_count" readDirtyKeys store - registerGauge "ghcide.indexing_pending_count" readIndexPending store - registerGauge "ghcide.exports_map_count" readExportsMap store - registerGauge "ghcide.database_count" readDatabaseCount store - registerCounter "ghcide.num_builds" readDatabaseStep store - return ideState + -- monitoring + let readValuesCounter = fromIntegral . countRelevantKeys checkParents <$> getStateKeys shakeExtras + readDirtyKeys = fromIntegral . countRelevantKeys checkParents . HSet.toList <$> readTVarIO(dirtyKeys shakeExtras) + readIndexPending = fromIntegral . HMap.size <$> readTVarIO (indexPending $ hiedbWriter shakeExtras) + readExportsMap = fromIntegral . HMap.size . getExportsMap <$> readTVarIO (exportsMap shakeExtras) + readDatabaseCount = fromIntegral . countRelevantKeys checkParents . map fst <$> shakeGetDatabaseKeys shakeDb + readDatabaseStep = fromIntegral <$> shakeGetBuildStep shakeDb -startTelemetry :: ShakeDatabase -> ShakeExtras -> IO (Async ()) -startTelemetry db extras@ShakeExtras{..} - | userTracingEnabled = do - countKeys <- mkValueObserver "cached keys count" - countDirty <- mkValueObserver "dirty keys count" - countBuilds <- mkValueObserver "builds count" - IdeOptions{optCheckParents} <- getIdeOptionsIO extras - checkParents <- optCheckParents - regularly 1 $ do - observe countKeys . countRelevantKeys checkParents =<< getStateKeys extras - readTVarIO dirtyKeys >>= observe countDirty . countRelevantKeys checkParents . HSet.toList - shakeGetBuildStep db >>= observe countBuilds + registerGauge monitoring "ghcide.values_count" readValuesCounter + registerGauge monitoring "ghcide.dirty_keys_count" readDirtyKeys + registerGauge monitoring "ghcide.indexing_pending_count" readIndexPending + registerGauge monitoring "ghcide.exports_map_count" readExportsMap + registerGauge monitoring "ghcide.database_count" readDatabaseCount + registerCounter monitoring "ghcide.num_builds" readDatabaseStep + + stopMonitoring <- start monitoring + + let ideState = IdeState{..} + return ideState - | otherwise = async (pure ()) - where - regularly :: Seconds -> IO () -> IO (Async ()) - regularly delay act = async $ forever (act >> sleep delay) getStateKeys :: ShakeExtras -> IO [Key] getStateKeys = (fmap.fmap) fst . atomically . ListT.toList . STM.listT . state @@ -679,6 +666,7 @@ shakeShut IdeState{..} = do for_ runner cancelShakeSession void $ shakeDatabaseProfile shakeDb progressStop $ progress shakeExtras + stopMonitoring -- | This is a variant of withMVar where the first argument is run unmasked and if it throws diff --git a/ghcide/src/Development/IDE/Main.hs b/ghcide/src/Development/IDE/Main.hs index 1180b00afc..f9fc05e161 100644 --- a/ghcide/src/Development/IDE/Main.hs +++ b/ghcide/src/Development/IDE/Main.hs @@ -1,3 +1,4 @@ +{-# LANGUAGE CPP #-} {-# LANGUAGE PackageImports #-} {-# OPTIONS_GHC -Wno-orphans #-} module Development.IDE.Main @@ -11,14 +12,12 @@ module Development.IDE.Main ,testing ,Log(..) ) where -import Control.Concurrent.Async (async, waitCatch) -import Control.Concurrent.Extra (killThread, withNumCapabilities) +import Control.Concurrent.Extra (withNumCapabilities) import Control.Concurrent.STM.Stats (atomically, dumpSTMStats) import Control.Exception.Safe (SomeException, catchAny, - displayException, - onException) -import Control.Monad.Extra (concatMapM, join, unless, + displayException) +import Control.Monad.Extra (concatMapM, unless, when) import qualified Data.Aeson.Encode.Pretty as A import Data.Default (Default (def)) @@ -31,13 +30,11 @@ import Data.Maybe (catMaybes, isJust) import qualified Data.Text as T import Data.Text.Lazy.Encoding (decodeUtf8) import qualified Data.Text.Lazy.IO as LT -import Data.Traversable (for) import Data.Typeable (typeOf) import Development.IDE (Action, GhcVersion (..), Priority (Debug, Error), Rules, ghcVersion, - hDuplicateTo', - logInfo) + hDuplicateTo') import Development.IDE.Core.Debouncer (Debouncer, newAsyncDebouncer) import Development.IDE.Core.FileStore (isWatchSupported) @@ -130,12 +127,15 @@ import System.IO (BufferMode (LineBufferin hSetEncoding, stderr, stdin, stdout, utf8) import System.Random (newStdGen) -import qualified System.Metrics as Monitoring -import System.Remote.Monitoring.Wai -import qualified System.Remote.Monitoring.Wai as Monitoring import System.Time.Extra (Seconds, offsetTime, showDuration) import Text.Printf (printf) +import Development.IDE.Types.Monitoring (Monitoring) +import qualified Development.IDE.Monitoring.OpenTelemetry as OpenTelemetry + +#ifdef MONITORING_EKG +import qualified Development.IDE.Monitoring.EKG as EKG +#endif data Log = LogHeapStats !HeapStats.Log @@ -238,10 +238,9 @@ data Arguments = Arguments , argsHandleIn :: IO Handle , argsHandleOut :: IO Handle , argsThreads :: Maybe Natural - , argsMonitoringPort :: Maybe Natural + , argsMonitoring :: IO Monitoring } - defaultArguments :: Recorder (WithPriority Log) -> Logger -> Arguments defaultArguments recorder logger = Arguments { argsProjectRoot = Nothing @@ -276,7 +275,10 @@ defaultArguments recorder logger = Arguments -- the language server tests without the redirection. putStr " " >> hFlush stdout return newStdout - , argsMonitoringPort = Just 8000 + , argsMonitoring = OpenTelemetry.monitoring +#ifdef MONITORING_EKG + <> EKG.monitoring logger 8999 +#endif } @@ -364,24 +366,7 @@ defaultMain recorder Arguments{..} = withHeapStats (cmapWithPrio LogHeapStats re -- FIXME: Remove this after GHC 9 gets fully supported when (ghcVersion == GHC90) $ log Warning LogOnlyPartialGhc9Support - server <- fmap join $ for argsMonitoringPort $ \p -> do - store <- Monitoring.newStore - Monitoring.registerGcMetrics store - let startServer = Monitoring.forkServerWith store "localhost" (fromIntegral p) - -- this can fail if the port is busy, throwing an async exception back to us - -- to handle that, wrap the server thread in an async - mb_server <- async startServer >>= waitCatch - case mb_server of - Right s -> do - logInfo logger $ T.pack $ - "Started monitoring server on port " <> show p - return $ Just s - Left e -> do - logInfo logger $ T.pack $ - "Unable to bind monitoring server on port " - <> show p <> ":" <> show e - return Nothing - + monitoring <- argsMonitoring initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig @@ -392,9 +377,7 @@ defaultMain recorder Arguments{..} = withHeapStats (cmapWithPrio LogHeapStats re options withHieDb hieChan - (Monitoring.serverMetricStore <$> server) - `onException` - traverse_ (killThread . serverThreadId) server + monitoring dumpSTMStats Check argFiles -> do dir <- maybe IO.getCurrentDirectory return argsProjectRoot @@ -427,7 +410,7 @@ defaultMain recorder Arguments{..} = withHeapStats (cmapWithPrio LogHeapStats re , optCheckProject = pure False , optModifyDynFlags = optModifyDynFlags def_options <> pluginModifyDynflags plugins } - ide <- initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig rules Nothing logger debouncer options hiedb hieChan Nothing + ide <- initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig rules Nothing logger debouncer options hiedb hieChan mempty shakeSessionInit (cmapWithPrio LogShake recorder) ide registerIdeConfiguration (shakeExtras ide) $ IdeConfiguration mempty (hashed Nothing) @@ -480,7 +463,7 @@ defaultMain recorder Arguments{..} = withHeapStats (cmapWithPrio LogHeapStats re , optCheckProject = pure False , optModifyDynFlags = optModifyDynFlags def_options <> pluginModifyDynflags plugins } - ide <- initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig rules Nothing logger debouncer options hiedb hieChan Nothing + ide <- initialise (cmapWithPrio LogService recorder) argsDefaultHlsConfig rules Nothing logger debouncer options hiedb hieChan mempty shakeSessionInit (cmapWithPrio LogShake recorder) ide registerIdeConfiguration (shakeExtras ide) $ IdeConfiguration mempty (hashed Nothing) c ide diff --git a/ghcide/src/Development/IDE/Monitoring/EKG.hs b/ghcide/src/Development/IDE/Monitoring/EKG.hs new file mode 100644 index 0000000000..3ffe300d07 --- /dev/null +++ b/ghcide/src/Development/IDE/Monitoring/EKG.hs @@ -0,0 +1,34 @@ +module Development.IDE.Monitoring.EKG(monitoring) where +import Control.Concurrent (killThread) +import Control.Concurrent.Async (async, waitCatch) +import Data.Text (pack) +import Development.IDE.Types.Logger (Logger, logInfo) +import Development.IDE.Types.Monitoring (Monitoring (..)) +import qualified System.Metrics as Monitoring +import qualified System.Remote.Monitoring.Wai as Monitoring + +-- | Monitoring using EKG +monitoring :: Logger -> Int -> IO Monitoring +monitoring logger port = do + store <- Monitoring.newStore + Monitoring.registerGcMetrics store + let registerCounter name read = Monitoring.registerGauge name read store + registerGauge name read = Monitoring.registerGauge name read store + start = do + server <- do + let startServer = Monitoring.forkServerWith store "localhost" port + -- this can fail if the port is busy, throwing an async exception back to us + -- to handle that, wrap the server thread in an async + mb_server <- async startServer >>= waitCatch + case mb_server of + Right s -> do + logInfo logger $ pack $ + "Started monitoring server on port " <> show port + return $ Just s + Left e -> do + logInfo logger $ pack $ + "Unable to bind monitoring server on port " + <> show port <> ":" <> show e + return Nothing + return $ mapM_ (killThread . Monitoring.serverThreadId) server + return $ Monitoring {..} diff --git a/ghcide/src/Development/IDE/Monitoring/OpenTelemetry.hs b/ghcide/src/Development/IDE/Monitoring/OpenTelemetry.hs new file mode 100644 index 0000000000..2a6efa3d2e --- /dev/null +++ b/ghcide/src/Development/IDE/Monitoring/OpenTelemetry.hs @@ -0,0 +1,31 @@ +module Development.IDE.Monitoring.OpenTelemetry (monitoring) where + +import Control.Concurrent.Async (Async, async, cancel) +import Control.Monad (forever) +import Data.IORef.Extra (atomicModifyIORef'_, + newIORef, readIORef) +import Data.Text.Encoding (encodeUtf8) +import Debug.Trace.Flags (userTracingEnabled) +import Development.IDE.Types.Monitoring (Monitoring (..)) +import OpenTelemetry.Eventlog (mkValueObserver, observe) +import System.Time.Extra (Seconds, sleep) + +-- | Dump monitoring to the eventlog using the Opentelemetry package +monitoring :: IO Monitoring +monitoring + | userTracingEnabled = do + actions <- newIORef [] + let registerCounter name read = do + observer <- mkValueObserver (encodeUtf8 name) + let update = observe observer . fromIntegral =<< read + atomicModifyIORef'_ actions (update :) + registerGauge = registerCounter + let start = do + a <- regularly 1 $ sequence_ =<< readIORef actions + return (cancel a) + return Monitoring{..} + | otherwise = mempty + + +regularly :: Seconds -> IO () -> IO (Async ()) +regularly delay act = async $ forever (act >> sleep delay) diff --git a/ghcide/src/Development/IDE/Types/Monitoring.hs b/ghcide/src/Development/IDE/Types/Monitoring.hs new file mode 100644 index 0000000000..08d3d88128 --- /dev/null +++ b/ghcide/src/Development/IDE/Types/Monitoring.hs @@ -0,0 +1,30 @@ +module Development.IDE.Types.Monitoring +(Monitoring(..) +) where + +import Data.Int +import Data.Text (Text) + +-- | An abstraction for runtime monitoring. +data Monitoring = Monitoring { + registerGauge :: Text -> IO Int64 -> IO (), + registerCounter :: Text -> IO Int64 -> IO (), + start :: IO (IO ()) + } + +instance Semigroup Monitoring where + a <> b = Monitoring { + registerGauge = \n v -> registerGauge a n v >> registerGauge b n v, + registerCounter = \n v -> registerCounter a n v >> registerCounter b n v, + start = do + a' <- start a + b' <- start b + return $ a' >> b' + } + +instance Monoid Monitoring where + mempty = Monitoring { + registerGauge = \_ _ -> return (), + registerCounter = \_ _ -> return (), + start = return $ return () + } From 55fc507586d7ac1b61aea333af461145b993e92e Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Sat, 30 Apr 2022 12:52:52 +0100 Subject: [PATCH 06/15] Add CI for the new flag --- .github/workflows/flags.yml | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/.github/workflows/flags.yml b/.github/workflows/flags.yml index 2283899d0c..3c7a12a82d 100644 --- a/.github/workflows/flags.yml +++ b/.github/workflows/flags.yml @@ -67,6 +67,10 @@ jobs: - name: Build `ghcide` with flags run: cabal v2-build ghcide --flags="ghc-patched-unboxed-bytecode test-exe executable bench-exe" + - if: matrix.ghc == '8.10.7' + name: Build `ghcide` with ekg + run: cabal v2-build ghcide --flags="ekg" + # we have to clean up warnings for 9.0 and 9.2 before enable -WAll - if: matrix.ghc != '9.0.2' && matrix.ghc != '9.2.2' name: Build with pedantic (-WError) From 7f69d7b35da823a540b18752330244a590672cdc Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Sun, 1 May 2022 15:29:02 +0100 Subject: [PATCH 07/15] fix double ifdef --- ghcide/exe/Main.hs | 3 --- 1 file changed, 3 deletions(-) diff --git a/ghcide/exe/Main.hs b/ghcide/exe/Main.hs index ff7e554b5a..ebceff7d45 100644 --- a/ghcide/exe/Main.hs +++ b/ghcide/exe/Main.hs @@ -149,8 +149,5 @@ main = withTelemetryLogger $ \telemetryLogger -> do } #ifdef MONITORING_EKG , IDEMain.argsMonitoring = OpenTelemetry.monitoring <> EKG.monitoring logger argsMonitoringPort -#ifdef MONITORING_EKG -#endif #endif - } From 7431cea783f3b92d327635c017dd5de87b4b8774 Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Sun, 1 May 2022 15:31:17 +0100 Subject: [PATCH 08/15] link to GHC docs for eventlogs --- docs/contributing/contributing.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/contributing/contributing.md b/docs/contributing/contributing.md index b885aa12c6..1907d40856 100644 --- a/docs/contributing/contributing.md +++ b/docs/contributing/contributing.md @@ -252,7 +252,7 @@ More details in [bench/README](../../ghcide/bench/README.md) ### Tracing -HLS records opentelemetry eventlog traces via [opentelemetry](https://hackage.haskell.org/package/opentelemetry). To generate the traces, build with `-eventlog` and run with `+RTS -l`. To visualize the traces, install [Tracy](https://github.com/wolfpld/tracy) and use [eventlog-to-tracy](https://hackage.haskell.org/package/opentelemetry-extra) to open the generated eventlog. +HLS records opentelemetry [eventlog traces](https://downloads.haskell.org/~ghc/latest/docs/html/users_guide/runtime_control.html#rts-eventlog) via [opentelemetry](https://hackage.haskell.org/package/opentelemetry). To generate the traces, build with `-eventlog` and run with `+RTS -l`. To visualize the traces, install [Tracy](https://github.com/wolfpld/tracy) and use [eventlog-to-tracy](https://hackage.haskell.org/package/opentelemetry-extra) to open the generated eventlog. ## Adding support for a new editor From a5bc2104f722502fbb4971b5d8791cb603459ec4 Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Sun, 1 May 2022 15:35:09 +0100 Subject: [PATCH 09/15] log when stopping the EKG server --- ghcide/src/Development/IDE/Monitoring/EKG.hs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/ghcide/src/Development/IDE/Monitoring/EKG.hs b/ghcide/src/Development/IDE/Monitoring/EKG.hs index 3ffe300d07..55fe399fe6 100644 --- a/ghcide/src/Development/IDE/Monitoring/EKG.hs +++ b/ghcide/src/Development/IDE/Monitoring/EKG.hs @@ -1,6 +1,7 @@ module Development.IDE.Monitoring.EKG(monitoring) where import Control.Concurrent (killThread) import Control.Concurrent.Async (async, waitCatch) +import Control.Monad (forM_) import Data.Text (pack) import Development.IDE.Types.Logger (Logger, logInfo) import Development.IDE.Types.Monitoring (Monitoring (..)) @@ -30,5 +31,7 @@ monitoring logger port = do "Unable to bind monitoring server on port " <> show port <> ":" <> show e return Nothing - return $ mapM_ (killThread . Monitoring.serverThreadId) server + return $ forM_ server $ \s -> do + logInfo logger "Stopping monitoring server" + killThread $ Monitoring.serverThreadId s return $ Monitoring {..} From 629452c4d9d42f5d1bc6b012a905329a616df4b3 Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Sun, 1 May 2022 15:38:30 +0100 Subject: [PATCH 10/15] Allow CPP in modules --- ghcide/.hlint.yaml | 2 ++ 1 file changed, 2 insertions(+) diff --git a/ghcide/.hlint.yaml b/ghcide/.hlint.yaml index 590a707570..c8dde37fa9 100644 --- a/ghcide/.hlint.yaml +++ b/ghcide/.hlint.yaml @@ -111,6 +111,7 @@ - Development.IDE.GHC.Util - Development.IDE.Import.FindImports - Development.IDE.LSP.Outline + - Development.IDE.Main - Development.IDE.Spans.Calculate - Development.IDE.Spans.Documentation - Development.IDE.Spans.Common @@ -123,6 +124,7 @@ - Development.IDE.Plugin.Completions.Logic - Development.IDE.Types.Location - Main + - Arguments - flags: - default: false From c687f4ea5065357776a71512b43faf1ef645269d Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Sun, 1 May 2022 15:38:34 +0100 Subject: [PATCH 11/15] Add doc comments --- ghcide/src/Development/IDE/Types/Monitoring.hs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/ghcide/src/Development/IDE/Types/Monitoring.hs b/ghcide/src/Development/IDE/Types/Monitoring.hs index 08d3d88128..22ff92639d 100644 --- a/ghcide/src/Development/IDE/Types/Monitoring.hs +++ b/ghcide/src/Development/IDE/Types/Monitoring.hs @@ -5,9 +5,11 @@ module Development.IDE.Types.Monitoring import Data.Int import Data.Text (Text) --- | An abstraction for runtime monitoring. +-- | An abstraction for runtime monitoring inspired by the 'ekg' package data Monitoring = Monitoring { + -- | Register an integer-valued metric. registerGauge :: Text -> IO Int64 -> IO (), + -- | Register a non-negative, monotonically increasing, integer-valued metric. registerCounter :: Text -> IO Int64 -> IO (), start :: IO (IO ()) } From 5319cb112310450b03874554d31878bc790a837a Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Sun, 1 May 2022 15:38:19 +0100 Subject: [PATCH 12/15] Apply suggestions from code review Co-authored-by: Michael Peyton Jones --- cabal.project | 5 ++++- ghcide/src/Development/IDE/Monitoring/EKG.hs | 2 +- ghcide/src/Development/IDE/Types/Monitoring.hs | 2 +- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/cabal.project b/cabal.project index 122d60eaf1..92f760eb22 100644 --- a/cabal.project +++ b/cabal.project @@ -53,7 +53,10 @@ constraints: ghc-lib-parser-ex -auto, stylish-haskell +ghc-lib - source-repository-package +-- This is benign and won't affect our ability to release to Hackage, +-- because we only depend on `ekg-json` when a non-default flag +-- is turned on. +source-repository-package type:git location: https://github.com/vshabanov/ekg-json tag: 00ebe7211c981686e65730b7144fbf5350462608 diff --git a/ghcide/src/Development/IDE/Monitoring/EKG.hs b/ghcide/src/Development/IDE/Monitoring/EKG.hs index 55fe399fe6..38a3ebbea8 100644 --- a/ghcide/src/Development/IDE/Monitoring/EKG.hs +++ b/ghcide/src/Development/IDE/Monitoring/EKG.hs @@ -13,7 +13,7 @@ monitoring :: Logger -> Int -> IO Monitoring monitoring logger port = do store <- Monitoring.newStore Monitoring.registerGcMetrics store - let registerCounter name read = Monitoring.registerGauge name read store + let registerCounter name read = Monitoring.registerCounter name read store registerGauge name read = Monitoring.registerGauge name read store start = do server <- do diff --git a/ghcide/src/Development/IDE/Types/Monitoring.hs b/ghcide/src/Development/IDE/Types/Monitoring.hs index 22ff92639d..256381e60a 100644 --- a/ghcide/src/Development/IDE/Types/Monitoring.hs +++ b/ghcide/src/Development/IDE/Types/Monitoring.hs @@ -11,7 +11,7 @@ data Monitoring = Monitoring { registerGauge :: Text -> IO Int64 -> IO (), -- | Register a non-negative, monotonically increasing, integer-valued metric. registerCounter :: Text -> IO Int64 -> IO (), - start :: IO (IO ()) + start :: IO (IO ()) -- ^ Start the monitoring system, returning an action which will stop the system. } instance Semigroup Monitoring where From ab347bee54f777c002cc33e6bbb350370abeb03a Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Mon, 2 May 2022 10:57:54 +0100 Subject: [PATCH 13/15] Compat. with ghc 9.2 --- .github/workflows/flags.yml | 6 +----- cabal.project | 2 ++ 2 files changed, 3 insertions(+), 5 deletions(-) diff --git a/.github/workflows/flags.yml b/.github/workflows/flags.yml index 3c7a12a82d..7b81bb08e8 100644 --- a/.github/workflows/flags.yml +++ b/.github/workflows/flags.yml @@ -65,11 +65,7 @@ jobs: run: cabal v2-build hls-graph --flags="embed-files stm-stats" - name: Build `ghcide` with flags - run: cabal v2-build ghcide --flags="ghc-patched-unboxed-bytecode test-exe executable bench-exe" - - - if: matrix.ghc == '8.10.7' - name: Build `ghcide` with ekg - run: cabal v2-build ghcide --flags="ekg" + run: cabal v2-build ghcide --flags="ghc-patched-unboxed-bytecode test-exe executable bench-exe ekg" # we have to clean up warnings for 9.0 and 9.2 before enable -WAll - if: matrix.ghc != '9.0.2' && matrix.ghc != '9.2.2' diff --git a/cabal.project b/cabal.project index 92f760eb22..22bd0405e4 100644 --- a/cabal.project +++ b/cabal.project @@ -82,7 +82,9 @@ allow-newer: -- for ekg ekg-core:base, + ekg-core:ghc-prim, ekg-wai:base, + ekg-wai:time, -- for shake-bench Chart-diagrams:diagrams-core, From 700d73f44094ed2f791b63d2da1c7efce52d4c63 Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Thu, 5 May 2022 21:50:09 +0100 Subject: [PATCH 14/15] use an ekg-json snapshot that preserves compat. with ghc 8.x --- cabal.project | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cabal.project b/cabal.project index 22bd0405e4..4cc16fa34a 100644 --- a/cabal.project +++ b/cabal.project @@ -58,8 +58,8 @@ constraints: -- is turned on. source-repository-package type:git - location: https://github.com/vshabanov/ekg-json - tag: 00ebe7211c981686e65730b7144fbf5350462608 + location: https://github.com/pepeiborra/ekg-json + tag: 7a0af7a8fd38045fd15fb13445bdcc7085325460 -- https://github.com/tibbe/ekg-json/pull/12 allow-newer: From e7f3df4db9f9b654f4695f150da2893a717ef8f2 Mon Sep 17 00:00:00 2001 From: Pepe Iborra Date: Fri, 6 May 2022 07:26:32 +0100 Subject: [PATCH 15/15] confine CPP to the EKG module --- ghcide/.hlint.yaml | 3 --- ghcide/exe/Arguments.hs | 7 +------ ghcide/exe/Main.hs | 10 ++-------- ghcide/ghcide.cabal | 3 +-- ghcide/src/Development/IDE/Main.hs | 15 ++++----------- ghcide/src/Development/IDE/Monitoring/EKG.hs | 17 ++++++++++++++--- 6 files changed, 22 insertions(+), 33 deletions(-) diff --git a/ghcide/.hlint.yaml b/ghcide/.hlint.yaml index c8dde37fa9..a188671994 100644 --- a/ghcide/.hlint.yaml +++ b/ghcide/.hlint.yaml @@ -111,7 +111,6 @@ - Development.IDE.GHC.Util - Development.IDE.Import.FindImports - Development.IDE.LSP.Outline - - Development.IDE.Main - Development.IDE.Spans.Calculate - Development.IDE.Spans.Documentation - Development.IDE.Spans.Common @@ -123,8 +122,6 @@ - Development.IDE.Plugin.Completions - Development.IDE.Plugin.Completions.Logic - Development.IDE.Types.Location - - Main - - Arguments - flags: - default: false diff --git a/ghcide/exe/Arguments.hs b/ghcide/exe/Arguments.hs index 5a9c443bc6..4d14b920bd 100644 --- a/ghcide/exe/Arguments.hs +++ b/ghcide/exe/Arguments.hs @@ -1,7 +1,6 @@ -- Copyright (c) 2019 The DAML Authors. All rights reserved. -- SPDX-License-Identifier: Apache-2.0 -{-# LANGUAGE CPP #-} module Arguments(Arguments(..), getArguments) where import Development.IDE (IdeState) @@ -20,9 +19,7 @@ data Arguments = Arguments ,argsVerbose :: Bool ,argsCommand :: Command ,argsConservativeChangeTracking :: Bool -#ifdef MONITORING_EKG ,argsMonitoringPort :: Int -#endif } getArguments :: IdePlugins IdeState -> IO Arguments @@ -44,9 +41,7 @@ arguments plugins = Arguments <*> switch (short 'd' <> long "verbose" <> help "Include internal events in logging output") <*> (commandP plugins <|> lspCommand <|> checkCommand) <*> switch (long "conservative-change-tracking" <> help "disable reactive change tracking (for testing/debugging)") -#ifdef MONITORING_EKG - <*> option auto (long "monitoring-port" <> metavar "PORT" <> value 8999 <> showDefault <> help "Port to use for monitoring") -#endif + <*> option auto (long "monitoring-port" <> metavar "PORT" <> value 8999 <> showDefault <> help "Port to use for EKG monitoring (if the binary is built with EKG)") where checkCommand = Check <$> many (argument str (metavar "FILES/DIRS...")) lspCommand = LSP <$ flag' True (long "lsp" <> help "Start talking to an LSP client") diff --git a/ghcide/exe/Main.hs b/ghcide/exe/Main.hs index ebceff7d45..e97f393d2a 100644 --- a/ghcide/exe/Main.hs +++ b/ghcide/exe/Main.hs @@ -1,7 +1,6 @@ -- Copyright (c) 2019 The DAML Authors. All rights reserved. -- SPDX-License-Identifier: Apache-2.0 {-# OPTIONS_GHC -Wno-dodgy-imports #-} -- GHC no longer exports def in GHC 8.6 and above -{-# LANGUAGE CPP #-} {-# LANGUAGE TemplateHaskell #-} module Main(main) where @@ -20,6 +19,8 @@ import Development.IDE.Core.Rules (mainRule) import qualified Development.IDE.Core.Rules as Rules import Development.IDE.Core.Tracing (withTelemetryLogger) import qualified Development.IDE.Main as IDEMain +import qualified Development.IDE.Monitoring.OpenTelemetry as OpenTelemetry +import qualified Development.IDE.Monitoring.EKG as EKG import qualified Development.IDE.Plugin.HLS.GhcIde as GhcIde import Development.IDE.Types.Logger (Logger (Logger), LoggingColumn (DataColumn, PriorityColumn), @@ -43,11 +44,6 @@ import System.Exit (exitSuccess) import System.IO (hPutStrLn, stderr) import System.Info (compilerVersion) -#ifdef MONITORING_EKG -import qualified Development.IDE.Monitoring.OpenTelemetry as OpenTelemetry -import qualified Development.IDE.Monitoring.EKG as EKG -#endif - data Log = LogIDEMain IDEMain.Log | LogRules Rules.Log @@ -147,7 +143,5 @@ main = withTelemetryLogger $ \telemetryLogger -> do , optCheckProject = pure $ checkProject config , optRunSubset = not argsConservativeChangeTracking } -#ifdef MONITORING_EKG , IDEMain.argsMonitoring = OpenTelemetry.monitoring <> EKG.monitoring logger argsMonitoringPort -#endif } diff --git a/ghcide/ghcide.cabal b/ghcide/ghcide.cabal index 4a6109bcc9..030cc88aad 100644 --- a/ghcide/ghcide.cabal +++ b/ghcide/ghcide.cabal @@ -187,6 +187,7 @@ library Development.IDE.GHC.Util Development.IDE.Import.DependencyInformation Development.IDE.Import.FindImports + Development.IDE.Monitoring.EKG Development.IDE.LSP.HoverDefinition Development.IDE.LSP.LanguageServer Development.IDE.LSP.Outline @@ -248,8 +249,6 @@ library ekg-wai, ekg-core, cpp-options: -DMONITORING_EKG - exposed-modules: - Development.IDE.Monitoring.EKG flag test-exe description: Build the ghcide-test-preprocessor executable diff --git a/ghcide/src/Development/IDE/Main.hs b/ghcide/src/Development/IDE/Main.hs index f9fc05e161..5acb2139d5 100644 --- a/ghcide/src/Development/IDE/Main.hs +++ b/ghcide/src/Development/IDE/Main.hs @@ -1,4 +1,3 @@ -{-# LANGUAGE CPP #-} {-# LANGUAGE PackageImports #-} {-# OPTIONS_GHC -Wno-orphans #-} module Development.IDE.Main @@ -63,6 +62,9 @@ import Development.IDE.LSP.LanguageServer (runLanguageServer) import qualified Development.IDE.LSP.LanguageServer as LanguageServer import Development.IDE.Main.HeapStats (withHeapStats) import qualified Development.IDE.Main.HeapStats as HeapStats +import Development.IDE.Types.Monitoring (Monitoring) +import qualified Development.IDE.Monitoring.EKG as EKG +import qualified Development.IDE.Monitoring.OpenTelemetry as OpenTelemetry import Development.IDE.Plugin (Plugin (pluginHandlers, pluginModifyDynflags, pluginRules)) import Development.IDE.Plugin.HLS (asGhcIdePlugin) import qualified Development.IDE.Plugin.HLS as PluginHLS @@ -130,12 +132,6 @@ import System.Random (newStdGen) import System.Time.Extra (Seconds, offsetTime, showDuration) import Text.Printf (printf) -import Development.IDE.Types.Monitoring (Monitoring) -import qualified Development.IDE.Monitoring.OpenTelemetry as OpenTelemetry - -#ifdef MONITORING_EKG -import qualified Development.IDE.Monitoring.EKG as EKG -#endif data Log = LogHeapStats !HeapStats.Log @@ -275,10 +271,7 @@ defaultArguments recorder logger = Arguments -- the language server tests without the redirection. putStr " " >> hFlush stdout return newStdout - , argsMonitoring = OpenTelemetry.monitoring -#ifdef MONITORING_EKG - <> EKG.monitoring logger 8999 -#endif + , argsMonitoring = OpenTelemetry.monitoring <> EKG.monitoring logger 8999 } diff --git a/ghcide/src/Development/IDE/Monitoring/EKG.hs b/ghcide/src/Development/IDE/Monitoring/EKG.hs index 38a3ebbea8..84bc85935a 100644 --- a/ghcide/src/Development/IDE/Monitoring/EKG.hs +++ b/ghcide/src/Development/IDE/Monitoring/EKG.hs @@ -1,12 +1,16 @@ +{-# LANGUAGE CPP #-} module Development.IDE.Monitoring.EKG(monitoring) where + +import Development.IDE.Types.Monitoring (Monitoring (..)) +import Development.IDE.Types.Logger (Logger) +#ifdef MONITORING_EKG import Control.Concurrent (killThread) import Control.Concurrent.Async (async, waitCatch) import Control.Monad (forM_) import Data.Text (pack) -import Development.IDE.Types.Logger (Logger, logInfo) -import Development.IDE.Types.Monitoring (Monitoring (..)) -import qualified System.Metrics as Monitoring +import Development.IDE.Types.Logger (logInfo) import qualified System.Remote.Monitoring.Wai as Monitoring +import qualified System.Metrics as Monitoring -- | Monitoring using EKG monitoring :: Logger -> Int -> IO Monitoring @@ -35,3 +39,10 @@ monitoring logger port = do logInfo logger "Stopping monitoring server" killThread $ Monitoring.serverThreadId s return $ Monitoring {..} + +#else + +monitoring :: Logger -> Int -> IO Monitoring +monitoring _ _ = mempty + +#endif