<div dir="ltr"><div>I noticed that many crash happen in testSendTimeout.</div><div>This test is organizing a race:</div><div>- Smalltalk fill the socket send buffer</div><div>- the OS tries to drain</div><div><br></div><div>The other thing I noticed is that <font face="verdana,sans-serif">[</font>SocketTest suite run] takes 7 to 8s on macos while only 2 to 3s on ubuntu and windows</div><div>So it might be that some test times out on macos, while it doesn't on other OS.</div><div><br></div><div>This would explain that many crash also happen in JITted Timer loop, and that we cannot observe it in other OSes.</div><div><br></div><div>The access to OS ressources and the race may also explain some randomization of the crash...<br></div><div><br></div><div>So one idea would be to make the test timeout in linux too, see if we can make it crash then try using rr.</div><div>Maybe it's possible with a huge Socket buffer, a smaller image side buffer (we could reduce the size from 1000 to 1 so as to increase overhead).</div><div><br></div><div>It's just theories I tried to construct while biking, not in front of a keyboard, and I won't be able to verify until this evening...</div><div>But the watchpoint strategy is too much vain shooting in the dark, we need more ellaborated plans ;)<br></div><div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">Le mar. 24 sept. 2019 à 00:28, Nicolas Cellier <<a href="mailto:nicolas.cellier.aka.nice@gmail.com">nicolas.cellier.aka.nice@gmail.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid 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 mar. 24 sept. 2019 à 00:25, 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:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>Follow up: so we have a problem of repeatability...</div><div>I found nothing like rr for macos, and CPU watchpoint capability is too restricted to be usefull.</div><div><br></div><div>So what I did is save a crash.image attempting to crash at resumption time:</div><div> Smalltalk saveAs: 'crash'.<br> Smalltalk snapshot: true andQuit: true.<br> 5 timesRepeat: [SocketTest suite run].<br></div><div><br></div><div>Then I launched the vm under lldb and gathered $pc stats to see if I could observe some reproducibility</div><div>(lldb) p/x $pc - methodZoneBase<br>0x00000000000a0e94<br>0x0000000000090f70<br>0x000000000009f824<br>0x000000000009bfc8<br>0x000000000009d030<br>0x000000000009c7c0<br>0x00000000000951e0<br>0x00000000000949c8 <- once<br>0x0000000000094418<br>0x00000000000949c8 <— twice<br>0x000000000009b848<br>0x00000000000a0e94 <- twice<br>0x000000000009a176<br>0x000000006dfff2e0 ???<br>0x00000000000996d1<br>0x00000000000949c8 <- thrice good candidate for watchpoint set<br>0x000000000009ae70<br>0x000000000009ae70<br>0x00000000000a18e7<br>0x0000000000095470<br>0x000000000009c458<br>0x00000000000a0a7c<br>0x0000000000093e89<br>0x000000000009beb0<br>0x0000000000095a37<br>0x0000000000095408<br>0x00000000000a06bc<br>0x000000000009cd48<br>0x0000000000095408 <- twice<br>0x000000000009ba41<br>0x0000000000095408 <- thrice new candidate for watchpoint set<br>0x0000000000045258 <— smallest ever<br>0x000000000009c7c0<br>0x0000000000095408 <- fourth ! the watch point was set here, why didn’t it stop??? argh methodZoneBase was incremented after I set the watchpoint!!!<br>0x00000000000a12dc<br>0x00000000000951e0<br>0x00000000000a0e24<br>0x000000000009ff8c<br>0x000000000009c7f6<br>0x000000000009a626</div><div><br></div><div>Then I have chosen to watch the most frequent crash address,</div><div>that is methodZoneBase+0x0000000000095408,</div><div>Unfortunately, s commented above, I missed one (I set the watchpoint too early, before methodZoneBase took its definitive address).</div><div><br></div><div> And after a few (a bunch of) trials, here is what I found:</div><div><br></div><div>(lldb) run ../../image/crash.image<br>There is a running process, kill it and restart?: [Y/n] <br>Process 28175 exited with status = 9 (0x00000009) <br>Process 28185 launched: '/Users/nicolas/Smalltalk/OpenSmalltalk/opensmalltalk-vm/build.macos64x64/squeak.cog.spur/Squeak.app/Contents/MacOS/Squeak' (x86_64)<br>Squeak was compiled with optimization - stepping may behave oddly; variables may not be available.<br>Process 28185 stopped<br>* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 6.1<br> frame #0: 0x000000010007bc22 Squeak`-[sqSqueakOSXApplication doHeadlessSetup](self=0x000000010066fc00, _cmd="doHeadlessSetup") at sqSqueakOSXApplication.m:125 [opt]<br> 122 //No super call here as we've already set headless from command line or info.plist<br> 123 extern BOOL gSqueakHeadless; <br> 124 // Notice that setActivationPolicy: is available in OSX 10.6 and later<br>-> 125 if ([NSApp respondsToSelector:@selector(setActivationPolicy:)]) {<br> 126 if (gSqueakHeadless) {<br> 127 [NSApp setActivationPolicy:NSApplicationActivationPolicyProhibited];<br> 128 } else {<br>Target 0: (Squeak) stopped.<br>(lldb) wa s e -s 1 -- methodZoneBase+0x0000000000095408<br>Watchpoint created: Watchpoint 33: addr = 0x107c58138 size = 1 state = enabled type = w<br> new value: -3689348814741910324<br>(lldb) cont<br>Process 28185 resuming<br><br>Watchpoint 33 hit:<br>old value: -3689348814741910324<br>new value: -3689348814741910836<br>Process 28185 stopped<br>* thread #1, queue = 'com.apple.main-thread', stop reason = watchpoint 33<br> frame #0: 0x00000001000731dc Squeak`fillInMethodHeadersizeselector(method=0x0000000107c58130, size=544, selector=4435118304) at cogitX64SysV.c:6320 [opt]<br> 6317 sqInt rawHeader;<br> 6318 <br> 6319 (method->cmType = CMMethod);<br>-> 6320 (method->objectHeader = nullHeaderForMachineCodeMethod());<br> 6321 (method->blockSize = size);<br> 6322 (method->methodObject = methodObj);<br> 6323 <br>Target 0: (Squeak) stopped.<br>(lldb) <br>Process 28185 resuming<br><br>Watchpoint 33 hit:<br>old value: -3689348814741910836<br>new value: -3689571654825360894<br>Process 28185 stopped<br>* thread #1, queue = 'com.apple.main-thread', stop reason = watchpoint 33<br> frame #0: 0x0000000100073255 Squeak`fillInMethodHeadersizeselector(method=0x0000000107c58130, size=544, selector=4435118304) at cogitX64SysV.c:6339 [opt]<br> 6336 (method->selector = selector);<br> 6337 (method->cmNumArgs = argumentCountOfMethodHeader(methodHeader));<br> 6338 (method->cmHasMovableLiteral = hasMovableLiteral);<br>-> 6339 if ((method->cmRefersToYoung = hasYoungReferent)) {<br> 6340 addToYoungReferrers(method);<br> 6341 }<br> 6342 (method->cmUsageCount = initialMethodUsageCount());<br>Target 0: (Squeak) stopped.<br>(lldb) bt<br>* thread #1, queue = 'com.apple.main-thread', stop reason = watchpoint 33<br> * frame #0: 0x0000000100073255 Squeak`fillInMethodHeadersizeselector(method=0x0000000107c58130, size=544, selector=4435118304) at cogitX64SysV.c:6339 [opt]<br> frame #1: 0x000000010004f90c Squeak`compileCogMethod [inlined] generateCogMethod(selector=<unavailable>) at cogitX64SysV.c:7098 [opt]<br> frame #2: 0x000000010004f7a5 Squeak`compileCogMethod(selector=4435118304) at cogitX64SysV.c:27780 [opt]<br> frame #3: 0x000000010004bc54 Squeak`cogselector(aMethodObj=4468481712, aSelectorOop=4435118304) at cogitX64SysV.c:4833 [opt]<br> frame #4: 0x0000000100013d4d Squeak`primitiveClosureValue at gcc3x-cointerp.c:27237 [opt]<br> frame #5: 0x0000000107bd1925<br> frame #6: 0x000000010000236b Squeak`interpret at gcc3x-cointerp.c:2767 [opt]<br> frame #7: 0x000000010008ed55 Squeak`-[sqSqueakMainApplication runSqueak](self=0x000000010066fc00, _cmd=<unavailable>) at sqSqueakMainApplication.m:201 [opt]<br> frame #8: 0x00007fff44b077b8 Foundation`__NSFirePerformWithOrder + 360<br> frame #9: 0x00007fff4297cf57 CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_AN_OBSERVER_CALLBACK_FUNCTION__ + 23<br> frame #10: 0x00007fff4297ce7f CoreFoundation`__CFRunLoopDoObservers + 527<br> frame #11: 0x00007fff4295f3f8 CoreFoundation`__CFRunLoopRun + 1240<br> frame #12: 0x00007fff4295ec93 CoreFoundation`CFRunLoopRunSpecific + 483<br> frame #13: 0x00007fff41c49d96 HIToolbox`RunCurrentEventLoopInMode + 286<br> frame #14: 0x00007fff41c49a0f HIToolbox`ReceiveNextEventCommon + 366<br> frame #15: 0x00007fff41c49884 HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter + 64<br> frame #16: 0x00007fff3fef9a73 AppKit`_DPSNextEvent + 2085<br> frame #17: 0x00007fff4068fe34 AppKit`-[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 3044<br> frame #18: 0x00007fff3feee885 AppKit`-[NSApplication run] + 764<br> frame #19: 0x00007fff3febda72 AppKit`NSApplicationMain + 804<br> frame #20: 0x00007fff6a88c015 libdyld.dylib`start + 1<br>(lldb) <br></div><div><br></div><div>Here I don't know how to proceed, because I have no knowledge of this part of the VM, it's also quite late now...<br></div><div>Eliot, does it ring some bell?<br></div></div><br></blockquote><div><br></div><div>Ah, forget it, I thought it was overwriting, but it is the first write on yet virgin methodeZone...</div><div>(it's just that the scenario was different from all the previous run)<br></div><div> <br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div class="gmail_quote"><div dir="ltr" class="gmail_attr">Le dim. 22 sept. 2019 à 11:21, Jan Vrany <<a href="mailto:jan.vrany@fit.cvut.cz" target="_blank">jan.vrany@fit.cvut.cz</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <br>
On 2019-09-22 10:57, Nicolas Cellier wrote:<br>
> Hi Jan,<br>
> Thanks, a recording debugger would indeed be a tremendous help!<br>
> Unfortunately, I'm unable to reproduce the bug under linux, only<br>
> macosx...<br>
> Do you know something equivalent to rr for mac?<br>
<br>
No, I don't. There might be something though, I never had a mac...<br>
<br>
Jan<br>
<br>
> <br>
> Le dim. 22 sept. 2019 à 09:55, Jan Vrany <<a href="mailto:jan.vrany@fit.cvut.cz" target="_blank">jan.vrany@fit.cvut.cz</a>> a<br>
> écrit :<br>
> <br>
>> Hi,<br>
>><br>
>>><br>
>>> - can anyone think of any other strategies I might take to try and<br>
>>> reproduce this?<br>
>>><br>
>> at the risk of stating the obvious, in cases similar to this rr (+<br>
>> VDB)<br>
>> helped<br>
>> me many times. See <a href="https://www.youtube.com/watch?v=Qbu4ED8wPYE" rel="noreferrer" target="_blank">https://www.youtube.com/watch?v=Qbu4ED8wPYE</a><br>
>><br>
>> Never used with opensmalltalk VM, though.<br>
>><br>
>> HTH, Jan<br>
</blockquote></div>
</blockquote></div></div>
</blockquote></div>