Strange behaviour in Release mode / Linux

We have a large F# module that performs some simulation and we observed that change (example in the code shown below) generated some unexpected values that we cannot yet explain.

The unexpected behaviour only happens when the code was deployed and used via nugets / release mode in Linux/Docker (We tried different SDK and still persisted)

The problem cannot be reproduced in development mode / Windows

let mainFunction 
        (a : bool)
        (b : bool)
        (c : float[]) 
        (d : bool)
        (e : float[][])
        (f : int[])
        (g : float[])
        (h : int[])
        (i : int)
        (j : float[])
        (k : float)
        (l : float)
        (x : float[][])
        (y : float[][])
        (z : float[][])
        
 let helperFunction = 
            mainFunction  a b c d f g h i j k l
            
            
 // Calling function             
 helperFunction x y z

Explicitely naming the arguments in the helper function and passing it down caused the issue

let mainFunction 
        (a : bool)
        (b : bool)
        (c : float[]) 
        (d : bool)
        (e : float[][])
        (f : int[])
        (g : float[])
        (h : int[])
        (i : int)
        (j : float[])
        (k : float)
        (l : float)
        (x : float[][])
        (y : float[][])
        (z : float[][])
        
 let helperFunction x y z = 
            mainFunction  a b c d f g h i j k l x y z
            
            
 // Calling function             
 helperFunction x y z

Any input is appreciated

The docker image it was deployed in

FROM mcr.microsoft.com/dotnet/aspnet:5.0 AS base
and
FROM mcr.microsoft.com/dotnet/aspnet:3.1-alpine AS base`` and FROM mcr.microsoft.com/dotnet/aspnet:3.1.9-alpine3.12 AS base``

The library targets netstandard2.0 and
it was compiled with
dotnet pack -c Release -o targets

We have a large F# module that performs some simulation and we observed that change (example in the code shown below) generated some unexpected values that we cannot yet explain.

Could you please give step by step reproducible instructions for where switching between Debug and Release or Window to Linux caused a change in behaviour. The above gives a hint but it's not enough for us to be able to work on this problem.

Thank you

Unfortunately we don't have step by step to reproduce nor we understand what happened between the two scenarios. I was hoping for some direction from someone with deeper knowledge on the compiler / Optimization so we know where to investigate further.

As mentioned the simulation doesn't crash just give very strange results. It is not clear if in one case some temporary array is created or code introduced. We have a very restrictive development environment and since this only occurs on Linux servers our debugging is not so simple.

I see. Given that the problem only occurs on Linux I suspect an interaction with a JIT optimization or other codegen.

I'd really like to get to the bottom of this. Is there any possibility of private access being given to one of the F# contributors at Microsoft? Under NDA or similar if necessary?

Methodologically we would try to trace execution through debug and release paths via printing until the inner states of the applications diverge, then try to reduce the program size as much as possible while still exhibiting the divergence. Hopefully that would reduce to a very small program.

If you like email me (dsyme at microsoft.com) and we can loop on Kevin and others and discuss.

Thanks for the reply, we are trying to make a small / reproducible example and we will send something in the coming week.

We sent some reproducability for the issue via email, please let me know if you need more information or if you have not received it.

I have the email, and have it flagged for follow up. It might take me a while to get to it

@issilva

@issilva and @dsyme --- if there is no private information divulged in the email can we have a dummary of it here please for public evaluation.

Thanks Kevin

@KevinRansom

@KevinRansom The summary is this - I looked and the problem really looks like a JIT bug in netcore 3.1. @lssilva self-reported that the problem no longer occurs in .NET 5.0.

Without a repro on .NET 5.0 or .NET 6.0 it seems kind of hard to report this to .NET Core team - I mean, we could but they would likely want a repro on latest bits and we don't have that.

It's certainly not an F# bug - if it was the behaviour would not be different on Windows etc.

Hi,

Here is the code that one could reproduce in Linux, The variable c changes value coming from outside with false and inside goes to true.

We first observed this running inside docker: aspnet:3.1.9-alpine3.12, it was also present with runtime 5.0-alpine.
Changing dotnet publish to -f net5.0 made the issue disappear. I am not sure however that it has been fixed as I don't know exactly what was happening.

Sometimes, even changing the variable name or size of arrays, the issue would dissappear.

type IOne =
    abstract Evaluate : spo:float [][] -> spoJ : float [][] -> v : float [][]  -> unit


type ITwo =
    abstract Next : variates:float [][] -> unit
    abstract N : int
    abstract NS : int
    abstract Reset : int -> unit


let s (m : int, n : int) =
    let rnd = System.Random(125)
    { new ITwo with
        member __.Reset(_) = ()
        member __.N = n
        member __.NS = m
        member __.Next(variates: float [][]) =
            for t = 0 to m - 1 do
                for v = 0 to n - 1 do
                    variates.[t].[v] <-rnd.NextDouble()
    }


let g               
    (indicesOne   : int[])
    (indicesTwo : int[]) : float =
    let mutable pr = 1.0
    let mutable i = 0
    let rnd = System.Random(875)
    let q = rnd.NextDouble()
    while i < indicesTwo.Length && pr > 0.0 do
        for j = 0 to indicesOne.Length - 1 do
            pr <- pr * (1.0 - q) 
        i <- i + 1 
    pr


let f 
    (c : bool)
    (ic : bool)
    (cbl : float[]) 
    (aps : bool)
    (dbl : float[][])
    (dboi : int[])
    (dbo : float[])
    (ui : int[])
    (ei : int)
    (sd : float[])
    (eps : float)
    (dt : float)
    (spo : float[][])
    (spoJ : float[][])
    (v : float[][]) =
    printfn "Variable c (passed as crossed from outside) inside f: %A." c
    if c then
        failwithf "c %A" c
    elif ic then failwith "not ok"
    elif aps then
        let res = g ui dboi
        printfn "resInisde %A" res
        res
    else failwith "not ok"


let fE () =
    let a = System.Random(123).NextDouble()
    printfn "Variable a created: %A." a
    let ei = if a >= -1.0 then 181 else failwith "not ok"
    let ui = if a >= -1.0 then [| 0; 1; 2; 3 |] else failwith "not ok"
    let ic = a <= -1.0
    let dboi = if a >= -1.0 then [| 181 |] else failwith "not ok" 
    let dbo = if a >= -1.0 then  [| 1.64 |] else failwith "not ok" 
    let dbl = if a >= -1.0 then  [| [| 102.0; 1267.0; 92.0; 30.0 |]|] else failwith "not ok"  
    let ap = a >= -1.0
    let eps         = if a >= -1.0 then 0.005 else failwith "not ok"
    let dt = if a >= -1.0 then 0.019 else failwith "not ok"
    let cbl = if a >= -1.0 then [||] else failwith "not ok"
    let crossed = a <= -5.0 
    printfn "Variable crossed created: %A." crossed
    let sdts =
        [| 0.037011660509880265;0.037011660509880265;0.03675330500399097;0.004365499396660423;0.037011660509880265;
           0.037011660509880265;0.037011660509880265;0.03725801341554944;0.03934957614215463;0.041462590034871155;
           0.043595390723549135;0.045747636779712046;0.0338997724370476;0.0338674858180635;0.050107380888273295;
           0.0523139112182485;0.03995454990159019;0.03712030846938784;0.056776351005374946;0.05903121352701333;
           0.019008763233177413;0.05234239225902137;0.02562758692440106;0.06358607344915934;0.06588535697577626;
           0.06819848780741894;0.07052500267301963;0.07286492510810424;0.056515489092430864;0.04963559497153821;
           0.07758299430007977;0.07996027362188335;0.08234978945595355;0.056814595615803834;0.05011402523360257;
           0.03799207840206929;0.08716350096547346;0.04379532152778386;0.07815229736196382;0.09202159045624238;
           0.09446704895574382;0.09692261947243416;0.0993886691711606;0.08088997921054182;0.06191340657522703;
           0.10435075058494209;0.04409441693997676;0.05011402523360257;0.08342935867784342;0.03547844687687914;
           0.10343632859916324;0.11186634501779698;0.11439016164725192;0.11692282706377088;0.08631848893613203;
           0.08258875888930464;0.09979939289861697;0.05011402523360257;0.04915605617779812;0.09365306590238945;
           0.08214506695081038;0.03525699300217697;0.12215522413038252;0.12971718250813502;0.12176574331707841;
           0.05173732096386035;0.11827897651801508;0.05011402523360257;0.04116902211046817;0.09624975702855994;
           0.0981854329781772;0.13848495294356286;0.13848495294356286;0.06370440242145102;0.12296272322906096;
           0.06370440242145102;0.12296272322906096;0.09766116394283193;0.0981854329781772;0.13848495294356286;
           0.13325494746860425;0.0376988218240351;0.08382295280861049;0.10358857855625753;0.0376988218240351;
           0.13848495294356286;0.13848495294356286;0.12347252933242407;0.05011402523360257;0.0376988218240351;
           0.13282592282276426;0.03918362436097377;0.09707495913739621;0.09876504695616602;0.13848495294356286;
           0.13848495294356286;0.036311497634728795;0.1336396547859351;0.036311497634728795;0.1336396547859351;
           0.13848495294356286;0.13848495294356286;0.08244984484686091;0.11126592145176072;0.03932982790147982;
           0.07246476076350086;0.11126592145176072;0.13848495294356286;0.03932982790147982;0.13278270530841282;
           0.13325494746860425;0.0376988218240351;0.13325494746860425;0.0376988218240351;0.09766116394283193;
           0.0981854329781772;0.13848495294356286;0.13848495294356286;0.036311497634728795;0.1336396547859351;
           0.036311497634728795;0.1336396547859351;0.13848495294356286;0.13848495294356286;0.09766116394283193;
           0.0981854329781772;0.06547183661817713;0.07246476076350086;0.0981854329781772;0.13848495294356286;
           0.08382295280861049;0.11023517938583073;0.09766116394283193;0.0981854329781772;0.13325494746860425;
           0.0376988218240351;0.13848495294356286;0.13848495294356286;0.13848495294356286;0.06370440242145102;
           0.12296272322906096;0.06370440242145102;0.12296272322906096;0.13848495294356286;0.13848495294356286;
           0.13325494746860425;0.0376988218240351;0.13325494746860425;0.0376988218240351;0.03932982790147982;
           0.13278270530841282;0.13848495294356286;0.13325494746860425;0.0376988218240351;0.13325494746860425;
           0.0376988218240351;0.13848495294356286;0.13848495294356286;0.13848495294356286;0.08244984484686091;
           0.11126592145176072;0.08244984484686091;0.11126592145176072;0.09766116394283193;0.0981854329781772;
           0.13848495294356286;0.13325494746860425;0.0376988218240351;0.12347252933242407;0.05011402523360257;
           0.0376988218240351;0.13848495294356286;0.13848495294356286;0.12347252933242407;0.05011402523360257;
           0.0376988218240351;0.13282592282276426;0.03918362436097377;0.13848495294356286;0.13848495294356286;
           0.13325494746860425;0.0376988218240351;0.13848495294356286;0.06370440242145102|]
    
    printfn "Variable crossed before passed to f: %A." crossed
    let h spo spoJ v = f crossed ic cbl ap dbl dboi dbo ui ei sdts eps dt spo spoJ v

    { new IOne with
        member __.Evaluate spo spoJ v = printfn "%A" (h spo spoJ v)
    }


type PMP() =
    static member B (p : IOne [][], ngen : ITwo, np : int)  =
        let n = 1
        let m = 1
        let l = 5
        let u = 185
        let spo = Array.init u (fun _ -> Array.zeroCreate<float> l)
        let spoJ = Array.init u (fun _ -> Array.zeroCreate<float> l)
        let v = Array.init u (fun _ -> Array.zeroCreate<float> l)
        let z = Array.init ngen.NS (fun _ -> Array.zeroCreate<float> ngen.N)
        let sa = [| 147.0; 2199.0; 148.0; 35.0; 0.85 |]
            
        for j = 0 to u - 1 do
            for i = 0 to l - 1 do
                spo.[j].[i] <- sa.[i]

        for _ in 0 .. np - 1 do
            ngen.Next z
            for j = 0 to n - 1 do
                for k = 0 to m - 1 do
                    p.[j].[k].Evaluate spo spoJ v


type MP() =
    static member A() =
        let dim = 184 ,5 
        let gen = s dim 
        let pm  = [| [| fE () |]|]
        PMP.B(pm, gen, 1)

[<EntryPoint>]
let main args =
    printfn "Started."
    MP.A()
    printfn "Finished."
    0

@lssilva

@lssilva Thank you. I've contacted @jkotas from the .NET Runtime team to understand whether they would like to look into this and try to relate the problem to a specific known fix that's present in .NET 5.0

Many thanks
Don

@lssilva

@lssilva So Jan Kotas suggests checking if disabling tailcalls in optimized code makes a difference on .NET Core 3.1

"My guess is that it will have something to do with tailcalls. IIRC, we have fixed some corner-case bugs with passing arguments to tailcalls."

Use /tailcalls- to disable

I believe this was fixed as a side effect of the more general approach taken in dotnet/coreclr#26255. In particular, it relates to the second paragraph there:

On unix x64 and arm64 this assumption does not hold. We previously tried
to workaround this by limiting our fast tailcalls to simple situations
where this assumption held, but this caused many missed fast tailcall
opportunities (for example, when arguments requires two slots or more).

The problem happens while compiling the local function h inside fE. The F# compiler adds the necessary captured variables as parameters to this function, including crossed. .NET Core 3.1 does not properly detect that it cannot safely do a tailcall to f because the stack slot that corresponds to the crossed parameter will end up being overridden by another argument to f before it is read.

The result is the following codegen:

	; Assembly listing for method Program:h@121(int,ref,bool,ref,ref,ref,bool,double,double,ref,bool,ref,ref,ref,ref):double	
; Emitting BLENDED_CODE for X64 CPU with AVX - Unix	
; optimized code	
; rbp based frame	
; fully interruptible	
; Final local variable assignments	
;	
;  V00 arg0         [V00,T04] (  3,  3   )     int  ->  rdi        	
;  V01 arg1         [V01,T00] (  3,  3   )     ref  ->  rsi         class-hnd	
;  V02 arg2         [V02,T05] (  3,  3   )    bool  ->  rdx        	
;  V03 arg3         [V03,T01] (  3,  3   )     ref  ->  rax         class-hnd	
;  V04 arg4         [V04,T02] (  3,  3   )     ref  ->   r8         class-hnd	
;  V05 arg5         [V05,T03] (  3,  3   )     ref  ->   r9         class-hnd	
;  V06 arg6         [V06,T13] (  1,  1   )    bool  ->  [rbp+0x10]  	
;  V07 arg7         [V07,T15] (  3,  3   )  double  ->  mm0        	
;  V08 arg8         [V08,T16] (  3,  3   )  double  ->  mm1        	
;  V09 arg9         [V09,T08] (  1,  1   )     ref  ->  [rbp+0x18]   class-hnd	
;  V10 arg10        [V10,T14] (  1,  1   )    bool  ->  [rbp+0x20]
;  V11 arg11        [V11,T09] (  1,  1   )     ref  ->  [rbp+0x28]   class-hnd	
;  V12 arg12        [V12,T10] (  1,  1   )     ref  ->  [rbp+0x30]   class-hnd	
;  V13 arg13        [V13,T11] (  1,  1   )     ref  ->  [rbp+0x38]   class-hnd	
;  V14 arg14        [V14,T12] (  1,  1   )     ref  ->  [rbp+0x40]   class-hnd	
;# V15 OutArgs      [V15    ] (  1,  1   )  lclBlk ( 0) [rsp+0x00]   "OutgoingArgSpace"	
;  V16 rat0         [V16,T07] (  2,  4   )     int  ->  rcx         "Fast tail call lowering is creating a new local variable"	
;  V17 rat1         [V17,T17] (  2,  4   )  double  ->  mm0         "Fast tail call lowering is creating a new local variable"	
;  V18 rat2         [V18,T18] (  2,  4   )  double  ->  mm1         "Fast tail call lowering is creating a new local variable"	
;  V19 rat3         [V19,T06] (  2,  4   )     ref  ->  r10         "Fast tail call lowering is creating a new local variable"	
;	
; Lcl frame size = 0	
G_M57259_IG01:	
       push     rbp	
       vzeroupper 	
       mov      rbp, rsp	
       mov      rax, rcx	
G_M57259_IG02:	
       movzx    rcx, byte  ptr [rbp+10H]	
       mov      r10, gword ptr [rbp+18H]	
G_M57259_IG03:	
       mov      gword ptr [rbp+10H], r8	
       mov      gword ptr [rbp+18H], rsi	
       mov      dword ptr [rbp+20H], edi	 ; This overrides `crossed`
       mov      rdi, gword ptr [rbp+28H]	
       mov      gword ptr [rbp+28H], rdi	
       mov      rdi, gword ptr [rbp+30H]	
       mov      gword ptr [rbp+30H], rdi	
       mov      rdi, gword ptr [rbp+38H]	
       mov      gword ptr [rbp+38H], rdi	
       mov      rdi, gword ptr [rbp+40H]	
       mov      gword ptr [rbp+40H], rdi	
       mov      edi, dword ptr [rbp+20H]	; This tries to pass `crossed` in `rdi`, but it was already overridden above
       movzx    rdi, dil	
       movzx    rsi, dl	
       movzx    rcx, cl	
       mov      rdx, r10	
       mov      r8, r9	
       mov      r9, rax	
       mov      rax, 0xD1FFAB1E	
G_M57259_IG04:	
       pop      rbp	
       rex.jmp  rax	
; Total bytes of code 98, prolog size 10 for method Program:h@121(int,ref,bool,ref,ref,ref,bool,double,double,ref,bool,ref,ref,ref,ref):double	
; ============================================================

The codegen we have nowadays is the following. Note that we store crossed in r11d temporarily here, which fixes the issue.

-G_M57259_IG01:
+G_M3653_IG01:
        push     rbp
        vzeroupper 
        mov      rbp, rsp
        mov      rax, rcx
-
-G_M57259_IG02:
-       movzx    rcx, byte  ptr [rbp+10H]
+						;; bbWeight=1    PerfScore 2.50
+G_M3653_IG02:
+       mov      ecx, dword ptr [rbp+10H]
        mov      r10, gword ptr [rbp+18H]
-
-G_M57259_IG03:
+       mov      r11d, dword ptr [rbp+20H]
        mov      gword ptr [rbp+10H], r8
        mov      gword ptr [rbp+18H], rsi
        mov      dword ptr [rbp+20H], edi
@@ -54,19 +52,22 @@ G_M57259_IG03:
        mov      gword ptr [rbp+38H], rdi
        mov      rdi, gword ptr [rbp+40H]
        mov      gword ptr [rbp+40H], rdi
-       mov      edi, dword ptr [rbp+20H]
-       movzx    rdi, dil
+       movzx    rdi, r11b
        movzx    rsi, dl
        movzx    rcx, cl
        mov      rdx, r10
        mov      r8, r9
        mov      r9, rax
-       mov      rax, 0xD1FFAB1E
-
-G_M57259_IG04:
+						;; bbWeight=1    PerfScore 15.50
+G_M3653_IG03:
        pop      rbp
-       rex.jmp  rax
+       jmp      Program:f(bool,bool,System.Double[],bool,System.Double[][],System.Int32[],System.Double[],System.Int32[],int,System.Double[],double,double,System.Double[][],System.Double[][],System.Double[][]):double
+						;; bbWeight=1    PerfScore 2.50

Unfortunately it is not enough to turn off tailcall generation in the F# compiler because .NET core 3.1 will still do this call as a tailcall in optimized code. If you need this fixed in .NET core 3.1 we can look into backporting the change linked above or a more targeted fix. Please let us know.

There was a similar problem reported in dotnet/runtime#2409 it looks like. That issue has some other workarounds you can try out.

@jakobbotsch

@jakobbotsch , @dsyme Thank you for the update. We have migrated the relevant code base to .Net 5.0 and for us backporting is not important, however, since this is so difficult to debug and track, it might be worth to consider for the user base out there.

Our main concern was that it was not crashing, but giving wrong results in a few selected scenarios only, with the fixes on .Net 5.0 we have a bit more peace of mind.

Thanks !

Ref Issues:
dotnet/runtime#2409
dotnet/coreclr#20643
dotnet/coreclr#26255
dotnet/coreclr#26158

Navigation Menu

Repository navigation

Strange behaviour in Release mode / Linux #12035

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Strange behaviour in Release mode / Linux #12035

Description

Activity

dsyme commented on Aug 25, 2021

lssilva commented on Aug 27, 2021

dsyme commented on Aug 27, 2021

lssilva commented on Sep 3, 2021

lssilva commented on Sep 13, 2021

dsyme commented on Sep 13, 2021

KevinRansom commented on Sep 22, 2021

dsyme commented on Sep 24, 2021

lssilva commented on Sep 28, 2021

dsyme commented on Oct 4, 2021

dsyme commented on Oct 4, 2021

jakobbotsch commented on Oct 4, 2021

jakobbotsch commented on Oct 4, 2021

lssilva commented on Oct 5, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions