[BOLT][Instrumentation] Fix hash table memory corruption and append-pid option

[treapster]

Summary

This diff fixes a few related issues:

Shared counters when using instrumentation-file-append-pid.
The point of append-pid option is to record separate profiles for separate forks, which is impossible when counters are the same for every process. It leads to a sum of all profiles in every file, plus GlobalWriteProfileMutex located in a shared memory prevents some processes from dumping their data at all. So, in this patch we only map counters as shared when append-pid is not used, and provide a test to ensure that different processes don't pollute each other's profiles.

Hash table corruption
In absence of instrumentation-file-append-pid option, global allocator uses shared pages for allocation. However, since it is a global variable, it gets COW'd after fork if instrumentation-sleep-time is used, or each time a process forks by itself. This means it handles the same pages to every process which causes hash table corruption - different entries overwrite each other, sometimes creating endless cycles. Thus, if we want shared pages, we need to put the allocator itself in a shared page, which we do in this patch in __bolt_instr_setup.

Unexpected/unspecified behavior of instrumentation-file-append-pid combined with instrumentation-{sleep-time,wait-forks}
The point of instrumentation-sleep-time option is to have a watcher process which shares memory with all other forks and dumps a common profile each n seconds. The append-pid is the opposite - it should record a private profile of each process. Combining the two suggests that we should get a private profile of each fork every n seconds, but such behavior is not implemented currently and is not easy to implement in general, because we somehow need to intercept each individual fork, launch a watcher process just for that fork, and also map counters so that they're only shared with that single fork. Since we're not doing that, the most reasonable thing to do seems to be disallowing such combination of options. I can make a separate diff for that if you think it doesn't fit here.

Also, while debugging all that i created a simple dump() function to understand what's happening, which i include here in case other hash table issues arise.

[treapster]

For some reason CHECK-ALL-DAG clause does not always work as expected on the second invocation, what may be happening here? I tried using {{}} regex to match the words exactly, but it didn't help

[rafauler]

bolt/test/runtime/instrumentation-indirect-2.c

65–80 ↗

(On Diff #534547)

For some reason this test is failing on shared build.

Build BOLT with BUILD_SHARED_LIBS=On to check that.

[rafauler]

In D153771#4449272, @treapster wrote:

For some reason CHECK-ALL-DAG clause does not always work as expected on the second invocation, what may be happening here? I tried using {{}} regex to match the words exactly, but it didn't help

missed this comment. Yes, it looks flaky.

[rafauler]

Thanks for working on fixing these issues, @treapster! I have some suggestions below.

bolt/runtime/instr.cpp

254

report -> dump

see Graph::dump() for an easier way to write (and read) this code

also include a call to this function inside a DEBUG() macro to showcase how/where you want this printed. If you don't want to always print it in debug, leave it commented out, so at least we know how to use it when we need it.

bolt/test/runtime/instrumentation-indirect-2.c

90–91 ↗

(On Diff #534547)

Here I would rather have a command that moves the child/parent fdata to fixed file names such as:

mv $t.$child_pid.fdata child.fdata
mv $t.$par_pid.fdata parent.fdata

The reason is because if we don't do that, each time a developer runs "ninja check-bolt", it will create a new unique file (with a different PID attached to the file name) in the Output folder and won't replace the previous one (the expected behavior), unnecessarily using more disk space over time.

96–97 ↗

(On Diff #534547)

This can accidentally match other entries in the profile, such as the activity in funcX calling printf(). I imagine what we want to match is the indirect call itself, right? For that I would rather use:

RUN: llvm-bolt %t.exe -data %t.child.fdata \
RUN:   -print-finalized -print-only=main -o /dev/null | FileCheck %s --check-prefix=CHECK_CHILD

And then match this string:

{{.*}}:   callq   *%rax # CallProfile: 8 (0 misses) :
    { func1: 1 (0 misses) },
    { func3: 1 (0 misses) },

...

Actually, I ran BOLT like that and surprisingly the profile is incorrect and it is printing this:
.LFT15 (8 instructions, align : 1)

Exec Count : 8
CFI State : 3
Predecessors: .Ltmp10
  000000d1:   movslq  -0x94(%rbp), %rax
  000000d8:   movq    -0x90(%rbp,%rax,8), %rax
  000000e0:   movl    -0x98(%rbp), %edi
  000000e6:   callq   *%rax # CallProfile: 8 (0 misses) :
      { <unknown>: 1 (0 misses) },
      { <unknown>: 1 (0 misses) },
      { <unknown>: 1 (0 misses) },
      { <unknown>: 1 (0 misses) },
      { <unknown>: 1 (0 misses) },
      { <unknown>: 1 (0 misses) },
      { <unknown>: 1 (0 misses) },
      { <unknown>: 1 (0 misses) }
  000000e8:   movl    -0x94(%rbp), %eax
  000000ee:   addl    $0x2, %eax
  000000f1:   movl    %eax, -0x94(%rbp)
  000000f7:   jmp     .Ltmp10
Successors: .Ltmp10 (mispreds: 0, count: 8)

I'm not sure why yet.

[rafauler]

bolt/test/runtime/instrumentation-indirect-2.c

65–80 ↗

(On Diff #534547)

The reason this doesn't work is because "func1" is matching to "func10"

Either remove func10-func16 or rename them with letters. e.g.: funca, funcb, funcc, funcd, funcf, funcg

[treapster]

Fix nits

[treapster]

bolt/runtime/instr.cpp

254

It is done this way because we want to construct a string once and print it atomically in a single call to write(). If write is called more than once, we get garbage when threads and processes are involved.

[treapster]

bolt/test/runtime/instrumentation-indirect-2.c

96–97 ↗

(On Diff #534547)

If we match instructions, it unnecessarily becomes arch-specific. I think we need to figure out why indirect calls are not recorded in profile and construct a regex to match them there.

[treapster]

bolt/test/runtime/instrumentation-indirect-2.c

65–80 ↗

(On Diff #534547)

I tried matching {{\bfunc1\b}} and similar constructs and it didn't help. I now changed numbers to letters and it still seems to fail sometimes..

[treapster]

Turns out, the [unknown] entries in profile are because addresses in indirect call descriptions are not relocated, which makes them meaningless in PIE because of ASLR. When the test is compiled with no-pie, indirect calls are recorded accurately. So, we should either compute base address and add it to stored entries, or produce dynamic relocations.

[treapster]

In D153771#4452452, @treapster wrote:

Turns out, the [unknown] entries in profile are because addresses in indirect call descriptions are not relocated, which makes them meaningless in PIE because of ASLR. When the test is compiled with no-pie, indirect calls are recorded accurately. So, we should either compute base address and add it to stored entries, or produce dynamic relocations.

But since .bolt.instr.tables is not allocatable, the only option is to perform relocation by hand. BTW, why isn't it allocatable?

[rafauler]

bolt/runtime/instr.cpp

254

Sounds good, can you write a comment explaining that? (regarding the single call to write() )

bolt/test/runtime/instrumentation-indirect-2.c

65–80 ↗

(On Diff #534547)

You're right, unfortunately it seems to be failing some times. That's annoying. I gave up on the DAG thing and tried this:

https://pastebin.com/rgn1hKr9

And it seems to be working consistently. That's one option forward, if you're OK with it.

96–97 ↗

(On Diff #534547)

Sounds good. Matching against the CallProfile annotation (ignoring the instruction opcode) shouldn't be arch-specific, though. But I'm also OK with regex matching fdata, whichever you prefer.

[rafauler]

In D153771#4452452, @treapster wrote:

Turns out, the [unknown] entries in profile are because addresses in indirect call descriptions are not relocated, which makes them meaningless in PIE because of ASLR. When the test is compiled with no-pie, indirect calls are recorded accurately. So, we should either compute base address and add it to stored entries, or produce dynamic relocations.

Good catch, that looks like a nasty bug in instrumentation for PIE objects. If you like, we can commit this diff forcing the test to be no-pie and then work on the fix for PIE on another diff.

[rafauler]

In D153771#4452461, @treapster wrote:

In D153771#4452452, @treapster wrote:

Turns out, the [unknown] entries in profile are because addresses in indirect call descriptions are not relocated, which makes them meaningless in PIE because of ASLR. When the test is compiled with no-pie, indirect calls are recorded accurately. So, we should either compute base address and add it to stored entries, or produce dynamic relocations.

But since .bolt.instr.tables is not allocatable, the only option is to perform relocation by hand. BTW, why isn't it allocatable?

Because it is encoded as an ELF note section. That's not allocatable at load time, but our runtime will open the ELF file and read them. I don't remember why exactly I did that, I think at the time my motivation was to avoid as much as possible relying on the linker (RuntimeDyld) resolving all references from code to this table. So we just manually deserialize it instead of encoding as a global object in the binary. When this was written I knew we were abusing RuntimeDyld and that it wouldn't work in a variety of scenarios, that's why I was trying to keep the code as easy on the linker as possible (see bolt/docs/RuntimeLibrary.md - section Limitations).

Anyway, even we do encode this section (.bolt.instr.tables) as allocatable data section with dynamic R_X86_64_RELATIVE relocs fixing these addresses, we will likely have to figure out how to generate and insert the .rela section correctly in the binary. Maybe now that we're using JITLink, this task will be easier, I don't know.

Manually adding the PIE load address in instr.cpp:readDescription() might or might not be easier.

[treapster]

bolt/test/runtime/instrumentation-indirect-2.c

65–80 ↗

(On Diff #534547)

It's ok but it will fire if the order in profile changes. Is it specified currently? Also we probably need to use -sleep-time for the first run, because otherwise the first process may start writing before the second finishes, and the second won't overwrite with newer profile because write mutex is locked. I'll play with it a bit more, it may not be a bug in FileCheck:)

[ayermolo]

bolt/runtime/instr.cpp

255

Can you add some kind of check that we are not overflowing Buf?

[treapster]

In D153771#4453993, @rafauler wrote:

Manually adding the PIE load address in instr.cpp:readDescription() might or might not be easier.

The main issue here is we'll have to either map the whole BinContents as RW, or memcpy just descriptions to another writeble region. Then just loop over entries and patch. Sounds a bit easier than messing with JITLink, though. Another solution may be to just subtract the base address every time inside lookupIndCallTarget.

[rafauler]

bolt/test/runtime/instrumentation-indirect-2.c

65–80 ↗

(On Diff #534547)

You're right, the order is not guaranteed.

[treapster]

Add comment and buffer overflow assertion

[treapster]

Fix test, use no-pie executable.

[treapster]

! In D153771#4453963, @rafauler wrote:
If you like, we can commit this diff forcing the test to be no-pie and then work on the fix for PIE on another diff.

Done, the test is non-pie now

[rafauler]

bolt/runtime/instr.cpp

216

void *

1627–1629

Drop the cast

GlobalMetadataStorage = 
    __mmap(0, 4096, PROT_READ | PROT_WRITE,
           (Shared ? MAP_SHARED : MAP_PRIVATE) | MAP_ANONYMOUS, -1, 0);

bolt/test/runtime/instrumentation-indirect-2.c

111 ↗

(On Diff #535379)

Do you really need that? (Lines 111 and 66)

I'm testing locally with the sleep timers removed and the test is not failing. If line 65 " Wait for profile and output to be fully written" is the problem, I don't know, perhaps something like https://linux.die.net/man/1/sync? (I don't know because I'm not sure what's happening in your machine, but it looks odd to me that the process will finish but your test script will access a half-finished output file).

If the problem is the one described in line 110 "in case child outlives parent", then perhaps using bash's "wait" command? https://phoenixnap.com/kb/bash-wait-command

[Amir]

bolt/runtime/common.h

85 ↗

(On Diff #535379)

@rafauler: so why don't we include mman.h?

@treapster: since this particular change is NFC, can you please split it out to reduce functional changes surface and simplify testing and reviewing?

[The patch should] be an isolated change. Independent changes should be submitted as separate patches as this makes reviewing easier.

https://llvm.org/docs/Contributing.html#how-to-submit-a-patch

[rafauler]

bolt/runtime/common.h

85 ↗

(On Diff #535379)

If we include any headers, it will pull the file from the host system, which might not match the target system.

I actually prefer this particular patch as is (non-split). In general I think it's harder for me to work reviewing large stacks (unless there are lots of lines of code changed) and I will internally squash a stack of diffs into one for easier testing.

But I agree there are many benefits to splitting a diff, so it's fine to me if @treapster wants to do that.

[treapster]

bolt/test/runtime/instrumentation-indirect-2.c

111 ↗

(On Diff #535379)

I do get spurious failures if i remove any of the sleeps, and in the second case it always looks like incomplete output. Wait only works for a background job of the shell, in our case we have the main process finished and the output file read by next commands before the child finishes and writes it's output. AFAIK there is no way for us to wait for the whole process tree so we have to just sleep and hope it's finished. Regarding sync, it is also not what we need because we don't care whether the file is flushed to disc or not, we just need to wait till a process stops writing to it. Although sync seems to be working, probably because it spends enough time flushing for child process to finish and write everything. But still can fail any time.
There is another solution, however: for stdout redirection, i imagine we'll have the file open till both processes finish. So we can wait in a loop until fuser returns 1, which will guarantee both processes finished. For instrumentation profile, we'll need to change watchProcess() so that it opens profile only once and keeps FD open until it's done, seeking to zero on every iteration. This way we can also query fuser on the file to know when it's safe to read it. But this is a topic for another diff:).

[treapster]

Fix nits, add mmap check

[rafauler]

LGTM without the test

Just commit the change without the test. Honestly it's not worth it including a test that might fail because the children process is not synced, and I fear sleep wouldn't be a proper sync if the system is heavily loaded. We have too much infrastructure that depends on tests being solid and stable, and the risk of random failures isn't worth the pain. We can work on fixing instrumentation testability on other diffs.

[Amir]

This change breaks upstream testing: https://lab.llvm.org/buildbot/#/builders/244/builds/13736. Reverted.

[Amir]

Also reverted append-pid commit due to the breakage in https://lab.llvm.org/buildbot/#/builders/252/builds/2700.

[Amir]

Clang-BOLT still fails: https://lab.llvm.org/buildbot/#/builders/252/builds/2701. Not sure what could be the reason, but started failing with this set of changes.

[Amir]

I'll be reverting one by one until https://lab.llvm.org/buildbot/#/builders/252 passes

[Amir]

The builder is now green at https://lab.llvm.org/buildbot/#/builders/252/builds/2707.
Looks like the last two reverted commits (NFC with defines + asserts) were not related. Sorry about the churn, please reland. The other two appear to be related, or at least one. Lmk if you need help reproducing that build, but it should generally be straightforward based on cmake args from the builder.

[treapster]

Thanks for catching&reverting that, i'll try to reproduce a bit later and report back.

[Amir]

Relanded "Don't share counters when using append-pid" – the crash wasn't in instrumented binary.
So the issue must be in "Put Allocator itslef in shared memory by default".

[treapster]

At first i couldn't reproduce with cmake configured to use clang, but with gcc the runtime library does indeed break. Turns out, the definition for

void *operator new(size_t, void *) noexcept;

which was declared in the problematic commit is not provided by gcc, and in runtimelib it's use is replaced with a call and a relocation to undefined symbol(demangled to operator new(unsigned long, void*):

0000000000008352  0000005700000004 R_X86_64_PLT32         0000000000000000 _ZnwmPv - 4

For some reason JITLink does not catch it, and after linking the runtime lib to the binary, the call is just left there with zero immediate which causes segfault.
If we provide a definition for operator new, the problem goes away. Now why i did not provide a definition:

• That answer says we only need declaration and doesn't mention definition
• The page on cppreference does not list (9) and (10) as replacable and in Notes section only allows definition in class scope, or in global scope with non-void pointer type.
• The page from that answer explicitly says: These functions are reserved; a C++ program may not define functions that displace the versions in the C++ standard library.

So it led me to believe that these forms of new are implicitly defined in the compiler and it is UB to define them in global scope. But apparently GCC requires them(or at least the one in question) to be explicitly defined. There is also ambiguity in whether we can call it "displacing the versions in the standard library" when we're not using standard library - whether UB arises from the definition alone or from definition when using standard library. We can probably assume the latter and get away with it, but it is not super clear. So, C++ is being C++ again.

[treapster]

Since we don't need generic global placement new operator, and defining it in class scope is legal according to cppreference, i decided to move the operator to BumpPtrAllocator scope and define it there.

[treapster]

Hello @Amir, i think it's ok to reland it now, do you agree?

[Amir]

Looks good on my end. Let's reland and monitor the buildbot.

bolt/runtime/instr.cpp

   void setShared(bool S) { Shared = S; }
 
   void destroy() {
     if (StackBase == nullptr)
       return;
     __munmap(StackBase, MaxSize);
   }
 
+  // Placement operator to construct allocator in possibly shared mmaped memory
+  static void *operator new(size_t, void *Ptr) { return Ptr; };
+
 private:
   static constexpr uint64_t Magic = 0x1122334455667788ull;
   uint64_t MaxSize = 0xa00000;
   uint8_t *StackBase{nullptr};
   uint64_t StackSize{0};
   bool Shared{false};
   Mutex M;
 };
 
 /// Used for allocating indirect call instrumentation counters. Initialized by
 /// __bolt_instr_setup, our initialization routine.
-BumpPtrAllocator GlobalAlloc;
+BumpPtrAllocator *GlobalAlloc;
+
+// Storage for GlobalAlloc which can be shared if not using
+// instrumentation-file-append-pid.
+void *GlobalMetadataStorage;
+
 } // anonymous namespace
 
 // User-defined placement new operators. We only use those (as opposed to
 // overriding the regular operator new) so we can keep our allocator in the
 // stack instead of in a data section (global).
 void *operator new(size_t Sz, BumpPtrAllocator &A) { return A.allocate(Sz); }
 void *operator new(size_t Sz, BumpPtrAllocator &A, char C) {
   auto *Ptr = reinterpret_cast<char *>(A.allocate(Sz));

 
 // Disable instrumentation optimizations that sacrifice profile accuracy
 extern "C" bool __bolt_instr_conservative;
 
 /// Basic key-val atom stored in our hash
 struct SimpleHashTableEntryBase {
   uint64_t Key;
   uint64_t Val;
   void dump(const char *Msg = nullptr) {
     // TODO: make some sort of formatting function
     // Currently we have to do it the ugly way because
     // we want every message to be printed atomically via a single call to
     // __write. If we use reportNumber() and others nultiple times, we'll get
     // garbage in mulithreaded environment
     char Buf[BufSize];
     char *Ptr = Buf;
     Ptr = intToStr(Ptr, __getpid(), 10);
     *Ptr++ = ':';

           uint32_t IncSize = 7>
 class SimpleHashTable {
 public:
   using MapEntry = T;
 
   /// Increment by 1 the value of \p Key. If it is not in this table, it will be
   /// added to the table and its value set to 1.
   void incrementVal(uint64_t Key, BumpPtrAllocator &Alloc) {
-    ++get(Key, Alloc).Val;
+    if (!__bolt_instr_conservative) {
+      TryLock L(M);
+      if (!L.isLocked())
+        return;
+      auto &E = getOrAllocEntry(Key, Alloc);
+      ++E.Val;
+      return;
+    }
+    Lock L(M);
+    auto &E = getOrAllocEntry(Key, Alloc);
+    ++E.Val;
   }
 
   /// Basic member accessing interface. Here we pass the allocator explicitly to
   /// avoid storing a pointer to it as part of this table (remember there is one
   /// hash for each indirect call site, so we wan't to minimize our footprint).
   MapEntry &get(uint64_t Key, BumpPtrAllocator &Alloc) {
     if (!__bolt_instr_conservative) {
       TryLock L(M);

   template <typename... Args>
   void forEachElement(void (*Callback)(MapEntry &, Args...),
                       uint32_t NumEntries, MapEntry *Entries, Args... args) {
     for (uint32_t I = 0; I < NumEntries; ++I) {
       MapEntry &Entry = Entries[I];
       if (Entry.Key == VacantMarker)
         continue;
       if (Entry.Key & FollowUpTableMarker) {
-        forEachElement(Callback, IncSize,
-                       reinterpret_cast<MapEntry *>(Entry.Key &
-                                                    ~FollowUpTableMarker),
-                       args...);
+        MapEntry *Next =
+            reinterpret_cast<MapEntry *>(Entry.Key & ~FollowUpTableMarker);
+        assert(Next != Entries, "Circular reference!");
+        forEachElement(Callback, IncSize, Next, args...);
         continue;
       }
       Callback(Entry, args...);
     }
   }
 
   MapEntry &firstAllocation(uint64_t Key, BumpPtrAllocator &Alloc) {
     TableRoot = new (Alloc, 0) MapEntry[InitialSize];

                uint64_t(Entries),
            "circular reference created!\n");
     // DEBUG(NextLevelTbl[CurEntrySelector].dump("New level entry: "));
     // DEBUG(Entry.dump("Updated old entry: "));
     return getEntry(NextLevelTbl, Key, Remainder, Alloc, CurLevel + 1);
   }
 
   MapEntry &getOrAllocEntry(uint64_t Key, BumpPtrAllocator &Alloc) {
-    if (TableRoot)
-      return getEntry(TableRoot, Key, Key, Alloc, 0);
+    if (TableRoot) {
+      MapEntry &E = getEntry(TableRoot, Key, Key, Alloc, 0);
+      assert(!(E.Key & FollowUpTableMarker), "Invalid entry!");
+      return E;
+    }
     return firstAllocation(Key, Alloc);
   }
 };
 
 template <typename T> void resetIndCallCounter(T &Entry) {
   Entry.Val = 0;
 }
 

   DEBUG(reportNumber("replace mmap stop: ", CountersEnd, 16));
   assert(CountersEnd > CountersStart, "no counters");
 
   const bool Shared = !__bolt_instr_use_pid;
   const uint64_t MapPrivateOrShared = Shared ? MAP_SHARED : MAP_PRIVATE;
 
   void *Ret =
       __mmap(CountersStart, CountersEnd - CountersStart, PROT_READ | PROT_WRITE,
              MAP_ANONYMOUS | MapPrivateOrShared | MAP_FIXED, -1, 0);
   assert(Ret != MAP_FAILED, "__bolt_instr_setup: Failed to mmap counters!");
 
-  // Conservatively reserve 100MiB shared pages
-  GlobalAlloc.setMaxSize(0x6400000);
-  GlobalAlloc.setShared(Shared);
-  GlobalWriteProfileMutex = new (GlobalAlloc, 0) Mutex();
+  GlobalMetadataStorage = __mmap(0, 4096, PROT_READ | PROT_WRITE,
+                                 MapPrivateOrShared | MAP_ANONYMOUS, -1, 0);
+  assert(GlobalMetadataStorage != MAP_FAILED,
+         "__bolt_instr_setup: failed to mmap page for metadata!");
+
+  GlobalAlloc = new (GlobalMetadataStorage) BumpPtrAllocator;
+  // Conservatively reserve 100MiB
+  GlobalAlloc->setMaxSize(0x6400000);
+  GlobalAlloc->setShared(Shared);
+  GlobalWriteProfileMutex = new (*GlobalAlloc, 0) Mutex();
   if (__bolt_instr_num_ind_calls > 0)
     GlobalIndCallCounters =
-        new (GlobalAlloc, 0) IndirectCallHashTable[__bolt_instr_num_ind_calls];
+        new (*GlobalAlloc, 0) IndirectCallHashTable[__bolt_instr_num_ind_calls];
 
   if (__bolt_instr_sleep_time != 0) {
     // Separate instrumented process to the own process group
     if (__bolt_instr_wait_forks)
       __setpgid(0, 0);
 
     if (long PID = __fork())
       return;
     watchProcess();
   }
 }
 
 extern "C" __attribute((force_align_arg_pointer)) void
 instrumentIndirectCall(uint64_t Target, uint64_t IndCallID) {
-  GlobalIndCallCounters[IndCallID].incrementVal(Target, GlobalAlloc);
+  GlobalIndCallCounters[IndCallID].incrementVal(Target, *GlobalAlloc);
 }
 
 /// We receive as in-stack arguments the identifier of the indirect call site
 /// as well as the target address for the call
 extern "C" __attribute((naked)) void __bolt_instr_indirect_call()
 {
   __asm__ __volatile__(SAVE_ALL
                        "mov 0xa0(%%rsp), %%rdi\n"