[Vm-dev] CI status

Wed Oct 28 21:21:35 UTC 2020

Le mer. 28 oct. 2020 à 22:11, Nicolas Cellier <
nicolas.cellier.aka.nice at gmail.com> a écrit :

>
>
> Le mer. 28 oct. 2020 à 17:23, Eliot Miranda <eliot.miranda at gmail.com> a
> écrit :
>
>>
>> Hi Tobi, Hi Levente,
>>
>> > On Oct 28, 2020, at 7:06 AM, Tobias Pape <Das.Linux at gmx.de> wrote:
>> >
>> > 
>> > Hi
>> >
>> >>>>> On 27.10.2020, at 23:39, Nicolas Cellier <
>> nicolas.cellier.aka.nice at gmail.com> wrote:
>> >> Hi Tim,
>> >> what is the result on that box with threaded heartbeat VM of:
>> >> [SUnitToolBuilderTests new testHandlingNotification] timeToRun.
>> >> If it is more than 5000 ms, then you would confirm the problem that I
>> encounter.
>> >> This testHandlingNotification is repeating 10 loops with a 200ms delay
>> wait.
>> >> The problem I've got with threaded heartbeat VM is that first 5 delays
>> run normally, but next 5 will last for 1 second instead of 200ms...
>> >> This is probably what happens on the CI server too (the test times out
>> and CI fails).
>> >
>> > Also note that the CI test builds both vms but uses the last one built
>> (because it overwrites the first), and that happens to be the itimer one,
>> not th ethreaded.
>> >
>> > The code above runs in around ~2000 ms on my machine (~2015, with
>> ubuntu 18.04)
>> >
>> > Things that happened:
>> > - I just ran the test suite in the DEBUG itimer headful and headless
>> variant and it passes.
>> > - I just ran the test suite in the DEBUG threaded headful and headless
>> variant and it passes.
>> > - I ran the RELEASE itimer headful and headless variant and it passes
>> > - I ran the RELEASE threaded headless variant and it FAILED as on the CI
>> > - I ran the RELEASE threaded headful variant and it FAILED LESS
>> >     I mean: testHandlingNotification passed, and so did
>> testValueWithinTimingBasic and testValueWithinTimingNestedInner
>> >     but testValueWithinTimingNestedOuter testValueWithinTimingRepeat
>> still fail!
>> >
>> > So there are discrepancies between
>> > debug and release    and
>> > headful and headless    (at least for threaded release)
>> >
>> > TL;DR: The linux x86_32 cog v3 threaded release vm has a timing problem
>> ...
>> >
>> > Does that help anyone?
>>
>> If you add code to extract the number of ioProcessEvents calls etc (see
>> About Squeak VM parameters tab for the relevant info) does that tell us
>> more?  IIRC one available vm parameter is the number of heartbeats.  So we
>> should be able to see if it is the heartbeat itself that is failing or if
>> it is further up stream.
>>
>>
> Hi Eliot,
> I instrumented the code like that:
>
> testHandlingNotification
>     | receivedSignal resumed |
>     receivedSignal := resumed := false.
>     [ | count |
>     "client-code puts up progress, and signals some notications"
>     Transcript cr; nextPutAll: 'test begins:'; print: Time
> utcMicrosecondClock \\ 3600000000.
>     count := 0.
>     'doing something'
>         displayProgressFrom: 0
>         to: 10
>         during:
>             [ : bar | 10 timesRepeat:
>                 [ bar value: (count := count + 1).
>                 Transcript cr; nextPutAll: 'count:'; print: count.
>                 Transcript cr; nextPutAll: 'before wait:'; print: Time
> utcMicrosecondClock \\ 3600000000.
>                 (Delay forMilliseconds: 200) wait.
>                 Transcript cr; nextPutAll: 'after wait:'; print: Time
> utcMicrosecondClock \\ 3600000000.
>                 Notification signal: 'message'.
>                 Transcript cr; nextPutAll: 'after notified:'; print: Time
> utcMicrosecondClock \\ 3600000000.
>                 Transcript cr; nextPutAll: '# ioProcessEvents: '; print:
> (Smalltalk vmParameterAt: 57).
>                 Transcript cr; nextPutAll: '# forceInterruptCheck: ';
> print: (Smalltalk vmParameterAt: 58).
>                 Transcript cr; nextPutAll: '# check event calls: '; print:
> (Smalltalk vmParameterAt: 59).
>                 resumed := true ] ] ]
>         on: Notification
>         do:
>             [ : noti | receivedSignal := true.
>             Transcript cr; nextPutAll: 'notified at:'; print: Time
> utcMicrosecondClock \\ 3600000000.
>             noti resume ].
>     Transcript endEntry.
>     self
>          assert: receivedSignal ;
>          assert: resumed
>
> The result I obtain with an updated trunk image and 64bits threaded VM:
> build.linux64x64/squeak.cog.spur/build$ ./squeak
> ../../../image/trunk6-64.image
>
> test begins:80631205
> notified at:80631251
> count:1
> before wait:80633324
> after wait:80834614
> after notified:80834670
> # ioProcessEvents: 94
> # forceInterruptCheck: 3368
> # check event calls: 815
> count:2
> before wait:80835008
> after wait:81036398
> after notified:81036454
> # ioProcessEvents: 103
> # forceInterruptCheck: 3459
> # check event calls: 906
> count:3
> before wait:81036755
> after wait:81238355
> after notified:81238374
> # ioProcessEvents: 113
> # forceInterruptCheck: 3549
> # check event calls: 996
> count:4
> before wait:81238633
> after wait:81440889
> after notified:81440909
> # ioProcessEvents: 123
> # forceInterruptCheck: 3639
> # check event calls: 1086
> count:5
> before wait:81441151
> after wait:82609021
> after notified:82609053
> # ioProcessEvents: 132
> # forceInterruptCheck: 4119
> # check event calls: 1161
> count:6
> before wait:82609520
> after wait:83611465
> after notified:83611497
> # ioProcessEvents: 133
> # forceInterruptCheck: 4536
> # check event calls: 1162
> count:7
> before wait:83611974
> after wait:84614429
> after notified:84614462
> # ioProcessEvents: 134
> # forceInterruptCheck: 4961
> # check event calls: 1165
> count:8
> before wait:84614926
> after wait:85617377
> after notified:85617404
> # ioProcessEvents: 135
> # forceInterruptCheck: 5368
> # check event calls: 1166
> count:9
> before wait:85617840
> after wait:86618396
> after notified:86618428
> # ioProcessEvents: 136
> # forceInterruptCheck: 5776
> # check event calls: 1167
> count:10
> before wait:86618896
> after wait:87620232
> after notified:87620291
> # ioProcessEvents: 137
> # forceInterruptCheck: 6196
> # check event calls: 1168
>
> Notice 10 ioProcessEvents and about 200ms wait on loop 1-5.
> Then a single ioProcessEvent and about 1000ms wait on loops 6-10 (single
> check event call too).
>

and on itimer heatbeat, 200ms per loop, 10 ioProcessEvents, 100
forceInterruptCheck and 100 check event calls
This is consistent with the 2ms heartbeat (vmParameter #26).
linux64x64/squeak.cog.spur/build.itimerheartbeat$ ./squeak
../../../image/trunk6-64.image

test begins:1013906366
notified at:1013906407
count:1
before wait:1013910362
after wait:1014112028
after notified:1014112085
# ioProcessEvents: 208
# forceInterruptCheck: 2299
# check event calls: 2236
count:2
before wait:1014112443
after wait:1014314011
after notified:1014314062
# ioProcessEvents: 218
# forceInterruptCheck: 2400
# check event calls: 2337
count:3
before wait:1014314405
after wait:1014516017
after notified:1014516052
# ioProcessEvents: 228
# forceInterruptCheck: 2501
# check event calls: 2438
count:4
before wait:1014516326
after wait:1014718011
after notified:1014718039
# ioProcessEvents: 237
# forceInterruptCheck: 2602
# check event calls: 2539
count:5
before wait:1014718296
after wait:1014920490
after notified:1014920521
# ioProcessEvents: 247
# forceInterruptCheck: 2703
# check event calls: 2640
count:6
before wait:1014920967
after wait:1015122184
after notified:1015122215
# ioProcessEvents: 256
# forceInterruptCheck: 2804
# check event calls: 2741
count:7
before wait:1015122608
after wait:1015324166
after notified:1015324198
# ioProcessEvents: 266
# forceInterruptCheck: 2905
# check event calls: 2841
count:8
before wait:1015324595
after wait:1015526278
after notified:1015526299
# ioProcessEvents: 275
# forceInterruptCheck: 3006
# check event calls: 2942
count:9
before wait:1015526556
after wait:1015728488
after notified:1015728518
# ioProcessEvents: 285
# forceInterruptCheck: 3107
# check event calls: 3042
count:10
before wait:1015728947
after wait:1015930499
after notified:1015930530
# ioProcessEvents: 295
# forceInterruptCheck: 3208
# check event calls: 3143
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squeakfoundation.org/pipermail/vm-dev/attachments/20201028/2c6b4b28/attachment.html>