#14841: Inconsistent allocation stats -------------------------------------+------------------------------------- Reporter: patrickdoc | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Runtime System | Version: Resolution: | Keywords: GCStats, | RTSStats Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Old description:
I'm looking at Criterion internals, and seeing an inconsistency in the allocations reported by `GCStats` and `RTSStats`. Here is a small reproduction:
{{{#!hs {-# LANGUAGE CPP #-} module Main where
import GHC.Stats import System.Mem (performGC)
main :: IO () main = do runOldThing 1000 #if __GLASGOW_HASKELL__ >= 802 putStrLn "Running new:" runThing 1000 #endif
runOldThing :: Int -> IO () runOldThing n = loop n 0 >> return () where loop 0 _ = return 0 loop count x = do performGC stats <- getGCStats putStrLn $ show (count `mod` 15) ++ ": " ++ show (bytesAllocated stats - x) ++ " num: " ++ show (numGcs stats) loop (count-1) (bytesAllocated stats)
#if __GLASGOW_HASKELL__ >= 802 runThing :: Int -> IO () runThing = loop where loop 0 = return () loop n = do performGC stats <- getRTSStats putStrLn $ show (n `mod` 15) ++ ": " ++ show (gcdetails_allocated_bytes (gc stats)) ++ " num: " ++ show (gcs stats) loop (n-1) #endif }}}
This code just performs a garbage collection and then prints the stats in a loop. Here is a snippet of the output.
{{{ ... 4: 8840 num: 1967 3: 4880 num: 1968 2: 4880 num: 1969 1: 4880 num: 1970 0: 4880 num: 1971 14: 4880 num: 1972 13: 4976 num: 1973 12: 4976 num: 1974 11: 4976 num: 1975 10: 4976 num: 1976 9: 4976 num: 1977 8: 4880 num: 1978 7: 4880 num: 1979 6: 4880 num: 1980 5: 4880 num: 1981 4: 8840 num: 1982 3: 4880 num: 1983 2: 4880 num: 1984 1: 4880 num: 1985 0: 4880 num: 1986 14: 4880 num: 1987 13: 4976 num: 1988 12: 4976 num: 1989 11: 4976 num: 1990 10: 4976 num: 1991 9: 4976 num: 1992 8: 4880 num: 1993 7: 4880 num: 1994 6: 4880 num: 1995 5: 4880 num: 1996 4: 8840 num: 1997 3: 4880 num: 1998 2: 4880 num: 1999 1: 4880 num: 2000 }}}
On the left, I've included the gc number `mod` 15 to show that exactly every 15 gcs, there is an extra 4k bytes reported. This output was made with 8.2.1. On 7.8.4, 7.10.3, and 8.0.2 it's every 23. And on 8.4.0.20180204 it's every 9.
I've played around with extra allocations between garbage collections, but the interval remained constant. I tried poking around the rts, but I've been unable to determine if this is a bug or just unavoidable noise.
New description: I'm looking at Criterion internals, and seeing an inconsistency in the allocations reported by `GCStats` and `RTSStats`. Here is a small reproduction: {{{#!hs {-# LANGUAGE CPP #-} module Main where import GHC.Stats import System.Mem (performGC) main :: IO () main = do runOldThing 1000 #if __GLASGOW_HASKELL__ >= 802 putStrLn "Running new:" runThing 1000 #endif runOldThing :: Int -> IO () runOldThing n = loop n 0 >> return () where loop 0 _ = return 0 loop count x = do performGC stats <- getGCStats putStrLn $ show (count `mod` 15) ++ ": " ++ show (bytesAllocated stats - x) ++ " num: " ++ show (numGcs stats) loop (count-1) (bytesAllocated stats) #if __GLASGOW_HASKELL__ >= 802 runThing :: Int -> IO () runThing = loop where loop 0 = return () loop n = do performGC stats <- getRTSStats putStrLn $ show (n `mod` 15) ++ ": " ++ show (gcdetails_allocated_bytes (gc stats)) ++ " num: " ++ show (gcs stats) loop (n-1) #endif }}} This code just performs a garbage collection and then prints the stats in a loop. Here is a snippet of the output. {{{ ... 4: 8840 num: 1967 3: 4880 num: 1968 2: 4880 num: 1969 1: 4880 num: 1970 0: 4880 num: 1971 14: 4880 num: 1972 13: 4976 num: 1973 12: 4976 num: 1974 11: 4976 num: 1975 10: 4976 num: 1976 9: 4976 num: 1977 8: 4880 num: 1978 7: 4880 num: 1979 6: 4880 num: 1980 5: 4880 num: 1981 4: 8840 num: 1982 3: 4880 num: 1983 2: 4880 num: 1984 1: 4880 num: 1985 0: 4880 num: 1986 14: 4880 num: 1987 13: 4976 num: 1988 12: 4976 num: 1989 11: 4976 num: 1990 10: 4976 num: 1991 9: 4976 num: 1992 8: 4880 num: 1993 7: 4880 num: 1994 6: 4880 num: 1995 5: 4880 num: 1996 4: 8840 num: 1997 3: 4880 num: 1998 2: 4880 num: 1999 1: 4880 num: 2000 }}} On the left, I've included the gc number `mod` 15 to show that exactly every 15 gcs, there is an extra 4k bytes reported. This output was made with 8.2.1. On 7.8.4, 7.10.3, and 8.0.2 it's every 23. And on 8.4.0.20180204 it's every 14. I've played around with extra allocations between garbage collections, but the interval remained constant. I tried poking around the rts, but I've been unable to determine if this is a bug or just unavoidable noise. -- Comment (by patrickdoc): I can't count in mod 15 apparently; on GHC HEAD it occurs every 14. I've traced the 15 -> 14 change to this commit: https://phabricator.haskell.org/D3658, which increases the size of `GCDetails` and `RTSStats` with an extra field. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14841#comment:1 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler