Inconsistent output when printing formatted strings to file

[GianlucaFuwa]

I was trying to cut down on allocations arising from printing formatted strings to file in an application that is not statically compiled and found that the results are very inconsistent depending on multiple factors. An MWE that I have is this:

using StaticTools

function mwe(with_extras::Bool)
    filename = c"mwe.txt"
    fp = fopen(filename, c"w")
    # printf(fp, c"some header...\n")
    fclose(fp)

    for i in 1:10
        v = rand(Float64)
        τ = 0.2
        fp = fopen(filename, c"a")
        printf(fp, c"%-9i\t", i::Int64)

        if with_extras
            printf(fp, c"%-9.5f\t", τ::Float64)
        end

        printf(fp, c"%+-22.15E\t", v::Float64)
        printf(fp, c"%+-22.15E\t", v::Float64)

        printf(fp, c"\n")
        fclose(fp)
    end

    return nothing
end

mwe(true)

If I run this file as above, I get the following output in "mwe.txt":

1           0.00000     +9.445493644111154E-01  +6.126737653876023E-62  
2           0.00000     +8.235657754038058E-01  +9.511677335669656E-43  
3           0.00000     +7.184351703725228E-01  +1.199878358402299E-71  
4           0.00000     +5.280713321258327E-01  +4.184875561680537E-62  
5           0.00000     +9.765792483145930E-02  +9.353006520611142E-67  
6           0.00000     +7.380412861392404E-01  +6.381266618977980E-67  
7           0.00000     +3.700248038898262E-01  +5.935085023208982E-38  
8           0.00000     +2.544724432210064E-01  +2.901918924806577E-57  
9           0.00000     +9.917970389599711E-01  +2.005620467711123E-76  
10          0.00000     +3.218949827679188E-01  +3.894907056644168E-33  

Notice, that column 2 and 4 print either zeros or random junk.

If I now uncomment the header part before the loop I get:

some header...
1           0.20000     +4.490086077189066E-01  +4.490086077189066E-01  
2           0.20000     +1.470808762272514E-01  +1.470808762272514E-01  
3           0.20000     +5.350469396912083E-01  +5.350469396912083E-01  
4           0.20000     +3.608204938822157E-02  +3.608204938822157E-02  
5           0.20000     +2.015223236450887E-01  +2.015223236450887E-01  
6           0.20000     +9.762384763210931E-01  +9.762384763210931E-01  
7           0.20000     +1.340377269733548E-01  +1.340377269733548E-01  
8           0.20000     +6.970016345570541E-01  +6.970016345570541E-01  
9           0.20000     +1.798754922164749E-01  +1.798754922164749E-01  
10          0.20000     +3.721347267230519E-01  +3.721347267230519E-01  

which is reasonable.

More weird stuff happens when I, e.g, set v to some fixed value instead of randomly generating it: Without header:

1           0.00000     +0.000000000000000E+00  +1.398043286095132E-76  
2           0.00000     +0.000000000000000E+00  +1.398043286095132E-76  
3           0.00000     +0.000000000000000E+00  +1.398043286095132E-76  
4           0.00000     +0.000000000000000E+00  +1.398043286095132E-76  
5           0.00000     +0.000000000000000E+00  +1.398043286095132E-76  
6           0.00000     +0.000000000000000E+00  +1.398043286095132E-76  
7           0.00000     +0.000000000000000E+00  +1.398043286095132E-76  
8           0.00000     +0.000000000000000E+00  +1.398043286095132E-76  
9           0.00000     +0.000000000000000E+00  +1.398043286095132E-76  
10          0.00000     +0.000000000000000E+00  +1.398043286095132E-76  

With header:

some header...
1           0.20000     +1.000000000000000E-01  +1.000000000000000E-01  
2           0.20000     +1.000000000000000E-01  +1.000000000000000E-01  
3           0.20000     +1.000000000000000E-01  +1.000000000000000E-01  
4           0.20000     +1.000000000000000E-01  +1.000000000000000E-01  
5           0.20000     +1.000000000000000E-01  +1.000000000000000E-01  
6           0.20000     +1.000000000000000E-01  +1.000000000000000E-01  
7           0.20000     +1.000000000000000E-01  +1.000000000000000E-01  
8           0.20000     +1.000000000000000E-01  +1.000000000000000E-01  
9           0.20000     +1.000000000000000E-01  +1.000000000000000E-01  
10          0.20000     +1.000000000000000E-01  +1.000000000000000E-01  

Similar things happen if I change how τ is defined. Alas, when using it in my package even with a header, I get faulty values (mainly zeros). Setting with_extras to false also doesn't ameliorate this behaviour.

The system I am running this on uses Ubuntu under Windows10-WSL2 on the latest version of StaticTools and Julia 1.9.4 (reason for this specific Julia version is that my package is bound to it), but I checked the MWE on 1.10.4 and got similar results. Full specs:

julia> versioninfo()
Julia Version 1.9.4
Commit 8e5136fa297 (2023-11-14 08:46 UTC)
Build Info:
  Official https://julialang.org/ release
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: 4 × Intel(R) Core(TM) i5-7600K CPU @ 3.80GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, skylake)
  Threads: 4 on 4 virtual cores

[brenhinkeller]

At first glance it seems to look like it's printing uninitialized memory somehow, which is certainly not what we want. I'm not sure why, and may not have time to investigate for a while. One possibility is https://github.com/brenhinkeller/StaticTools.jl/issues/33, which will be time consuming to fix unless @ccalls finally fully work with standalone StaticCompiler now (I had to avoid them initially to get things to compile). Alternatively, it may be another bug, or maybe even something WSL- or OS-specific (I don't know enough about WSL to be sure on that latter point though).

This package is still very experimental so I probably wouldn't recommend it in general unless you need to statically compile for now, but if we fix #33 (esp. if that also fixes this) then it could be possible to use more widely at some point in the future.

[GianlucaFuwa]

Another thing to note, in case you or someone else find time to investigate this bug at some point, is that I have only seen this behavior so far when printing Floats but not with Ints or Strings

[brenhinkeller]

Ah thanks, that’s very helpful for narrowing it down!