help with threadDelay
Hi, I'm using GHC 6.6 (debian/etch) - and having some fun with threadDelay. When compiled without the -threaded compiler argument it "behaves" as documented - waits at least the interval - for example: Tgt/Actual = 0.000000/0.036174s, diff = 0.036174s Tgt/Actual = 0.000001/0.049385s, diff = 0.049384s Tgt/Actual = 0.000005/0.049492s, diff = 0.049487s Tgt/Actual = 0.000025/0.049596s, diff = 0.049571s Tgt/Actual = 0.000125/0.049655s, diff = 0.04953s Tgt/Actual = 0.000625/0.04969s, diff = 0.049065s Tgt/Actual = 0.003125/0.049684s, diff = 0.046559s Tgt/Actual = 0.015625/0.04962s, diff = 0.033995s Tgt/Actual = 0.078125/0.099668s, diff = 0.021543s Tgt/Actual = 0.390625/0.399637s, diff = 0.009012s Tgt/Actual = 1.953125/1.999515s, diff = 0.04639s Tgt/Actual = 9.765625/9.799505s, diff = 0.03388s however when -threaded is used you get some interesting effects, including returning too early: Tgt/Actual = 0.000000/0.000093s, diff = 0.000093s Tgt/Actual = 0.000001/0.000031s, diff = 0.00003s Tgt/Actual = 0.000005/0.000029s, diff = 0.000024s Tgt/Actual = 0.000025/0.000028s, diff = 0.000003s Tgt/Actual = 0.000125/0.000034s, diff = -0.000091s Tgt/Actual = 0.000625/0.000035s, diff = -0.00059s Tgt/Actual = 0.003125/0.000029s, diff = -0.003096s Tgt/Actual = 0.015625/0.000028s, diff = -0.015597s Tgt/Actual = 0.078125/0.058525s, diff = -0.0196s Tgt/Actual = 0.390625/0.389669s, diff = -0.000956s Tgt/Actual = 1.953125/1.939513s, diff = -0.013612s Tgt/Actual = 9.765625/9.749573s, diff = -0.016052s The program I used to generate this is :- import Control.Concurrent import Data.Time import Text.Printf main = mapM_ delay (0 : take 11 (iterate (*5) 1)) delay n = do tS <- getCurrentTime threadDelay n tE <- getCurrentTime let n' = toRational n / 10^6 n'' = fromRational (n') :: Double obs = diffUTCTime tE tS printf "Tgt/Actual = %0.6f/%s, diff = %s\n" n'' (show obs) (show $ obs - fromRational n') return () Any suggestions? Neil
[moving to glasgow-haskell-bugs] On Wed, Nov 15, 2006 at 11:40:12PM +0000, Neil Davies wrote:
however when -threaded is used you get some interesting effects, including returning too early:
Tgt/Actual = 0.000125/0.000034s, diff = -0.000091s
Thanks for the report; I can reproduce it on Linux/amd64. OK, so the bug here is that threadDelay n might return after less than n microseconds. This looks like it's caused by truncation problems when converting times to ticks (where a tick is 1/50 of a second), e.g. while trying to sleep for 1.953125s one run started at 1164157960.773726s which is (Int) 1164157960 * 50 + 773726 * 50 / 1000000 = (Int) 58207898038.6863 = 58207898038 ticks and woke the thread up at 1164157962.708609s which is (Int) 1164157962 * 50 + 708609 * 50 / 1000000 = (Int) 58207898135.4305 = 58207898135 ticks The difference is 58207898135 - 58207898038 = 97 ticks. Meanwhile we're trying to sleep for (Int) 50 * 1.953125 = (Int) 97.65625 = 97 ticks However, 1164157962.708609s - 1164157960.773726s = 1.93488311767578s which is 0.0182418823242201s too short. The problem is that we have counted 0.6863 ticks before the start time, not counted 0.4305 ticks before the finish time and have been waiting 0.65625 ticks too short a time. Thus we have counted (0.6863-0.4305 + 0.65625) / 50 == 0.018241 too much time. I think the answer is that let target = now + usecs `quot` tick_usecs in GHC/Conc.lhs should be let target = 1 + now + (usecs + tick_usecs - 1) `quot` tick_usecs I'm also a bit dubious about the use of the constant "50" for the number of ticks per second, but the results with +RTS -V0.001 don't look any more wrong so perhaps I just need to get some sleep. You can get the same symptoms with the non-threaded RTS with +RTS -V0.001, although they are less frequent. I suspect we need a similar fix to target = (R1 / (TO_W_(RtsFlags_MiscFlags_tickInterval(RtsFlags))*1000)) + time; in delayzh_fast in PrimOps.cmm. Thanks Ian
Ian Lynagh wrote:
[moving to glasgow-haskell-bugs]
On Wed, Nov 15, 2006 at 11:40:12PM +0000, Neil Davies wrote:
however when -threaded is used you get some interesting effects, including returning too early:
Tgt/Actual = 0.000125/0.000034s, diff = -0.000091s
Thanks for the report; I can reproduce it on Linux/amd64.
OK, so the bug here is that threadDelay n might return after less than n microseconds.
This looks like it's caused by truncation problems when converting times to ticks (where a tick is 1/50 of a second), e.g. while trying to sleep for 1.953125s one run started at 1164157960.773726s which is (Int) 1164157960 * 50 + 773726 * 50 / 1000000 = (Int) 58207898038.6863 = 58207898038 ticks and woke the thread up at 1164157962.708609s which is (Int) 1164157962 * 50 + 708609 * 50 / 1000000 = (Int) 58207898135.4305 = 58207898135 ticks
The difference is 58207898135 - 58207898038 = 97 ticks.
Meanwhile we're trying to sleep for (Int) 50 * 1.953125 = (Int) 97.65625 = 97 ticks
However, 1164157962.708609s - 1164157960.773726s = 1.93488311767578s which is 0.0182418823242201s too short.
The problem is that we have counted 0.6863 ticks before the start time, not counted 0.4305 ticks before the finish time and have been waiting 0.65625 ticks too short a time. Thus we have counted (0.6863-0.4305 + 0.65625) / 50 == 0.018241 too much time.
I think the answer is that
let target = now + usecs `quot` tick_usecs
in GHC/Conc.lhs should be
let target = 1 + now + (usecs + tick_usecs - 1) `quot` tick_usecs
I'm also a bit dubious about the use of the constant "50" for the number of ticks per second, but the results with +RTS -V0.001 don't look any more wrong so perhaps I just need to get some sleep.
The hardcoded 50 in GHC/Conc.lhs matches up with TICK_FREQ in libraries/base/includes/HsBase.h. It could probably be made larger without any ill effects. I agree that we should round up the target time to the nearest tick rather than rounding down, though. Cheers, Simon
participants (3)
-
Ian Lynagh -
Neil Davies -
Simon Marlow