From 79395c7f17807bd850ff62913bd5c2110c57713e Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Tue, 13 Sep 2022 18:45:57 +0200 Subject: [PATCH 01/11] Added caching in PyperfNativeStack --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 159 +++++++++++++++--- examples/cpp/pyperf/PyPerfNativeStackTrace.h | 27 ++- 2 files changed, 164 insertions(+), 22 deletions(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index d33772695bee..14bced4e024b 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -8,11 +8,12 @@ #include #include #include -#include - #include #include #include +#include +#include +#include #include "PyPerfLoggingHelper.h" @@ -20,10 +21,13 @@ namespace ebpf { namespace pyperf { // Ideally it was preferable to save this as the context in libunwind accessors, but it's already used by UPT +const uint16_t NativeStackTrace::CacheMaxSizeMB = 56; +const uint16_t NativeStackTrace::CacheMaxTTL = 300; // In seconds const uint8_t *NativeStackTrace::stack = NULL; size_t NativeStackTrace::stack_len = 0; uintptr_t NativeStackTrace::sp = 0; uintptr_t NativeStackTrace::ip = 0; +MAP NativeStackTrace::cache; NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, size_t stack_len, uintptr_t ip, uintptr_t sp) : error_occurred(false) { @@ -43,26 +47,47 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, // The UPT implementation of these functions uses ptrace. We want to make sure they aren't getting called my_accessors.access_fpreg = NULL; my_accessors.resume = NULL; - + unw_addr_space_t as; + unw_cursor_t cursor; + void *upt; int res; - unw_addr_space_t as = unw_create_addr_space(&my_accessors, 0); - void *upt = _UPT_create(pid); - if (!upt) { - this->symbols.push_back(std::string("[Error _UPT_create (system OOM)]")); - this->error_occurred = true; - goto out; - } - unw_cursor_t cursor; - // TODO: It's possible to make libunwind use cache using unw_set_caching_policy, which might lead to significent - // performance improvement. We just need to make sure it's not dangerous. For now the overhead is good enough. - res = unw_init_remote(&cursor, as, upt); - if (res) { - std::ostringstream error; - error << "[Error unw_init_remote (" << unw_strerror(res) << ")]"; - this->symbols.push_back(error.str()); - this->error_occurred = true; - goto out; + // Pseudo-proactive way of implementing TTL - whenever any call is made, all expired entries are removed + cache_eviction(cache); + + // Check whether the entry for the process ID is presented in the cache + if (is_cached(cache, pid) == false) { + logInfo(2,"The given key %d is not presented in the cache\n", pid); + + as = unw_create_addr_space(&my_accessors, 0); + upt = _UPT_create(pid); + if (!upt) { + this->symbols.push_back(std::string("[Error _UPT_create (system OOM)]")); + this->error_occurred = true; + cleanup(upt, as); + return; + } + + res = unw_init_remote(&cursor, as, &upt); + if (res) { + std::ostringstream error; + error << "[Error unw_init_remote (" << unw_strerror(res) << ")]"; + this->symbols.push_back(error.str()); + this->error_occurred = true; + cleanup(upt, as); + return; + } + + // Put to the cache + cache_put(cache, pid, cursor, as, upt); + + } else { + logInfo(2,"Found entry for the given key %d in the cache\n", pid); + // Get from the cache + Object cached_value = cache_get(cache, pid); + cursor = cached_value.cursor; + as = cached_value.as; + upt = cached_value.upt; } do { @@ -107,7 +132,9 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, } } while (unw_step(&cursor) > 0); -out: +} + +void NativeStackTrace::cleanup(void *upt, unw_addr_space_t as) { if (upt) { _UPT_destroy(upt); } @@ -200,5 +227,95 @@ bool NativeStackTrace::error_occured() const { return error_occurred; } +bool NativeStackTrace::is_cached(const MAP &map, const uint32_t &key) { + try { + map.at(key); + return true; + } + catch (const std::out_of_range&) { + logInfo(2, "No entry for %d in the cache\n", key); + } + return false; +} + +Object NativeStackTrace::cache_get(const MAP &map, const uint32_t &key) { + const Object & value = map.at(key); + return value; +} + +// cache_put adds a new entry to the map if the capacity allows +void NativeStackTrace::cache_put(MAP &map, const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt) { + + // Check available capacity + if (cache_size() > NativeStackTrace::CacheMaxSizeMB*1024*1024 - cache_single_entry_size()) { + logInfo(2, "The cache usage is %.2f MB, close to reaching the max memory usage (%d MB)\n", cache_size_KB()/1024, NativeStackTrace::CacheMaxSizeMB); + logInfo(2, "Skipping adding an entry for %d to the cache\n", key); + + return; + } + + Object obj = {cursor, as, upt, time(NULL)}; + map[key] = obj; + logInfo(2, "New entry for %d was added to the cache\n", key); +} + +// cache_delete_key removes the element from the cache and destroys unwind address space and UPT +// to ensure that all memory and other resources are freed up +bool NativeStackTrace::cache_delete_key(MAP &map, const uint32_t &key) { + try { + Object v = cache_get(map, key); + map.erase(key); + cleanup(v.upt, v.as); + logInfo(2, "The entry for %d was deleted from the cache\n", key); + return true; + } + catch (const std::out_of_range&) { + logInfo(2, "Failed to delete entry for %d: no such key in the cache\n", key); + } + return false; +} + +// cache_single_entry_size returns the number of bytes taken by single entry +uint32_t NativeStackTrace::cache_single_entry_size() const { + return sizeof(decltype(cache)::key_type) + sizeof(decltype(cache)::mapped_type); +} + +// cache_size returns the number of bytes currently in use by the cache +uint32_t NativeStackTrace::cache_size() const { + return sizeof(cache) + cache.size()*cache_single_entry_size(); +} + +// cache_size_KB returns the number of kilobytes currently in use by the cache +float NativeStackTrace::cache_size_KB() const { + return cache_size()/1024; +} + +// cache_eviction removes elements older than 5 minutes (CacheMaxTTL=300) +void NativeStackTrace::cache_eviction(MAP &map) { + std::vector keys_to_delete; + float _prev_cache_size = cache_size_KB(); + + for(std::map::iterator iter = map.begin(); iter != map.end(); ++iter) + { + uint32_t k = iter->first; + const Object & v = iter->second; + if (std::abs(difftime(v.timestamp, time(NULL))) > NativeStackTrace::CacheMaxTTL) { + // exceeding TTL + keys_to_delete.push_back(k); + } + } + + // Delete expired entries + for( size_t i = 0; i < keys_to_delete.size(); i++ ) { + cache_delete_key(map, keys_to_delete[i]); + } + + if (keys_to_delete.size() > 0) { + float _cache_size = cache_size_KB(); + logInfo(2,"Evicted %d item(s) from the cache\n", keys_to_delete.size()); + logInfo(2,"The cache usage after eviction action is %.2f KB (released %.2f KB)\n", _cache_size, _prev_cache_size - _cache_size); + } +} + } // namespace pyperf } // namespace ebpf diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.h b/examples/cpp/pyperf/PyPerfNativeStackTrace.h index 3d06e8b7797e..ead3e8460f3b 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.h +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.h @@ -8,10 +8,20 @@ #include #include +#include namespace ebpf { namespace pyperf { +typedef struct { + unw_cursor_t cursor; + unw_addr_space_t as; + void *upt; + time_t timestamp; +} Object; + +typedef std::map MAP; + class NativeStackTrace { public: explicit NativeStackTrace(uint32_t pid, const uint8_t *raw_stack, @@ -19,7 +29,6 @@ class NativeStackTrace { std::vector get_stack_symbol() const; bool error_occured() const; - private: std::vector symbols; bool error_occurred; @@ -29,11 +38,27 @@ class NativeStackTrace { static uintptr_t ip; static uintptr_t sp; + static MAP cache; + static const uint16_t CacheMaxSizeMB; + static const uint16_t CacheMaxTTL; + + uint32_t cache_size() const; + uint32_t cache_single_entry_size() const; + float cache_size_KB() const; + static int access_reg(unw_addr_space_t as, unw_regnum_t regnum, unw_word_t *valp, int write, void *arg); static int access_mem(unw_addr_space_t as, unw_word_t addr, unw_word_t *valp, int write, void *arg); + + void cleanup(void *upt, unw_addr_space_t as); + + bool is_cached(const MAP &map, const uint32_t &key); + void cache_put(MAP &map, const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt); + Object cache_get(const MAP &map, const uint32_t &key); + bool cache_delete_key(MAP &map, const uint32_t &key); + void cache_eviction(MAP &map); }; } // namespace pyperf From 7c711d6eac546482e19fc314d816b1dfb9f06f38 Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Wed, 14 Sep 2022 16:45:03 +0200 Subject: [PATCH 02/11] Addressed review comments --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 61 ++++++++++--------- examples/cpp/pyperf/PyPerfNativeStackTrace.h | 17 +++--- 2 files changed, 41 insertions(+), 37 deletions(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index 14bced4e024b..b67439f8526d 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -27,7 +27,9 @@ const uint8_t *NativeStackTrace::stack = NULL; size_t NativeStackTrace::stack_len = 0; uintptr_t NativeStackTrace::sp = 0; uintptr_t NativeStackTrace::ip = 0; -MAP NativeStackTrace::cache; +time_t NativeStackTrace::now; +UnwindCache NativeStackTrace::cache; + NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, size_t stack_len, uintptr_t ip, uintptr_t sp) : error_occurred(false) { @@ -35,6 +37,7 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, NativeStackTrace::stack_len = stack_len; NativeStackTrace::ip = ip; NativeStackTrace::sp = sp; + NativeStackTrace::now = time(NULL); if (stack_len == 0) { return; @@ -56,7 +59,7 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, cache_eviction(cache); // Check whether the entry for the process ID is presented in the cache - if (is_cached(cache, pid) == false) { + if (!is_cached(cache, pid)) { logInfo(2,"The given key %d is not presented in the cache\n", pid); as = unw_create_addr_space(&my_accessors, 0); @@ -84,10 +87,10 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, } else { logInfo(2,"Found entry for the given key %d in the cache\n", pid); // Get from the cache - Object cached_value = cache_get(cache, pid); - cursor = cached_value.cursor; - as = cached_value.as; - upt = cached_value.upt; + UnwindCacheEntry cached_entry = cache_get(cache, pid); + cursor = cached_entry.cursor; + as = cached_entry.as; + upt = cached_entry.upt; } do { @@ -227,7 +230,7 @@ bool NativeStackTrace::error_occured() const { return error_occurred; } -bool NativeStackTrace::is_cached(const MAP &map, const uint32_t &key) { +bool NativeStackTrace::is_cached(const UnwindCache &map, const uint32_t &key) { try { map.at(key); return true; @@ -238,41 +241,41 @@ bool NativeStackTrace::is_cached(const MAP &map, const uint32_t &key) { return false; } -Object NativeStackTrace::cache_get(const MAP &map, const uint32_t &key) { - const Object & value = map.at(key); - return value; +UnwindCacheEntry NativeStackTrace::cache_get(const UnwindCache &map, const uint32_t &key) { + const UnwindCacheEntry & entry = map.at(key); + return entry; } -// cache_put adds a new entry to the map if the capacity allows -void NativeStackTrace::cache_put(MAP &map, const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt) { - +// cache_put adds a new entry to the unwind cache if the capacity allows +void NativeStackTrace::cache_put(UnwindCache &mp, const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt) { // Check available capacity if (cache_size() > NativeStackTrace::CacheMaxSizeMB*1024*1024 - cache_single_entry_size()) { logInfo(2, "The cache usage is %.2f MB, close to reaching the max memory usage (%d MB)\n", cache_size_KB()/1024, NativeStackTrace::CacheMaxSizeMB); - logInfo(2, "Skipping adding an entry for %d to the cache\n", key); - + logInfo(2, "Skipping adding an entry for %d to the cache\n", key); return; } - Object obj = {cursor, as, upt, time(NULL)}; - map[key] = obj; + UnwindCacheEntry entry = {cursor, as, upt, now}; + mp[key] = entry; logInfo(2, "New entry for %d was added to the cache\n", key); } // cache_delete_key removes the element from the cache and destroys unwind address space and UPT // to ensure that all memory and other resources are freed up -bool NativeStackTrace::cache_delete_key(MAP &map, const uint32_t &key) { +bool NativeStackTrace::cache_delete_key(UnwindCache &mp, const uint32_t &key) { + UnwindCacheEntry e; try { - Object v = cache_get(map, key); - map.erase(key); - cleanup(v.upt, v.as); - logInfo(2, "The entry for %d was deleted from the cache\n", key); - return true; + e = cache_get(mp, key); } catch (const std::out_of_range&) { logInfo(2, "Failed to delete entry for %d: no such key in the cache\n", key); + return false; } - return false; + + mp.erase(key); + cleanup(e.upt, e.as); + logInfo(2, "The entry for %d was deleted from the cache\n", key); + return true; } // cache_single_entry_size returns the number of bytes taken by single entry @@ -291,15 +294,15 @@ float NativeStackTrace::cache_size_KB() const { } // cache_eviction removes elements older than 5 minutes (CacheMaxTTL=300) -void NativeStackTrace::cache_eviction(MAP &map) { +void NativeStackTrace::cache_eviction(UnwindCache &mp) { std::vector keys_to_delete; float _prev_cache_size = cache_size_KB(); - for(std::map::iterator iter = map.begin(); iter != map.end(); ++iter) + for(std::map::iterator iter = mp.begin(); iter != mp.end(); ++iter) { uint32_t k = iter->first; - const Object & v = iter->second; - if (std::abs(difftime(v.timestamp, time(NULL))) > NativeStackTrace::CacheMaxTTL) { + const UnwindCacheEntry & e = iter->second; + if (std::abs(difftime(e.timestamp, NativeStackTrace::now)) > NativeStackTrace::CacheMaxTTL) { // exceeding TTL keys_to_delete.push_back(k); } @@ -307,7 +310,7 @@ void NativeStackTrace::cache_eviction(MAP &map) { // Delete expired entries for( size_t i = 0; i < keys_to_delete.size(); i++ ) { - cache_delete_key(map, keys_to_delete[i]); + cache_delete_key(mp, keys_to_delete[i]); } if (keys_to_delete.size() > 0) { diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.h b/examples/cpp/pyperf/PyPerfNativeStackTrace.h index ead3e8460f3b..cb0503eeb071 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.h +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.h @@ -18,9 +18,9 @@ typedef struct { unw_addr_space_t as; void *upt; time_t timestamp; -} Object; +} UnwindCacheEntry; -typedef std::map MAP; +typedef std::map UnwindCache; class NativeStackTrace { public: @@ -37,8 +37,9 @@ class NativeStackTrace { static size_t stack_len; static uintptr_t ip; static uintptr_t sp; + static time_t now; - static MAP cache; + static UnwindCache cache; static const uint16_t CacheMaxSizeMB; static const uint16_t CacheMaxTTL; @@ -54,11 +55,11 @@ class NativeStackTrace { void cleanup(void *upt, unw_addr_space_t as); - bool is_cached(const MAP &map, const uint32_t &key); - void cache_put(MAP &map, const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt); - Object cache_get(const MAP &map, const uint32_t &key); - bool cache_delete_key(MAP &map, const uint32_t &key); - void cache_eviction(MAP &map); + bool is_cached(const UnwindCache &map, const uint32_t &key); + void cache_put(UnwindCache &map, const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt); + UnwindCacheEntry cache_get(const UnwindCache &map, const uint32_t &key); + bool cache_delete_key(UnwindCache &map, const uint32_t &key); + void cache_eviction(UnwindCache &map); }; } // namespace pyperf From 9cc65a88c13d98613b2897ab24be59dad5c780e3 Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Tue, 20 Sep 2022 12:56:14 +0200 Subject: [PATCH 03/11] Removed whitespace --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index b67439f8526d..e4b01ad1d1ff 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -27,7 +27,7 @@ const uint8_t *NativeStackTrace::stack = NULL; size_t NativeStackTrace::stack_len = 0; uintptr_t NativeStackTrace::sp = 0; uintptr_t NativeStackTrace::ip = 0; -time_t NativeStackTrace::now; +time_t NativeStackTrace::now; UnwindCache NativeStackTrace::cache; From b6da37235a7d9635a901218cc754b13b78121911 Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Tue, 20 Sep 2022 13:40:54 +0200 Subject: [PATCH 04/11] Set logLevel=3 for informative logs in PyperfNativeStack --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 20 +++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index e4b01ad1d1ff..3f678605ce22 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -60,7 +60,7 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, // Check whether the entry for the process ID is presented in the cache if (!is_cached(cache, pid)) { - logInfo(2,"The given key %d is not presented in the cache\n", pid); + logInfo(3,"The given key %d is not presented in the cache\n", pid); as = unw_create_addr_space(&my_accessors, 0); upt = _UPT_create(pid); @@ -85,7 +85,7 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, cache_put(cache, pid, cursor, as, upt); } else { - logInfo(2,"Found entry for the given key %d in the cache\n", pid); + logInfo(3,"Found entry for the given key %d in the cache\n", pid); // Get from the cache UnwindCacheEntry cached_entry = cache_get(cache, pid); cursor = cached_entry.cursor; @@ -236,7 +236,7 @@ bool NativeStackTrace::is_cached(const UnwindCache &map, const uint32_t &key) { return true; } catch (const std::out_of_range&) { - logInfo(2, "No entry for %d in the cache\n", key); + logInfo(3, "No entry for %d in the cache\n", key); } return false; } @@ -250,14 +250,14 @@ UnwindCacheEntry NativeStackTrace::cache_get(const UnwindCache &map, const uint3 void NativeStackTrace::cache_put(UnwindCache &mp, const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt) { // Check available capacity if (cache_size() > NativeStackTrace::CacheMaxSizeMB*1024*1024 - cache_single_entry_size()) { - logInfo(2, "The cache usage is %.2f MB, close to reaching the max memory usage (%d MB)\n", cache_size_KB()/1024, NativeStackTrace::CacheMaxSizeMB); - logInfo(2, "Skipping adding an entry for %d to the cache\n", key); + logInfo(3, "The cache usage is %.2f MB, close to reaching the max memory usage (%d MB)\n", cache_size_KB()/1024, NativeStackTrace::CacheMaxSizeMB); + logInfo(3, "Skipping adding an entry for %d to the cache\n", key); return; } UnwindCacheEntry entry = {cursor, as, upt, now}; mp[key] = entry; - logInfo(2, "New entry for %d was added to the cache\n", key); + logInfo(3, "New entry for %d was added to the cache\n", key); } // cache_delete_key removes the element from the cache and destroys unwind address space and UPT @@ -268,13 +268,13 @@ bool NativeStackTrace::cache_delete_key(UnwindCache &mp, const uint32_t &key) { e = cache_get(mp, key); } catch (const std::out_of_range&) { - logInfo(2, "Failed to delete entry for %d: no such key in the cache\n", key); + logInfo(3, "Failed to delete entry for %d: no such key in the cache\n", key); return false; } mp.erase(key); cleanup(e.upt, e.as); - logInfo(2, "The entry for %d was deleted from the cache\n", key); + logInfo(3, "The entry for %d was deleted from the cache\n", key); return true; } @@ -315,8 +315,8 @@ void NativeStackTrace::cache_eviction(UnwindCache &mp) { if (keys_to_delete.size() > 0) { float _cache_size = cache_size_KB(); - logInfo(2,"Evicted %d item(s) from the cache\n", keys_to_delete.size()); - logInfo(2,"The cache usage after eviction action is %.2f KB (released %.2f KB)\n", _cache_size, _prev_cache_size - _cache_size); + logInfo(3,"Evicted %d item(s) from the cache\n", keys_to_delete.size()); + logInfo(3,"The cache usage after eviction action is %.2f KB (released %.2f KB)\n", _cache_size, _prev_cache_size - _cache_size); } } From 673562d5f4aae632e0bbd2de467c8f61f8a738fe Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Mon, 3 Oct 2022 18:07:08 +0200 Subject: [PATCH 05/11] Added pruning dead pip called in PyPerfProfiler::populatePidTable() --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 58 ++++++++++--------- examples/cpp/pyperf/PyPerfNativeStackTrace.h | 22 +++---- examples/cpp/pyperf/PyPerfProfiler.cc | 5 ++ 3 files changed, 49 insertions(+), 36 deletions(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index 3f678605ce22..3a2b783ae8b3 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -8,6 +8,7 @@ #include #include #include +#include #include #include #include @@ -31,6 +32,7 @@ time_t NativeStackTrace::now; UnwindCache NativeStackTrace::cache; + NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, size_t stack_len, uintptr_t ip, uintptr_t sp) : error_occurred(false) { NativeStackTrace::stack = raw_stack; @@ -56,10 +58,10 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, int res; // Pseudo-proactive way of implementing TTL - whenever any call is made, all expired entries are removed - cache_eviction(cache); + cache_eviction(); // Check whether the entry for the process ID is presented in the cache - if (!is_cached(cache, pid)) { + if (!is_cached(pid)) { logInfo(3,"The given key %d is not presented in the cache\n", pid); as = unw_create_addr_space(&my_accessors, 0); @@ -82,12 +84,12 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, } // Put to the cache - cache_put(cache, pid, cursor, as, upt); + cache_put(pid, cursor, as, upt); } else { logInfo(3,"Found entry for the given key %d in the cache\n", pid); // Get from the cache - UnwindCacheEntry cached_entry = cache_get(cache, pid); + UnwindCacheEntry cached_entry = cache_get(pid); cursor = cached_entry.cursor; as = cached_entry.as; upt = cached_entry.upt; @@ -137,6 +139,10 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, } +void NativeStackTrace::Prune_dead_pid(uint32_t dead_pid) { + cache_delete_key(dead_pid); +} + void NativeStackTrace::cleanup(void *upt, unw_addr_space_t as) { if (upt) { _UPT_destroy(upt); @@ -230,75 +236,75 @@ bool NativeStackTrace::error_occured() const { return error_occurred; } -bool NativeStackTrace::is_cached(const UnwindCache &map, const uint32_t &key) { +bool NativeStackTrace::is_cached(const uint32_t &key) { try { - map.at(key); + cache.at(key); return true; } catch (const std::out_of_range&) { - logInfo(3, "No entry for %d in the cache\n", key); + logInfo(3, "is_cached: no entry for pid %d\n", key); } return false; } -UnwindCacheEntry NativeStackTrace::cache_get(const UnwindCache &map, const uint32_t &key) { - const UnwindCacheEntry & entry = map.at(key); +UnwindCacheEntry NativeStackTrace::cache_get(const uint32_t &key) { + const UnwindCacheEntry & entry = cache.at(key); return entry; } -// cache_put adds a new entry to the unwind cache if the capacity allows -void NativeStackTrace::cache_put(UnwindCache &mp, const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt) { +// cache_put adds a new entry to the unwind cache if its capacity allows +void NativeStackTrace::cache_put(const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt) { // Check available capacity if (cache_size() > NativeStackTrace::CacheMaxSizeMB*1024*1024 - cache_single_entry_size()) { - logInfo(3, "The cache usage is %.2f MB, close to reaching the max memory usage (%d MB)\n", cache_size_KB()/1024, NativeStackTrace::CacheMaxSizeMB); - logInfo(3, "Skipping adding an entry for %d to the cache\n", key); + logInfo(2, "Skipping caching entry for pid %d due to the current cache usage equals to %.2f MB is close to the limit (%d MB)\n", + key, cache_size_KB()/1024, NativeStackTrace::CacheMaxSizeMB); return; } UnwindCacheEntry entry = {cursor, as, upt, now}; - mp[key] = entry; - logInfo(3, "New entry for %d was added to the cache\n", key); + cache[key] = entry; + logInfo(3, "New entry for pid %d was added to the cache\n", key); } // cache_delete_key removes the element from the cache and destroys unwind address space and UPT // to ensure that all memory and other resources are freed up -bool NativeStackTrace::cache_delete_key(UnwindCache &mp, const uint32_t &key) { +bool NativeStackTrace::cache_delete_key(const uint32_t &key) { UnwindCacheEntry e; try { - e = cache_get(mp, key); + e = cache_get(key); } catch (const std::out_of_range&) { - logInfo(3, "Failed to delete entry for %d: no such key in the cache\n", key); + logInfo(3, "cache_delete_key: no entry for pid %d\n", key); return false; } - mp.erase(key); + cache.erase(key); cleanup(e.upt, e.as); - logInfo(3, "The entry for %d was deleted from the cache\n", key); + logInfo(3, "The entry for pid %d was deleted from the cache\n", key); return true; } // cache_single_entry_size returns the number of bytes taken by single entry -uint32_t NativeStackTrace::cache_single_entry_size() const { +uint32_t NativeStackTrace::cache_single_entry_size() { return sizeof(decltype(cache)::key_type) + sizeof(decltype(cache)::mapped_type); } // cache_size returns the number of bytes currently in use by the cache -uint32_t NativeStackTrace::cache_size() const { +uint32_t NativeStackTrace::cache_size() { return sizeof(cache) + cache.size()*cache_single_entry_size(); } // cache_size_KB returns the number of kilobytes currently in use by the cache -float NativeStackTrace::cache_size_KB() const { +float NativeStackTrace::cache_size_KB() { return cache_size()/1024; } // cache_eviction removes elements older than 5 minutes (CacheMaxTTL=300) -void NativeStackTrace::cache_eviction(UnwindCache &mp) { +void NativeStackTrace::cache_eviction() { std::vector keys_to_delete; float _prev_cache_size = cache_size_KB(); - for(std::map::iterator iter = mp.begin(); iter != mp.end(); ++iter) + for(std::map::iterator iter = cache.begin(); iter != cache.end(); ++iter) { uint32_t k = iter->first; const UnwindCacheEntry & e = iter->second; @@ -310,7 +316,7 @@ void NativeStackTrace::cache_eviction(UnwindCache &mp) { // Delete expired entries for( size_t i = 0; i < keys_to_delete.size(); i++ ) { - cache_delete_key(mp, keys_to_delete[i]); + cache_delete_key(keys_to_delete[i]); } if (keys_to_delete.size() > 0) { diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.h b/examples/cpp/pyperf/PyPerfNativeStackTrace.h index cb0503eeb071..f9cf5ca7b701 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.h +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.h @@ -22,16 +22,19 @@ typedef struct { typedef std::map UnwindCache; + class NativeStackTrace { public: explicit NativeStackTrace(uint32_t pid, const uint8_t *raw_stack, size_t stack_len, uintptr_t ip, uintptr_t sp); + static void Prune_dead_pid(uint32_t dead_pid); std::vector get_stack_symbol() const; bool error_occured() const; private: std::vector symbols; bool error_occurred; + static UnwindCache cache; static const uint8_t *stack; static size_t stack_len; @@ -39,13 +42,12 @@ class NativeStackTrace { static uintptr_t sp; static time_t now; - static UnwindCache cache; static const uint16_t CacheMaxSizeMB; static const uint16_t CacheMaxTTL; - uint32_t cache_size() const; - uint32_t cache_single_entry_size() const; - float cache_size_KB() const; + static uint32_t cache_size(); + static uint32_t cache_single_entry_size(); + static float cache_size_KB(); static int access_reg(unw_addr_space_t as, unw_regnum_t regnum, unw_word_t *valp, int write, void *arg); @@ -53,13 +55,13 @@ class NativeStackTrace { static int access_mem(unw_addr_space_t as, unw_word_t addr, unw_word_t *valp, int write, void *arg); - void cleanup(void *upt, unw_addr_space_t as); + static void cleanup(void *upt, unw_addr_space_t as); - bool is_cached(const UnwindCache &map, const uint32_t &key); - void cache_put(UnwindCache &map, const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt); - UnwindCacheEntry cache_get(const UnwindCache &map, const uint32_t &key); - bool cache_delete_key(UnwindCache &map, const uint32_t &key); - void cache_eviction(UnwindCache &map); + bool is_cached(const uint32_t &key); + void cache_put(const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt); + static UnwindCacheEntry cache_get(const uint32_t &key); + static bool cache_delete_key(const uint32_t &key); + static void cache_eviction(); }; } // namespace pyperf diff --git a/examples/cpp/pyperf/PyPerfProfiler.cc b/examples/cpp/pyperf/PyPerfProfiler.cc index 9db85915ee3e..d97e7a9e8e62 100644 --- a/examples/cpp/pyperf/PyPerfProfiler.cc +++ b/examples/cpp/pyperf/PyPerfProfiler.cc @@ -29,6 +29,7 @@ #include "PyPerfLoggingHelper.h" #include "PyPerfVersion.h" #include "PyPerfProc.h" +#include "PyPerfNativeStackTrace.h" #include "bcc_elf.h" #include "bcc_proc.h" #include "bcc_syms.h" @@ -239,15 +240,19 @@ bool PyPerfProfiler::populatePidTable() { for (const auto pid : pid_config_keys) { auto pos = std::find(pids.begin(), pids.end(), pid); if (pos == pids.end()) { + // Remove dead pid from config map and native stack trace's cache pid_config_map.remove_value(pid); + NativeStackTrace::Prune_dead_pid(pid); } else { result = true; + // To avoid re-population pids.erase(pos); } } logInfo(3, "Populating pid table\n"); + // Populate only those pids not seen before for (const auto pid : pids) { PidData pidData; From 762f80de9f00a442e5e6e51800580308f278721b Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Mon, 3 Oct 2022 18:09:03 +0200 Subject: [PATCH 06/11] Formatting (git-clang-format) --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 43 +++++++++---------- examples/cpp/pyperf/PyPerfNativeStackTrace.h | 10 ++--- examples/cpp/pyperf/PyPerfProfiler.cc | 4 +- 3 files changed, 28 insertions(+), 29 deletions(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index 3a2b783ae8b3..e3753e400f89 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -5,15 +5,15 @@ #include "PyPerfNativeStackTrace.h" -#include +#include #include +#include +#include #include -#include +#include #include #include #include -#include -#include #include #include "PyPerfLoggingHelper.h" @@ -31,8 +31,6 @@ uintptr_t NativeStackTrace::ip = 0; time_t NativeStackTrace::now; UnwindCache NativeStackTrace::cache; - - NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, size_t stack_len, uintptr_t ip, uintptr_t sp) : error_occurred(false) { NativeStackTrace::stack = raw_stack; @@ -238,26 +236,29 @@ bool NativeStackTrace::error_occured() const { bool NativeStackTrace::is_cached(const uint32_t &key) { try { - cache.at(key); - return true; + cache.at(key); + return true; } catch (const std::out_of_range&) { - logInfo(3, "is_cached: no entry for pid %d\n", key); + logInfo(3, "is_cached: no entry for pid %d\n", key); } return false; } UnwindCacheEntry NativeStackTrace::cache_get(const uint32_t &key) { - const UnwindCacheEntry & entry = cache.at(key); + const UnwindCacheEntry &entry = cache.at(key); return entry; } // cache_put adds a new entry to the unwind cache if its capacity allows -void NativeStackTrace::cache_put(const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt) { +void NativeStackTrace::cache_put(const uint32_t &key, const unw_cursor_t cursor, + const unw_addr_space_t as, void *upt) { // Check available capacity - if (cache_size() > NativeStackTrace::CacheMaxSizeMB*1024*1024 - cache_single_entry_size()) { - logInfo(2, "Skipping caching entry for pid %d due to the current cache usage equals to %.2f MB is close to the limit (%d MB)\n", - key, cache_size_KB()/1024, NativeStackTrace::CacheMaxSizeMB); + if (cache_size() > NativeStackTrace::CacheMaxSizeMB*1024*1024 - cache_single_entry_size()) { + logInfo(2, + "Skipping caching entry for pid %d due to the current cache usage " + "equals to %.2f MB is close to the limit (%d MB)\n", + key, cache_size_KB() / 1024, NativeStackTrace::CacheMaxSizeMB); return; } @@ -285,27 +286,25 @@ bool NativeStackTrace::cache_delete_key(const uint32_t &key) { } // cache_single_entry_size returns the number of bytes taken by single entry -uint32_t NativeStackTrace::cache_single_entry_size() { +uint32_t NativeStackTrace::cache_single_entry_size() { return sizeof(decltype(cache)::key_type) + sizeof(decltype(cache)::mapped_type); } // cache_size returns the number of bytes currently in use by the cache -uint32_t NativeStackTrace::cache_size() { +uint32_t NativeStackTrace::cache_size() { return sizeof(cache) + cache.size()*cache_single_entry_size(); } // cache_size_KB returns the number of kilobytes currently in use by the cache -float NativeStackTrace::cache_size_KB() { - return cache_size()/1024; -} +float NativeStackTrace::cache_size_KB() { return cache_size() / 1024; } // cache_eviction removes elements older than 5 minutes (CacheMaxTTL=300) void NativeStackTrace::cache_eviction() { std::vector keys_to_delete; float _prev_cache_size = cache_size_KB(); - for(std::map::iterator iter = cache.begin(); iter != cache.end(); ++iter) - { + for (std::map::iterator iter = cache.begin(); + iter != cache.end(); ++iter) { uint32_t k = iter->first; const UnwindCacheEntry & e = iter->second; if (std::abs(difftime(e.timestamp, NativeStackTrace::now)) > NativeStackTrace::CacheMaxTTL) { @@ -316,7 +315,7 @@ void NativeStackTrace::cache_eviction() { // Delete expired entries for( size_t i = 0; i < keys_to_delete.size(); i++ ) { - cache_delete_key(keys_to_delete[i]); + cache_delete_key(keys_to_delete[i]); } if (keys_to_delete.size() > 0) { diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.h b/examples/cpp/pyperf/PyPerfNativeStackTrace.h index f9cf5ca7b701..179826d62791 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.h +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.h @@ -22,7 +22,6 @@ typedef struct { typedef std::map UnwindCache; - class NativeStackTrace { public: explicit NativeStackTrace(uint32_t pid, const uint8_t *raw_stack, @@ -45,10 +44,10 @@ class NativeStackTrace { static const uint16_t CacheMaxSizeMB; static const uint16_t CacheMaxTTL; - static uint32_t cache_size(); + static uint32_t cache_size(); static uint32_t cache_single_entry_size(); - static float cache_size_KB(); - + static float cache_size_KB(); + static int access_reg(unw_addr_space_t as, unw_regnum_t regnum, unw_word_t *valp, int write, void *arg); @@ -58,7 +57,8 @@ class NativeStackTrace { static void cleanup(void *upt, unw_addr_space_t as); bool is_cached(const uint32_t &key); - void cache_put(const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt); + void cache_put(const uint32_t &key, const unw_cursor_t cursor, + const unw_addr_space_t as, void *upt); static UnwindCacheEntry cache_get(const uint32_t &key); static bool cache_delete_key(const uint32_t &key); static void cache_eviction(); diff --git a/examples/cpp/pyperf/PyPerfProfiler.cc b/examples/cpp/pyperf/PyPerfProfiler.cc index d97e7a9e8e62..ce405ccfa130 100644 --- a/examples/cpp/pyperf/PyPerfProfiler.cc +++ b/examples/cpp/pyperf/PyPerfProfiler.cc @@ -27,9 +27,9 @@ #include #include "PyPerfLoggingHelper.h" -#include "PyPerfVersion.h" -#include "PyPerfProc.h" #include "PyPerfNativeStackTrace.h" +#include "PyPerfProc.h" +#include "PyPerfVersion.h" #include "bcc_elf.h" #include "bcc_proc.h" #include "bcc_syms.h" From 15f609e9b68baebdb513bfbfa7b08297798ee97a Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Thu, 6 Oct 2022 16:46:45 +0200 Subject: [PATCH 07/11] Fixed 'missing' symbols --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index e3753e400f89..ae2c3ca0dcb3 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -71,7 +71,7 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, return; } - res = unw_init_remote(&cursor, as, &upt); + res = unw_init_remote(&cursor, as, upt); if (res) { std::ostringstream error; error << "[Error unw_init_remote (" << unw_strerror(res) << ")]"; From 53968d35d3d8fa2fcd6cc3e951276fcaeff29cf0 Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Tue, 11 Oct 2022 21:03:59 +0200 Subject: [PATCH 08/11] Limit variable assignments - if cached, only cursor is needed in do...while loop --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 15 ++++++--------- 1 file changed, 6 insertions(+), 9 deletions(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index ae2c3ca0dcb3..70eff1c5cf25 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -50,9 +50,8 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, // The UPT implementation of these functions uses ptrace. We want to make sure they aren't getting called my_accessors.access_fpreg = NULL; my_accessors.resume = NULL; - unw_addr_space_t as; + unw_cursor_t cursor; - void *upt; int res; // Pseudo-proactive way of implementing TTL - whenever any call is made, all expired entries are removed @@ -61,7 +60,8 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, // Check whether the entry for the process ID is presented in the cache if (!is_cached(pid)) { logInfo(3,"The given key %d is not presented in the cache\n", pid); - + unw_addr_space_t as; + void *upt; as = unw_create_addr_space(&my_accessors, 0); upt = _UPT_create(pid); if (!upt) { @@ -86,11 +86,8 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, } else { logInfo(3,"Found entry for the given key %d in the cache\n", pid); - // Get from the cache - UnwindCacheEntry cached_entry = cache_get(pid); - cursor = cached_entry.cursor; - as = cached_entry.as; - upt = cached_entry.upt; + // Get cursor from the cache + cursor = cache_get(pid).cursor; } do { @@ -246,7 +243,7 @@ bool NativeStackTrace::is_cached(const uint32_t &key) { } UnwindCacheEntry NativeStackTrace::cache_get(const uint32_t &key) { - const UnwindCacheEntry &entry = cache.at(key); + UnwindCacheEntry entry = cache.at(key); return entry; } From ba3df2b052f415dffae9760bb6857bda06668ff8 Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Wed, 12 Oct 2022 19:23:45 +0200 Subject: [PATCH 09/11] Set unwind caching policy of address space 'as' to UNW_CACHE_GLOBAL. It enables global cache shared by all threads. --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index 70eff1c5cf25..57843ad329b6 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -50,9 +50,9 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, // The UPT implementation of these functions uses ptrace. We want to make sure they aren't getting called my_accessors.access_fpreg = NULL; my_accessors.resume = NULL; - unw_cursor_t cursor; int res; + std::ostringstream error; // Pseudo-proactive way of implementing TTL - whenever any call is made, all expired entries are removed cache_eviction(); @@ -63,6 +63,15 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, unw_addr_space_t as; void *upt; as = unw_create_addr_space(&my_accessors, 0); + res = unw_set_caching_policy(as, UNW_CACHE_GLOBAL); + if (res) { + error << "[Error unw_set_caching_policy (" << unw_strerror(res) << ")]"; + this->symbols.push_back(error.str()); + this->error_occurred = true; + cleanup(upt, as); + return; + } + upt = _UPT_create(pid); if (!upt) { this->symbols.push_back(std::string("[Error _UPT_create (system OOM)]")); @@ -73,7 +82,6 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, res = unw_init_remote(&cursor, as, upt); if (res) { - std::ostringstream error; error << "[Error unw_init_remote (" << unw_strerror(res) << ")]"; this->symbols.push_back(error.str()); this->error_occurred = true; @@ -243,7 +251,7 @@ bool NativeStackTrace::is_cached(const uint32_t &key) { } UnwindCacheEntry NativeStackTrace::cache_get(const uint32_t &key) { - UnwindCacheEntry entry = cache.at(key); + UnwindCacheEntry &entry = cache.at(key); return entry; } From 739f411f3124920d2d3b6165b0d50185ae2f7b22 Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Mon, 31 Oct 2022 18:35:12 +0100 Subject: [PATCH 10/11] Added symbols returned by unw_get_proc_name into cache --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 95 +++++++++++-------- examples/cpp/pyperf/PyPerfNativeStackTrace.h | 2 + 2 files changed, 56 insertions(+), 41 deletions(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index 57843ad329b6..3087c644849a 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -56,12 +56,13 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, // Pseudo-proactive way of implementing TTL - whenever any call is made, all expired entries are removed cache_eviction(); + void *upt; // Check whether the entry for the process ID is presented in the cache if (!is_cached(pid)) { logInfo(3,"The given key %d is not presented in the cache\n", pid); unw_addr_space_t as; - void *upt; + as = unw_create_addr_space(&my_accessors, 0); res = unw_set_caching_policy(as, UNW_CACHE_GLOBAL); if (res) { @@ -72,7 +73,7 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, return; } - upt = _UPT_create(pid); + upt=_UPT_create(pid); if (!upt) { this->symbols.push_back(std::string("[Error _UPT_create (system OOM)]")); this->error_occurred = true; @@ -96,49 +97,61 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, logInfo(3,"Found entry for the given key %d in the cache\n", pid); // Get cursor from the cache cursor = cache_get(pid).cursor; + upt =cache_get(pid).upt; } - do { - unw_word_t offset; - char sym[256]; - char *realname; - int status; - - // TODO: This function is very heavy. We should try to do some caching here, maybe in the - // underlying UPT function. - res = unw_get_proc_name(&cursor, sym, sizeof(sym), &offset); - if (res == 0) { - realname = abi::__cxa_demangle(sym, NULL, NULL, &status); - if (status == 0) { - this->symbols.push_back(std::string(realname)); - } else { - this->symbols.push_back(std::string(sym)); - } - free(realname); - } else { - unw_word_t ip; - unw_get_reg(&cursor, UNW_REG_IP, &ip); - unw_word_t sp; - unw_get_reg(&cursor, UNW_REG_SP, &sp); - logInfo(2, - "IP=0x%lx -- error: unable to obtain symbol name for this frame - %s " - "(frame SP=0x%lx)\n", - ip, unw_strerror(res), sp); - this->symbols.push_back(std::string("(missing)")); - this->error_occurred = true; - break; + if (cache.at(pid).unwinded) { + for (std::string proc_name : cache.at(pid).proc_names) { + this->symbols.push_back(proc_name); } - // Unwind only until we get to the function from which the current Python function is executed. - // On Python3 the main loop function is called "_PyEval_EvalFrameDefault", and on Python2 it's - // "PyEval_EvalFrameEx". - if (memcmp(sym, "_PyEval_EvalFrameDefault", - sizeof("_PyEval_EvalFrameDefault")) == 0 || - memcmp(sym, "PyEval_EvalFrameEx", sizeof("PyEval_EvalFrameEx")) == 0) - { - break; - } - } while (unw_step(&cursor) > 0); + } else { + do { + unw_word_t offset; + char sym[256]; + char *realname; + int status; + + // TODO: This function is very heavy. We should try to do some caching here, maybe in the + // underlying UPT function. + res = unw_get_proc_name(&cursor, sym, sizeof(sym), &offset); + if (res == 0) { + realname = abi::__cxa_demangle(sym, NULL, NULL, &status); + if (status == 0) { + this->symbols.push_back(std::string(realname)); + cache[pid].proc_names.push_back(std::string(realname)); + } else { + this->symbols.push_back(std::string(sym)); + cache[pid].proc_names.push_back(std::string(sym)); + } + free(realname); + } else { + unw_word_t ip; + unw_get_reg(&cursor, UNW_REG_IP, &ip); + unw_word_t sp; + unw_get_reg(&cursor, UNW_REG_SP, &sp); + logInfo(2, + "IP=0x%lx -- error: unable to obtain symbol name for this frame - %s " + "(frame SP=0x%lx)\n", + ip, unw_strerror(res), sp); + this->symbols.push_back(std::string("(missing)")); + cache[pid].proc_names.push_back(std::string("(missing)")); + this->error_occurred = true; + break; + } + + // Unwind only until we get to the function from which the current Python function is executed. + // On Python3 the main loop function is called "_PyEval_EvalFrameDefault", and on Python2 it's + // "PyEval_EvalFrameEx". + if (memcmp(sym, "_PyEval_EvalFrameDefault", + sizeof("_PyEval_EvalFrameDefault")) == 0 || + memcmp(sym, "PyEval_EvalFrameEx", sizeof("PyEval_EvalFrameEx")) == 0) + { + break; + } + } while (unw_step(&cursor) > 0); + cache[pid].unwinded = true; + } } diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.h b/examples/cpp/pyperf/PyPerfNativeStackTrace.h index 179826d62791..37c92a2d3fe0 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.h +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.h @@ -18,6 +18,8 @@ typedef struct { unw_addr_space_t as; void *upt; time_t timestamp; + std::vector proc_names; + bool unwinded = false; } UnwindCacheEntry; typedef std::map UnwindCache; From 624f0ef841e7e767982a3f72bb7db79b7983f9cf Mon Sep 17 00:00:00 2001 From: Izabella Raulin Date: Mon, 31 Oct 2022 19:53:27 +0100 Subject: [PATCH 11/11] Added log to monitor number of cache's entries and size --- examples/cpp/pyperf/PyPerfNativeStackTrace.cc | 65 ++++++++++++++++--- examples/cpp/pyperf/PyPerfNativeStackTrace.h | 2 + 2 files changed, 58 insertions(+), 9 deletions(-) diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc index 3087c644849a..423472a2bfcf 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.cc +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.cc @@ -31,6 +31,13 @@ uintptr_t NativeStackTrace::ip = 0; time_t NativeStackTrace::now; UnwindCache NativeStackTrace::cache; +// DEBUG SECTION +bool dbg_Unlimited_Cache = true; +float NativeStackTrace::dbg_maxSize = 0.0; +int NativeStackTrace::dbg_counter = 0; +int dbg_maxNumOfKeys = 0; +// THE END OF DEBUG SECTION + NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, size_t stack_len, uintptr_t ip, uintptr_t sp) : error_occurred(false) { NativeStackTrace::stack = raw_stack; @@ -56,8 +63,31 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, // Pseudo-proactive way of implementing TTL - whenever any call is made, all expired entries are removed cache_eviction(); - void *upt; + // DEBUG SECTION + float dbg_current_cache_size = cache_size_KB(); + if (dbg_maxSize < dbg_current_cache_size) { + logInfo(2, "DEBUGIZA - Increase in cache usage by %.2f KB\n", + dbg_current_cache_size - dbg_maxSize); + dbg_maxSize = dbg_current_cache_size; + dbg_maxNumOfKeys = cache.size(); + dbg_counter = 0; + } else { + dbg_counter++; + if (dbg_counter >= 10) { + // after 10 times we are sure that the cache max size is stable + logInfo(2, "DEBUGIZA - cache usage stops growing\n"); + } + } + + logInfo(2, "DEBUGIZA - cache_size=%.2f KB | %d entries \n", + dbg_current_cache_size, cache.size()); + logInfo(2, "DEBUGIZA - cache_max_size=%.2f KB | %d entries \n", dbg_maxSize, + dbg_maxNumOfKeys); + + // THE END OF DEBUG-SECTION + + void *upt; // Check whether the entry for the process ID is presented in the cache if (!is_cached(pid)) { logInfo(3,"The given key %d is not presented in the cache\n", pid); @@ -73,7 +103,7 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, return; } - upt=_UPT_create(pid); + upt = _UPT_create(pid); if (!upt) { this->symbols.push_back(std::string("[Error _UPT_create (system OOM)]")); this->error_occurred = true; @@ -94,19 +124,25 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, cache_put(pid, cursor, as, upt); } else { - logInfo(3,"Found entry for the given key %d in the cache\n", pid); + logInfo(2, "Found entry for the given key %d in the cache\n", pid); // Get cursor from the cache cursor = cache_get(pid).cursor; upt =cache_get(pid).upt; } if (cache.at(pid).unwinded) { + // logInfo(2, "DEBUGIZA: unwiding is already done for pid %d\n", pid); for (std::string proc_name : cache.at(pid).proc_names) { + // logInfo(2, "DEBUGIZA: read unwinded symbol=%s\n", + // std::string(proc_name)); this->symbols.push_back(proc_name); } } else { + logInfo(2, "DEBUGIZA: process unwinwining for pid %d\n", pid); + int dbg_proc_name_counter = 0; do { + dbg_proc_name_counter++; unw_word_t offset; char sym[256]; char *realname; @@ -116,6 +152,7 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, // underlying UPT function. res = unw_get_proc_name(&cursor, sym, sizeof(sym), &offset); if (res == 0) { + logInfo(2, "DEBUGIZA offset = %lx name = %s\n", (long)offset, sym); realname = abi::__cxa_demangle(sym, NULL, NULL, &status); if (status == 0) { this->symbols.push_back(std::string(realname)); @@ -150,7 +187,12 @@ NativeStackTrace::NativeStackTrace(uint32_t pid, const unsigned char *raw_stack, break; } } while (unw_step(&cursor) > 0); + + logInfo(2, "DEBUGIZA: setting unwind=true for pid %d\n", pid); + cache[pid].unwinded = true; + logInfo(2, "DEBUGIZA: for pid=%d stored %d proc_names\n", pid, + dbg_proc_name_counter); } } @@ -272,12 +314,17 @@ UnwindCacheEntry NativeStackTrace::cache_get(const uint32_t &key) { void NativeStackTrace::cache_put(const uint32_t &key, const unw_cursor_t cursor, const unw_addr_space_t as, void *upt) { // Check available capacity - if (cache_size() > NativeStackTrace::CacheMaxSizeMB*1024*1024 - cache_single_entry_size()) { - logInfo(2, - "Skipping caching entry for pid %d due to the current cache usage " - "equals to %.2f MB is close to the limit (%d MB)\n", - key, cache_size_KB() / 1024, NativeStackTrace::CacheMaxSizeMB); - return; + // For debug purpose, skip the limit + if (!dbg_Unlimited_Cache) { + if (cache_size() > NativeStackTrace::CacheMaxSizeMB * 1024 * 1024 - + cache_single_entry_size()) { + logInfo( + 2, + "Skipping caching entry for pid %d due to the current cache usage " + "equals to %.2f MB is close to the limit (%d MB)\n", + key, cache_size_KB() / 1024, NativeStackTrace::CacheMaxSizeMB); + return; + } } UnwindCacheEntry entry = {cursor, as, upt, now}; diff --git a/examples/cpp/pyperf/PyPerfNativeStackTrace.h b/examples/cpp/pyperf/PyPerfNativeStackTrace.h index 37c92a2d3fe0..172376d5393e 100644 --- a/examples/cpp/pyperf/PyPerfNativeStackTrace.h +++ b/examples/cpp/pyperf/PyPerfNativeStackTrace.h @@ -42,6 +42,8 @@ class NativeStackTrace { static uintptr_t ip; static uintptr_t sp; static time_t now; + static int dbg_counter; + static float dbg_maxSize; static const uint16_t CacheMaxSizeMB; static const uint16_t CacheMaxTTL;