Tcl Source Code

View Ticket
Login
Ticket UUID: 2904418
Title: One millisecond of busyloop in [after]
Type: Bug Version: None
Submitter: ferrieux Created on: 2009-11-26 10:01:46
Subsystem: 03. Timer Events Assigned To: kennykb
Priority: 8 Severity:
Status: Closed Last Modified: 2010-10-29 23:37:40
Resolution: Duplicate Closed By: ferrieux
    Closed on: 2010-10-29 16:37:40
Description:
A synchronous [after] may waste up to a full millisecond of CPU busylooping on gettimeofday().
Strace -tt -T output from an interactive tclsh where I typed "after 10":

10:43:11.589638 read(0, "after 10\n", 4096) = 9 <3.160754>
10:43:14.750481 gettimeofday({1259228594, 750498}, NULL) = 0 <0.000006>
10:43:14.750519 gettimeofday({1259228594, 750535}, NULL) = 0 <0.000006>
10:43:14.750555 gettimeofday({1259228594, 750571}, NULL) = 0 <0.000005>
10:43:14.750593 select(0, NULL, NULL, NULL, {0, 9000}) = 0 (Timeout) <0.009340>
10:43:14.759973 gettimeofday({1259228594, 759991}, NULL) = 0 <0.000007>
10:43:14.760021 gettimeofday({1259228594, 760035}, NULL) = 0 <0.000005>
10:43:14.760055 gettimeofday({1259228594, 760069}, NULL) = 0 <0.000006>
10:43:14.760094 gettimeofday({1259228594, 760106}, NULL) = 0 <0.000004>
10:43:14.760132 gettimeofday({1259228594, 760144}, NULL) = 0 <0.000006>
10:43:14.760162 gettimeofday({1259228594, 760177}, NULL) = 0 <0.000007>
10:43:14.760197 gettimeofday({1259228594, 760209}, NULL) = 0 <0.000006>
10:43:14.760234 gettimeofday({1259228594, 760248}, NULL) = 0 <0.000005>
10:43:14.760268 gettimeofday({1259228594, 760281}, NULL) = 0 <0.000005>
10:43:14.760299 gettimeofday({1259228594, 760311}, NULL) = 0 <0.000005>
10:43:14.760331 gettimeofday({1259228594, 760344}, NULL) = 0 <0.000006>
10:43:14.760362 gettimeofday({1259228594, 760375}, NULL) = 0 <0.000005>
10:43:14.760397 gettimeofday({1259228594, 760413}, NULL) = 0 <0.000007>
10:43:14.760432 gettimeofday({1259228594, 760444}, NULL) = 0 <0.000006>
10:43:14.760462 gettimeofday({1259228594, 760474}, NULL) = 0 <0.000005>
10:43:14.760492 gettimeofday({1259228594, 760505}, NULL) = 0 <0.000005>
10:43:14.760534 write(1, "% ", 2)       = 2 <0.000009>
10:43:14.760575 read(0, 

Clearly what happens is a rounding problem: the select() does an efficient wait on the integer part, in milliseconds, of the computed ETA, then the loop in AfterDelay checks again, and finds a submillisecond remaining time, so no more select()s, and busily calls gettimeofday until the target is reached.

(As a side note, the fact that the select() rounds to milliseconds while its argument is in microseconds seems strange. But this is a red herring, since the OS's resolution isn't that fine anyway).

I think that [after] should have a declared policy of either "undershooting" (floor of value) or "overshooting" (ceiling of value) to compute the select() millisecond timeout, and just call it once and return, without busylooping to fine-tune the result. The rationale is that anybody wanting a non-drifting clock can simply use [clock clicks] or [clock milliseconds] and recompute his [after] argument. Atomic accuracy of [after] is a pipe dream in soft-realtime OSes in any case.

FWIW, I put this a high prio even though it is an old bug, because, it completely cripples the performance of a script of mine which otherwise happily swallows megabits per seconds of MPEG TS stream and achieves absolutely no drift. Yes, in Tcl :)
User Comments: ferrieux added on 2010-10-29 23:37:40:

allow_comments - 1

Marking this one as dupe, since 2905784 has the final patch grouping [after] optimizations.

ferrieux added on 2009-11-30 07:22:40:
Also see 2905784 for further squeezing out of unneeded gettimeofday()s.

ferrieux added on 2009-11-27 20:25:47:
Attached trivial patch breaking out of the loop when <1ms is left.
Please review.

ferrieux added on 2009-11-27 20:23:21:

File Added - 352776: after.patch

dkf added on 2009-11-26 17:14:11:
At least that will stop me from worrying about the granularity of poll() when I get back to working on the poll-based notifier (it's also millisecond-level).

Attachments: