diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 99c42eda4..cb47a89f7 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -122,6 +122,7 @@ jobs: --project-file="${{ matrix.cabal-project-file || env.DEFAULT_CABAL_PROJECT_FILE }}" - name: ๐Ÿงช Test + id: test if: ${{ !matrix.cabal-skip-tests }} run: | cabal test all \ @@ -131,6 +132,19 @@ jobs: env: TASTY_TIMEOUT: "5m" + # Golden test output is not printed to the screen, so if a golden test fails + # then it is not clear from the logs why the test fails. Uploading the + # directory containing the golden files after running the goldens tests + # allows us to diff the expected and actual golden file contents. + - name: ๐Ÿ“ฆ Upload golden files + if: ${{ !matrix.cabal-skip-tests && steps.test.outcome != 'success' && always() }} + uses: actions/upload-artifact@v4 + with: + name: golden-files-${{ runner.os }}-ghc-${{ steps.setup-haskell.outputs.ghc-version }}-cabal-${{ steps.setup-haskell.outputs.cabal-version }}-plan-${{ hashFiles('dist-newstyle/cache/plan.json') }} + path: test/golden-file-data + if-no-files-found: error + retention-days: 1 + - name: ๐Ÿ› ๏ธ Setup cabal-docspec (Linux) if: ${{ !matrix.cabal-skip-tests && runner.os == 'Linux' }} uses: ./.github/actions/setup-cabal-docspec diff --git a/lsm-tree.cabal b/lsm-tree.cabal index 892abff25..0bec61f59 100644 --- a/lsm-tree.cabal +++ b/lsm-tree.cabal @@ -811,6 +811,7 @@ test-suite lsm-tree-test Test.Database.LSMTree.StateMachine Test.Database.LSMTree.StateMachine.DL Test.Database.LSMTree.StateMachine.Op + Test.Database.LSMTree.Tracer.Golden Test.Database.LSMTree.UnitTests Test.FS Test.Util.Arbitrary diff --git a/src/Database/LSMTree.hs b/src/Database/LSMTree.hs index 04cd1c412..51097b4cc 100644 --- a/src/Database/LSMTree.hs +++ b/src/Database/LSMTree.hs @@ -175,11 +175,13 @@ module Database.LSMTree ( -- * Traces #traces# Tracer, LSMTreeTrace (..), + SessionTrace (..), TableTrace (..), CursorTrace (..), MergeTrace (..), - CursorId (..), + SessionId (..), TableId (..), + CursorId (..), AtLevel (..), LevelNo (..), NumEntries (..), @@ -251,7 +253,8 @@ import Database.LSMTree.Internal.Unsafe (BlobRefInvalidError (..), ResolveSerialisedValue, SessionClosedError (..), SessionDirCorruptedError (..), SessionDirDoesNotExistError (..), - SessionDirLockedError (..), SnapshotCorruptedError (..), + SessionDirLockedError (..), SessionId (..), + SessionTrace (..), SnapshotCorruptedError (..), SnapshotDoesNotExistError (..), SnapshotExistsError (..), SnapshotNotCompatibleError (..), TableClosedError (..), TableCorruptedError (..), TableTooLargeError (..), diff --git a/src/Database/LSMTree/Internal/RunReader.hs b/src/Database/LSMTree/Internal/RunReader.hs index ad44106fb..0dfa97190 100644 --- a/src/Database/LSMTree/Internal/RunReader.hs +++ b/src/Database/LSMTree/Internal/RunReader.hs @@ -90,6 +90,7 @@ data RunReader m h = RunReader { } data OffsetKey = NoOffsetKey | OffsetKey !SerialisedKey + deriving stock Show {-# SPECIALISE new :: OffsetKey diff --git a/src/Database/LSMTree/Internal/UniqCounter.hs b/src/Database/LSMTree/Internal/UniqCounter.hs index 481b40b66..e927ca8ed 100644 --- a/src/Database/LSMTree/Internal/UniqCounter.hs +++ b/src/Database/LSMTree/Internal/UniqCounter.hs @@ -11,6 +11,7 @@ module Database.LSMTree.Internal.UniqCounter ( uniqueToCursorId, ) where +import Control.DeepSeq (NFData (..)) import Control.Monad.Primitive (PrimMonad, PrimState) import Data.Primitive.PrimVar as P import Database.LSMTree.Internal.RunNumber @@ -35,6 +36,9 @@ uniqueToCursorId (Unique n) = CursorId n -- newtype UniqCounter m = UniqCounter (PrimVar (PrimState m) Int) +instance NFData (UniqCounter m) where + rnf (UniqCounter (P.PrimVar mba)) = rnf mba + {-# INLINE newUniqCounter #-} newUniqCounter :: PrimMonad m => Int -> m (UniqCounter m) newUniqCounter = fmap UniqCounter . P.newPrimVar diff --git a/src/Database/LSMTree/Internal/Unsafe.hs b/src/Database/LSMTree/Internal/Unsafe.hs index 0ab05717d..86371587c 100644 --- a/src/Database/LSMTree/Internal/Unsafe.hs +++ b/src/Database/LSMTree/Internal/Unsafe.hs @@ -29,7 +29,10 @@ module Database.LSMTree.Internal.Unsafe ( , FileCorruptedError (..) , Paths.InvalidSnapshotNameError (..) -- * Tracing + -- $traces , LSMTreeTrace (..) + , SessionId (..) + , SessionTrace (..) , TableTrace (..) , CursorTrace (..) -- * Session @@ -151,46 +154,156 @@ import System.FS.BlockIO.API (HasBlockIO) Traces -------------------------------------------------------------------------------} +{- $traces + + Trace messages are divided into three categories for each type of resource: + sessions, tables, and cursors. The trace messages are structured so that: + + 1. Resources have (unique) identifiers, and these are included in each + message. + + 2. Operations that modify, create, or close resources trace a start and end + message. The reasoning here is that it's useful for troubleshooting + purposes to know not only that an operation started but also that it ended. + To an extent this would also be useful for read-only operations like + lookups, but since read-only operations do not modify resources, we've left + out end messages for those. They could be added if asked for by users. + + 3. When we are in the process of creating a new resource from existing + resources, then the /child/ resource traces the identifier(s) of its + /parent/ resource(s). + + These properties ensure that troubleshooting using tracers in a concurrent + setting is possible. Messages can be interleaved, so it's important to find + meaningful pairings of messages, like 'TraceCloseTable' and + 'TraceClosedTable'. +-} + data LSMTreeTrace = - -- Session - TraceOpenSession FsPath + -- | Trace messages related to sessions. + TraceSession + -- | Sessions are identified by the path to their root directory. + SessionId + SessionTrace + + -- | Trace messages related to tables. + | TraceTable + -- | Tables are identified by a unique number. + TableId + TableTrace + + -- | Trace messages related to cursors. + | TraceCursor + -- | Cursors are identified by a unique number. + CursorId + CursorTrace + deriving stock Show + +-- | Sessions are identified by the path to their root directory. +newtype SessionId = SessionId FsPath + deriving stock (Eq, Show) + +-- | Trace messages related to sessions. +data SessionTrace = + -- | We are opening a session in the requested session directory. A + -- 'TraceNewSession'\/'TraceRestoreSession' and 'TraceOpenedSession' message + -- should follow if succesful. + TraceOpenSession + -- | The requested session directory is empty, so we are creating a new, + -- fresh session. | TraceNewSession + -- | The requested session directory is non-empty, so we are restoring a + -- session from the directory contents. | TraceRestoreSession + -- | Opening a session was successful. + | TraceOpenedSession + + -- | We are closing the session. A 'TraceClosedSession' message should + -- follow if succesful. | TraceCloseSession - -- Table - | TraceNewTable - | TraceOpenTableFromSnapshot SnapshotName OverrideDiskCachePolicy - | TraceTable TableId TableTrace + -- | Closing the session was successful. + | TraceClosedSession + + -- | We are deleting the snapshot with the given name. A + -- 'TraceDeletedSnapshot' message should follow if succesful. | TraceDeleteSnapshot SnapshotName + -- | We have successfully deleted the snapshot with the given name. + | TraceDeletedSnapshot SnapshotName + -- | We are listing snapshots. | TraceListSnapshots - -- Cursor - | TraceCursor CursorId CursorTrace - -- Unions - | TraceUnions (NonEmpty TableId) + + -- | We are retrieving blobs. + | TraceRetrieveBlobs Int deriving stock Show +-- | Trace messages related to tables. data TableTrace = - -- | A table is created with the specified config. - -- - -- This message is traced in addition to messages like 'TraceNewTable' and - -- 'TraceDuplicate'. - TraceCreateTable TableConfig + -- | A table has been successfully created with the specified config. + TraceCreatedTable + -- | The parent session + SessionId + TableConfig + -- | We are creating a new, fresh table with the specified config. A + -- 'TraceCreatedTable' message should follow if successful. + | TraceNewTable TableConfig + -- | We are closing the table. A 'TraceClosedTable' message should follow if + -- successful. + | TraceCloseTable - -- Lookups - | TraceLookups Int + -- | Closing the table was succesful. + | TraceClosedTable + -- | We are performing a batch of lookups. + + | TraceLookups + -- | The number of keys that are looked up. + Int + -- | We are performing a range lookup. | TraceRangeLookup (Range SerialisedKey) - -- Updates - | TraceUpdates Int -#ifdef DEBUG_TRACES - | TraceMerge (AtLevel MergeTrace) -#endif - -- Snapshot - | TraceSnapshot SnapshotName - -- Duplicate + -- | We are performing a batch of updates. + | TraceUpdates + -- | The number of keys will be updated. + Int + -- | We have successfully performed a batch of updates. + | TraceUpdated + -- | The number of keys that are updated. + Int + + -- | We are opening a table from a snapshot. A 'TraceCreatedTable' message + -- should follow if successful. + | TraceOpenTableFromSnapshot SnapshotName OverrideDiskCachePolicy + -- | We are saving a snapshot with the given name. A 'TraceSavedSnapshot' + -- message should follow if successful. + | TraceSaveSnapshot SnapshotName + -- | A snapshot with the given name was saved successfully. + | TraceSavedSnapshot SnapshotName + + -- | We are creating a duplicate of a table. A 'TraceCreatedTable' message + -- should follow if successful. | TraceDuplicate - -- Unions + -- | The parent table + TableId + + -- | We are creating an incremental union of a list of tables. A + -- 'TraceCreatedTable' message should follow if successful. + | TraceIncrementalUnions + -- | Unique identifiers for the tables that are used as inputs to the + -- union. + (NonEmpty TableId) + -- | We are querying the remaining union debt. | TraceRemainingUnionDebt + -- | We are supplying the given number of union credits. | TraceSupplyUnionCredits UnionCredits + -- | We have supplied union credits. + | TraceSuppliedUnionCredits + -- | The number of input credits to supply. + UnionCredits + -- | Leftover credits. + UnionCredits + +#ifdef DEBUG_TRACES + -- | INTERNAL: debug traces for the merge schedule + | TraceMerge (AtLevel MergeTrace) +#endif deriving stock Show contramapTraceMerge :: Monad m => Tracer m TableTrace -> Tracer m (AtLevel MergeTrace) @@ -200,10 +313,36 @@ contramapTraceMerge t = TraceMerge `contramap` t contramapTraceMerge t = traceMaybe (const Nothing) t #endif +-- | Trace messages related to cursors. data CursorTrace = - TraceCreateCursor TableId + -- | A cursor has been successfully created. + TraceCreatedCursor + -- | The parent session + SessionId + -- | We are creating a new, fresh cursor positioned at the given offset key. + -- A 'TraceCreatedCursor' message should follow if successful. + | TraceNewCursor + -- | The parent table + TableId + OffsetKey + + -- | We are closing the cursor. A 'TraceClosedCursor' message should follow + -- if successful. | TraceCloseCursor - | TraceReadCursor Int + -- | Closing the cursor was succesful. + | TraceClosedCursor + + -- | We are reading from the cursor. A 'TraceReadCursor' message should + -- follow if successful. + | TraceReadingCursor + -- | Requested number of entries to read at most. + Int + -- | We have succesfully read from the cursor. + | TraceReadCursor + -- | Requested number of entries to read at most. + Int + -- | Actual number of entries read. + Int deriving stock Show {------------------------------------------------------------------------------- @@ -222,12 +361,20 @@ data Session m h = Session { -- -- INVARIANT: once the session state is changed from 'SessionOpen' to -- 'SessionClosed', it is never changed back to 'SessionOpen' again. - sessionState :: !(RWVar m (SessionState m h)) - , sessionTracer :: !(Tracer m LSMTreeTrace) + sessionState :: !(RWVar m (SessionState m h)) + , lsmTreeTracer :: !(Tracer m LSMTreeTrace) + , sessionTracer :: !(Tracer m SessionTrace) + + -- | A session-wide shared, atomic counter that is used to produce unique + -- names, for example: run names, table IDs. + -- + -- This counter lives in 'Session' instead of 'SessionEnv' because it is an + -- atomic counter, and so does not need to be guarded by a lock. + , sessionUniqCounter :: !(UniqCounter m) } instance NFData (Session m h) where - rnf (Session a b) = rnf a `seq` rwhnf b + rnf (Session a b c d) = rnf a `seq` rwhnf b `seq` rwhnf c `seq` rnf d data SessionState m h = SessionOpen !(SessionEnv m h) @@ -243,9 +390,6 @@ data SessionEnv m h = SessionEnv { , sessionHasFS :: !(HasFS m h) , sessionHasBlockIO :: !(HasBlockIO m h) , sessionLockFile :: !(FS.LockFileHandle m) - -- | A session-wide shared, atomic counter that is used to produce unique - -- names, for example: run names, table IDs. - , sessionUniqCounter :: !(UniqCounter m) -- | Open tables are tracked here so they can be closed once the session is -- closed. Tables also become untracked when they are closed manually. -- @@ -267,6 +411,10 @@ data SessionEnv m h = SessionEnv { , sessionOpenCursors :: !(StrictMVar m (Map CursorId (Cursor m h))) } +{-# INLINE sessionId #-} +sessionId :: SessionEnv m h -> SessionId +sessionId = SessionId . getSessionRoot . sessionRoot + -- | The session is closed. data SessionClosedError = ErrSessionClosed @@ -346,13 +494,13 @@ openSession :: -> HasBlockIO m h -- TODO: could we prevent the user from having to pass this in? -> FsPath -- ^ Path to the session directory -> m (Session m h) -openSession tr hfs hbio dir = +openSession tr hfs hbio dir = do + traceWith sessionTracer TraceOpenSession -- We can not use modifyWithActionRegistry here, since there is no in-memory -- state to modify. We use withActionRegistry instead, which may have a tiny -- chance of leaking resources if openSession is not called in a masked -- state. withActionRegistry $ \reg -> do - traceWith tr (TraceOpenSession dir) dirExists <- FS.doesDirectoryExist hfs dir unless dirExists $ throwIO (ErrSessionDirDoesNotExist (FS.mkFsErrorPath hfs dir)) @@ -382,6 +530,8 @@ openSession tr hfs hbio dir = if Set.null dirContents then newSession reg sessionFileLock else restoreSession reg sessionFileLock where + sessionTracer = TraceSession (SessionId dir) `contramap` tr + root = Paths.SessionRoot dir lockFilePath = Paths.lockFile root activeDirPath = Paths.getActiveDir (Paths.activeDir root) @@ -391,7 +541,7 @@ openSession tr hfs hbio dir = releaseLock = FS.hUnlock - mkSession lockFile = do + mkSession reg lockFile = do counterVar <- newUniqCounter 0 openTablesVar <- newMVar Map.empty openCursorsVar <- newMVar Map.empty @@ -400,24 +550,34 @@ openSession tr hfs hbio dir = , sessionHasFS = hfs , sessionHasBlockIO = hbio , sessionLockFile = lockFile - , sessionUniqCounter = counterVar , sessionOpenTables = openTablesVar , sessionOpenCursors = openCursorsVar } - pure $! Session sessionVar tr + + -- Note: we're "abusing" the action registry to trace the success + -- message as late as possible. + delayedCommit reg $ + traceWith sessionTracer TraceOpenedSession + + pure $! Session { + sessionState = sessionVar + , lsmTreeTracer = tr + , sessionTracer + , sessionUniqCounter = counterVar + } newSession reg sessionFileLock = do - traceWith tr TraceNewSession + traceWith sessionTracer TraceNewSession withRollback_ reg (FS.createDirectory hfs activeDirPath) (FS.removeDirectoryRecursive hfs activeDirPath) withRollback_ reg (FS.createDirectory hfs snapshotsDirPath) (FS.removeDirectoryRecursive hfs snapshotsDirPath) - mkSession sessionFileLock + mkSession reg sessionFileLock - restoreSession _reg sessionFileLock = do - traceWith tr TraceRestoreSession + restoreSession reg sessionFileLock = do + traceWith sessionTracer TraceRestoreSession -- If the layouts are wrong, we throw an exception checkTopLevelDirLayout @@ -428,7 +588,7 @@ openSession tr hfs hbio dir = checkActiveDirLayout checkSnapshotsDirLayout - mkSession sessionFileLock + mkSession reg sessionFileLock -- Check that the active directory and snapshots directory exist. We assume -- the lock file already exists at this point. @@ -500,6 +660,10 @@ closeSession Session{sessionState, sessionTracer} = do delayedCommit reg $ FS.close (sessionHasBlockIO seshEnv) delayedCommit reg $ FS.hUnlock (sessionLockFile seshEnv) + -- Note: we're "abusing" the action registry to trace the success + -- message as late as possible. + delayedCommit reg $ traceWith sessionTracer TraceClosedSession + pure SessionClosed {------------------------------------------------------------------------------- @@ -568,6 +732,11 @@ data TableEnv m h = TableEnv { tableSessionRoot :: TableEnv m h -> SessionRoot tableSessionRoot = sessionRoot . tableSessionEnv +{-# INLINE tableSessionId #-} + -- | Inherited from session for ease of access. +tableSessionId :: TableEnv m h -> SessionId +tableSessionId = sessionId . tableSessionEnv + {-# INLINE tableHasFS #-} -- | Inherited from session for ease of access. tableHasFS :: TableEnv m h -> HasFS m h @@ -580,8 +749,8 @@ tableHasBlockIO = sessionHasBlockIO . tableSessionEnv {-# INLINE tableSessionUniqCounter #-} -- | Inherited from session for ease of access. -tableSessionUniqCounter :: TableEnv m h -> UniqCounter m -tableSessionUniqCounter = sessionUniqCounter . tableSessionEnv +tableSessionUniqCounter :: Table m h -> UniqCounter m +tableSessionUniqCounter = sessionUniqCounter . tableSession {-# INLINE tableSessionUntrackTable #-} {-# SPECIALISE tableSessionUntrackTable :: TableId -> TableEnv IO h -> IO () #-} @@ -644,25 +813,30 @@ new :: -> TableConfig -> m (Table m h) new sesh conf = do - traceWith (sessionTracer sesh) TraceNewTable + tableId <- uniqueToTableId <$> incrUniqCounter (sessionUniqCounter sesh) + let tr = TraceTable tableId `contramap` lsmTreeTracer sesh + traceWith tr $ TraceNewTable conf + withOpenSession sesh $ \seshEnv -> withActionRegistry $ \reg -> do am <- newArenaManager - tc <- newEmptyTableContent seshEnv reg - newWith reg sesh seshEnv conf am tc + tc <- newEmptyTableContent (sessionUniqCounter sesh) seshEnv reg + newWith reg sesh seshEnv conf am tr tableId tc {-# SPECIALISE newEmptyTableContent :: - SessionEnv IO h + UniqCounter IO + -> SessionEnv IO h -> ActionRegistry IO -> IO (TableContent IO h) #-} newEmptyTableContent :: (PrimMonad m, MonadMask m, MonadMVar m) - => SessionEnv m h + => UniqCounter m + -> SessionEnv m h -> ActionRegistry m -> m (TableContent m h) -newEmptyTableContent seshEnv reg = do +newEmptyTableContent uc seshEnv reg = do blobpath <- Paths.tableBlobPath (sessionRoot seshEnv) <$> - incrUniqCounter (sessionUniqCounter seshEnv) + incrUniqCounter uc let tableWriteBuffer = WB.empty tableWriteBufferBlobs <- withRollback reg @@ -685,6 +859,8 @@ newEmptyTableContent seshEnv reg = do -> SessionEnv IO h -> TableConfig -> ArenaManager RealWorld + -> Tracer IO TableTrace + -> TableId -> TableContent IO h -> IO (Table IO h) #-} newWith :: @@ -694,12 +870,11 @@ newWith :: -> SessionEnv m h -> TableConfig -> ArenaManager (PrimState m) + -> Tracer m TableTrace + -> TableId -> TableContent m h -> m (Table m h) -newWith reg sesh seshEnv conf !am !tc = do - tableId <- uniqueToTableId <$> incrUniqCounter (sessionUniqCounter seshEnv) - let tr = TraceTable tableId `contramap` sessionTracer sesh - traceWith tr $ TraceCreateTable conf +newWith reg sesh seshEnv conf !am !tr !tableId !tc = do -- The session is kept open until we've updated the session's set of tracked -- tables. If 'closeSession' is called by another thread while this code -- block is being executed, that thread will block until it reads the @@ -714,6 +889,12 @@ newWith reg sesh seshEnv conf !am !tc = do delayedCommit reg $ modifyMVar_ (sessionOpenTables seshEnv) $ pure . Map.insert tableId t + + -- Note: we're "abusing" the action registry to trace the success + -- message as late as possible. + delayedCommit reg $ + traceWith tr $ TraceCreatedTable (sessionId seshEnv) conf + pure $! t {-# SPECIALISE close :: Table IO h -> IO () #-} @@ -736,6 +917,12 @@ close t = do RW.withWriteAccess_ (tableContent tEnv) $ \tc -> do releaseTableContent reg tc pure tc + + -- Note: we're "abusing" the action registry to trace the success + -- message as late as possible. + delayedCommit reg $ + traceWith (tableTracer t) TraceClosedTable + pure TableClosed {-# SPECIALISE lookups :: @@ -866,17 +1053,26 @@ updates resolve es t = do let hfs = tableHasFS tEnv modifyWithActionRegistry_ (RW.unsafeAcquireWriteAccess (tableContent tEnv)) - (atomically . RW.unsafeReleaseWriteAccess (tableContent tEnv)) $ \reg -> do - updatesWithInterleavedFlushes - (contramapTraceMerge $ tableTracer t) - conf - resolve - hfs - (tableHasBlockIO tEnv) - (tableSessionRoot tEnv) - (tableSessionUniqCounter tEnv) - es - reg + (atomically . RW.unsafeReleaseWriteAccess (tableContent tEnv)) $ \reg tc -> do + tc' <- + updatesWithInterleavedFlushes + (contramapTraceMerge $ tableTracer t) + conf + resolve + hfs + (tableHasBlockIO tEnv) + (tableSessionRoot tEnv) + (tableSessionUniqCounter t) + es + reg + tc + + -- Note: we're "abusing" the action registry to trace the success + -- message as late as possible. + delayedCommit reg $ + traceWith (tableTracer t) $ TraceUpdated (V.length es) + + pure tc' {------------------------------------------------------------------------------- Blobs @@ -906,7 +1102,8 @@ retrieveBlobs :: => Session m h -> V.Vector (WeakBlobRef m h) -> m (V.Vector SerialisedBlob) -retrieveBlobs sesh wrefs = +retrieveBlobs sesh wrefs = do + traceWith (sessionTracer sesh) $ TraceRetrieveBlobs (V.length wrefs) withOpenSession sesh $ \seshEnv -> let hbio = sessionHasBlockIO seshEnv in handle (\(BlobRef.WeakBlobRefInvalid i) -> @@ -1017,9 +1214,9 @@ newCursor !resolve !offsetKey t = withOpenTable t $ \tEnv -> do let cursorSession = tableSession t let cursorSessionEnv = tableSessionEnv tEnv cursorId <- uniqueToCursorId <$> - incrUniqCounter (sessionUniqCounter cursorSessionEnv) - let cursorTracer = TraceCursor cursorId `contramap` sessionTracer cursorSession - traceWith cursorTracer $ TraceCreateCursor (tableId t) + incrUniqCounter (tableSessionUniqCounter t) + let cursorTracer = TraceCursor cursorId `contramap` lsmTreeTracer cursorSession + traceWith cursorTracer $ TraceNewCursor (tableId t) offsetKey -- We acquire a read-lock on the session open-state to prevent races, see -- 'sessionOpenTables'. @@ -1049,6 +1246,12 @@ newCursor !resolve !offsetKey t = withOpenTable t $ \tEnv -> do delayedCommit reg $ modifyMVar_ (sessionOpenCursors cursorSessionEnv) $ pure . Map.insert cursorId cursor + + -- Note: we're "abusing" the action registry to trace the success + -- message as late as possible. + delayedCommit reg $ + traceWith cursorTracer $ TraceCreatedCursor (tableSessionId tEnv) + pure $! cursor where -- The table contents escape the read access, but we just duplicate @@ -1105,6 +1308,12 @@ closeCursor Cursor {..} = do V.forM_ cursorRuns $ delayedCommit reg . releaseRef forM_ cursorUnion $ releaseUnionCache reg delayedCommit reg (releaseRef cursorWBB) + + -- Note: we're "abusing" the action registry to trace the success + -- message as late as possible. + delayedCommit reg $ + traceWith cursorTracer $ TraceClosedCursor + pure CursorClosed {-# SPECIALISE readCursor :: @@ -1158,8 +1367,8 @@ readCursorWhile :: -- ^ How to map to a query result -> m (V.Vector res) readCursorWhile resolve keyIsWanted n Cursor {..} fromEntry = do - traceWith cursorTracer $ TraceReadCursor n - modifyMVar cursorState $ \case + traceWith cursorTracer $ TraceReadingCursor n + res <- modifyMVar cursorState $ \case CursorClosed -> throwIO ErrCursorClosed state@(CursorOpen cursorEnv) -> do case cursorReaders cursorEnv of @@ -1174,6 +1383,10 @@ readCursorWhile resolve keyIsWanted n Cursor {..} fromEntry = do Readers.Drained -> CursorOpen (cursorEnv {cursorReaders = Nothing}) pure (state', vec) + traceWith cursorTracer $ TraceReadCursor n (V.length res) + + pure res + {------------------------------------------------------------------------------- Snapshots -------------------------------------------------------------------------------} @@ -1197,12 +1410,12 @@ saveSnapshot :: -> Table m h -> m () saveSnapshot snap label t = do - traceWith (tableTracer t) $ TraceSnapshot snap + traceWith (tableTracer t) $ TraceSaveSnapshot snap withOpenTable t $ \tEnv -> withActionRegistry $ \reg -> do -- TODO: use the action registry for all side effects let hfs = tableHasFS tEnv hbio = tableHasBlockIO tEnv - activeUc = tableSessionUniqCounter tEnv + activeUc = tableSessionUniqCounter t -- Guard that the snapshot does not exist already let snapDir = Paths.namedSnapshotDir (tableSessionRoot tEnv) snap @@ -1260,6 +1473,11 @@ saveSnapshot snap label t = do -- Make the directory and its contents durable. FS.synchroniseDirectoryRecursive hfs hbio (Paths.getNamedSnapshotDir snapDir) + -- Note: we're "abusing" the action registry to trace the success + -- message as late as possible. + delayedCommit reg $ + traceWith (tableTracer t) $ TraceSavedSnapshot snap + -- | The named snapshot does not exist. data SnapshotDoesNotExistError = ErrSnapshotDoesNotExist !SnapshotName @@ -1302,14 +1520,17 @@ openTableFromSnapshot :: -> SnapshotLabel -- ^ Expected label -> ResolveSerialisedValue -> m (Table m h) -openTableFromSnapshot policyOveride sesh snap label resolve = +openTableFromSnapshot policyOveride sesh snap label resolve = do + tableId <- uniqueToTableId <$> incrUniqCounter (sessionUniqCounter sesh) + let tr = TraceTable tableId `contramap` lsmTreeTracer sesh + traceWith tr $ TraceOpenTableFromSnapshot snap policyOveride + wrapFileCorruptedErrorAsSnapshotCorruptedError snap $ do - traceWith (sessionTracer sesh) $ TraceOpenTableFromSnapshot snap policyOveride withOpenSession sesh $ \seshEnv -> do withActionRegistry $ \reg -> do let hfs = sessionHasFS seshEnv hbio = sessionHasBlockIO seshEnv - uc = sessionUniqCounter seshEnv + uc = sessionUniqCounter sesh -- Guard that the snapshot exists let snapDir = Paths.namedSnapshotDir (sessionRoot seshEnv) snap @@ -1356,7 +1577,7 @@ openTableFromSnapshot policyOveride sesh snap label resolve = traverse_ (delayedCommit reg . releaseRef) snapLevels' tableCache <- mkLevelsCache reg tableLevels - newWith reg sesh seshEnv conf am $! TableContent { + newWith reg sesh seshEnv conf am tr tableId $! TableContent { tableWriteBuffer , tableWriteBufferBlobs , tableLevels @@ -1413,6 +1634,7 @@ deleteSnapshot sesh snap = do snapshotExists <- doesSnapshotDirExist snap seshEnv unless snapshotExists $ throwIO (ErrSnapshotDoesNotExist snap) FS.removeDirectoryRecursive (sessionHasFS seshEnv) (Paths.getNamedSnapshotDir snapDir) + traceWith (sessionTracer sesh) $ TraceDeletedSnapshot snap {-# SPECIALISE listSnapshots :: Session IO h -> IO [SnapshotName] #-} -- | See 'Database.LSMTree.listSnapshots'. @@ -1449,7 +1671,11 @@ duplicate :: => Table m h -> m (Table m h) duplicate t@Table{..} = do - traceWith tableTracer TraceDuplicate + childTableId <- uniqueToTableId <$> incrUniqCounter (tableSessionUniqCounter t) + let childTableTracer = TraceTable childTableId `contramap` lsmTreeTracer tableSession + parentTableId = tableId + traceWith childTableTracer $ TraceDuplicate parentTableId + withOpenTable t $ \TableEnv{..} -> do -- We acquire a read-lock on the session open-state to prevent races, see -- 'sessionOpenTables'. @@ -1464,6 +1690,8 @@ duplicate t@Table{..} = do tableSessionEnv tableConfig tableArenaManager + childTableTracer + childTableId content {------------------------------------------------------------------------------- @@ -1502,7 +1730,9 @@ unions :: unions ts = do sesh <- ensureSessionsMatch ts - traceWith (sessionTracer sesh) $ TraceUnions (NE.map tableId ts) + childTableId <- uniqueToTableId <$> incrUniqCounter (sessionUniqCounter sesh) + let childTableTracer = TraceTable childTableId `contramap` lsmTreeTracer sesh + traceWith childTableTracer $ TraceIncrementalUnions (NE.map tableId ts) -- The TableConfig for the new table is taken from the last table in the -- union. This corresponds to the "Data.Map.union updates baseMap" order, @@ -1523,7 +1753,7 @@ unions ts = do \reg -> \case SessionClosed -> throwIO ErrSessionClosed seshState@(SessionOpen seshEnv) -> do - t <- unionsInOpenSession reg sesh seshEnv conf ts + t <- unionsInOpenSession reg sesh seshEnv conf childTableTracer childTableId ts pure (seshState, t) {-# SPECIALISE unionsInOpenSession :: @@ -1531,6 +1761,8 @@ unions ts = do -> Session IO h -> SessionEnv IO h -> TableConfig + -> Tracer IO TableTrace + -> TableId -> NonEmpty (Table IO h) -> IO (Table IO h) #-} unionsInOpenSession :: @@ -1539,9 +1771,11 @@ unionsInOpenSession :: -> Session m h -> SessionEnv m h -> TableConfig + -> Tracer m TableTrace + -> TableId -> NonEmpty (Table m h) -> m (Table m h) -unionsInOpenSession reg sesh seshEnv conf ts = do +unionsInOpenSession reg sesh seshEnv conf tr !tableId ts = do mts <- forM (NE.toList ts) $ \t -> withOpenTable t $ \tEnv -> RW.withReadAccess (tableContent tEnv) $ \tc -> @@ -1549,7 +1783,7 @@ unionsInOpenSession reg sesh seshEnv conf ts = do -- so the ones from the tableContent here do not escape -- the read access. withRollback reg - (tableContentToMergingTree seshEnv conf tc) + (tableContentToMergingTree (sessionUniqCounter sesh) seshEnv conf tc) releaseRef mt <- withRollback reg (newPendingUnionMerge mts) releaseRef @@ -1562,9 +1796,9 @@ unionsInOpenSession reg sesh seshEnv conf ts = do True -> do -- no need to have an empty merging tree delayedCommit reg (releaseRef mt) - newEmptyTableContent seshEnv reg + newEmptyTableContent ((sessionUniqCounter sesh)) seshEnv reg False -> do - empty <- newEmptyTableContent seshEnv reg + empty <- newEmptyTableContent (sessionUniqCounter sesh) seshEnv reg cache <- mkUnionCache reg mt pure empty { tableUnionLevel = Union mt cache } @@ -1573,26 +1807,28 @@ unionsInOpenSession reg sesh seshEnv conf ts = do -- by reusing the arena manager from the last one. let am = tableArenaManager (NE.last ts) - newWith reg sesh seshEnv conf am content + newWith reg sesh seshEnv conf am tr tableId content {-# SPECIALISE tableContentToMergingTree :: - SessionEnv IO h + UniqCounter IO + -> SessionEnv IO h -> TableConfig -> TableContent IO h -> IO (Ref (MergingTree IO h)) #-} tableContentToMergingTree :: forall m h. (MonadMask m, MonadMVar m, MonadST m, MonadSTM m) - => SessionEnv m h + => UniqCounter m + -> SessionEnv m h -> TableConfig -> TableContent m h -> m (Ref (MergingTree m h)) -tableContentToMergingTree seshEnv conf +tableContentToMergingTree uc seshEnv conf tc@TableContent { tableLevels, tableUnionLevel } = - bracket (writeBufferToNewRun seshEnv conf tc) + bracket (writeBufferToNewRun uc seshEnv conf tc) (mapM_ releaseRef) $ \mwbr -> let runs :: [PreExistingRun m h] runs = maybeToList (fmap PreExistingRun mwbr) @@ -1613,21 +1849,23 @@ tableContentToMergingTree seshEnv conf --TODO: can we share this or move it to MergeSchedule? {-# SPECIALISE writeBufferToNewRun :: - SessionEnv IO h + UniqCounter IO + -> SessionEnv IO h -> TableConfig -> TableContent IO h -> IO (Maybe (Ref (Run IO h))) #-} writeBufferToNewRun :: (MonadMask m, MonadST m, MonadSTM m) - => SessionEnv m h + => UniqCounter m + -> SessionEnv m h -> TableConfig -> TableContent m h -> m (Maybe (Ref (Run m h))) -writeBufferToNewRun SessionEnv { +writeBufferToNewRun uc + SessionEnv { sessionRoot = root, sessionHasFS = hfs, - sessionHasBlockIO = hbio, - sessionUniqCounter = uc + sessionHasBlockIO = hbio } conf TableContent{ @@ -1741,9 +1979,12 @@ supplyUnionCredits resolve t credits = do (runParamsForLevel conf UnionLevel) thresh (tableSessionRoot tEnv) - (tableSessionUniqCounter tEnv) + (tableSessionUniqCounter t) mt (let UnionCredits c = credits in MergeCredits c) + + traceWith (tableTracer t) $ TraceSuppliedUnionCredits credits (UnionCredits leftovers) + pure (UnionCredits leftovers) -- TODO: don't go into this section if we know there is NoUnion modifyWithActionRegistry_ diff --git a/test/Main.hs b/test/Main.hs index d3382bca2..74eaa5521 100644 --- a/test/Main.hs +++ b/test/Main.hs @@ -44,6 +44,7 @@ import qualified Test.Database.LSMTree.Model.Table import qualified Test.Database.LSMTree.Resolve import qualified Test.Database.LSMTree.StateMachine import qualified Test.Database.LSMTree.StateMachine.DL +import qualified Test.Database.LSMTree.Tracer.Golden import qualified Test.Database.LSMTree.UnitTests import qualified Test.FS import Test.Tasty @@ -89,9 +90,10 @@ main = do , Test.Database.LSMTree.Internal.WriteBufferReader.FS.tests , Test.Database.LSMTree.Model.Table.tests , Test.Database.LSMTree.Resolve.tests - , Test.Database.LSMTree.UnitTests.tests , Test.Database.LSMTree.StateMachine.tests , Test.Database.LSMTree.StateMachine.DL.tests + , Test.Database.LSMTree.Tracer.Golden.tests + , Test.Database.LSMTree.UnitTests.tests , Test.FS.tests ] Control.RefCount.checkForgottenRefs diff --git a/test/Test/Database/LSMTree/Tracer/Golden.hs b/test/Test/Database/LSMTree/Tracer/Golden.hs new file mode 100644 index 000000000..60f9b4625 --- /dev/null +++ b/test/Test/Database/LSMTree/Tracer/Golden.hs @@ -0,0 +1,157 @@ +{-# LANGUAGE OverloadedLists #-} +{-# LANGUAGE OverloadedStrings #-} + +module Test.Database.LSMTree.Tracer.Golden (tests) where + +import Control.Exception (mask_) +import Control.Monad (void) +import Control.Tracer +import qualified Data.List.NonEmpty as NE +import Data.Monoid (Sum (..)) +import Data.Word +import Database.LSMTree as R +import Prelude hiding (lookup) +import System.FilePath +import qualified System.FS.API as FS +import qualified System.IO as IO +import Test.Tasty (TestTree, localOption, testGroup) +import Test.Tasty.Golden +import Test.Util.FS (withTempIOHasBlockIO) + + +tests :: TestTree +tests = + localOption OnPass $ + testGroup "Test.Database.LSMTree.Tracer.Golden" [ + goldenVsFile + "golden_traceMessages" + goldenDataFile + dataFile + (golden_traceMessages dataFile) + ] + +goldenDataDirectory :: FilePath +goldenDataDirectory = "test/golden-file-data/tracer" + +-- | Path to the /golden/ file for 'golden_traceMessages' +goldenDataFile :: FilePath +goldenDataFile = dataFile <.> "golden" + +-- | Path to the output file for 'golden_traceMessages' +dataFile :: FilePath +dataFile = goldenDataDirectory "golden_traceMessages" + +-- | A monadic action that traces messages emitted by the public API of +-- @lsm-tree@ to a file. +-- +-- The idea is to cover as much of the public API as possible to trace most (if +-- not all) unique trace messages at least once. The trace output is useful in +-- two ways: +-- +-- * By using golden tests based on the trace output we can help to ensure that +-- trace datatypes and their printing do not change unexpectedly. +-- +-- * The trace output serves as an example that can be manually inspected to see +-- whether the trace messages are printed correctly and whether they are +-- useful. +golden_traceMessages :: FilePath -> IO () +golden_traceMessages file = + withTempIOHasBlockIO "golden_traceMessages" $ \hfs hbio -> + withBinaryFileTracer file $ \(contramap show -> tr) -> do + + let sessionPath = FS.mkFsPath ["session-dir"] + FS.createDirectory hfs sessionPath + + -- Open and close a session + withSession tr hfs hbio sessionPath $ \s -> do + -- Open and close a table + withTable s $ \(t1 :: Table IO K V B) -> do + -- Try out all the update variants + update t1 (K 0) (Insert (V 0) Nothing) + insert t1 (K 1) (V 1) (Just (B 1)) + delete t1 (K 2) + upsert t1 (K 3) (V 3) + + -- Perform a lookup and its member variant + FoundWithBlob (V 1) bref <- lookup t1 (K 1) + void $ member t1 (K 2) + + void $ rangeLookup t1 (FromToExcluding (K 0) (K 3)) + + -- Open and close a cursor + withCursorAtOffset t1 (K 1) $ \c -> do + -- Read from a cursor + [EntryWithBlob (K 1) (V 1) _] <- R.takeWhile 2 (< K 3) c + void $ R.next c + -- Retrieve blobs (we didn't try this before this part) + B 1 <- retrieveBlob s bref + pure () + + let snapA = "snapshot_a" + snapB = "snapshot_b" + + -- Try out a few snapshot operations, and keep one saved snapshot for + -- later + saveSnapshot snapA snapLabel t1 + saveSnapshot snapB snapLabel t1 + void $ listSnapshots s + deleteSnapshot s snapB + void $ doesSnapshotExist s snapA + + -- Open a table from a snapshot and close it again + withTableFromSnapshot s snapA snapLabel $ \ t2 -> do + + -- Create a table duplicate and close it again + withDuplicate t1 $ \t3 -> do + + let unionInputs = NE.fromList [t1, t2, t3] + + -- One-shot union + withUnions unionInputs $ \_ -> pure () + + -- Incremental union + withIncrementalUnions unionInputs $ \t4 -> do + UnionDebt d <- remainingUnionDebt t4 + void $ supplyUnionCredits t4 (UnionCredits (d - 1)) + UnionDebt d' <- remainingUnionDebt t4 + void $ supplyUnionCredits t4 (UnionCredits (d' + 1)) + void $ remainingUnionDebt t4 + + -- Open a table and cursor, but close them automatically as part of + -- closing the session instead of closing them manually. + (t :: Table IO K V B) <- mask_ $ newTable s + _c <- mask_ $ newCursor t + + pure () + +-- | A tracer that emits trace messages to a file handle +fileHandleTracer :: IO.Handle -> Tracer IO String +fileHandleTracer h = Tracer $ emit (IO.hPutStrLn h) + + +-- | A tracer that emits trace messages to a binary file +withBinaryFileTracer :: FilePath -> (Tracer IO String -> IO a) -> IO a +withBinaryFileTracer fp k = + IO.withBinaryFile fp IO.WriteMode $ \h -> + k (fileHandleTracer h) + +{------------------------------------------------------------------------------- + Key and value types +-------------------------------------------------------------------------------} + +newtype K = K Word64 + deriving stock (Show, Eq, Ord) + deriving newtype (SerialiseKey) + +newtype V = V Word64 + deriving stock (Show, Eq, Ord) + deriving newtype (SerialiseValue) + +deriving via Sum Word64 instance ResolveValue V + +newtype B = B Word64 + deriving stock (Show, Eq, Ord) + deriving newtype (SerialiseValue) + +snapLabel :: SnapshotLabel +snapLabel = SnapshotLabel "KVBs" diff --git a/test/golden-file-data/tracer/golden_traceMessages.golden b/test/golden-file-data/tracer/golden_traceMessages.golden new file mode 100644 index 000000000..d07b5add9 --- /dev/null +++ b/test/golden-file-data/tracer/golden_traceMessages.golden @@ -0,0 +1,76 @@ +TraceSession (SessionId session-dir) TraceOpenSession +TraceSession (SessionId session-dir) TraceNewSession +TraceSession (SessionId session-dir) TraceOpenedSession +TraceTable (TableId 0) (TraceNewTable (TableConfig {confMergePolicy = LazyLevelling, confMergeSchedule = Incremental, confSizeRatio = Four, confWriteBufferAlloc = AllocNumEntries 20000, confBloomFilterAlloc = AllocRequestFPR 1.0e-3, confFencePointerIndex = OrdinaryIndex, confDiskCachePolicy = DiskCacheAll})) +TraceTable (TableId 0) (TraceCreatedTable (SessionId session-dir) (TableConfig {confMergePolicy = LazyLevelling, confMergeSchedule = Incremental, confSizeRatio = Four, confWriteBufferAlloc = AllocNumEntries 20000, confBloomFilterAlloc = AllocRequestFPR 1.0e-3, confFencePointerIndex = OrdinaryIndex, confDiskCachePolicy = DiskCacheAll})) +TraceTable (TableId 0) (TraceUpdates 1) +TraceTable (TableId 0) (TraceUpdated 1) +TraceTable (TableId 0) (TraceUpdates 1) +TraceTable (TableId 0) (TraceUpdated 1) +TraceTable (TableId 0) (TraceUpdates 1) +TraceTable (TableId 0) (TraceUpdated 1) +TraceTable (TableId 0) (TraceUpdates 1) +TraceTable (TableId 0) (TraceUpdated 1) +TraceTable (TableId 0) (TraceLookups 1) +TraceTable (TableId 0) (TraceLookups 1) +TraceTable (TableId 0) (TraceRangeLookup (FromToExcluding (SerialisedKey [0,0,0,0,0,0,0,0]) (SerialisedKey [0,0,0,0,0,0,0,3]))) +TraceCursor (CursorId 2) (TraceNewCursor (TableId 0) (OffsetKey (SerialisedKey [0,0,0,0,0,0,0,0]))) +TraceCursor (CursorId 2) (TraceCreatedCursor (SessionId session-dir)) +TraceCursor (CursorId 2) (TraceReadingCursor 500) +TraceCursor (CursorId 2) (TraceReadCursor 500 2) +TraceCursor (CursorId 2) TraceCloseCursor +TraceCursor (CursorId 2) TraceClosedCursor +TraceCursor (CursorId 3) (TraceNewCursor (TableId 0) (OffsetKey (SerialisedKey [0,0,0,0,0,0,0,1]))) +TraceCursor (CursorId 3) (TraceCreatedCursor (SessionId session-dir)) +TraceCursor (CursorId 3) (TraceReadingCursor 2) +TraceCursor (CursorId 3) (TraceReadCursor 2 1) +TraceCursor (CursorId 3) (TraceReadingCursor 1) +TraceCursor (CursorId 3) (TraceReadCursor 1 1) +TraceSession (SessionId session-dir) (TraceRetrieveBlobs 1) +TraceCursor (CursorId 3) TraceCloseCursor +TraceCursor (CursorId 3) TraceClosedCursor +TraceTable (TableId 0) (TraceSaveSnapshot "snapshot_a") +TraceTable (TableId 0) (TraceSavedSnapshot "snapshot_a") +TraceTable (TableId 0) (TraceSaveSnapshot "snapshot_b") +TraceTable (TableId 0) (TraceSavedSnapshot "snapshot_b") +TraceSession (SessionId session-dir) TraceListSnapshots +TraceSession (SessionId session-dir) (TraceDeleteSnapshot "snapshot_b") +TraceSession (SessionId session-dir) (TraceDeletedSnapshot "snapshot_b") +TraceTable (TableId 6) (TraceOpenTableFromSnapshot "snapshot_a" NoOverrideDiskCachePolicy) +TraceTable (TableId 6) (TraceCreatedTable (SessionId session-dir) (TableConfig {confMergePolicy = LazyLevelling, confMergeSchedule = Incremental, confSizeRatio = Four, confWriteBufferAlloc = AllocNumEntries 20000, confBloomFilterAlloc = AllocRequestFPR 1.0e-3, confFencePointerIndex = OrdinaryIndex, confDiskCachePolicy = DiskCacheAll})) +TraceTable (TableId 8) (TraceDuplicate (TableId 0)) +TraceTable (TableId 8) (TraceCreatedTable (SessionId session-dir) (TableConfig {confMergePolicy = LazyLevelling, confMergeSchedule = Incremental, confSizeRatio = Four, confWriteBufferAlloc = AllocNumEntries 20000, confBloomFilterAlloc = AllocRequestFPR 1.0e-3, confFencePointerIndex = OrdinaryIndex, confDiskCachePolicy = DiskCacheAll})) +TraceTable (TableId 9) (TraceIncrementalUnions (TableId 0 :| [TableId 6,TableId 8])) +TraceTable (TableId 9) (TraceCreatedTable (SessionId session-dir) (TableConfig {confMergePolicy = LazyLevelling, confMergeSchedule = Incremental, confSizeRatio = Four, confWriteBufferAlloc = AllocNumEntries 20000, confBloomFilterAlloc = AllocRequestFPR 1.0e-3, confFencePointerIndex = OrdinaryIndex, confDiskCachePolicy = DiskCacheAll})) +TraceTable (TableId 9) TraceRemainingUnionDebt +TraceTable (TableId 9) (TraceSupplyUnionCredits 13) +TraceTable (TableId 9) (TraceSuppliedUnionCredits 13 1) +TraceTable (TableId 9) TraceCloseTable +TraceTable (TableId 9) TraceClosedTable +TraceTable (TableId 15) (TraceIncrementalUnions (TableId 0 :| [TableId 6,TableId 8])) +TraceTable (TableId 15) (TraceCreatedTable (SessionId session-dir) (TableConfig {confMergePolicy = LazyLevelling, confMergeSchedule = Incremental, confSizeRatio = Four, confWriteBufferAlloc = AllocNumEntries 20000, confBloomFilterAlloc = AllocRequestFPR 1.0e-3, confFencePointerIndex = OrdinaryIndex, confDiskCachePolicy = DiskCacheAll})) +TraceTable (TableId 15) TraceRemainingUnionDebt +TraceTable (TableId 15) (TraceSupplyUnionCredits 12) +TraceTable (TableId 15) (TraceSuppliedUnionCredits 12 0) +TraceTable (TableId 15) TraceRemainingUnionDebt +TraceTable (TableId 15) (TraceSupplyUnionCredits 2) +TraceTable (TableId 15) (TraceSuppliedUnionCredits 2 2) +TraceTable (TableId 15) TraceRemainingUnionDebt +TraceTable (TableId 15) TraceCloseTable +TraceTable (TableId 15) TraceClosedTable +TraceTable (TableId 8) TraceCloseTable +TraceTable (TableId 8) TraceClosedTable +TraceTable (TableId 6) TraceCloseTable +TraceTable (TableId 6) TraceClosedTable +TraceTable (TableId 0) TraceCloseTable +TraceTable (TableId 0) TraceClosedTable +TraceTable (TableId 21) (TraceNewTable (TableConfig {confMergePolicy = LazyLevelling, confMergeSchedule = Incremental, confSizeRatio = Four, confWriteBufferAlloc = AllocNumEntries 20000, confBloomFilterAlloc = AllocRequestFPR 1.0e-3, confFencePointerIndex = OrdinaryIndex, confDiskCachePolicy = DiskCacheAll})) +TraceTable (TableId 21) (TraceCreatedTable (SessionId session-dir) (TableConfig {confMergePolicy = LazyLevelling, confMergeSchedule = Incremental, confSizeRatio = Four, confWriteBufferAlloc = AllocNumEntries 20000, confBloomFilterAlloc = AllocRequestFPR 1.0e-3, confFencePointerIndex = OrdinaryIndex, confDiskCachePolicy = DiskCacheAll})) +TraceCursor (CursorId 23) (TraceNewCursor (TableId 21) NoOffsetKey) +TraceCursor (CursorId 23) (TraceCreatedCursor (SessionId session-dir)) +TraceSession (SessionId session-dir) TraceCloseSession +TraceCursor (CursorId 23) TraceCloseCursor +TraceCursor (CursorId 23) TraceClosedCursor +TraceTable (TableId 21) TraceCloseTable +TraceTable (TableId 21) TraceClosedTable +TraceSession (SessionId session-dir) TraceClosedSession