<div dir="ltr"><div dir="ltr"><div class="gmail_default" style="font-size:large">Hi Nicolas,</div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Wed, Oct 28, 2020 at 2:21 PM Nicolas Cellier <<a href="mailto:nicolas.cellier.aka.nice@gmail.com">nicolas.cellier.aka.nice@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"> <div dir="ltr"><div dir="ltr"><br></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">Le mer. 28 oct. 2020 à 22:11, Nicolas Cellier <<a href="mailto:nicolas.cellier.aka.nice@gmail.com" target="_blank">nicolas.cellier.aka.nice@gmail.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div dir="ltr"><br></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">Le mer. 28 oct. 2020 à 17:23, Eliot Miranda <<a href="mailto:eliot.miranda@gmail.com" target="_blank">eliot.miranda@gmail.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"> <br>
Hi Tobi, Hi Levente,<br>
<br>
> On Oct 28, 2020, at 7:06 AM, Tobias Pape <<a href="mailto:Das.Linux@gmx.de" target="_blank">Das.Linux@gmx.de</a>> wrote:<br>
> <br>
> <br>
> Hi<br>
> <br>
>>>>> On 27.10.2020, at 23:39, Nicolas Cellier <<a href="mailto:nicolas.cellier.aka.nice@gmail.com" target="_blank">nicolas.cellier.aka.nice@gmail.com</a>> wrote:<br>
>> Hi Tim,<br>
>> what is the result on that box with threaded heartbeat VM of:<br>
>> [SUnitToolBuilderTests new testHandlingNotification] timeToRun.<br>
>> If it is more than 5000 ms, then you would confirm the problem that I encounter.<br>
>> This testHandlingNotification is repeating 10 loops with a 200ms delay wait.<br>
>> 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...<br>
>> This is probably what happens on the CI server too (the test times out and CI fails).<br>
> <br>
> 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.<br>
> <br>
> The code above runs in around ~2000 ms on my machine (~2015, with ubuntu 18.04)<br>
> <br>
> Things that happened:<br>
> - I just ran the test suite in the DEBUG itimer headful and headless variant and it passes.<br>
> - I just ran the test suite in the DEBUG threaded headful and headless variant and it passes.<br>
> - I ran the RELEASE itimer headful and headless variant and it passes<br>
> - I ran the RELEASE threaded headless variant and it FAILED as on the CI<br>
> - I ran the RELEASE threaded headful variant and it FAILED LESS<br>
> I mean: testHandlingNotification passed, and so did testValueWithinTimingBasic and testValueWithinTimingNestedInner<br>
> but testValueWithinTimingNestedOuter testValueWithinTimingRepeat still fail!<br>
> <br>
> So there are discrepancies between <br>
> debug and release and <br>
> headful and headless (at least for threaded release)<br>
> <br>
> TL;DR: The linux x86_32 cog v3 threaded release vm has a timing problem ...<br>
> <br>
> Does that help anyone?<br>
<br>
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.<br>
<br></blockquote><div><br></div><div>Hi Eliot,</div><div>I instrumented the code like that:</div><div><br></div><div>testHandlingNotification<br> | receivedSignal resumed |<br> receivedSignal := resumed := false.<br> [ | count |<br> "client-code puts up progress, and signals some notications"<br> Transcript cr; nextPutAll: 'test begins:'; print: Time utcMicrosecondClock \\ 3600000000.<br> count := 0.<br> 'doing something'<br> displayProgressFrom: 0<br> to: 10<br> during:<br> [ : bar | 10 timesRepeat:<br> [ bar value: (count := count + 1).<br> Transcript cr; nextPutAll: 'count:'; print: count.<br> Transcript cr; nextPutAll: 'before wait:'; print: Time utcMicrosecondClock \\ 3600000000.<br> (Delay forMilliseconds: 200) wait.<br> Transcript cr; nextPutAll: 'after wait:'; print: Time utcMicrosecondClock \\ 3600000000.<br> Notification signal: 'message'.<br> Transcript cr; nextPutAll: 'after notified:'; print: Time utcMicrosecondClock \\ 3600000000.<br> Transcript cr; nextPutAll: '# ioProcessEvents: '; print: (Smalltalk vmParameterAt: 57).<br> Transcript cr; nextPutAll: '# forceInterruptCheck: '; print: (Smalltalk vmParameterAt: 58).<br> Transcript cr; nextPutAll: '# check event calls: '; print: (Smalltalk vmParameterAt: 59).<br> resumed := true ] ] ]<br> on: Notification<br> do:<br> [ : noti | receivedSignal := true.<br> Transcript cr; nextPutAll: 'notified at:'; print: Time utcMicrosecondClock \\ 3600000000.<br> noti resume ].<br> Transcript endEntry.<br> self<br> assert: receivedSignal ;<br> assert: resumed</div><div><br></div><div>The result I obtain with an updated trunk image and 64bits threaded VM:<br></div><div>build.linux64x64/squeak.cog.spur/build$ ./squeak ../../../image/trunk6-64.image</div><div><br></div><div>test begins:80631205<br>notified at:80631251<br>count:1<br>before wait:80633324<br>after wait:80834614<br>after notified:80834670<br># ioProcessEvents: 94<br># forceInterruptCheck: 3368<br># check event calls: 815<br>count:2<br>before wait:80835008<br>after wait:81036398<br>after notified:81036454<br># ioProcessEvents: 103<br># forceInterruptCheck: 3459<br># check event calls: 906<br>count:3<br>before wait:81036755<br>after wait:81238355<br>after notified:81238374<br># ioProcessEvents: 113<br># forceInterruptCheck: 3549<br># check event calls: 996<br>count:4<br>before wait:81238633<br>after wait:81440889<br>after notified:81440909<br># ioProcessEvents: 123<br># forceInterruptCheck: 3639<br># check event calls: 1086<br>count:5<br>before wait:81441151<br>after wait:82609021<br>after notified:82609053<br># ioProcessEvents: 132<br># forceInterruptCheck: 4119<br># check event calls: 1161<br>count:6<br>before wait:82609520<br>after wait:83611465<br>after notified:83611497<br># ioProcessEvents: 133<br># forceInterruptCheck: 4536<br># check event calls: 1162<br>count:7<br>before wait:83611974<br>after wait:84614429<br>after notified:84614462<br># ioProcessEvents: 134<br># forceInterruptCheck: 4961<br># check event calls: 1165<br>count:8<br>before wait:84614926<br>after wait:85617377<br>after notified:85617404<br># ioProcessEvents: 135<br># forceInterruptCheck: 5368<br># check event calls: 1166<br>count:9<br>before wait:85617840<br>after wait:86618396<br>after notified:86618428<br># ioProcessEvents: 136<br># forceInterruptCheck: 5776<br># check event calls: 1167<br>count:10<br>before wait:86618896<br>after wait:87620232<br>after notified:87620291<br># ioProcessEvents: 137<br># forceInterruptCheck: 6196<br># check event calls: 1168</div><div><br></div><div>Notice 10 ioProcessEvents and about 200ms wait on loop 1-5.</div><div>Then a single ioProcessEvent and about 1000ms wait on loops 6-10 (single check event call too).<br></div></div></div></blockquote><div><br></div><div>and on itimer heatbeat, 200ms per loop, 10 ioProcessEvents, 100 forceInterruptCheck and 100 check event calls</div><div>This is consistent with the 2ms heartbeat (vmParameter #26).<br></div><div> linux64x64/squeak.cog.spur/build.itimerheartbeat$ ./squeak ../../../image/trunk6-64.image</div><div><br></div><div> test begins:1013906366<br>notified at:1013906407<br>count:1<br>before wait:1013910362<br>after wait:1014112028<br>after notified:1014112085<br># ioProcessEvents: 208<br># forceInterruptCheck: 2299<br># check event calls: 2236<br>count:2<br>before wait:1014112443<br>after wait:1014314011<br>after notified:1014314062<br># ioProcessEvents: 218<br># forceInterruptCheck: 2400<br># check event calls: 2337<br>count:3<br>before wait:1014314405<br>after wait:1014516017<br>after notified:1014516052<br># ioProcessEvents: 228<br># forceInterruptCheck: 2501<br># check event calls: 2438<br>count:4<br>before wait:1014516326<br>after wait:1014718011<br>after notified:1014718039<br># ioProcessEvents: 237<br># forceInterruptCheck: 2602<br># check event calls: 2539<br>count:5<br>before wait:1014718296<br>after wait:1014920490<br>after notified:1014920521<br># ioProcessEvents: 247<br># forceInterruptCheck: 2703<br># check event calls: 2640<br>count:6<br>before wait:1014920967<br>after wait:1015122184<br>after notified:1015122215<br># ioProcessEvents: 256<br># forceInterruptCheck: 2804<br># check event calls: 2741<br>count:7<br>before wait:1015122608<br>after wait:1015324166<br>after notified:1015324198<br># ioProcessEvents: 266<br># forceInterruptCheck: 2905<br># check event calls: 2841<br>count:8<br>before wait:1015324595<br>after wait:1015526278<br>after notified:1015526299<br># ioProcessEvents: 275<br># forceInterruptCheck: 3006<br># check event calls: 2942<br>count:9<br>before wait:1015526556<br>after wait:1015728488<br>after notified:1015728518<br># ioProcessEvents: 285<br># forceInterruptCheck: 3107<br># check event calls: 3042<br>count:10<br>before wait:1015728947<br>after wait:1015930499<br>after notified:1015930530<br># ioProcessEvents: 295<br># forceInterruptCheck: 3208<br># check event calls: 3143</div></div></div></blockquote><div><br></div><div class="gmail_default" style="font-size:large">Thanks that's great. SO the problem is nothing to do with the heartbeat. It seems to be working perfectly OK, right?</div><div class="gmail_default" style="font-size:large"></div></div><div dir="ltr" class="gmail_signature"><div dir="ltr"><div><span style="font-size:small;border-collapse:separate"><div>_,,,^..^,,,_<br></div><div>best, Eliot</div></span></div></div></div></div>