Cloud Profiler - Continuous Profiling trong Production

Tại sao profiling khác với tracing

Tracing (Cloud Trace):

• "Request này tốn bao nhiêu thời gian?"
• "Request tôi chậm là vì đợi chỗ nào?"
• Macro-level: request → services → spans

Profiling (Cloud Profiler):

• "Tại sao function A chậm?"
• "Heap đang giữ những gì?"
• "Goroutine bị stuck ở đâu?"
• Micro-level: function → instructions → CPU cycles

Combination: Trace nói KHI NÀO, profiler nói TẠI SAO.

Internal Model: Statistical Sampling

Cloud Profiler không instrument code (expensive), mà dùng statistical sampling:

CPU Profiler Timeline:

t=0ms   ┌─ Sample 1: "What function is executing?"
        │  Stack trace: main() → handle_request() → db.query()
t=10ms  │
        ├─ Sample 2: "What function is executing?"
        │  Stack trace: main() → handle_request() → serialize_json()
t=20ms  │
        ├─ Sample 3: "What function is executing?"
        │  Stack trace: main() → handle_request() → db.query()
        │
        ... (many more samples)
        │
        └─ Result: "db.query() appeared in 40% of samples → 40% of CPU time spent there"

Sampling Frequency

Cloud Profiler typically samples:

Profile Type	Sampling Frequency	Why
CPU	Every 10ms (100 Hz)	Balances accuracy vs overhead
Heap	Every N MB allocated	Track memory allocation
Goroutine	On-demand	Very low overhead

Frequent sampling = accurate profile, but higher overhead. Infrequent sampling = low overhead, but miss short-lived functions.

100 Hz (10ms interval) is standard compromise:

• Captures functions ~10ms or longer
• Misses sub-millisecond functions
• ~0.5% CPU overhead

Sampling Bias

Statistical sampling introduce bias: short-lived functions are under-represented.

Function A: runs 1000 times × 1ms each = 1 second CPU
Function B: runs 1 time × 1 second = 1 second CPU

At 100 Hz (10ms samples):
- Function A: ~100 samples (correct)
- Function B: ~100 samples (correct)
- Ratio: 1:1 (correct)

But at 1 Hz (1 second samples):
- Function A: ~1-2 samples (huge variance, might be 0!)
- Function B: ~1 sample
- Ratio: can be 0:1 or 1:1 (inaccurate!)

This is why sampling frequency matters. Too infrequent → miss short functions.

CPU Profiling - Time on Processor

What CPU Profiler Measures

"On-CPU time" - thời gian CPU thực sự chạy code.

Timeline:

t=0s    ┌─ Function starts
        │  CPU: executing
t=0.1s  │  CPU: executing (sample: "allocate_memory")
        │
t=0.2s  ├─ I/O call (read from database)
        │  CPU: NOT executing (off-CPU)
        │  Disk: working
        │
t=0.3s  │  I/O completes, function resumes
        │  CPU: executing (sample: "process_data")
        │
t=0.4s  └─ Function completes

CPU profiler captures: t=0.1s and t=0.3s samples CPU time: 0.2s (not including I/O wait)

Flame Graph Interpretation

[Stack Trace at t=0.1s]
main
└── handle_request
    └── process_order
        └── validate_order
            └── regex_match  ← CPU spent here

[Stack Trace at t=0.3s]
main
└── handle_request
    └── process_order
        └── calculate_price

Flame graph visualization:

                     [main]
                       |
                [handle_request]
                  /           \
          [process_order]    ...
            /            \
    [validate_order]  [calculate_price]
        |                   |
    [regex_match]        ...

Width represents time spent. regex_match is widest → most CPU time there.

Flame Graph Navigation

In Cloud Profiler console:

1. Click on function → Drill down to called functions
2. Search → Find specific function
3. Filter by library → Only show user code (exclude stdlib)

Heap Profiling - Memory Allocation

What Heap Profiler Measures

"Memory allocation" - total bytes allocated (not current usage).

def process_orders(orders):
    results = []
    for order in orders:
        # Allocate temporary dict for each order
        temp_dict = {k: v for k, v in order.items() if v}  # Allocate
        results.append(temp_dict)
    return results

# With 10,000 orders:
# - 10,000 dicts allocated
# - Total heap: ~50 MB allocated (even if garbage collected later)

Heap profiler tracks:

• Which function allocated memory
• How much
• When (timeline)

Allocation vs Live Memory

Allocation (what heap profiler shows):

Timeline:
t=0s   allocate 10 MB (dict A)
t=1s   allocate 20 MB (dict B)
t=2s   deallocate dict A (10 MB freed)
t=3s   allocate 5 MB (dict C)

Total allocation: 35 MB

Live memory (current heap usage):

Same timeline:
t=0s   live: 10 MB
t=1s   live: 30 MB
t=2s   live: 20 MB (dict A freed)
t=3s   live: 25 MB

Cloud Profiler shows both:

• Allocated (what you see in flame graph)
• Live (what you might see in heapq or memory tools)

Heap Profiler Sampling

Instead of sampling by time (like CPU), heap profiler samples by allocation size:

When application allocates memory:
  if random() < (allocation_size / sample_rate):
    record_allocation(stack_trace)

Default sample rate: ~512 KB

• Small allocs (<512KB): probabilistically sampled
• Large allocs (>512MB): always sampled

Example:

• Allocate 1 MB array: P(sample) = 1M / 512K = ~2x prob (almost certainly sampled)
• Allocate 1 KB string: P(sample) = 1K / 512K = low prob

Result: Large memory consumers are well-represented, small allocations undersampled.

Common Heap Issues

Memory leak pattern (allocation never freed):

Timeline:
t=0s   allocate (live: 10 MB)
t=1s   allocate (live: 20 MB)
t=2s   allocate (live: 30 MB)
t=3s   allocate (live: 40 MB)
t=4s   allocate (live: 50 MB)

Heap keeps growing → memory leak!

In heap profiler: "allocate_connection" function showing sustained growth.

Memory spike pattern (allocation + deallocation):

Timeline:
t=0s   allocate 100 MB (live: 100 MB)
t=1s   deallocate (live: 0 MB)

Spike detected, but no leak (memory returned).

In heap profiler: Snapshot shows 100 MB allocated, but live memory is 0 MB.

Goroutine Profiling - Concurrent Execution

What Goroutine Profiler Measures

"Goroutine count & stack trace" - how many goroutines and what are they doing?

func main() {
    go process_order_1()  // Goroutine 1
    go process_order_2()  // Goroutine 2
    go process_order_3()  // Goroutine 3 - STUCK!
    
    // Wait forever
    select {}
}

func process_order_3() {
    // Trying to read from channel, but channel is closed
    // Goroutine stuck indefinitely
    data := <-closed_channel
}

Goroutine profiler snapshot:

Goroutine Profile (100 goroutines)
├── 50 goroutines in "processing"
├── 30 goroutines in "idle/waiting"
├── 19 goroutines in "system"
└── 1 goroutine STUCK in "process_order_3"
    └── Stack: main() → process_order_3() → <-chan (blocked)

Goroutine Profiler Output

goroutine 1234 [chan receive]:
main.process_order_3()
    /app/main.go:45 +0x2c
runtime.goexit()
    /usr/local/go/src/runtime/proc.go:267 +0x0

goroutine 1235 [select]:
main.poll_health_check()
    /app/health.go:18 +0x1c
runtime.goexit()
    /usr/local/go/src/runtime/proc.go:267 +0x0

State meanings:

• runnable: Ready to run but waiting for CPU
• sleep: Waiting on timer
• chan receive/send: Blocked on channel operation
• select: Blocked in select statement
• mutex: Waiting for lock

Contention Profiling - Lock Waiting

What Contention Profiler Measures

"Time spent waiting for locks" - how much CPU time wasted competing for mutexes.

var mu sync.Mutex

func handler() {
    mu.Lock()     // ← Might wait here!
    // Critical section
    do_work()
    mu.Unlock()
}

// If many goroutines call handler():
// - Some get lock immediately
// - Others wait (contention)
// - High contention = throughput reduced

Contention profiler timeline:

Goroutine A: [====== critical section ======]
              Lock           Unlock
              
Goroutine B: wait...wait...wait... [== critical section ==]
              Wants lock     Gets it      Releases

Contention time for Goroutine B: "wait...wait...wait..."

Detecting Contention

High contention symptoms:

• CPU usage high, throughput low
• Lock stack traces show same mutex appearing repeatedly
• Goroutines stuck waiting for single lock

Solution:

• Reduce critical section size
• Use lock-free data structures
• Reduce lock scope

Cloud Profiler Architecture

Profiler Agent

Every application must run a profiler agent (library):

from google.cloud.profiler import Profile

# Start profiling agent
Profile().start()

# Application runs with profiling enabled

Agent responsibilities:

1. Periodically sample (CPU: 100 Hz, Heap: every N MB)
2. Collect stack traces (capture call stack at each sample)
3. Aggregate data (count occurrences)
4. Upload periodically (send to Cloud Profiler API every ~60 seconds)

Cloud Profiler Backend

Backend responsibilities:

1. Receive uploads from multiple agents
2. Merge profiles (combine from multiple instances)
3. Symbolicate (convert addresses to function names)
4. Generate flame graphs
5. Store for retention (typically 30 days)

Profile Selection & Aggregation

Each minute, Cloud Profiler backend:

# For each (project, service, version):
#   Select 1 agent
#   Request CPU profile from that agent
#   Receive profile
#   Symbolicate
#   Store

selected_agent = random.choice(agents_for_service)
profile = selected_agent.get_profile("cpu")

Result: Each service version gets 1 CPU profile per minute (sampled from random instance).

Trade-off:

• Single profile per minute: low storage
• Representative (random agent chosen): good for scale-out services
• But: rare functions on other instances might be missed

If you need profile from specific instance → use gcloud debug source to debug specific server.

Overhead Analysis

CPU Profiler Overhead

At 100 Hz sampling:

Sample collection cost: ~1 microsecond per sample
10,000 samples per second: 10 milliseconds

CPU time available per second: 1000 milliseconds
Overhead: 10 / 1000 = 1% CPU

But this is per-core. On 8-core server:

• Total CPU: 8000 ms/sec
• Profiler overhead: 10 ms/sec
• Net overhead: 0.125% CPU

Practical measurement (from Google's testing):

At 1,000 QPS:

• CPU overhead: <0.5%
• Memory overhead: 32 MB (includes buffer, negligible)

At 10,000 QPS:

• CPU overhead: <0.5%
• Memory overhead: 23 MB

Conclusion: Cloud Profiler overhead is negligible for production use.

Memory Profiler Overhead

Memory profiler doesn't have time-based sampling, but allocation-based.

Overhead depends on:

• Allocation rate (faster allocation = more overhead)
• Sample rate (lower sample rate = less overhead)

Typical overhead: <5% memory usage (just the buffer holding recent allocations).

Production Patterns

Pattern 1: Continuous Profiling with Regular Reviews

Deploy profiling to all production services (overhead is low):

from google.cloud.profiler import Profile

Profile().start()  # Enable in all services

# In background job:
def review_profiles():
    profiles = fetch_profiles("service_name", hours=1)
    
    for profile in profiles:
        flame_graph = profile.flame_graph()
        
        # Alert if unexpected function uses >50% CPU
        for func in flame_graph:
            if func.percent > 50 and func.name not in EXPECTED_HOT:
                alert(f"{func.name} using {func.percent}% CPU")

Pattern 2: Baseline Profiling Before Changes

Before shipping performance-critical change:

1. Baseline: Take profile of current code
2. Baseline stats: Record top 10 functions + CPU time
3. Deploy change
4. New profile: Take new profile
5. Diff: Compare top 10 functions

baseline = fetch_profile_range("2026-06-24T00:00Z", "2026-06-24T01:00Z")
new = fetch_profile_range("2026-06-24T01:00Z", "2026-06-24T02:00Z")

for func in baseline.top_functions:
    baseline_time = func.cpu_time
    new_time = new.function(func.name).cpu_time
    diff_percent = (new_time - baseline_time) / baseline_time * 100
    
    if diff_percent > 10:
        alert(f"{func.name}: {diff_percent}% regression!")

Pattern 3: Heap Profiler for Memory Leaks

Set up continuous monitoring:

def check_heap_growth():
    current = fetch_profile("heap", latest=True)
    previous = fetch_profile("heap", hours_ago=1)
    
    # Check if same functions allocating more
    for func in current.top_functions:
        old_alloc = previous.function(func.name).allocation_bytes
        new_alloc = func.allocation_bytes
        
        if new_alloc > old_alloc * 1.5:  # 50% increase
            alert(f"{func.name}: memory allocation grew 50%")

Pattern 4: Goroutine Leak Detection

Monitor goroutine count over time:

def check_goroutine_leaks():
    current_count = get_goroutine_count()
    
    if current_count > GOROUTINE_THRESHOLD:
        profile = fetch_goroutine_profile()
        
        # Find stuck goroutines
        stuck = [g for g in profile if g.state == "chan receive"]
        if len(stuck) > 0:
            alert(f"{len(stuck)} goroutines stuck waiting for channel")

Constraints & Limitations

Limitation 1: Symbolication

Stack traces need source code / debug symbols to convert addresses to function names.

Raw address: 0x12345678
After symbolication: main() → process_order() → validate()

If symbols missing:

• GCP requires debug symbols in binary
• Symbols must match exact build
• If no symbols: stack traces show raw addresses (useless)

Limitation 2: Profile Aggregation

With 1000 instances, Cloud Profiler selects random instance each minute.

Instance 1: Profile A
Instance 2: Profile B
Instance 3: Profile C
Instance 4: Profile D

Selected each minute: 1 random instance
Result: Profile from random instances

Rare function (appears in 1% code paths):
- Might not show up in selected instance → invisible

Mitigation: If you need to find rare hot spots, increase sampling window or manually profile specific instance.

Limitation 3: Time-Based View Limitation

Profiler shows aggregate view across entire minute, not time-series.

What we see:
- function_A: 40% CPU (aggregate for 1 minute)

What we don't see:
- Did function_A spike at t=30s then drop?
- Or was it steady 40% the whole minute?

For time-series analysis of functions, combine with Cloud Trace.

Anti-Patterns

Anti-pattern 1: "Profiler overhead too high, disable it"

Misconception: Profiler adds 10-20% overhead. Reality: Profiler adds <1% overhead at typical sampling rates.

Disabling profiler = losing visibility. Not worth it.

Anti-pattern 2: "Profile only when there's a problem"

# BAD
if latency_spike:
    Profile().start()  # Start profiling NOW

Problem: By time you get profiler running, spike might be over. Also, you need baseline to compare.

Better: Always-on profiling.

Anti-pattern 3: "Look at CPU time, not wall-clock time"

Function A:
- CPU time: 100ms (CPU was busy)
- Wall-clock time: 500ms (including I/O wait)

If you only look at CPU time, you miss that function A spent 400ms waiting for I/O.

Better: Look at both CPU + I/O time.

References

• Cloud Profiler Documentation
• Cloud Profiler Profiling Concepts
• Cloud Profiler CPU Profiling
• Cloud Profiler Heap Profiling
• Cloud Profiler Goroutine Profiling (Go)
• Flame Graph Interpretation