Added caching in PyperfNativeStack

[IzabellaRaulin]

• Updating the performance results after caching returned symbols by unw_get_proc_name
• in-progress: Updating the performance results for the latest commit
  Full description and results are available at [Ready-to-review] Adding caching to PyPerfNativeStackTrace gprofiler#421

Before (docker image granulate/gprofiler:1.6.0):

[Outdated] After enabling caching

[Jongy]

Suggested change

	time_t NativeStackTrace::now;
	time_t NativeStackTrace::now;

[Jongy]

There some other formatting issues - you can run ./scripts/git-clang-format to fix them all :)

[IzabellaRaulin]

The last commit contains git-clang-format formatting changes for files modified in the PR.

[Jongy]

Why not return a reference here?

[IzabellaRaulin]

My objective was to limit cache_get to read-only access and to make it more explicit that the content of the cache is only changing when cache_put or cache_delete_key are called. The code is then easier to maintain especially since there is no need to have a reference there.

Do you prefer having a reference here? Might you provide briefly why you think so? Maybe I missed something...I am open to your suggestion and looking forward to your opinion and guidelines.

[Jongy]

2 means it's not printed by default - only if we pass -v 2 or higher. Correct?

(these should not be printed by default, only when debugging)

[IzabellaRaulin]

It is not printed by default (and longer story below), but it makes sense to put here logLevel=3 to distinguish this info from others that are more of a warning nature.

Long story short, this is related to what I reported regarding my troubles getting/finding logs from PyPerfNativeStack. Increasing verbosity on granulate/gprofiler does not make those bcc/pyperf logs visible in gprofiler stdout. Increasing setVerbosityLevel in PyPerfLoggingHelper.cc) does not help as well.

I understand no one has reported this problem before so maybe it's my lack of knowledge of how the gprofiler handles logs coming from its modules. So, I decided to check the correctness of those new logs (especially passed values - how they look like) by dumping them into a temp file. For this purpose, I modified locally void logInfo to open a /tmp/myfile.txt and process vfprintf to it. Below I share the code diff.

 void logInfo(uint64_t logLevel, const char* fmt, ...) {
+
+  if (logLevel <= 2 ) {
+    va_list va;
+    va_start(va, fmt);
+    FILE * pFile;
+    pFile = fopen("/tmp/gprofiler_tmp/izahelperfile.txt","a");
+    if (pFile) {
+      std::vfprintf(pFile, fmt, va);
+      fclose (pFile);
+      va_end(va);
+    }
 [...]
 }

[Jongy]

It's an interesting idea to increase verbosity in PyPerf when you increase verbosity in gProfiler indeed. It's not the case. That doesn't explain why PyPerf shows no prints though.

[Jongy]

I applied this diff on gProfiler and now I do see log messages in the PyPerf output: print:

diff --git a/gprofiler/profilers/python_ebpf.py b/gprofiler/profilers/python_ebpf.py
index 9113f355..649f9367 100644
--- a/gprofiler/profilers/python_ebpf.py
+++ b/gprofiler/profilers/python_ebpf.py
@@ -175,6 +175,8 @@ class PythonEbpfProfiler(ProfilerBase):
             str(self._EVENTS_BUFFER_PAGES),
             "--symbols-map-size",
             str(self._SYMBOLS_MAP_SIZE),
+            "-v",
+            "9",
             # Duration is irrelevant here, we want to run continuously.
         ] + self._offset_args()

I'll open a ticket to add it, it's a good feature that'll help debug PyPerf in the future.

[Jongy]

Created Granulate/gprofiler#516

[Jongy]

Together with TTL-based eviction - PyPerf already tracks PIDs exiting so we can (and should) make use of that - otherwise we risk PID reuse getting us false results.

See populatePidTable where in the Pruning dead pids step it removes PIDs. We should call cache_delete_key there as well. Please ensure it actually works in removing PIDs that exit

[IzabellaRaulin]

I push a draft of implementation.
populatePIDTable calls static NativeStackTrace::Pruning_dead_pid(). Please take a look at the proposal and let me know if such an approach is acceptable. It is WIP, so please ignore debug logs. I will remove it later.

In the meantime, I am debugging why the cache version gives missing and do not manage to add native symbols properly.

[Jongy]

It's fine with me. Despite written in C++ this entire project is fairly functional.

[IzabellaRaulin]

Thanks! I removed debug leftovers.

[Jongy]

@IzabellaRaulin , next times if you need to update from master, you can just merge it instead of rebasing. Rebase causes github to lose the current review state (I cannot see just the new changes). In any case we use squash-and-merge here, so whether you used merge or rebase to update your branch doesn't matter much eventually :)

[Jongy]

Besides the debug prints etc - please also remove all unrelated formatting changes before we merge (e.g all blank lines addition/removals, ...)

[IzabellaRaulin]

@IzabellaRaulin , next times if you need to update from master, you can just merge it instead of rebasing. Rebase causes github to lose the current review state (I cannot see just the new changes). In any case we use squash-and-merge here, so whether you used merge or rebase to update your branch doesn't matter much eventually :)

Sorry, I didn't realize. But I put new changes in separate commits, so I hope that will help to track what is new

[IzabellaRaulin]

Added commit 'Fixed missing symbols` to address the observed issue with missing native symbols in the version with enabled caching.

After:

Before (to prove the root cause was identified properly):