getCPUTime returns fixed value with -threaded

[blackgnezdo]

This test fails:

lib/base/T16916.run T16916 [bad stdout] (normal)

Once instrumented with some prints the output is puzzling:

% ghc -threaded -O2 -o /tmp/a /tmp/a.hs                                                                                                   
Linking /tmp/a ...
% /tmp/a                                                                                                                                  "startCPUTime 0"
"endCPUTime 0"
"startTime 174897.364331696"
"endTime 174902.38197417"
"startCPUTime 0"
"endCPUTime 0"
"startTime 174902.382501444"
"endTime 174907.391930155"
False
eventTriggeredUsage 0.0
noEventUsage 0.0

In other cases observed:

% /tmp/a                                                                                                                                  
"startCPUTime 20000000000"
"endCPUTime 20000000000"
"startTime 175015.590683467"
"endTime 175020.610736021"
"startCPUTime 20000000000"
"endCPUTime 20000000000"
"startTime 175020.611046369"
"endTime 175025.63069346"
False
eventTriggeredUsage 0.0
noEventUsage 0.0

Apparently getCPUTime returns a fixed value. At the same time, when executed from ghci this doesn't reproduce:

% ghci
GHCi, version 8.10.1: https://www.haskell.org/ghc/  :? for help
Loaded GHCi configuration from /home/greg/.ghci
Prelude     
> import System.CPUTime      
> mapM_ (\_ -> getCPUTime >>= print) [0..30]
780000000000
780000000000
...
790000000000            
790000000000                
790000000000             
...
800000000000
800000000000           

Instrumented source:

module Main where

import Control.Concurrent
import Foreign.C
import GHC.Clock
import GHC.Event
import System.CPUTime
import System.Posix.Types

foreign import ccall unsafe "socket" c_socket ::
               CInt -> CInt -> CInt -> IO CInt

makeTestSocketFd :: IO Fd
makeTestSocketFd = do
    sockNum <-
        c_socket
            1 -- PF_LOCAL
            2 -- SOCK_DGRAM
            0
    return $ (fromIntegral sockNum :: Fd)

callback :: FdKey -> Event -> IO ()
callback _ _ = return ()

-- Idle CPU usage with 0 for 0% and 10^12 for 100%
idleCpuUsage :: IO Double
idleCpuUsage = do
  startTime <- getMonotonicTime
  startCPUTime <- getCPUTime
  threadDelay 15000000
  endCPUTime <- getCPUTime
  endTime <- getMonotonicTime

  print $ "startCPUTime " ++ show startCPUTime
  print $ "endCPUTime " ++ show endCPUTime
  print $ "startTime " ++ show startTime
  print $ "endTime " ++ show endTime
  
  return $ fromIntegral (endCPUTime - startCPUTime) / (endTime - startTime)

main :: IO ()
main = do
  (Just eventMgr) <- getSystemEventManager
  fd <- makeTestSocketFd

  noEventUsage <- idleCpuUsage

  registerFd eventMgr callback fd evtRead OneShot
  registerFd eventMgr callback fd evtWrite OneShot

  eventTriggeredUsage <- idleCpuUsage

  -- CPU consumption should roughly be the same when just idling vs
  -- when idling after the event been triggered
  print $ eventTriggeredUsage / noEventUsage < 10.0
  putStrLn $ "eventTriggeredUsage " ++ show eventTriggeredUsage
  putStrLn $ "noEventUsage " ++ show noEventUsage