Tcl Source Code

The runtime of [update] explodes with the number of events to work on. This is illustrated by this script:

proc stack_after_idle {howmuch} {
    for {set i 0} {$i < $howmuch} {incr i} {
        after idle {
            # Do something.
            set foo bar
        }
    }
}
 
foreach howmuch {
    10000
    20000
    40000
    60000
} {
    stack_after_idle $howmuch
    set start [clock milliseconds]
    update
    puts "$howmuch: [expr {[clock milliseconds] - $start}]"
}


It isnt' obvious, why the overhead isn't linear to the nr of events.

I made a small review and several fixes after comparison to my forks of 8.5-th/8.6-th branches.

Reintegrated resp. back-ported as 8.6-th based into [sebres-8-6-event-perf-branch].

I finished my rebase (currently for 8.5 only, can be reintegrated higher), and placed it on my github sebres/tcl#4 as interim artificial PR (squashed).

This is although a biggish RFE, where all changes together makes sense only (of course some things can be changed/reverted), but basically as ultimate only...

BTW this also fully implements TIP #302 and many many other things, always bothering me.

I would like to make a decent rebase to fossil with commit-history and review (because backported from my own fork, that is much more sophisticated and very much further developed as standard tcl-core). And then merge it to 8.6/trunk branches. Currently all test-cases passes on my unix/windows systems.

But firstly I would like know if this is imaginable to be a part of core at all? Just because I already invested here too many time and effort by the back-porting (not to mention the development). So I would avoid more effort on my part, if it would meet again on lack of understanding of the TCT (basically I have just no time to work for the recycle-bin)...

What's about this implementation of TIP #302 (and monotonic based time-handling): - on all my systems (many projects, some of them very very large) it worked a long time (several years) without any problem. - in all of this projects only few lines were changed from "after $startOffset ..." to "after at $startTime ..." (was originally named "after -term"). But this changes were not really necessary, because almost all the time-jumps are short adjustments of NTP-service and in the worse case some "cron" task with absolute time will be executed just few seconds later as expected. But in the most cases the due-time is anyway long interval. In my opinion exactly very short intervals (so no "cron" tasks) but retarded events are more important: if you do a lot of events like "after 5 [list accept $sock]" and they will be executed firstly in 10 seconds (if the time jumps backwards) it would be IMHO much worse as retarded "cron" event which due-time is first in 1 hour. I mean the relation between "5ms" and "10s" is much more serious as "1h" and "1h+10s".

Also I'm totally agree with Kevin and I mean the pros outweigh the cons many times, also if it may potential break theoretical possible incompatibility.

All other changes are totally backwards-compatible (and I tried to hold all the enhancements in API as non-public, except the tcl-commands).

So I'm open and waiting for review, objections and conclusions...

Thx and regards, Sergey.

Sorry for silence, I had short vacation...

> Does this change fix the problem pointsman reported? 

Conditionally, because the whole handling round about tcl timer events is very slow. 
E. g. for the canceling, the event should be firstly found in the list (no matter whether forwards or backwards).
I've made it a little bit differently - the pointer to the timer-event saved in the object representation (so can be used directly).
I'll commit now my "ultimate" solution for this + small bonus on top...

Christian, I like this change. Looks good to me.

@sebres. Does this change fix the problem pointsman reported? If not, I would still like to merge Christian's proposal to core-8-6-branch (after doing some more testing, of course). But first I would like to know if this change is sufficient or maybe that more changes will be needed to address this fully.

Thanks, Christian!

The changes in https://www.androwish.org/index.html/info/f97755fb7cf48507
add a "previous" pointer to the AfterInfo struct and eliminate some
otherwise expensive iterations.

Below enclosed an excerpt just to exactly represent the issue of the subject (exploding runtime with growing list of events):

 ********************************************************************************
 *** 10000 events ***
 ********************************************************************************
-Total 8 cases in 4.67 sec. (3.65 nett-sec.):
+Total 8 cases in 0.04 sec. (0.03 nett-sec.):
 Average:
-456355.125000 µs/# 1 # 2 #/sec 456.355 nett-ms
+3580.625000 µs/# 1 # 279 #/sec 3.581 nett-ms
 Min:
-206160.0 µs/# 1 # 4.851 #/sec 206.160 nett-ms
+2363.00 µs/# 1 # 423.19 #/sec 2.363 nett-ms
 Max:
-1035573 µs/# 1 # 0.966 #/sec 1035.573 nett-ms
+5026.00 µs/# 1 # 198.97 #/sec 5.026 nett-ms
 ********************************************************************************
 *** 20000 events ***
 ********************************************************************************
-Total 8 cases in 24.93 sec. (19.64 nett-sec.):
+Total 8 cases in 0.13 sec. (0.06 nett-sec.):
 Average:
-2455366.875000 µs/# 1 # 0 #/sec 2455.367 nett-ms
+7244.250000 µs/# 1 # 138 #/sec 7.244 nett-ms
 Min:
-1053719 µs/# 1 # 0.949 #/sec 1053.719 nett-ms
+5015.00 µs/# 1 # 199.40 #/sec 5.015 nett-ms
 Max:
-5089423 µs/# 1 # 0.196 #/sec 5089.423 nett-ms
+9334.00 µs/# 1 # 107.14 #/sec 9.334 nett-ms
 ********************************************************************************
 *** 40000 events ***
 ********************************************************************************
-Total 8 cases in 136.16 sec. (109.02 nett-sec.):
+Total 8 cases in 0.27 sec. (0.12 nett-sec.):
 Average:
-13627877.125000 µs/# 1 # 0 #/sec 13627.877 nett-ms
+14827.375000 µs/# 1 # 67 #/sec 14.827 nett-ms
 Min:
-6220205 µs/# 1 # 0.161 #/sec 6220.205 nett-ms
+10186.0 µs/# 1 # 98.174 #/sec 10.186 nett-ms
 Max:
-26786735 µs/# 1 # 0.037 #/sec 26786.735 nett-ms
+18437.0 µs/# 1 # 54.239 #/sec 18.437 nett-ms
 ********************************************************************************
 *** 60000 events ***
 ********************************************************************************
-Total 8 cases in 425.33 sec. (346.60 nett-sec.):
+Total 8 cases in 0.38 sec. (0.17 nett-sec.):
 Average:
-43324884.250000 µs/# 1 # 0 #/sec 43324.884 nett-ms
+21700.250000 µs/# 1 # 46 #/sec 21.700 nett-ms
 Min:
-15858878 µs/# 1 # 0.063 #/sec 15858.878 nett-ms
+14384.0 µs/# 1 # 69.522 #/sec 14.384 nett-ms
 Max:
-93546474 µs/# 1 # 0.011 #/sec 93546.474 nett-ms
+27942.0 µs/# 1 # 35.788 #/sec 27.942 nett-ms
 ********************************************************************************

In the meantime as long as I rebase my events-performance branch, attached a diff with comparison (to core-8-5-branch with timerate).

I'm doing it soon

So, sebres, it's up to you to provide more input/patch. It's appreciated!

gcov points pretty clearly to tclTimer.c:1178 - which makes sense, as after events are executed in FIFO order but the AfterAssocData list is filled in reverse.

https://core.tcl.tk/tcl/artifact/f53860c8d7315222?ln=1178-1181

I see sebres is way ahead of me, so won't attempt a patch .. getting my hands dirty with gcov was still worth it!

I know already this issue (or the same by comparable one with usage of `after 0` instead of `after idle`).
And I've a branch where it is fixed, would try to port it in tcl-core.

BTW. It's currently possible as replacement for this to use the thread::send -async to self (needed thread package).
I known it not really the same as after idle, but...

So JFYI (hope it helps):
```
package require Thread

proc stack_after_idle {howmuch} {
    time {
        thread::send -async [thread::id] {
            # Do something.
            set foo bar
        }
    } $howmuch
}

foreach howmuch {
    10000
    20000
    40000
    60000
} {
    stack_after_idle $howmuch
    set start [clock milliseconds]
    update
    puts "$howmuch: [expr {[clock milliseconds] - $start}]"
}
```

You'll see it has a linear execution time:

10000: 11
20000: 22
40000: 44
60000: 66