Some regression with Cro::WebSocket

[AlexDaniel]

zef install Cro::WebSocket

===> Searching for: Cro::WebSocket
===> Testing: Cro::WebSocket:ver<0.8.0>
# Failed test '256 bytes binary message in a single unmasked frame'
# at t/websocket-frame-parser.t line 38
# Failed test '64 KiB binary message in a single unmasked frame'
# at t/websocket-frame-parser.t line 38
# Looks like you failed 2 tests of 44
===> Testing [FAIL]: Cro::WebSocket:ver<0.8.0>
Aborting due to test failure: Cro::WebSocket:ver<0.8.0> (use --force-test to override)

This happens almost every time (if not always). As far as I can see this issue didn't exist in 2018.12.

Not bisected yet.

IRC discussion: https://colabti.org/irclogger/irclogger_log/perl6?date=2019-01-25#l57

[AlexDaniel]

Also, it eats memory like crazy during tests (like more than 6G). Not sure if that is related or if it's new.

EDIT: just measured, a bit closer to the end of the testing phase the memory rapidly spikes to more than 5G

[MasterDuke17]

After looking at a run under heaptrack I added a debug print of offset and count here https://github.com/MoarVM/MoarVM/blob/master/src/6model/reprs/VMArray.c#L926 (in asplice). Here's part of the end of the output:

offset = 50565504, count = 0
offset = 1520018838, count = 0
offset = 50565696, count = 0
offset = 1520037012, count = 0
offset = 50565888, count = 0
offset = 1520055186, count = 0
offset = 50566080, count = 0
offset = 1520073360, count = 0
not ok 44 - 64 KiB binary message in a single unmasked frame
offset = 50566272, count = 0
offset = 1520091534, count = 0
offset = 50566464, count = 0
offset = 1520109708, count = 0
offset = 50566656, count = 0
offset = 1520127882, count = 0
offset = 50566848, count = 0
offset = 1520146056, count = 0
offset = 50567040, count = 0
offset = 1520164230, count = 0
offset = 50567232, count = 0
# Failed test '64 KiB binary message in a single unmasked frame'
# at t/websocket-frame-parser.t line 38
offset = 1520182404, count = 0
offset = 50567424, count = 0
offset = 1520200578, count = 0
offset = 50567616, count = 0
offset = 1520218752, count = 0
offset = 50567808, count = 0
offset = 1520236926, count = 0
offset = 50568000, count = 0
offset = 1520255100, count = 0
1..44
offset = 50568192, count = 0
offset = 1520273274, count = 0
offset = 50568384, count = 0
offset = 1520291448, count = 0
offset = 50568576, count = 0
offset = 1520309622, count = 0
offset = 50568768, count = 0
# Looks like you failed 2 tests of 44
offset = 1520327796, count = 0
offset = 50568960, count = 0
offset = 1520345970, count = 0
offset = 50569152, count = 0
offset = 1520364144, count = 0
offset = 50569344, count = 0
offset = 1520382318, count = 0
offset = 50569536, count = 0
offset = 1520400492, count = 0
offset = 50569728, count = 0
offset = 1520418666, count = 0
offset = 50569920, count = 0
offset = 1520436840, count = 0
offset = 50570112, count = 0
offset = 1520455014, count = 0
offset = 50570304, count = 0
offset = 1520473188, count = 0
offset = 50570496, count = 0
offset = 1520491362, count = 0
offset = 50570688, count = 0
offset = 1520509536, count = 0
offset = 50570880, count = 0
offset = 1520527710, count = 0
offset = 50571072, count = 0
offset = 1520545884, count = 0
offset = 50571264, count = 0
offset = 1520564058, count = 0
offset = 50571456, count = 0
offset = 1520582232, count = 0
offset = 50571648, count = 0
offset = 1520600406, count = 0
offset = 50571840, count = 0
offset = 1520618580, count = 0
offset = 1520636754, count = 0
offset = 50572032, count = 0
offset = 1520654928, count = 0
offset = 50572224, count = 0
offset = 1520673102, count = 0
offset = 50572416, count = 0
offset = 1520691276, count = 0
offset = 50572608, count = 0
offset = 50572800, count = 0
offset = 1520709450, count = 0
offset = 50572992, count = 0
offset = 1520727624, count = 0
offset = 50573184, count = 0
offset = 1520745798, count = 0
offset = 50573376, count = 0
offset = 1520763972, count = 0
offset = 50573568, count = 0
offset = 1520782146, count = 0
offset = 50573760, count = 0
offset = 1520800320, count = 0
Command exited with non-zero status 2

[dogbert17]

A manual bisect points towards 541a4f1.

[jnthn]

The bisect did indeed point to the right commit. The code relied on an optimizer bug where in some cases, the success of a when would cause termination of the enclosing block. That is, it would not only leave the loop, but the block containing the loop, and not execute statements after the loop! This only occurred with some loop constructs (it depended on if they declared anything of their own). The updated optimizer doesn't make this mistake.

Cro::WebSocket had a piece of code accidentally relying on the bug. It has been patched and I can make a new release.

Furthermore, the modified optimizer not making the mistake it used to feels as much luck as judgement, so we should also:

• Robustly fix it
• Spectest it

[jnthn]

Rakudo optimizer patched, spectest added. I will do a release of Cro::WebSocket that does not depend on the compiler bug.

[jnthn]

Cro-WebSocket-0.8.0.1 uploaded to PAUSE. I think that concludes all that can be done with this issue.

[AlexDaniel]

@jnthn yeah! Thank you!

However, what about the memory issue? Any info on that?

[jnthn]

@AlexDaniel Yes, that was easily explained. The code relied on a bug for a loop the terminate. With the bug gone, the loop kept going on and on. In each iteration, it added stuff into an array, which thus grew and grew. A 5s is a long timeout, so some gigabytes in that time are easily achieved. I measured after the fix, and it's normal again.

[AlexDaniel]

OK, nice. There's nothing to do here then, I guess? Tests were added in Raku/roast@e95d29d, maybe it can be tested better, but the issue is resolved I think.

[jnthn]

I think we've done as much as is reasonable. Deliberately re-introducing a bug into the optimizer is as likely to risk creating new problems, so I'd be very reluctant to do that.