Serialize data back to heaptrack in another thread + cache searches on trace tree

[brenoguim]

Do not merge!

I've been using heaptrack every now and then, and while it's much faster than valgrind (which simply gives up), it takes over a day to run it on my case. So I spent some time to optimize it.

If improvements like this have been discussed and ruled out, please go ahead and close it. I imagine there may be subtle details which could invalidate this proposal

This pull request contains experimental changes to improve the performance of the allocation data serialization back to heaptrack interpreter. It's just a proof of concept, really.

There are two main changes here:

1. Instead of calling fprintf on every allocation/deallocation, just add the data to a queue. A thread is created to consume data on this queue and call fprintf.

• I'm a bit concerned fprintf may call malloc/free, which I suppose could cause deadlock. It hasn't deadlocked in any of the runs though, so maybe I'm missing something.

2. Create a cache of "last search" on each node of the trace tree. This helps speeding up consecutive allocations on the same (or similar) stack.

I used the following testcase for performance validation:
main.txt

This testcase is tailored for the two optimizations, so I wouldn't expect the same results on real scenarios. I did not test this on my testcase yet (don't have access to the company network on weekend :) )

This does a bunch of string manipulations and sleep every now and then. The sleep is to simulate time not doing allocations on real applications.

• Time without heaptrack: 54 seconds
• Time with heaptrack: 100 seconds
• Time with heaptrack + this patch: 74 seconds

I will validate this patch on my 1 day testcase during this week, and if it gives significant improvement, I can work on separate it on two or three changesets, fix bugs, improve error handling and so on...

I created a pull request to kick off a discussion (if it hasn't been discussed yet), and gather feedback.

[milianw]

Some early comments, while we wait for your real-world test data to arrive:

1. I find it strange that introducing buffering is improving things. Consider that the FILE API we are using is actually buffered already, no? Maybe we want to increase the internal buffer there?

2. If against my intuition (see above) we do want to build our own buffer, then please at least reuse code form boost for a lockfree queue

3. My long-term plan to optimize heaptrack I/O is to introduce a binary data protocol to get rid of the text conversion overhead. While this will drastically increase the size of an uncompressed heaptrack data stream, I don't think it's important as we apply zstd/gz compression anyways.

4. Once we have binary data streams, I also would like to try and split the data streams apart. I.e. instead of generating just one file, actually create multiple files, one for every "type" of message. This will allow us to load the strings, trees and other meta data once, and then we can just go through the allocation data stream that should just have one 32bit integer entry per (de)allocation. These integers are then just indices, negative values will encode deallocations. The timestamps file will map times to offsets into the (de)allocation stream. This should drastically reduce the size of the data files, since we won't need to keep repeating ourselves for the "type" of the message. And it should also allow us to parse the allocation data stream in parallel eventually.

5. Your idea to cache the last IP in TraceTree sounds like a very good idea, please split that out into a separate commit and we can merge it.

[brenoguim]

I hope to get these results by the end of the week. Some comments on your feedback:

1. I wasn't very explicit about that. The expensive part on fprintf is actually the string formatting part, since as you pointed, the actual sending is buffered.
2. I refrained from using a lock-free queue, because it will (most likely) use malloc/free to add items to the queue. I wasn't sure if that would be ok, but I guess it is.
3. This is probably the best solution. This could be done in two parts (right?) - change the communication of the user process and heaptrack_interpret, and change the serialization to the actual file. I guess just the first one would give significant performance improvement.
4. This would be heaven I guess :)
5. Great! Will do.

[brenoguim]

As I moved to trunk, I got a few problems about "Trace recursion detected - corrupt data file?". I'll dig into that first.

[milianw]

For an old data file, or for a new data file? There was a bug that got fixed recently which sometimes lead to bogus data files. I extended the error checking and then ensured this shouldn't happen anymore - or so I thought...

[brenoguim]

Ran a bisect and heaptrack stopped working on my environment as of changeset:

commit ab2a8222da3cbf2c061578f8215a1b771ff5bb90
Author: Milian Wolff <milian.wolff@kdab.com>
Date:   Wed Jan 17 16:17:57 2018 +0100

    Check symbol table size before accessing it
    
    Fixes crash on 32bit systems when using attach.

diff --git a/src/track/heaptrack_inject.cpp b/src/track/heaptrack_inject.cpp
index 717d391..e67afa3 100644
--- a/src/track/heaptrack_inject.cpp
+++ b/src/track/heaptrack_inject.cpp
@@ -241,9 +241,11 @@ void try_overwrite_elftable(const T& jumps, const elf_string_table& strings, con
     const auto rela_end = reinterpret_cast<Elf::Rela*>(reinterpret_cast<char*>(jumps.table) + jumps.size);
     for (auto rela = jumps.table; rela < rela_end; rela++) {
         const auto index = ELF_R_SYM(rela->r_info);
-        const char* symname = strings.table + symbols.table[index].st_name;
-        auto addr = rela->r_offset + base;
-        hooks::apply(symname, addr, restore);
+        if (index > 0 && index < symbols.size) {
+            const char* symname = strings.table + symbols.table[index].st_name;
+            auto addr = rela->r_offset + base;
+            hooks::apply(symname, addr, restore);
+        }
     }
 }

Not sure why yet

[milianw]

I doubt that, unless you are runtime attaching? Did you run the bisect test multiple times - maybe it's a race or other flaky failure?

[brenoguim]

The bisect is very stable. I am doing runtime attaching.
The index < symbols.size is the condition causing that behavior.

Commenting that clause on the head of the repository works for me. I'll put a pin on that for now.

[milianw]

what is the value of index? What is the value of symbols.size? Note also that there was an issue in this commit which was fixed in the follow-up commit (it should read index >= 0).

I also don't see how this yields the "trace recursion" error you are encountering...

[brenoguim]

I'll get the value of index as soon as I can. I'm running my tests now. I ran the baseline (trunk + index "fix") and it took 20 hours. I kicked off the version with this patch (trunk + index "fix" + this patch) and let's see how it goest tomorrow.

[brenoguim]

Well, 20 hours again. It did not improve the performance. That's sad, because then I'd have to start profiling my own application with heaptrack... but that takes 20h. It will be a nightmare.

Things to do:

1. Create a smaller version of my testcase and profile it
2. Create a separate patch for the trace tree caching
3. Investigate the issue with the index (perhaps stop using the runtime injection?)

But I must say... I'm much more inclined to work on the binary serialization rather than this queue/threading complexity.

[milianw]

How long does it take without heaptrack? I'd welcome if you could do 2. and 3. The former can be applied right away, the latter is a serious bug that needs to be fixed, but which I cannot reproduce. And that's more important than performance :)

If you then want to work on binary serialization, let's discuss this afterwards in more detail.

[brenoguim]

It takes around 1h30 to run without heaptrack. That's why I'm so eager to get performance improvement.
It might be relevant to mention it runs on a JVM, but the heavy stuff is done in C++.

I'll try to do 3 next then.

[milianw]

Did you get a profile with perf to see where the time is actually spent?

[milianw]

Hey @brenoguim,

the fallout to fix https://bugs.kde.org/show_bug.cgi?id=393387 included some patches that should also drastically improve the performance of heaptrack under some conditions. Can you please test current heaptrack git master against your workload again to see how long it takes now? I hope it's now less than 20x slower than without it.

The new code base should also make it super trivial to add a separate writer thread, if desired. Though I don't believe that this should be required. The perf results I've measured locally don't point at I/O anymore.

Cheers

[brenoguim]

That's awesome! I'll try that ASAP. Thanks @milianw !

[brenoguim]

Hey! I tested the trunk and got the same 20h time.

But I was finally able to get perf to run on my actual work environment and it's embarrassing... Libunwind was the one taking all the time, not heaptrack. I still don't know why it's behaving SO bad.

Anyway, I built a recent libunwind from source and now the time dropped to 2 hours. It's amazing!
Now I can run my tests several times a day instead of once a day.

Thanks for this amazing tool!

PS: I was kind of hoping that running with the new libunwind the "index" problem would go away, but it didn't. Still have to look into that.

[milianw]

On Montag, 30. April 2018 12:52:47 CEST Breno Rodrigues Guimarães wrote: Hey! I tested the trunk and got the same 20h time. But I was finally able to get perf to run on my actual work environment and it's embarrassing... Libunwind was the one taking all the time, not heaptrack. I still don't know why it's behaving SO bad. Anyway, I built a recent libunwind from source and now the time dropped to 2 hours. It's amazing! Now I can run my tests several times a day instead of once a day.

Yay! You probably ran a very old libunwind version then. Basically anything prior to 1.2 is pretty damn slow. I should probably add a runtime warning for this somehow to make people better aware of this.

Thanks for this amazing tool!

Thanks for the feedback, much appreciated :)

PS: I was kind of hoping that running with the new libunwind the "index" problem would go away, but it didn't. Still have to look into that.

Hah, thanks Breno for bringing this up again! I actually was in the middle of a debug session for why runtime attaching didn't work. So I looked at this commit again and indeed, it's complete rubbish. I've reverted it again and explained why it's so bad, cf.: https://github.com/KDE/heaptrack/commit/ 8aec0f5 This should make vanilla heaptrack useable for you again, I hope! Thanks a lot for bringin this to my attention, I'd have wasted tons of time without your hint here. Cheers

…

-- Milian Wolff mail@milianw.de http://milianw.de

[brenoguim]

I'm glad this worked out well for both of us! :)