Delayed processing for ProcessManager.pidToProcessInfo #321

christos68k · 2025-01-22T23:45:10Z

Summary

Renamed SymbolizationComplete to ProcessedUntil and moved to processinfo.go
Dropped no longer needed "symbolize now" remnants
Implemented delayed ProcessManager.pidToProcessInfo cleanup

Leverages #307 to ensure that process metadata is not discarded before all relevant trace events have been processed.

Fixes #278.

You may find reviewing commit-by-commit to be simpler.

The old "symbolize now" mechanism is no longer needed.

christos68k · 2025-01-22T23:51:21Z

processmanager/processinfo.go

 	if !ok {
 		log.Debugf("Skip process exit handling for unknown PID %d", pid)
-		return symbolize
+		return
 	}

 	// Delete all entries we have for this particular PID from pid_page_to_mapping_info.


I kept this cleanup here as there's no immediate need to postpone cleaning up the eBPF map until traceCaptureKTime >= pidExitKtime (unlike pidToProcessInfo). This also speeds up execution of ProcessedUntil compared to having the map cleanup take place there.

christos68k · 2025-01-22T23:52:21Z

processmanager/processinfo.go

 // fast enough and this particular pid is reused again by the system.
 // NOTE: Exported only for tracer.
-func (pm *ProcessManager) ProcessPIDExit(pid libpf.PID) bool {
+func (pm *ProcessManager) ProcessPIDExit(pid libpf.PID) {
+	exitKTime := times.GetKTime()


Moved this outside the lock for improved accuracy (there's a debug log in ProcessedUntil that prints exit latency).

Uses ProcessedUntil mechanism to guarantee that process metadata is not discarded before all relevant trace events have been processed.

christos68k · 2025-01-23T01:06:28Z

processmanager/processinfo.go

-		return symbolize
+		return
+	}
+	if pidExited {


We don't want to attempt a repeat cleanup for the same PID, if we've previously performed it.

christos68k · 2025-01-23T01:07:30Z

processmanager/manager.go

@@ -348,34 +347,6 @@ func (pm *ProcessManager) MaybeNotifyAPMAgent(
 	return serviceName
 }

-func (pm *ProcessManager) SymbolizationComplete(traceCaptureKTime times.KTime) {


Moved to processinfo.go for consistency (all pidToProcessInfo accessors in one place), renamed to ProcessedUntil and updated to also cleanup pidToProcessInfo.

christos68k · 2025-01-23T01:12:39Z

processmanager/processinfo.go

@@ -548,9 +553,6 @@ func (pm *ProcessManager) ProcessPIDExit(pid libpf.PID) bool {
 				address, pid, err)
 		}
 	}
-	delete(pm.pidToProcessInfo, pid)


This is now taking place in ProcessedUntil, delayed until traceCaptureKTime >= exitKTime.

christos68k · 2025-01-23T01:18:16Z

processmanager/manager.go

@@ -294,33 +293,6 @@ func (pm *ProcessManager) ConvertTrace(trace *host.Trace) (newTrace *libpf.Trace
 	return newTrace
 }

-// findMappingForTrace locates the mapping for a given host trace.


Moved without changes to processinfo.go for consistency.

christos68k · 2025-01-23T01:23:43Z

processmanager/processinfo.go

-		if len(pm.interpreters[pid]) > 0 {
+	pidExited := false
+	info, pidExists := pm.pidToProcessInfo[pid]
+	if pidExists || (pm.interpreterTracerEnabled &&


Essentially same logic as before with these additions:

Don't add exitKTime to pm.exitEvents if it already exists.

Also add exitKTime to pm.exitEvents if pm.pidToProcessInfo[pid] exists, as we want to cleanup the latter in delayed fashion.

christos68k · 2025-01-23T01:39:22Z

processmanager/processinfo.go

+			continue
+		}
+
+		delete(pm.pidToProcessInfo, pid)


Same logic as before with this single-line addition.

florianl

first look with some comments

florianl · 2025-01-23T09:34:30Z

processmanager/processinfo.go

-
-	info, ok := pm.pidToProcessInfo[pid]
-	if !ok {
+	if !pidExists {


To keep the global read & write lock as short as possible, the if !pidExists {..} part should be moved before if pidExists || (pm.interpreterTracerEnabled && len(pm.interpreters[pid]) > 0) {..}.

That would prevent executing if _, pidExited = ... in case (pm.interpreterTracerEnabled && len(pm.interpreters[pid]) > 0 is true.

As Tim wrote, this would alter the logic. I tried to keep as much of the original semantics the same to avoid introducing new races. Maybe here it's possible to safely say that if !pidExists then it's OK not to write exitKTime in pm.exitEvents but we'd need to carefully examine all subsystem interactions, check for race conditions etc.

follow up is done in #325

florianl · 2025-01-23T09:37:56Z

processmanager/processinfo.go

-		return symbolize
+		return
+	}
+	if pidExited {


I think, pidExited should be renamed to pidExitProcessed so something similar, this would it make obvious, that we want to avoid duplicate work.

florianl · 2025-01-23T09:41:39Z

processmanager/processinfo.go

+	pm.mu.Lock()
+	defer pm.mu.Unlock()
+
+	nowKTime := times.GetKTime()
+	log.Debugf("ProcessedUntil captureKT: %v latency: %v ms",
+		traceCaptureKTime, (nowKTime-traceCaptureKTime)/1e6)
+


keep the lock holding as short as possible:

Suggested change

pm.mu.Lock()

defer pm.mu.Unlock()

nowKTime := times.GetKTime()

log.Debugf("ProcessedUntil captureKT: %v latency: %v ms",

traceCaptureKTime, (nowKTime-traceCaptureKTime)/1e6)

nowKTime := times.GetKTime()

log.Debugf("ProcessedUntil captureKT: %v latency: %v ms",

traceCaptureKTime, (nowKTime-traceCaptureKTime)/1e6)

pm.mu.Lock()

defer pm.mu.Unlock()

This can affect the latency measurement, since we're timing before the lock.

processmanager/processinfo.go

christos68k added 2 commits January 22, 2025 16:44

Rename SymbolizationComplete to ProcessedUntil

cbdc6f9

Simplify ProcessManager.ProcessPIDExit

5317c8f

The old "symbolize now" mechanism is no longer needed.

christos68k self-assigned this Jan 22, 2025

christos68k requested review from a team as code owners January 22, 2025 23:45

christos68k commented Jan 22, 2025

View reviewed changes

Delayed ProcessManager.pidToProcessInfo cleanup

a8c3852

Uses ProcessedUntil mechanism to guarantee that process metadata is not discarded before all relevant trace events have been processed.

christos68k force-pushed the ck/processed-until branch from 5629d4b to a8c3852 Compare January 23, 2025 00:55

Move ProcessManager.ProcessedUntil to processinfo.go

84c6ca8

christos68k commented Jan 23, 2025

View reviewed changes

Move ProcessManager.findMappingForTrace to processinfo.go

5cd4b3a

christos68k commented Jan 23, 2025

View reviewed changes

florianl reviewed Jan 23, 2025

View reviewed changes

rockdaboot reviewed Jan 23, 2025

View reviewed changes

processmanager/processinfo.go Show resolved Hide resolved

rockdaboot reviewed Jan 23, 2025

View reviewed changes

processmanager/processinfo.go Show resolved Hide resolved

rockdaboot reviewed Jan 23, 2025

View reviewed changes

processmanager/processinfo.go Show resolved Hide resolved

Renamed pidExited to pidExitProcessed

b1e2622

rockdaboot approved these changes Jan 23, 2025

View reviewed changes

christos68k mentioned this pull request Jan 24, 2025

Metrics for trace event perf event monitor #322

Merged

florianl approved these changes Jan 24, 2025

View reviewed changes

christos68k merged commit f094776 into main Jan 24, 2025
24 checks passed

christos68k deleted the ck/processed-until branch January 24, 2025 13:28

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Delayed processing for ProcessManager.pidToProcessInfo #321

Delayed processing for ProcessManager.pidToProcessInfo #321

christos68k commented Jan 22, 2025 •

edited

Loading

christos68k Jan 22, 2025 •

edited

Loading

christos68k Jan 22, 2025

christos68k Jan 23, 2025

christos68k Jan 23, 2025 •

edited

Loading

christos68k Jan 23, 2025 •

edited

Loading

christos68k Jan 23, 2025

christos68k Jan 23, 2025

christos68k Jan 23, 2025

florianl left a comment

florianl Jan 23, 2025

rockdaboot Jan 23, 2025

christos68k Jan 23, 2025 •

edited

Loading

florianl Jan 24, 2025

florianl Jan 23, 2025

christos68k Jan 23, 2025

florianl Jan 23, 2025

christos68k Jan 23, 2025

Delayed processing for ProcessManager.pidToProcessInfo #321

Delayed processing for ProcessManager.pidToProcessInfo #321

Conversation

christos68k commented Jan 22, 2025 • edited Loading

Summary

christos68k Jan 22, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

christos68k Jan 23, 2025 • edited Loading

Choose a reason for hiding this comment

christos68k Jan 23, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

florianl left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

christos68k Jan 23, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

christos68k commented Jan 22, 2025 •

edited

Loading

christos68k Jan 22, 2025 •

edited

Loading

christos68k Jan 23, 2025 •

edited

Loading

christos68k Jan 23, 2025 •

edited

Loading

christos68k Jan 23, 2025 •

edited

Loading