Constant opt cycles when running LargePositiveIntegerTest>>testReciprocalModulo

[johenning]

Last line ifFalse: [self should: [ a reciprocalModulo: b ] raise: Error] causes deopts

[fniephaus]

Problem could be a related to splitting, see example output:

[truffle] opt done         Random>>nextInt: <opt> <split-29451c4d>                     |ASTSize      86/  554 |Time   302( 255+47  )ms |DirectCallNodes I   22/D    1 |GraalNodes  1239/ 2134 |CodeSize         7477 |CodeAddress 0x11f05bf10 |Source Random>>nextInt::1
[truffle] opt done         LargePositiveIntegerTest>>testReciprocalModulo <opt>        |ASTSize     264/ 1008 |Time   539( 441+98  )ms |DirectCallNodes I   39/D    3 |GraalNodes  2005/ 3297 |CodeSize        12604 |CodeAddress 0x11f0c2550 |Source LargePositiveIntegerTest>>testReciprocalModulo:1
[truffle] opt done         Random>>nextInt: <opt> <split-239bb532>                     |ASTSize      86/  554 |Time   324( 270+55  )ms |DirectCallNodes I   22/D    1 |GraalNodes  1239/ 2134 |CodeSize         7477 |CodeAddress 0x11f6fbf90 |Source Random>>nextInt::1
[truffle] opt done         LargePositiveIntegerTest>>testReciprocalModulo <opt>        |ASTSize     264/ 1008 |Time   553( 427+126 )ms |DirectCallNodes I   39/D    3 |GraalNodes  2005/ 3297 |CodeSize        12604 |CodeAddress 0x11f0b5f10 |Source LargePositiveIntegerTest>>testReciprocalModulo:1
[truffle] opt done         Random>>nextInt: <opt> <split-157835a6>                     |ASTSize      86/  554 |Time   358( 300+58  )ms |DirectCallNodes I   22/D    1 |GraalNodes  1239/ 2134 |CodeSize         7477 |CodeAddress 0x11f0ad0d0 |Source Random>>nextInt::1
[truffle] opt done         LargePositiveIntegerTest>>testReciprocalModulo <opt>        |ASTSize     264/ 1008 |Time   564( 473+91  )ms |DirectCallNodes I   39/D    3 |GraalNodes  2005/ 3297 |CodeSize        12604 |CodeAddress 0x11efe43d0 |Source LargePositiveIntegerTest>>testReciprocalModulo:1
[truffle] opt done         Random>>nextInt: <opt> <split-403222dc>                     |ASTSize      86/  554 |Time   298( 252+46  )ms |DirectCallNodes I   22/D    1 |GraalNodes  1239/ 2134 |CodeSize         7477 |CodeAddress 0x11eefbcd0 |Source Random>>nextInt::1
[truffle] opt done         LargePositiveIntegerTest>>testReciprocalModulo <opt>        |ASTSize     264/ 1008 |Time   506( 421+85  )ms |DirectCallNodes I   39/D    3 |GraalNodes  2005/ 3297 |CodeSize        12604 |CodeAddress 0x11efd7d90 |Source LargePositiveIntegerTest>>testReciprocalModulo:1
[truffle] opt done         Random>>nextInt: <opt> <split-5cd9c3f8>                     |ASTSize      86/  554 |Time   263( 220+44  )ms |DirectCallNodes I   22/D    1 |GraalNodes  1239/ 2134 |CodeSize         7477 |CodeAddress 0x11efa1550 |Source Random>>nextInt::1

[fniephaus]

This is still an issue in 1.0.0-rc7:

[truffle] opt deopt        Exception>>return: <opt>                                    |ASTSize      19/   19 |Calls/Thres    6399/    3 |CallsAndLoop/Thres    6399/ 1000 |Inval#              0
[truffle] opt deopt        Exception>>return: <opt>                                    |ASTSize      19/   19 |Calls/Thres    6399/    3 |CallsAndLoop/Thres    6399/ 1000 |Inval#              0
[truffle] opt deopt        Exception>>return: <opt>                                    |ASTSize      19/   19 |Calls/Thres    6399/    3 |CallsAndLoop/Thres    6399/ 1000 |Inval#              0
[truffle] opt deopt        Exception>>return: <opt>                                    |ASTSize      19/   19 |Calls/Thres    6399/    3 |CallsAndLoop/Thres    6399/ 1000 |Inval#              0
[truffle] opt deopt        Exception>>return: <opt>                                    |ASTSize      19/   19 |Calls/Thres    6399/    3 |CallsAndLoop/Thres    6399/ 1000 |Inval#              0
[truffle] opt deopt        Exception>>return: <opt>                                    |ASTSize      19/   19 |Calls/Thres    6399/    3 |CallsAndLoop/Thres    6399/ 1000 |Inval#              0
[truffle] opt deopt        Exception>>return: <opt>                                    |ASTSize      19/   19 |Calls/Thres    6399/    3 |CallsAndLoop/Thres    6399/ 1000 |Inval#              0
[truffle] opt deopt        Exception>>return: <opt>                                    |ASTSize      19/   19 |Calls/Thres    6399/    3 |CallsAndLoop/Thres    6399/ 1000 |Inval#              0
[truffle] opt deopt        Exception>>return: <opt>                                    |ASTSize      19/   19 |Calls/Thres    6399/    3 |CallsAndLoop/Thres    6399/ 1000 |Inval#              0

[fniephaus]

@eregon mentioned that there are new docs on how to debug deoptimizations:

If you see unexpected deoptimization in a Truffle language, I have added docs at https://github.com/oracle/graal/blob/master/truffle/docs/Optimizing.md#debugging-deoptimizations and there is also a new option --engine.TraceDeoptimizeFrame to trace frame deopts

[fniephaus]

It seems this got fixed along the way and is no longer reproducible. :)