Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Profiler incorrectly handles process exit when non-main threads are still running #365

Open
korniltsev opened this issue Feb 21, 2025 · 1 comment
Open

Profiler incorrectly handles process exit when non-main threads are still running #365

korniltsev opened this issue Feb 21, 2025 · 1 comment

Comments

@korniltsev
Copy link
Contributor

When profiling multithreaded applications, the profiler incorrectly assumes the entire process has exited when only the main thread terminates. This leads to the following issues:

  1. Ebpf program reports pid whan pid==tgid is dead
  2. Userspace handles the dead process cleaning up all process info and mappings
  3. When eBPF program detects activity from remaining threads, it reports them as a new process again
  4. Profiler fails to find any mappings for this "new" process and marks it as dead
  5. This cycle repeats for remaining active threads leading to infinite attempts to enable&disable profiling for this process.

Reproducer:

#define _GNU_SOURCE
#include <stdio.h>
#include <pthread.h>
#include <unistd.h>

int fib(int n)
{
    if (n <= 1) return 1;
    return fib(n-1) + fib(n-2);
}

void* thread_function(void* arg) {
    printf("Thread T1 is still running... %d\n", gettid());
    while(1) {
        fib(43);
    }
    return NULL;
}

int main() {
    printf("Main thread is starting... %d \n", gettid());

    pthread_t thread_id;
    if (pthread_create(&thread_id, NULL, thread_function, NULL) != 0) {
        return 1;
    }
    fib(43);
    printf("Main thread is exiting... %d \n", gettid());
    pthread_exit(NULL);
    return 0;
}

Busy logs:

cat log | grep 964585 | head -n 100
time="2025-02-21T22:11:20+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:20+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:21+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:21+08:00" level=debug msg="ProcessManager doesn't know about PID 964585"
time="2025-02-21T22:11:21+08:00" level=debug msg="Added 4 mappings, removed 0 mappings for PID: 964585"
time="2025-02-21T22:11:21+08:00" level=debug msg="+ PID: 964585"
time="2025-02-21T22:11:21+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:21+08:00" level=debug msg="ProcessManager doesn't know about PID 964585"
time="2025-02-21T22:11:25+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:25+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:25+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:25+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:25+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:25+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:25+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip duplicate process exit handling for PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="PID 964585 exit latency 637 ms"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip process exit handling for unknown PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip process exit handling for unknown PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip process exit handling for unknown PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip process exit handling for unknown PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip process exit handling for unknown PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip process exit handling for unknown PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="Skip process exit handling for unknown PID 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="=> PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="= PID: 964585"
time="2025-02-21T22:11:26+08:00" level=debug msg="- PID: 964585"

Potential workarounds:

  1. Maybe we should not report the process to userspace if a process with pid=tgid already dead.
  2. Or as an alternative we could maybe hook into disassociate_ctty, but Im not 100% sure yet, this requires more thorough investigation and 👀
@christos68k
Copy link
Member

christos68k commented Feb 21, 2025 •
edited
Loading

If we want to be able to keep profiling the remaining threads, when the main thread calls pthread_exit (instead of returning from main or explicitly calling exit) we should not unload process information which implies that we need to be able to detect when this happens. To me this seems like a legitimate use-case that the profiler should support, even if it may not be very prevalent.

We can use the presence of /proc/PID, which will still be there if main thread exits but other threads are still running and update the mapping synchronization logic to NOT call processPIDExit when no mappings can be retrieved from /proc/PID/maps (which will be empty when main thread exits).

This can take place in userspace code (no updates to eBPF needed). However, this creates two new problems:

  1. Userspace will not receive another notification for PID when process eventually dies. So triggering cleanup in userspace will be left solely to the periodic cleanup PIDs logic, which right now executes every 5 minutes. This may introduce a PID reuse concern.
  2. As /proc/PID/maps will be empty after main thread exits, the profiler has no way to detect mapping changes (e.g. by one of the remaining threads).

For 1. we could execute the PID cleanup logic more frequently (e.g. once a minute or less). We could also keep a separate set of PIDs whose main thread has called pthread_exit and only use a higher frequency for them.

To fully support 2. we'd need a more elaborate solution. One option is to introduce thread tracking into process manager (for example, instead of having kernel only report PID to userspace, we could also send TID and have processmanager also track TIDs).

Alternatively, we could first start with 1. and leave solving 2. for another day.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@korniltsev @christos68k