Skip to content

Commit fbbf76b

Browse files
authored
Review masking and add traces when things don't cancel timely (#2768)
* Review masking and add traces when things don't cancel timely * fixup * use sleep consistently * redundant imports * hlints * fix 9.2 build * Fix 9.2 build for real * remove unnecessary polymorphism * Avoid spawning loop async unnecessrily * flush asyncs ref * Add comments and apply @michaelpj suggestions
1 parent 7e361f0 commit fbbf76b

File tree

3 files changed

+62
-30
lines changed

3 files changed

+62
-30
lines changed

ghcide/src/Development/IDE/Core/FileExists.hs

+1-2
Original file line numberDiff line numberDiff line change
@@ -109,8 +109,7 @@ modifyFileExists :: IdeState -> [(NormalizedFilePath, FileChangeType)] -> IO ()
109109
modifyFileExists state changes = do
110110
FileExistsMapVar var <- getIdeGlobalState state
111111
-- Masked to ensure that the previous values are flushed together with the map update
112-
-- update the map
113-
mask_ $ join $ atomicallyNamed "modifyFileExists" $ do
112+
join $ mask_ $ atomicallyNamed "modifyFileExists" $ do
114113
forM_ changes $ \(f,c) ->
115114
case fromChange c of
116115
Just c' -> STM.focus (Focus.insert c') f var

ghcide/src/Development/IDE/Core/Shake.hs

+15-9
Original file line numberDiff line numberDiff line change
@@ -151,7 +151,6 @@ import Development.IDE.Types.Options
151151
import Development.IDE.Types.Shake
152152
import qualified Focus
153153
import GHC.Fingerprint
154-
import GHC.Generics
155154
import HieDb.Types
156155
import Ide.Plugin.Config
157156
import qualified Ide.PluginUtils as HLS
@@ -173,6 +172,7 @@ data Log
173172
= LogCreateHieDbExportsMapStart
174173
| LogCreateHieDbExportsMapFinish !Int
175174
| LogBuildSessionRestart !String ![DelayedActionInternal] !(HashSet Key) !Seconds !(Maybe FilePath)
175+
| LogBuildSessionRestartTakingTooLong !Seconds
176176
| LogDelayedAction !(DelayedAction ()) !Seconds
177177
| LogBuildSessionFinish !(Maybe SomeException)
178178
| LogDiagsDiffButNoLspEnv ![FileDiagnostic]
@@ -192,6 +192,8 @@ instance Pretty Log where
192192
, "Action Queue:" <+> pretty (map actionName actionQueue)
193193
, "Keys:" <+> pretty (map show $ HSet.toList keyBackLog)
194194
, "Aborting previous build session took" <+> pretty (showDuration abortDuration) <+> pretty shakeProfilePath ]
195+
LogBuildSessionRestartTakingTooLong seconds ->
196+
"Build restart is taking too long (" <> pretty seconds <> " seconds)"
195197
LogDelayedAction delayedAction duration ->
196198
hsep
197199
[ "Finished:" <+> pretty (actionName delayedAction)
@@ -322,7 +324,7 @@ getVirtualFile nf = do
322324
-- Take a snapshot of the current LSP VFS
323325
vfsSnapshot :: Maybe (LSP.LanguageContextEnv a) -> IO VFS
324326
vfsSnapshot Nothing = pure $ VFS mempty ""
325-
vfsSnapshot (Just lspEnv) = LSP.runLspT lspEnv $ LSP.getVirtualFiles
327+
vfsSnapshot (Just lspEnv) = LSP.runLspT lspEnv LSP.getVirtualFiles
326328

327329

328330
addIdeGlobal :: IsIdeGlobal a => a -> Rules ()
@@ -596,7 +598,7 @@ shakeOpen recorder lspEnv defaultConfig logger debouncer
596598

597599
dirtyKeys <- newTVarIO mempty
598600
-- Take one VFS snapshot at the start
599-
vfs <- atomically . newTVar =<< vfsSnapshot lspEnv
601+
vfs <- newTVarIO =<< vfsSnapshot lspEnv
600602
pure ShakeExtras{..}
601603
shakeDb <-
602604
shakeNewDatabase
@@ -683,7 +685,7 @@ shakeRestart recorder IdeState{..} reason acts =
683685
shakeSession
684686
(\runner -> do
685687
let log = logWith recorder
686-
(stopTime,()) <- duration (cancelShakeSession runner)
688+
(stopTime,()) <- duration $ logErrorAfter 10 recorder $ cancelShakeSession runner
687689
res <- shakeDatabaseProfile shakeDb
688690
backlog <- readTVarIO $ dirtyKeys shakeExtras
689691
queue <- atomicallyNamed "actionQueue - peek" $ peekInProgress $ actionQueue shakeExtras
@@ -706,6 +708,11 @@ shakeRestart recorder IdeState{..} reason acts =
706708
-- See https://github.com/haskell/ghcide/issues/79
707709
(\() -> do
708710
(,()) <$> newSession recorder shakeExtras shakeDb acts reason)
711+
where
712+
logErrorAfter :: Seconds -> Recorder (WithPriority Log) -> IO () -> IO ()
713+
logErrorAfter seconds recorder action = flip withAsync (const action) $ do
714+
sleep seconds
715+
logWith recorder Error (LogBuildSessionRestartTakingTooLong seconds)
709716

710717
notifyTestingLogMessage :: ShakeExtras -> T.Text -> IO ()
711718
notifyTestingLogMessage extras msg = do
@@ -1100,7 +1107,7 @@ defineEarlyCutoff' doDiagnostics cmp key file old mode action = do
11001107
-- No changes in the dependencies and we have
11011108
-- an existing successful result.
11021109
Just (v@(Succeeded _ x), diags) -> do
1103-
ver <- estimateFileVersionUnsafely state key (Just x) file
1110+
ver <- estimateFileVersionUnsafely key (Just x) file
11041111
doDiagnostics (vfsVersion =<< ver) $ Vector.toList diags
11051112
return $ Just $ RunResult ChangedNothing old $ A v
11061113
_ -> return Nothing
@@ -1121,7 +1128,7 @@ defineEarlyCutoff' doDiagnostics cmp key file old mode action = do
11211128
\(e :: SomeException) -> do
11221129
pure (Nothing, ([ideErrorText file $ T.pack $ show e | not $ isBadDependency e],Nothing))
11231130

1124-
ver <- estimateFileVersionUnsafely state key res file
1131+
ver <- estimateFileVersionUnsafely key res file
11251132
(bs, res) <- case res of
11261133
Nothing -> do
11271134
pure (toShakeValue ShakeStale bs, staleV)
@@ -1147,12 +1154,11 @@ defineEarlyCutoff' doDiagnostics cmp key file old mode action = do
11471154
estimateFileVersionUnsafely
11481155
:: forall k v
11491156
. IdeRule k v
1150-
=> Values
1151-
-> k
1157+
=> k
11521158
-> Maybe v
11531159
-> NormalizedFilePath
11541160
-> Action (Maybe FileVersion)
1155-
estimateFileVersionUnsafely state _k v fp
1161+
estimateFileVersionUnsafely _k v fp
11561162
| fp == emptyFilePath = pure Nothing
11571163
| Just Refl <- eqT @k @GetModificationTime = pure v
11581164
-- GetModificationTime depends on these rules, so avoid creating a cycle

hls-graph/src/Development/IDE/Graph/Internal/Database.hs

+46-19
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@
88
{-# LANGUAGE RecordWildCards #-}
99
{-# LANGUAGE ScopedTypeVariables #-}
1010
{-# LANGUAGE TypeFamilies #-}
11+
{-# LANGUAGE TupleSections #-}
1112

1213
module Development.IDE.Graph.Internal.Database (newDatabase, incDatabase, build, getDirtySet, getKeysAndVisitAge) where
1314

@@ -32,14 +33,15 @@ import Data.IORef.Extra
3233
import Data.Maybe
3334
import Data.Traversable (for)
3435
import Data.Tuple.Extra
36+
import Debug.Trace (traceM)
3537
import Development.IDE.Graph.Classes
3638
import Development.IDE.Graph.Internal.Rules
3739
import Development.IDE.Graph.Internal.Types
3840
import qualified Focus
3941
import qualified ListT
4042
import qualified StmContainers.Map as SMap
43+
import System.Time.Extra (duration, sleep)
4144
import System.IO.Unsafe
42-
import System.Time.Extra (duration)
4345

4446
newDatabase :: Dynamic -> TheRules -> IO Database
4547
newDatabase databaseExtra databaseRules = do
@@ -120,7 +122,7 @@ builder db@Database{..} stack keys = withRunInIO $ \(RunInIO run) -> do
120122
pure (id, val)
121123

122124
toForceList <- liftIO $ readTVarIO toForce
123-
let waitAll = run $ mapConcurrentlyAIO_ id toForceList
125+
let waitAll = run $ waitConcurrently_ toForceList
124126
case toForceList of
125127
[] -> return $ Left results
126128
_ -> return $ Right $ do
@@ -170,6 +172,10 @@ compute db@Database{..} stack key mode result = do
170172
deps | not(null deps)
171173
&& runChanged /= ChangedNothing
172174
-> do
175+
-- IMPORTANT: record the reverse deps **before** marking the key Clean.
176+
-- If an async exception strikes before the deps have been recorded,
177+
-- we won't be able to accurately propagate dirtiness for this key
178+
-- on the next build.
173179
void $
174180
updateReverseDeps key db
175181
(getResultDepsDefault [] previousDeps)
@@ -224,7 +230,8 @@ updateReverseDeps
224230
-> [Key] -- ^ Previous direct dependencies of Id
225231
-> HashSet Key -- ^ Current direct dependencies of Id
226232
-> IO ()
227-
updateReverseDeps myId db prev new = uninterruptibleMask_ $ do
233+
-- mask to ensure that all the reverse dependencies are updated
234+
updateReverseDeps myId db prev new = do
228235
forM_ prev $ \d ->
229236
unless (d `HSet.member` new) $
230237
doOne (HSet.delete myId) d
@@ -252,20 +259,27 @@ transitiveDirtySet database = flip State.execStateT HSet.empty . traverse_ loop
252259
next <- lift $ atomically $ getReverseDependencies database x
253260
traverse_ loop (maybe mempty HSet.toList next)
254261

255-
-- | IO extended to track created asyncs to clean them up when the thread is killed,
256-
-- generalizing 'withAsync'
262+
--------------------------------------------------------------------------------
263+
-- Asynchronous computations with cancellation
264+
265+
-- | A simple monad to implement cancellation on top of 'Async',
266+
-- generalizing 'withAsync' to monadic scopes.
257267
newtype AIO a = AIO { unAIO :: ReaderT (IORef [Async ()]) IO a }
258268
deriving newtype (Applicative, Functor, Monad, MonadIO)
259269

270+
-- | Run the monadic computation, cancelling all the spawned asyncs if an exception arises
260271
runAIO :: AIO a -> IO a
261272
runAIO (AIO act) = do
262273
asyncs <- newIORef []
263274
runReaderT act asyncs `onException` cleanupAsync asyncs
264275

276+
-- | Like 'async' but with built-in cancellation.
277+
-- Returns an IO action to wait on the result.
265278
asyncWithCleanUp :: AIO a -> AIO (IO a)
266279
asyncWithCleanUp act = do
267280
st <- AIO ask
268281
io <- unliftAIO act
282+
-- mask to make sure we keep track of the spawned async
269283
liftIO $ uninterruptibleMask $ \restore -> do
270284
a <- async $ restore io
271285
atomicModifyIORef'_ st (void a :)
@@ -284,27 +298,40 @@ withRunInIO k = do
284298
k $ RunInIO (\aio -> runReaderT (unAIO aio) st)
285299

286300
cleanupAsync :: IORef [Async a] -> IO ()
287-
cleanupAsync ref = uninterruptibleMask_ $ do
288-
asyncs <- readIORef ref
301+
-- mask to make sure we interrupt all the asyncs
302+
cleanupAsync ref = uninterruptibleMask $ \unmask -> do
303+
asyncs <- atomicModifyIORef' ref ([],)
304+
-- interrupt all the asyncs without waiting
289305
mapM_ (\a -> throwTo (asyncThreadId a) AsyncCancelled) asyncs
290-
mapM_ waitCatch asyncs
306+
-- Wait until all the asyncs are done
307+
-- But if it takes more than 10 seconds, log to stderr
308+
unless (null asyncs) $ do
309+
let warnIfTakingTooLong = unmask $ forever $ do
310+
sleep 10
311+
traceM "cleanupAsync: waiting for asyncs to finish"
312+
withAsync warnIfTakingTooLong $ \_ ->
313+
mapM_ waitCatch asyncs
314+
315+
data Wait
316+
= Wait {justWait :: !(IO ())}
317+
| Spawn {justWait :: !(IO ())}
291318

292-
data Wait a
293-
= Wait {justWait :: !a}
294-
| Spawn {justWait :: !a}
295-
deriving Functor
319+
fmapWait :: (IO () -> IO ()) -> Wait -> Wait
320+
fmapWait f (Wait io) = Wait (f io)
321+
fmapWait f (Spawn io) = Spawn (f io)
296322

297-
waitOrSpawn :: Wait (IO a) -> IO (Either (IO a) (Async a))
323+
waitOrSpawn :: Wait -> IO (Either (IO ()) (Async ()))
298324
waitOrSpawn (Wait io) = pure $ Left io
299325
waitOrSpawn (Spawn io) = Right <$> async io
300326

301-
mapConcurrentlyAIO_ :: (a -> IO ()) -> [Wait a] -> AIO ()
302-
mapConcurrentlyAIO_ _ [] = pure ()
303-
mapConcurrentlyAIO_ f [one] = liftIO $ justWait $ fmap f one
304-
mapConcurrentlyAIO_ f many = do
327+
waitConcurrently_ :: [Wait] -> AIO ()
328+
waitConcurrently_ [] = pure ()
329+
waitConcurrently_ [one] = liftIO $ justWait one
330+
waitConcurrently_ many = do
305331
ref <- AIO ask
306-
waits <- liftIO $ uninterruptibleMask $ \restore -> do
307-
waits <- liftIO $ traverse (waitOrSpawn . fmap (restore . f)) many
332+
-- mask to make sure we keep track of all the asyncs
333+
waits <- liftIO $ uninterruptibleMask $ \unmask -> do
334+
waits <- liftIO $ traverse (waitOrSpawn . fmapWait unmask) many
308335
let asyncs = rights waits
309336
liftIO $ atomicModifyIORef'_ ref (asyncs ++)
310337
return waits

0 commit comments

Comments
 (0)