base: fdReady(): Fix timeouts > ~49 days overflowing. Fixes #14262.
ClosedPublic

Authored by nh2 on Sep 22 2017, 12:49 PM.

Details

Summary

On 64-bit UNIX and Windows, Haskell Int has 64 bits
but C int msecs has 32 bits, resulting in an overflow.

This commit fixes it by switching fdReady() to take int64_t,
into which a Haskell Int will always fit.

(Note we could not switch to long long because that is
32 bit on 64-bit Windows machines.)

Further, to be able to actually wait longer than ~49 days,
we put loops around the waiting syscalls (they all accept only
32-bit integers).

Note the timer signal would typically interrupt the syscalls
before the ~49 days are over, but you can run Haskell programs
without the timer signal, an we want it to be correct in all
cases.

Diff Detail

Repository
rGHC Glasgow Haskell Compiler
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.
nh2 created this revision.Sep 22 2017, 12:49 PM
nh2 updated this revision to Diff 14060.Sep 22 2017, 6:43 PM

Rebased

nh2 updated this revision to Diff 14122.Sep 26 2017, 8:27 AM

Rebase

Phyx requested changes to this revision.Sep 27 2017, 1:15 PM
Phyx added a subscriber: Phyx.

Your summary is incorrect, Windows 64-bit is LLP64, so long long & pointers are 64bit long.

You can also see this on https://msdn.microsoft.com/en-us/library/windows/desktop/aa383751(v=vs.85).aspx
on the LONGLONG type.

libraries/base/cbits/inputReady.c
38

If it's bool why not make it a bool? We're trying to move to C99 types.

58

probably should check remaining_tv here.

356

I'm dubious about these sleeps. Would SwitchToThread() work here to temporarily give control to another thread to do something useful before we check again?

This revision now requires changes to proceed.Sep 27 2017, 1:15 PM
nh2 added a comment.Sep 27 2017, 2:17 PM
In D4011#112953, @Phyx wrote:

Your summary is incorrect, Windows 64-bit is LLP64, so long long & pointers are 64bit long.

You're right, I typoed that, I meant long instead of long long.

Will fix the commit message.

nh2 added inline comments.Sep 27 2017, 2:31 PM
libraries/base/cbits/inputReady.c
58

Why? If you want to wait infinitely, then the remaining time doesn't matter.

Also see the note further down:

// Invariant of all code below:
// If `infinite`, then `remaining` and `endTime` are never used.

Does that make sense, or would you like me to say it more explicitly somewhere, e.g. in the comment on the function?

356

If there is nothing else to do, that approach would result in 100% CPU usage as far as I can tell.

Can you confirm whether that is correct?

I think a "proper" fix would be switching to IOCP but that is a bigger task and I think we should do it separately (and it also should be done by somebody who's familiar IOCP).

Also note that before I introduced the sleeps in a previous commit of this patch series, the logic just ran PeekNamedPipe() and immediately returned, ignoring the passed msecs, so while this is still extremely ugly, it is at least a bit more correct than before.

Phyx added inline comments.Sep 27 2017, 2:49 PM
libraries/base/cbits/inputReady.c
58

The invariant doesn't preclude !infinite && !remaining_tv. So the function can segfault quite trivially.

356

Why would the approach result in 100% CPU usage? you're just yielding control to another thread if it has anything else to do instead of sleeping.

nh2 added inline comments.Sep 27 2017, 3:07 PM
libraries/base/cbits/inputReady.c
58

Hmm, I still don't get what exactly you're after.

Checking for non-NULL-ness of remaining_tv? If yes, what would that help (beyond perhaps being a useful standard die-early assertion), a non-NULL bad pointer might be just as bad.

I must be missing something.

356

If we're yielding control to another thread, but there is no other thread that has something to do, would we not immediately regain control?

For example, this C program creates 100% CPU usage on Linux on an idle system:

#define _GNU_SOURCE
#include <pthread.h>

int main(int argc, char const *argv[])
{
  while (1) pthread_yield();
  return 0;
}

when run with gcc -O yield-loop.c -o yield-loop -lpthread && ./yield-loop.

nh2 updated this revision to Diff 14165.Sep 27 2017, 3:33 PM
nh2 edited edge metadata.
nh2 marked an inline comment as done.

Added assertion and more comments

nh2 marked 4 inline comments as done.Sep 27 2017, 3:34 PM
nh2 added inline comments.
libraries/base/cbits/inputReady.c
38

Ah, I wasn't aware. I found some pre-existing int bools in here, so I just stuck to the style.

OK, I've put out https://phabricator.haskell.org/D4041 for switching all bools in this file to bool.

58

Clarified on IRC:

(22:08:14) Phyx-: nh2: I mean it should be checked for validity and return if it's not. I only highlighted that line because return NULL would be a valid thing to do if !remaining_tv
(22:09:10) nh2: Phyx-: ah, you just replied here, I just replied on Phab, let me check what you said
(22:11:42) nh2: Phyx-: ah, you mean that it should be legal to call `compute_windows_select_timeout(true, remaining, NULL)`? Currently I require that you pass a non-NULL third argument in all cases
(22:13:02) Phyx-: nh2: I'm saying that the function on it's own is unsafe. the next person to use it may not know about your implicit requirements
(22:13:15) Phyx-: a simple NULL check or assert now prevents a lot of pain later
(22:21:26) nh2: Phyx-: OK, I misunderstood, thinking that you meant I'd have to check for non-NULL-ness of remaining_tv for the correctness of the logic, opposed to defensive programming. Is there an assertion macro in scrope / commonly used in the RTS I should use for this?
(22:21:53) bgamari: nh2, ASSERT
(22:21:55) Phyx-: ASSERT(...)

I've pushed an assertion now.

nh2 marked 4 inline comments as done.Sep 27 2017, 3:35 PM
Phyx added inline comments.Sep 27 2017, 3:49 PM
libraries/base/cbits/inputReady.c
71

I think you want ASSERT(remaining_tv), as the assert will fire when the condition is not true.

356

Right, fair enough.

nh2 updated this revision to Diff 14166.Sep 27 2017, 4:00 PM

Fix assert bool flip

nh2 marked 2 inline comments as done.Sep 27 2017, 4:01 PM
nh2 added inline comments.
libraries/base/cbits/inputReady.c
71

Oops, fixed.

nh2 marked 5 inline comments as done.Sep 28 2017, 5:55 AM
Phyx accepted this revision.Sep 28 2017, 6:26 AM

OK, looks good to me, but please update the cover letter, it's somewhat confusing at the moment.

You talk about Int but only change a function which has CInt. Looking through the ticket I assume
you meant the Int in hWaitForInput. So I think the summary should only talk about what this patch actually
fixes, which is the ability to wait longer than (DWORD)-1 ms.

This revision is now accepted and ready to land.Sep 28 2017, 6:26 AM
nh2 abandoned this revision.Sep 28 2017, 9:31 AM
nh2 reclaimed this revision.
This revision is now accepted and ready to land.Sep 28 2017, 9:31 AM
nh2 planned changes to this revision.Sep 28 2017, 9:31 AM

What is the status of this, @nh2?

nh2 added a subscriber: syd.Oct 25 2017, 7:02 PM

@bgamari A bug was found by @syd in a corner case, I'll be fixing that.

nh2 updated this revision to Diff 14649.Nov 13 2017, 2:34 PM

Improved poll/select logic and readability

This revision is now accepted and ready to land.Nov 13 2017, 2:34 PM
nh2 requested review of this revision.Nov 13 2017, 2:36 PM

Please take another look after I improved logic handling. I also have to re-run my manual tests (but have already pushed before so that phab can build my changes in parallel).

nh2 updated this revision to Diff 14651.Nov 13 2017, 2:41 PM

Turn a few more ints into bools

nh2 updated this revision to Diff 14652.Nov 13 2017, 2:44 PM

Also update FFI signature of unsafe_fdReady

nh2 updated this revision to Diff 14655.Nov 13 2017, 3:41 PM

Also update call site that used 0xFFFFFFFF on Windows

nh2 updated this revision to Diff 14657.Nov 13 2017, 7:30 PM

Fix Windows build

syd added inline comments.Nov 14 2017, 4:33 AM
libraries/base/cbits/inputReady.c
189

I think this while loop is still missing some branches.
You may want to comment about the exclusiveness of the branches, because I needed pen and paper to check.

These are the branches I think you're missing:

res < 0 && errno == EINTR
res == 0 && infinite
res == 0 && !infinite && remaining > MsToTime

This is purely from a satisfiability standpoint. It could be that these don't occur in practice, but that's not obvious to me.

246

This block has the same problems as the ones I outlined in my comment above.

nh2 updated this revision to Diff 14664.Nov 14 2017, 4:52 AM

Make comment an assertion instead

nh2 updated this revision to Diff 14665.Nov 14 2017, 6:20 AM

Remove bit that says fdReady() doesn't support waiting indefinitely (it does)

nh2 added a comment.Nov 14 2017, 6:35 AM

@syd I've turned my comment into a CHECK() containing exactly the cases you mentioned.

nh2 added a comment.Nov 14 2017, 7:03 AM

Testing the accuracy can be frustrating: In my Windows VM, in Mingw-w64 64bit, I get, very rarely, time measured by time that is not consistent with GHC's understanding of time, with significant difference:

$ cat ../ghc-bug-13497-accuracy-test.hs
import System.IO

main = hWaitForInput stdin (5 * 1000)
$ time ../ghc-bug-13497-accuracy-test

real    0m4.505s
user    0m0.000s
sys     0m0.031s

With a debugging printf in:

$ time ../ghc-bug-13497-accuracy-test
now 1240031432378, endTime 1245031432067
...
now 1245026664498, endTime 1245031432067
now 1245029653128, endTime 1245031432067
now 1245031570104, endTime 1245031432067

real    0m3.941s
user    0m0.000s
sys     0m0.031s

Here we can see that endTime - now indeed starts with exactly 5 seconds, and counts down correctly, but time reports < 4 seconds real time.

Can clock skew be that significant? Also, how does time measure time on Windows, does it also use an atomic clock?

nh2 added a comment.Nov 14 2017, 9:37 AM

Annoyingly, I cannot reproduce this time issue when I run it wrapped in date invocations: date '+%s%N' && time ../ghc-bug-13497-accuracy-test && date '+%s%N'. With that, time always reports slightly above 5 seconds, as expected.

I suppose the output from +RTS -s is consistent with Haskell's conception of time?

nh2 added a comment.Nov 16 2017, 6:16 AM

I noticed that one invocation of make said just now (in another, new Win10 VM based on QEMU instead of VirtualBox):

make[1]: Warning: File 'ghc/stage1/build/.depend.c_asm' has modification time 4774 s in the future

Looks like that is indeed a big time skew issue with the VM, so we probably don't have to worry about it.

bgamari accepted this revision.Nov 23 2017, 11:46 AM

This looks like a great improvement over the previous implementation. Thanks @nh2!

libraries/base/cbits/inputReady.c
356

Indeed this looks terrible. That being said, I agree that it looks like the only sensible option, short of IOCP which seems like overkill here.

This revision is now accepted and ready to land.Nov 23 2017, 11:46 AM
nh2 marked 3 inline comments as done.Nov 23 2017, 12:59 PM
nh2 updated this revision to Diff 14786.Nov 23 2017, 1:03 PM

Rebase / cleanup

This revision was automatically updated to reflect the committed changes.
nh2 added a comment.Nov 25 2017, 11:16 AM
In D4011#117088, @nh2 wrote:

Annoyingly, I cannot reproduce this time issue when I run it wrapped in date invocations: date '+%s%N' && time ../ghc-bug-13497-accuracy-test && date '+%s%N'. With that, time always reports slightly above 5 seconds, as expected.

For completeness, here's another case where I observed this after the VM being idle for a while.

I changed fdReady() to call printf("fdReady called with msecs = %d\n", msecs); and got, with two immediately subsequent runs:

IEUser@MSEDGEWIN10 /c/Users/IEUser/ghc (git)-[bug-8684-interruptible-hWaitForInput] % ../8684.exe

fdReady called with msecs = 5000
fdReady called with msecs = 4998
fdReady called with msecs = 4996
fdReady called with msecs = 4994
fdReady called with msecs = 4992
fdReady called with msecs = 4990
fdReady called with msecs = 4988
fdReady called with msecs = 4986
fdReady called with msecs = 4984
fdReady called with msecs = 4983
fdReady called with msecs = 4982
fdReady called with msecs = 4980
fdReady called with msecs = 4978
fdReady called with msecs = 4976
fdReady called with msecs = 4974
fdReady called with msecs = 4972
fdReady called with msecs = 4970
fdReady called with msecs = 4968
fdReady called with msecs = 4966
fdReady called with msecs = 4964
fdReady called with msecs = 4962
fdReady called with msecs = 4960
fdReady called with msecs = 4959
fdReady called with msecs = 4957
fdReady called with msecs = 4956
fdReady called with msecs = 4954
fdReady called with msecs = 4952
fdReady called with msecs = 4950
fdReady called with msecs = 4948
fdReady called with msecs = 4946
fdReady called with msecs = 4944
fdReady called with msecs = 4942
fdReady called with msecs = 4940
IEUser@MSEDGEWIN10 /c/Users/IEUser/ghc (git)-[bug-8684-interruptible-hWaitForInput] % time ../8684.exe
fdReady called with msecs = 5000
fdReady called with msecs = 4998
fdReady called with msecs = 4996
fdReady called with msecs = 4994
fdReady called with msecs = 4989
fdReady called with msecs = 4986
fdReady called with msecs = 4984
fdReady called with msecs = 4983
fdReady called with msecs = 4981
fdReady called with msecs = 4979
fdReady called with msecs = 4977
fdReady called with msecs = 4974
fdReady called with msecs = 4973
fdReady called with msecs = 4971
fdReady called with msecs = 4969
fdReady called with msecs = 4967
fdReady called with msecs = 4965
fdReady called with msecs = 4963
fdReady called with msecs = 4961
fdReady called with msecs = 4959
fdReady called with msecs = 4957
fdReady called with msecs = 4955
fdReady called with msecs = 4953
fdReady called with msecs = 4951
fdReady called with msecs = 4949
fdReady called with msecs = 4947
fdReady called with msecs = 4945
fdReady called with msecs = 4944
fdReady called with msecs = 4942
fdReady called with msecs = 4940
fdReady called with msecs = 4938
fdReady called with msecs = 4936
fdReady called with msecs = 4934
fdReady called with msecs = 4932
fdReady called with msecs = 4930
fdReady called with msecs = 4928
fdReady called with msecs = 4926
fdReady called with msecs = 4924
fdReady called with msecs = 4922
fdReady called with msecs = 4920
fdReady called with msecs = 4918
fdReady called with msecs = 4916
fdReady called with msecs = 4914
fdReady called with msecs = 4912
fdReady called with msecs = 4910
fdReady called with msecs = 4908
fdReady called with msecs = 4906
fdReady called with msecs = 4905
fdReady called with msecs = 4903
fdReady called with msecs = 4901
fdReady called with msecs = 4899
fdReady called with msecs = 4897
fdReady called with msecs = 4895
fdReady called with msecs = 4893
fdReady called with msecs = 4891
fdReady called with msecs = 4889
fdReady called with msecs = 4887
fdReady called with msecs = 4885
fdReady called with msecs = 4883
fdReady called with msecs = 4881
fdReady called with msecs = 4879
fdReady called with msecs = 4876
fdReady called with msecs = 4875
fdReady called with msecs = 4873
fdReady called with msecs = 4871
fdReady called with msecs = 4869
fdReady called with msecs = 4867
fdReady called with msecs = 4865
fdReady called with msecs = 4863
fdReady called with msecs = 4862
fdReady called with msecs = 4860
fdReady called with msecs = 4858
fdReady called with msecs = 4856
fdReady called with msecs = 4854
fdReady called with msecs = 4852
fdReady called with msecs = 4850
fdReady called with msecs = 4848
fdReady called with msecs = 4846
fdReady called with msecs = 4844
fdReady called with msecs = 4842
fdReady called with msecs = 4840
fdReady called with msecs = 4838
fdReady called with msecs = 4836
fdReady called with msecs = 4834
fdReady called with msecs = 4832
fdReady called with msecs = 4830
fdReady called with msecs = 4828
fdReady called with msecs = 4826
fdReady called with msecs = 4824
fdReady called with msecs = 4822
fdReady called with msecs = 4821
fdReady called with msecs = 4818
fdReady called with msecs = 4817
fdReady called with msecs = 4815
fdReady called with msecs = 4813
fdReady called with msecs = 4811
fdReady called with msecs = 4809
fdReady called with msecs = 4807
fdReady called with msecs = 4805
fdReady called with msecs = 4803
fdReady called with msecs = 4801
fdReady called with msecs = 4799
fdReady called with msecs = 4797
fdReady called with msecs = 4795
fdReady called with msecs = 4793
fdReady called with msecs = 4791
fdReady called with msecs = 4789
fdReady called with msecs = 4787
fdReady called with msecs = 4785
fdReady called with msecs = 4783
fdReady called with msecs = 4781
fdReady called with msecs = 4779
fdReady called with msecs = 4778
fdReady called with msecs = 4776
fdReady called with msecs = 4774
fdReady called with msecs = 4773
fdReady called with msecs = 4771
fdReady called with msecs = 4769
fdReady called with msecs = 4767
fdReady called with msecs = 4765
fdReady called with msecs = 4763
fdReady called with msecs = 4762
fdReady called with msecs = 4760
fdReady called with msecs = 4758
fdReady called with msecs = 4756
fdReady called with msecs = 4754
fdReady called with msecs = 4752
fdReady called with msecs = 4750
fdReady called with msecs = 4748
fdReady called with msecs = 4747
fdReady called with msecs = 4745
fdReady called with msecs = 4743
fdReady called with msecs = 4741
fdReady called with msecs = 4739
fdReady called with msecs = 4738
fdReady called with msecs = 4736
fdReady called with msecs = 4734
fdReady called with msecs = 4732
fdReady called with msecs = 4730
fdReady called with msecs = 4728
fdReady called with msecs = 4727
fdReady called with msecs = 4725
fdReady called with msecs = 4724
fdReady called with msecs = 4722
fdReady called with msecs = 4720
fdReady called with msecs = 4718
fdReady called with msecs = 4716
fdReady called with msecs = 4714
fdReady called with msecs = 4712
fdReady called with msecs = 4710
fdReady called with msecs = 4708
fdReady called with msecs = 4706
fdReady called with msecs = 4704
fdReady called with msecs = 4702
fdReady called with msecs = 4700
fdReady called with msecs = 4698
fdReady called with msecs = 4697
fdReady called with msecs = 4695
fdReady called with msecs = 4694
fdReady called with msecs = 4691
fdReady called with msecs = 4690
fdReady called with msecs = 4688
fdReady called with msecs = 4686
fdReady called with msecs = 4683
fdReady called with msecs = 4681
fdReady called with msecs = 4679
fdReady called with msecs = 4677
fdReady called with msecs = 4675
fdReady called with msecs = 4673
fdReady called with msecs = 4671
fdReady called with msecs = 4669
fdReady called with msecs = 4667
fdReady called with msecs = 4665
fdReady called with msecs = 4663
fdReady called with msecs = 4661
fdReady called with msecs = 4659
fdReady called with msecs = 4657
fdReady called with msecs = 4655
fdReady called with msecs = 4654
fdReady called with msecs = 4652
fdReady called with msecs = 4650
fdReady called with msecs = 4648
fdReady called with msecs = 4646
fdReady called with msecs = 4644
fdReady called with msecs = 4642
fdReady called with msecs = 4640
fdReady called with msecs = 4638
fdReady called with msecs = 4636
fdReady called with msecs = 4634
fdReady called with msecs = 4632
fdReady called with msecs = 4630
fdReady called with msecs = 4628
fdReady called with msecs = 4626
fdReady called with msecs = 4624
fdReady called with msecs = 4622
fdReady called with msecs = 4620
fdReady called with msecs = 4618
fdReady called with msecs = 4616
fdReady called with msecs = 4614
fdReady called with msecs = 4612
fdReady called with msecs = 4611
fdReady called with msecs = 4609
fdReady called with msecs = 4607
fdReady called with msecs = 4605
fdReady called with msecs = 4603
fdReady called with msecs = 4601
fdReady called with msecs = 4599
fdReady called with msecs = 4597
fdReady called with msecs = 4596
fdReady called with msecs = 4594
fdReady called with msecs = 4592
fdReady called with msecs = 4590
fdReady called with msecs = 4588
fdReady called with msecs = 4586
fdReady called with msecs = 4584
fdReady called with msecs = 4582
fdReady called with msecs = 4580
fdReady called with msecs = 4578
fdReady called with msecs = 4577
fdReady called with msecs = 4575
fdReady called with msecs = 4573
fdReady called with msecs = 4571
fdReady called with msecs = 4570
fdReady called with msecs = 4567
fdReady called with msecs = 4566
fdReady called with msecs = 4564
fdReady called with msecs = 4562
fdReady called with msecs = 4560
fdReady called with msecs = 4558
fdReady called with msecs = 4556
fdReady called with msecs = 4554
fdReady called with msecs = 4552
fdReady called with msecs = 4550
fdReady called with msecs = 4548
fdReady called with msecs = 4546
fdReady called with msecs = 4544
fdReady called with msecs = 4542
fdReady called with msecs = 4540
fdReady called with msecs = 4538
fdReady called with msecs = 4536
fdReady called with msecs = 4534
fdReady called with msecs = 4532
fdReady called with msecs = 4530
fdReady called with msecs = 4528
fdReady called with msecs = 4527
fdReady called with msecs = 4525
fdReady called with msecs = 4523
fdReady called with msecs = 4521
fdReady called with msecs = 4519
fdReady called with msecs = 4517
fdReady called with msecs = 4515
fdReady called with msecs = 4513
fdReady called with msecs = 4511
fdReady called with msecs = 4509
fdReady called with msecs = 4507
fdReady called with msecs = 4505
fdReady called with msecs = 4503
fdReady called with msecs = 4501
fdReady called with msecs = 4499
fdReady called with msecs = 4497
fdReady called with msecs = 4495
fdReady called with msecs = 4493
fdReady called with msecs = 4491
fdReady called with msecs = 4489
fdReady called with msecs = 4486
fdReady called with msecs = 4484
fdReady called with msecs = 4482
fdReady called with msecs = 4480
fdReady called with msecs = 4478
fdReady called with msecs = 4476
fdReady called with msecs = 4474
fdReady called with msecs = 4472
fdReady called with msecs = 4470
fdReady called with msecs = 4468
fdReady called with msecs = 4466
fdReady called with msecs = 4464
fdReady called with msecs = 4462
fdReady called with msecs = 4460
fdReady called with msecs = 4458
fdReady called with msecs = 4456
fdReady called with msecs = 4454
fdReady called with msecs = 4452
fdReady called with msecs = 4450
fdReady called with msecs = 4448
fdReady called with msecs = 4443
fdReady called with msecs = 4442
fdReady called with msecs = 4440
fdReady called with msecs = 4438
fdReady called with msecs = 4437
fdReady called with msecs = 4435
fdReady called with msecs = 4433
fdReady called with msecs = 4431
fdReady called with msecs = 4429
fdReady called with msecs = 4427
fdReady called with msecs = 4425
fdReady called with msecs = 4423
fdReady called with msecs = 4421
fdReady called with msecs = 4419
fdReady called with msecs = 4417
fdReady called with msecs = 4415
fdReady called with msecs = 4413
fdReady called with msecs = 4411
fdReady called with msecs = 4409
fdReady called with msecs = 4407
fdReady called with msecs = 4405
fdReady called with msecs = 4403
fdReady called with msecs = 4402
fdReady called with msecs = 4399
fdReady called with msecs = 4398
fdReady called with msecs = 4396
fdReady called with msecs = 4394
fdReady called with msecs = 4392
fdReady called with msecs = 4390
fdReady called with msecs = 4388
fdReady called with msecs = 4387
fdReady called with msecs = 4385
fdReady called with msecs = 4383
fdReady called with msecs = 4381
fdReady called with msecs = 4379
fdReady called with msecs = 4377
fdReady called with msecs = 4375
fdReady called with msecs = 4373
fdReady called with msecs = 4371
fdReady called with msecs = 4369
fdReady called with msecs = 4367
fdReady called with msecs = 4365
fdReady called with msecs = 4364
fdReady called with msecs = 4362
fdReady called with msecs = 4360
fdReady called with msecs = 4359
fdReady called with msecs = 4357
fdReady called with msecs = 4355
fdReady called with msecs = 4353
fdReady called with msecs = 4351
fdReady called with msecs = 4349
fdReady called with msecs = 4348
fdReady called with msecs = 4346
fdReady called with msecs = 4344
fdReady called with msecs = 4343
fdReady called with msecs = 4341
fdReady called with msecs = 4339
fdReady called with msecs = 4337
fdReady called with msecs = 4336
fdReady called with msecs = 4334
fdReady called with msecs = 4332
fdReady called with msecs = 4330
fdReady called with msecs = 4328
fdReady called with msecs = 4326
fdReady called with msecs = 4325
fdReady called with msecs = 4323
fdReady called with msecs = 4321
fdReady called with msecs = 4319
fdReady called with msecs = 4318
fdReady called with msecs = 4316
fdReady called with msecs = 4314
fdReady called with msecs = 4313
fdReady called with msecs = 4311
fdReady called with msecs = 4309
fdReady called with msecs = 4307
fdReady called with msecs = 4305
fdReady called with msecs = 4303
fdReady called with msecs = 4301
fdReady called with msecs = 4299
fdReady called with msecs = 4297
fdReady called with msecs = 4295
fdReady called with msecs = 4293
fdReady called with msecs = 4291
fdReady called with msecs = 4289
fdReady called with msecs = 4287
fdReady called with msecs = 4285
fdReady called with msecs = 4283
fdReady called with msecs = 4282
fdReady called with msecs = 4280
fdReady called with msecs = 4279
fdReady called with msecs = 4277
fdReady called with msecs = 4275
fdReady called with msecs = 4273
fdReady called with msecs = 4271
fdReady called with msecs = 4269
fdReady called with msecs = 4267
fdReady called with msecs = 4265
fdReady called with msecs = 4263
fdReady called with msecs = 4261
fdReady called with msecs = 4259
fdReady called with msecs = 4257
fdReady called with msecs = 4255
fdReady called with msecs = 4254
fdReady called with msecs = 4252
fdReady called with msecs = 4250
fdReady called with msecs = 4249
fdReady called with msecs = 4247
fdReady called with msecs = 4245
fdReady called with msecs = 4243
fdReady called with msecs = 4241
fdReady called with msecs = 4239
fdReady called with msecs = 4237
fdReady called with msecs = 4236
fdReady called with msecs = 4234
fdReady called with msecs = 4232
fdReady called with msecs = 4230
fdReady called with msecs = 4228
fdReady called with msecs = 4226
fdReady called with msecs = 4224
fdReady called with msecs = 4222
fdReady called with msecs = 4220
fdReady called with msecs = 4218
fdReady called with msecs = 4216
fdReady called with msecs = 4214
fdReady called with msecs = 4212
fdReady called with msecs = 4210
fdReady called with msecs = 4208
fdReady called with msecs = 4206
fdReady called with msecs = 4204
fdReady called with msecs = 4202
fdReady called with msecs = 4200
fdReady called with msecs = 4199
fdReady called with msecs = 4197
fdReady called with msecs = 4195
fdReady called with msecs = 4193
fdReady called with msecs = 4192
fdReady called with msecs = 4189
fdReady called with msecs = 4188
fdReady called with msecs = 4186
fdReady called with msecs = 4184
fdReady called with msecs = 4182
fdReady called with msecs = 4180
fdReady called with msecs = 4178
fdReady called with msecs = 4176
fdReady called with msecs = 4174
fdReady called with msecs = 4172
fdReady called with msecs = 4170
fdReady called with msecs = 4168
fdReady called with msecs = 4166
fdReady called with msecs = 4164
fdReady called with msecs = 4162
fdReady called with msecs = 4160
fdReady called with msecs = 4158
fdReady called with msecs = 4157
fdReady called with msecs = 4155
fdReady called with msecs = 4153
fdReady called with msecs = 4151
fdReady called with msecs = 4149
fdReady called with msecs = 4147
fdReady called with msecs = 4145
fdReady called with msecs = 4143
fdReady called with msecs = 4141
fdReady called with msecs = 4139
fdReady called with msecs = 4137
fdReady called with msecs = 4135
fdReady called with msecs = 4133
fdReady called with msecs = 4131
fdReady called with msecs = 4129
fdReady called with msecs = 4127
fdReady called with msecs = 4125
fdReady called with msecs = 4123
fdReady called with msecs = 4121
fdReady called with msecs = 4119
fdReady called with msecs = 4117
fdReady called with msecs = 4115
fdReady called with msecs = 4113
fdReady called with msecs = 4112
fdReady called with msecs = 4110
fdReady called with msecs = 4108
fdReady called with msecs = 4106
fdReady called with msecs = 4104
fdReady called with msecs = 4102
fdReady called with msecs = 4100
fdReady called with msecs = 4098
fdReady called with msecs = 4096
fdReady called with msecs = 4094
fdReady called with msecs = 4092
fdReady called with msecs = 4090
fdReady called with msecs = 4088
fdReady called with msecs = 4086
fdReady called with msecs = 4084
fdReady called with msecs = 4082
fdReady called with msecs = 4080
fdReady called with msecs = 4078
fdReady called with msecs = 4076
fdReady called with msecs = 4074
fdReady called with msecs = 4072
fdReady called with msecs = 4071
fdReady called with msecs = 4069
fdReady called with msecs = 4067
fdReady called with msecs = 4065
fdReady called with msecs = 4063
fdReady called with msecs = 4061
fdReady called with msecs = 4059
fdReady called with msecs = 4057
fdReady called with msecs = 4055
fdReady called with msecs = 4054
fdReady called with msecs = 4052
fdReady called with msecs = 4050
fdReady called with msecs = 4048
fdReady called with msecs = 4046
fdReady called with msecs = 4043
fdReady called with msecs = 4042
fdReady called with msecs = 4039
fdReady called with msecs = 4038
fdReady called with msecs = 4035
fdReady called with msecs = 4033
fdReady called with msecs = 4031
fdReady called with msecs = 4029
fdReady called with msecs = 4028
fdReady called with msecs = 4026
fdReady called with msecs = 4024
fdReady called with msecs = 4022
fdReady called with msecs = 4020
fdReady called with msecs = 4018
fdReady called with msecs = 4016
fdReady called with msecs = 4014
fdReady called with msecs = 4012
fdReady called with msecs = 4010
fdReady called with msecs = 4009
fdReady called with msecs = 4007
fdReady called with msecs = 4005
fdReady called with msecs = 4003
fdReady called with msecs = 4001
fdReady called with msecs = 3999
../8684.exe  0.00s user 0.00s system 0% cpu 1.045 total
nh2 added a comment.EditedJan 9 2018, 11:52 AM

I think the weird timing problems reported above might actually be due to Windows Defender's live scanning.

Running a compiled

import System.IO
import System.Timeout

main = timeout (1 * 1000000) $ hWaitForInput stdin (5 * 1000)

with Windows Defender's "Real-time protection" on in Windows 10 and time ../8684 gives:

../8684  0.00s user 0.05s system 2% cpu 2.151 total
../8684  0.00s user 0.01s system 0% cpu 2.047 total
../8684  0.00s user 0.00s system 0% cpu 2.070 total

and I can see Antimalware Service Executable take high CPU in Task Manager. When the real-time protection is turned off it gives:

../8684  0.00s user 0.01s system 1% cpu 1.047 total
../8684  0.00s user 0.01s system 1% cpu 1.034 total
../8684  0.00s user 0.00s system 0% cpu 1.031 total