Make LLVM Profiling robust for multithreaded programs

[bachdavi]

This is a draft PR to make LLVM optimization logging correct for multithreaded programs.

It guards against the case where you enable or disable LLVM optimization logging (@snoopl) in one thread, while another thread is midway through an ongoing optimization, or stopping it before it's finished. Without this PR, this can result in a malformed .yaml file, since the logging might start with the "after" clause, or it might only contain the "begin" clause.

After this PR, such cases will simply not be logged, and only LLVM optimizations that occurred completely while logging was enabled would be logged.

[pchintalapudi]

It's not super clear to me what the purpose of this PR is. Is the intent to allow access to these timings within Julia code? If so, why is the timing struct embedding a vector<> and not a julia array? Also, the previous implementation of timing reporting should have been thread-safe, albeit not manipulable from Julia, since we locked before ever operating on the stream.

[bachdavi]

@pchintalapudi This is very much a work in progress :)
Sorry, could have mentioned this in the description, am adding it right now.
I pushed a PR such that @NHDaly and @vilterp can work on this together.
We'll ping you once this is in any state to review it!

[bachdavi]

Exactly, we want to access the timings from within Julia while potentially having another thread do code generation. Interesting, we thought that we might run into a case where we unset the streams, and codgen is trying to write to it, finding a null pointer. Where does the locking happen?

[bachdavi]

@pchintalapudi Does the actual optimization in jitlayers.cpp: (***PMs).run(M); acquire any locks? If not, would it be feasible to hold the stream lock over the whole optimization time to ensure we don't write just the first part of the YAML block or just the second one? I've adapted this PR to do that. The alternative would be to write the first part into a string and write the whole YAML block atomically after optimization.

[NHDaly]

🤔 @bachdavi: now that i'm looking at the PR change, we maybe don't want to hold the lock over the whole LLVM optimization, since that would force serialization of two different threads doing LLVM optimization if we were profiling..

So i think that the string-buffer approach is probably the best one. 👍 Sorry i didn't think of this when we discussed it earlier! Thanks for the quick change today :)

[pchintalapudi]

We actually specifically want to avoid holding a lock during optimization, so that in the future multiple modules can be optimizing at the same time. Rather than write to a string first, I would say holding the data in variables and dumping the entire yaml block post-optimization using those variables would be a better solution.

Guess I got sniped by @NHDaly :)

[NHDaly]

💡 @pchintalapudi, yeah, just keeping the results in variables seems even better. 👍 👍

[pchintalapudi]

As an aside, we currently don't measure machine code optimization and emission time at the moment (this is in jitlayers.cpp, CompilerT::operator()) although this probably constitutes a decent fraction of optimization time. That may also be something of interest if you're looking to collect optimization statistics.

[NHDaly]

I was wondering about that, @pchintalapudi: Does that get measured in @snoopc (codegen)?

[pchintalapudi]

It does get measured by @snoopc since that relies on the dump_compiles_stream instead of the dump_llvm_opt_stream, but that includes time spent in codegen, middle-end optimization, and backend optimization/mc emission. We don't currently have anything measuring the contribution of just backend optimization/mc emission.

[bachdavi]

This uses a stringstream, instead we could use a map and store instructions and basicblocks as a tuple. The downside of the stringstream is the lack of proper formatting, afaik std::format is only available from c++20.

[NHDaly]

LGTM, thanks, @bachdavi!
I've updated the description as well, to explain this situation better.

@pchintalapudi: Can you do a final review pass as well?

[NHDaly]

Friendly ping for @pchintalapudi. Do you want to review? We've been using this in production at RAI and so far it seems to be working correctly. Can we merge this?

CC: @IanButterworth as well, since this is profiling related.

[pchintalapudi]

Seems fine to me

[vchuravy]

Needs a rebase

[NHDaly]

Also, are the test failures here real? Or unrelated?

[vchuravy]

analyzegc failure seems relevant.

[bachdavi]

analyzegc failure seems relevant.

Mh, it seems so indeed!

[NHDaly]

Thanks Valentin and David. The remaining failures look unrelated:

Error During Test at C:\buildkite-agent\builds\win2k22-aws-vms-2\julialang\julia-master\julia-4d55f71f4d\share\julia\stdlib\v1.10\Downloads\test\runtests.jl:12
  Got exception outside of a @test
  RequestError: Could not resolve host: httpbingo.julialang.org while requesting https://httpbingo.julialang.org/base64/SnVsaWEgaXMgZ3JlYXQh
  Stacktrace:
    [1] (::Downloads.var"#9#18"{IOStream, Base.DevNull, Nothing, Vector{Pair{String, String}}, Float64, Nothing, Bool, Nothing, Bool, String, Bool, Bool})(easy::Downloads.Curl.Easy)

and

intrinsics                                       (5) |        started at 2023-01-09T13:12:37.840
      From worker 4:
      From worker 4:	[180] signal (11.1): Segmentation fault
      From worker 4:	in expression starting at /cache/build/default-power9bot2-0/julialang/julia-master/julia-4d55f71f4d/share/julia/test/atomics.jl:281