The VM potentially skips some method invocations

[chloestefantsova]

Steps to reproduce:

1. Patch in the CL: https://dart-review.googlesource.com/c/sdk/+/174242.
2. Run out/ReleaseX64/dart pkg/front_end/test/fasta/type_inference/type_schema_environment_nnbd_test.dart.
3. Observe that the test passes.
4. Uncomment lines with debug output in pkg/kernel/lib/src/replacement_visitor.dart, method visitInterfaceType (close to line 135).
5. Run the same test again.
6. Observe that the test now fails.

It seems that the invocation of visitNullability is skipped when not present in the debug output.

[a-siva]

//cc @crelier @alexmarkov

[crelier]

I modified the repro in visitInterfaceType :

  @override
  DartType visitInterfaceType(InterfaceType node) {
    Nullability newNullability = visitNullability(node);
    // Add these lines:
    if (false) {
      Nullability newNullability2 = visitNullability(node);
      if (newNullability2 != newNullability) {
        print('never reaching here');
      }
      if ('${node}'.contains('num')) {  // Side effect??
        newNullability = visitNullability(node);
        if (newNullability != newNullability2) {
          print('$newNullability != $newNullability2');
          print(runtimeType);
          print(node);
        }
      }
    }

I kept the prints to identify which version of visitNullability is called, but made them unconditional (just in case).
After recompiling the compiler, I changed false to true and run the test, which now fails.
The printed lines make no sense to me:

!!! ReplacementVisitor.visitNullability

!!! ReplacementVisitor.visitNullability

!!! _DemotionNullabilityNormalization.visitNullability

Nullability.nonNullable != null

_DemotionNullabilityNormalization

InterfaceType(num*)

The first 2 calls are always made to ReplacementVisitor.visitNullability.
However, executing '${node}'.contains('num') is apparently having a side effect, so that the 3rd call is made to _DemotionNullabilityNormalization.visitNullability instead, which returns Nullability.nonNullable instead of null.

I did not look at the code emitted for the string interpolation, but the issue must hide in there.
Calling toString() on node is having similar weird side effects.

[chloestefantsova]

FWIW, I used '${node}'.contains('num') in the original repro to specifically invoke _DemotionNullabilityNormalization.visitNullability from within visitInterfaceType when the test is run. And it seems that the test is a false positive: it should be failing and it's currently passing. I expect visitNullability to return Nullability.nonNullable when the test is run and the condition '${node}'.contains('num') applies.

[crelier]

If I do not apply your patch, but add this code instead, the test fails when run without any optimizations (i.e using --optimization-counter-threshold=-1)

  DartType visitInterfaceType(InterfaceType node) {
    Nullability newNullability = visitNullability(node);
    // >>>
    if ('${node}'.contains('num')) {  // Side effect??
      Nullability newNullability2 = visitNullability(node);
      if (newNullability2 != newNullability) {
        throw '** bug **';
      }
    }
   // <<<
    List<DartType> newTypeArguments = null;

The test prints:

  Expected: InterfaceType:<InterfaceType(num*)>
    Actual: InterfaceType:<InterfaceType(num)>

I assume that it is the correct behavior, since you write that the test is a false positive and should be failing.

Now, if I let optimizations kick in, the code throws '** bug **'.

The optimized graph looks like this:

==== package:kernel/src/replacement_visitor.dart_ReplacementVisitor_visitInterfaceType (RegularFunction)
  0: B0[graph]:0 {
      v0 <- Constant(#null) T{Null?}
      v1 <- Constant(#<optimized out>) T{_OneByteString}
      v8 <- Constant(#num) T{_OneByteString}
      v11 <- Constant(#true) T{bool}
      v12 <- Constant(#0) [0, 0] T{_Smi}
      v29 <- Constant(#TypeArguments: (H4f50c3f) [Type: DartType*]) T{TypeArguments}
      v40 <- Constant(#1) [1, 1] T{_Smi}
      v49 <- Constant(#false) T{bool}
      v56 <- Constant(#********** bug *************) T{_OneByteString}
      v90 <- Constant(#75) [75, 75] T{_Smi}
      v110 <- Constant(#_ImmutableList len:5) T{_ImmutableList}
      v144 <- Constant(#1236) [1236, 1236] T{_Smi}
      v145 <- Constant(#1241) [1241, 1241] T{_Smi}
      v177 <- Constant(#53) [53, 53] T{_Smi}
      v210 <- Constant(#Type: String) T{_Type}
      v324 <- Constant(#Type: InvalidType*) T{_Type}
      v325 <- Constant(#1230) [1230, 1230] T{_Smi}
      v383 <- Constant(#1331) [1331, 1331] T{_Smi}
      v384 <- Constant(#1351) [1351, 1351] T{_Smi}
      v385 <- Constant(#1376) [1376, 1376] T{_Smi}
      v424 <- Constant(#3) [3, 3] T{_Smi}
      v425 <- Constant(#InterfaceType() T{_OneByteString}
      v426 <- Constant(#2) [2, 2] T{_Smi}
      v427 <- Constant(#)) T{_OneByteString}
      v528 <- Constant(#Instance of 'Nullability') T{Nullability}
      v530 <- Constant(#1233) [1233, 1233] T{_Smi}
      v859 <- Constant(#Never) T{_OneByteString}
      v1275 <- Constant(#5) [5, 5] T{_Smi}
}
  2: B1[function entry]:2 {
      v2 <- Parameter(0) T{ReplacementVisitor}
      v3 <- Parameter(1) T{InterfaceType?}
}
  4:     CheckStackOverflow:8(stack=0, loop=0)
  5:     ParallelMove rax <- S+2
  6:     v195 <- TestCids:12(v3 is [0x31:false 0x4e:true 0xfc:false 0x102:false 0x4d4:false ] else deoptimize ) T{bool}
  8:     Branch if StrictCompare:16(===, v195, v11) goto (55, 56)
 10: B55[target]:20
 12:     ParallelMove rax <- rax goto:24 B132
 14: B56[target]:26
 16:     v429 <- LoadClassId(v3) [-4611686018427387904, 4611686018427387903] T{_Smi}
 18:     Branch if StrictCompare:28(===, v429, v144) goto (115, 118)
 20: B115[target]:2
 21:     ParallelMove rbx <- C, r10 <- C
 22:     v410 <- CreateArray:12(v0, v424) T{_List}
 23:     ParallelMove rax <- rax
 24:     ParallelMove S-3 <- rax
 24:     StoreIndexed(v410, v12, v425, NoStoreBarrier)
 26:     PushArgument(v3 T{InterfaceType})
 28:     v415 <- StaticCall:14( toStringInternal<0> v3 T{InterfaceType}, using unchecked entrypoint) T{String?}
 29:     ParallelMove rdx <- S-3, rax <- rax
 30:     StoreIndexed(v410, v40, v415 T{String?})
 31:     ParallelMove rcx <- S-3
 32:     StoreIndexed(v410, v426, v427, NoStoreBarrier)
 33:     ParallelMove rax <- rcx
 34:     v419 <- StringInterpolate:16(v410) T{String}
 35:     ParallelMove rax <- rax
 36:     ParallelMove rax <- rax goto:20 B119
 38: B118[target]:28
 40:     PushArgument(v3 T{InterfaceType?})
 42:     v430 <- PolymorphicInstanceCall:28( toString<0>, v3 T{InterfaceType?} Targets[2: StringBuffer cid 252 cnt:18 trgt:'StringBuffer.toString' | _SimpleUri@0150898 cid 258 cnt:16 trgt:'_SimpleUri@0150898.toString']) T{String?}
 43:     ParallelMove rax <- rax
 44:     ParallelMove rax <- rax goto:29 B119
 46: B119[join]:29 pred(B115, B118) {
      v431 <- phi(v419, v430) alive T{String?}
}
 47:     ParallelMove S-3 <- rax
 48:     Branch if StrictCompare(===, v431 T{String?}, v0) T{bool} goto (57, 58)
 50: B57[target]:38
 52:     v202 <- AllocateObject(ArgumentError) T{ArgumentError}
 53:     ParallelMove rax <- rax
 54:     ParallelMove S-4 <- rax
 54:     PushArgument(v202)
 56:     PushArgument(v431 T{String?})
 58:     StaticCall:40( ArgumentError.<0> v202, v431 T{String?})
 59:     ParallelMove rax <- S-4
 60:     Throw:42(v202)
 62: B58[target]:44
 64:     ParallelMove rax <- S-3 goto:48 B132
 66: B132[join]:15 pred(B55, B58) {
      v208 <- phi(v3 T{InterfaceType}, v431 T{String}) alive T{Object}
}
 67:     ParallelMove S-3 <- rax
 68:     CheckClass:16(v208 T{String} Cids[1: _OneByteString@0150898 etc.  cid 78])
 70:     PushArgument(v208 T{_OneByteString})
 72:     PushArgument(v8)
 74:     PushArgument(v12)
 76:     v741 <- StaticCall:200( indexOf<0> v208 T{_OneByteString}, v8, v12, using unchecked entrypoint) T{int?}
 77:     ParallelMove rax <- rax
 78:     CheckSmi:80(v741 T{int?})
 80:     Branch if RelationalOp:80(>=, v741 T{_Smi}, v12) T{bool} goto (3, 6)
 82: B3[target]:24
 84:     PushArgument(v2)
 86:     PushArgument(v3)
 88:     v52 <- InstanceCall:26( visitNullability<0>, v2, v3 IC[0: ] using unchecked entrypoint) T{Nullability?}
 89:     ParallelMove rax <- rax
 90:     PushArgument(v52)
 92:     PushArgument(v0)
 94:     v54 <- InstanceCall:28( ==<0>, v52, v0 IC[1: _Smi@0150898, _Smi@0150898 cnt:0 trgt:'_IntegerImplementation@0150898.==']) T{bool?}
 95:     ParallelMove rax <- rax, rcx <- rax
 96:     ParallelMove S-3 <- rcx
 96:     AssertBoolean:30(v54) T{bool}
 97:     ParallelMove rax <- S-3
 98:     Branch if StrictCompare:32(!==, v54 T{bool}, v11) goto (4, 5)
100: B4[target]:36
101:     ParallelMove rax <- C
102:     Throw:40(v56)

I do not think inlining or CHA are the culprits. However, you can see that the first call to VisitNullability is not made and simply replaced by constant v0 <- Constant(#null) T{Null?}, which would be the correct value if the receiver was a ReplacementVisitor, but it is actually a _DemotionNullabilityNormalization. I do not see any code that would deoptimize in case the receiver is not of the assumed type. Or I do not read the code correctly.

Not being familiar with our various code optimization passes, I cannot point to the bug or where things go wrong.

Maybe @alexmarkov can have a look?

[alexmarkov]

The first optimized version of ReplacementVisitor.visitInterfaceType is compiled with the assumption that ReplacementVisitor.visitNullability is not overridden.

Later, constant instance of class _DemotionNullabilityNormalization (which overrides visitNullability) comes into play, but compiled code is not discarded.

The problem is that _DemotionNullabilityNormalization class is finalized but not allocate-finalized, so RemoveCHAOptimizedCode is not called and optimized code is not disabled. We should make sure that classes are allocate-finalized before constant instances are created.

Small repro:

class A {
  const A();

  void foo() {
  }

  void bar() {
    foo();
  }
}

class B extends A {
}

class C extends A {
  const C();

  void foo() {
    print('OK');
  }
}

A x = B();
A y = const C();

main(List<String> args) {
  for (int i = 0; i < 30000; ++i) {
    x.bar(); // Optimize A.bar() with inlined A.foo().
  }
  y.bar(); // Should print 'OK'.
}

The correct behavior of this example is to print OK. The incorrect behavior is to print nothing.

Finalization of classes of constants was broken in b387ebc (it worked at previous revision ba459f9). @aam

[chloestefantsova]

Thanks for fixing the bug!