As a junior computer science student, I encountered a magical tool during my performance optimization learning journey - flame graphs. This tool completely changed my understanding of program performance analysis, transforming me from a novice who could only guess performance bottlenecks into a developer capable of precisely locating problems.
My First Encounter with Flame Graphs
My first contact with flame graphs was when optimizing the school's course selection system. At that time, the system responded slowly during peak hours, and I tried various optimization methods, but the effects were not obvious. It wasn't until my advisor introduced me to flame graphs that I truly understood what "data-driven performance optimization" means.
In my ten years of programming learning experience, flame graphs are the most intuitive and effective performance analysis tool I have encountered. They can not only display the program's call stack but, more importantly, can intuitively show the execution time proportion of each function.
use hyperlane::*;
use hyperlane_macros::*;
use std::time::{Duration, Instant};
use std::collections::HashMap;
use std::sync::{Arc, Mutex};
// Performance profiler
struct PerformanceProfiler {
call_stack: Arc<Mutex<Vec<CallFrame>>>,
function_stats: Arc<Mutex<HashMap<String, FunctionStats>>>,
sampling_interval: Duration,
is_profiling: Arc<Mutex<bool>>,
}
#[derive(Clone, Debug)]
struct CallFrame {
function_name: String,
start_time: Instant,
end_time: Option<Instant>,
children: Vec<CallFrame>,
self_time: Duration,
total_time: Duration,
}
#[derive(Clone, Debug)]
struct FunctionStats {
total_calls: u64,
total_time: Duration,
self_time: Duration,
average_time: Duration,
max_time: Duration,
min_time: Duration,
}
impl PerformanceProfiler {
fn new(sampling_interval: Duration) -> Self {
Self {
call_stack: Arc::new(Mutex::new(Vec::new())),
function_stats: Arc::new(Mutex::new(HashMap::new())),
sampling_interval,
is_profiling: Arc::new(Mutex::new(false)),
}
}
fn start_profiling(&self) {
let mut is_profiling = self.is_profiling.lock().unwrap();
*is_profiling = true;
// Clear previous data
self.call_stack.lock().unwrap().clear();
self.function_stats.lock().unwrap().clear();
}
fn stop_profiling(&self) {
let mut is_profiling = self.is_profiling.lock().unwrap();
*is_profiling = false;
}
fn enter_function(&self, function_name: &str) -> FunctionProfiler {
if !*self.is_profiling.lock().unwrap() {
return FunctionProfiler::new(function_name.to_string(), None);
}
let start_time = Instant::now();
let frame = CallFrame {
function_name: function_name.to_string(),
start_time,
end_time: None,
children: Vec::new(),
self_time: Duration::ZERO,
total_time: Duration::ZERO,
};
self.call_stack.lock().unwrap().push(frame);
FunctionProfiler::new(function_name.to_string(), Some(self.clone()))
}
fn exit_function(&self, function_name: &str, start_time: Instant) {
if !*self.is_profiling.lock().unwrap() {
return;
}
let end_time = Instant::now();
let total_time = end_time.duration_since(start_time);
// Update call stack
if let Some(frame) = self.call_stack.lock().unwrap().last_mut() {
if frame.function_name == function_name {
frame.end_time = Some(end_time);
frame.total_time = total_time;
frame.self_time = total_time; // Temporarily set to total time, will subtract child function time later
}
}
// Update function statistics
let mut stats = self.function_stats.lock().unwrap();
let function_stats = stats.entry(function_name.to_string()).or_insert(FunctionStats {
total_calls: 0,
total_time: Duration::ZERO,
self_time: Duration::ZERO,
average_time: Duration::ZERO,
max_time: Duration::ZERO,
min_time: Duration::MAX,
});
function_stats.total_calls += 1;
function_stats.total_time += total_time;
function_stats.self_time += total_time; // Simplified handling
function_stats.average_time = function_stats.total_time / function_stats.total_calls as u32;
function_stats.max_time = function_stats.max_time.max(total_time);
function_stats.min_time = function_stats.min_time.min(total_time);
}
fn generate_flame_graph_data(&self) -> FlameGraphData {
let stats = self.function_stats.lock().unwrap();
let total_time: Duration = stats.values().map(|s| s.total_time).sum();
let mut flame_graph_nodes = Vec::new();
for (function_name, function_stats) in stats.iter() {
let percentage = if total_time.as_nanos() > 0 {
(function_stats.total_time.as_nanos() as f64 / total_time.as_nanos() as f64) * 100.0
} else {
0.0
};
flame_graph_nodes.push(FlameGraphNode {
function_name: function_name.clone(),
total_time_ms: function_stats.total_time.as_millis() as u64,
self_time_ms: function_stats.self_time.as_millis() as u64,
call_count: function_stats.total_calls,
percentage,
average_time_ms: function_stats.average_time.as_millis() as u64,
});
}
// Sort by time percentage
flame_graph_nodes.sort_by(|a, b| b.percentage.partial_cmp(&a.percentage).unwrap());
FlameGraphData {
total_time_ms: total_time.as_millis() as u64,
total_functions: flame_graph_nodes.len(),
nodes: flame_graph_nodes,
}
}
}
impl Clone for PerformanceProfiler {
fn clone(&self) -> Self {
Self {
call_stack: self.call_stack.clone(),
function_stats: self.function_stats.clone(),
sampling_interval: self.sampling_interval,
is_profiling: self.is_profiling.clone(),
}
}
}
struct FunctionProfiler {
function_name: String,
start_time: Instant,
profiler: Option<PerformanceProfiler>,
}
impl FunctionProfiler {
fn new(function_name: String, profiler: Option<PerformanceProfiler>) -> Self {
Self {
function_name,
start_time: Instant::now(),
profiler,
}
}
}
impl Drop for FunctionProfiler {
fn drop(&mut self) {
if let Some(profiler) = &self.profiler {
profiler.exit_function(&self.function_name, self.start_time);
}
}
}
#[derive(serde::Serialize)]
struct FlameGraphData {
total_time_ms: u64,
total_functions: usize,
nodes: Vec<FlameGraphNode>,
}
#[derive(serde::Serialize)]
struct FlameGraphNode {
function_name: String,
total_time_ms: u64,
self_time_ms: u64,
call_count: u64,
percentage: f64,
average_time_ms: u64,
}
static PROFILER: once_cell::sync::Lazy<PerformanceProfiler> =
once_cell::sync::Lazy::new(|| PerformanceProfiler::new(Duration::from_millis(1)));
// Macro definition to simplify performance analysis
macro_rules! profile_function {
($func_name:expr, $code:block) => {
{
let _profiler = PROFILER.enter_function($func_name);
$code
}
};
}
// Simulate complex business logic functions
async fn complex_business_logic(data_size: usize) -> BusinessResult {
let _profiler = PROFILER.enter_function("complex_business_logic");
let validation_result = validate_input_data(data_size).await;
let processed_data = process_data(validation_result.data).await;
let enriched_data = enrich_data(processed_data).await;
let final_result = generate_output(enriched_data).await;
final_result
}
async fn validate_input_data(data_size: usize) -> ValidationResult {
let _profiler = PROFILER.enter_function("validate_input_data");
// Simulate input validation delay
tokio::time::sleep(Duration::from_millis(10 + (data_size / 100) as u64)).await;
ValidationResult {
is_valid: true,
data: (0..data_size).map(|i| format!("data_{}", i)).collect(),
}
}
async fn process_data(input_data: Vec<String>) -> ProcessedData {
let _profiler = PROFILER.enter_function("process_data");
let mut processed_items = Vec::new();
for (index, item) in input_data.iter().enumerate() {
let processed_item = process_single_item(item, index).await;
processed_items.push(processed_item);
// Simulate batch processing optimization
if processed_items.len() % 100 == 0 {
batch_optimize(&mut processed_items).await;
}
}
ProcessedData {
items: processed_items,
processing_metadata: ProcessingMetadata {
total_items: input_data.len(),
processing_time_ms: 50,
},
}
}
async fn process_single_item(item: &str, index: usize) -> ProcessedItem {
let _profiler = PROFILER.enter_function("process_single_item");
// Simulate single item processing delay
tokio::time::sleep(Duration::from_micros(100)).await;
ProcessedItem {
original: item.to_string(),
processed: format!("processed_{}_{}", item, index),
metadata: ItemMetadata {
processing_order: index,
timestamp: chrono::Utc::now().timestamp(),
},
}
}
async fn batch_optimize(items: &mut Vec<ProcessedItem>) {
let _profiler = PROFILER.enter_function("batch_optimize");
// Simulate batch optimization processing
tokio::time::sleep(Duration::from_millis(5)).await;
// Simple optimization: deduplication
items.sort_by(|a, b| a.original.cmp(&b.original));
items.dedup_by(|a, b| a.original == b.original);
}
async fn enrich_data(processed_data: ProcessedData) -> EnrichedData {
let _profiler = PROFILER.enter_function("enrich_data");
let mut enriched_items = Vec::new();
for item in processed_data.items {
let enriched_item = enrich_single_item(item).await;
enriched_items.push(enriched_item);
}
EnrichedData {
items: enriched_items,
enrichment_metadata: EnrichmentMetadata {
enrichment_sources: vec!["cache".to_string(), "database".to_string()],
enrichment_time_ms: 30,
},
}
}
async fn enrich_single_item(item: ProcessedItem) -> EnrichedItem {
let _profiler = PROFILER.enter_function("enrich_single_item");
// Simulate data enrichment delay
tokio::time::sleep(Duration::from_micros(200)).await;
EnrichedItem {
processed_item: item,
additional_data: AdditionalData {
category: "default".to_string(),
priority: rand::random::<u8>() % 10,
tags: vec!["tag1".to_string(), "tag2".to_string()],
},
}
}
async fn generate_output(enriched_data: EnrichedData) -> BusinessResult {
let _profiler = PROFILER.enter_function("generate_output");
// Simulate output generation delay
tokio::time::sleep(Duration::from_millis(20)).await;
BusinessResult {
success: true,
data: enriched_data,
summary: ResultSummary {
total_items: enriched_data.items.len(),
processing_stages: 4,
total_processing_time_ms: 100,
},
}
}
// Data structure definitions
#[derive(serde::Serialize)]
struct ValidationResult {
is_valid: bool,
data: Vec<String>,
}
#[derive(serde::Serialize)]
struct ProcessedData {
items: Vec<ProcessedItem>,
processing_metadata: ProcessingMetadata,
}
#[derive(serde::Serialize, Clone)]
struct ProcessedItem {
original: String,
processed: String,
metadata: ItemMetadata,
}
#[derive(serde::Serialize, Clone)]
struct ItemMetadata {
processing_order: usize,
timestamp: i64,
}
#[derive(serde::Serialize)]
struct ProcessingMetadata {
total_items: usize,
processing_time_ms: u64,
}
#[derive(serde::Serialize)]
struct EnrichedData {
items: Vec<EnrichedItem>,
enrichment_metadata: EnrichmentMetadata,
}
#[derive(serde::Serialize)]
struct EnrichedItem {
processed_item: ProcessedItem,
additional_data: AdditionalData,
}
#[derive(serde::Serialize)]
struct AdditionalData {
category: String,
priority: u8,
tags: Vec<String>,
}
#[derive(serde::Serialize)]
struct EnrichmentMetadata {
enrichment_sources: Vec<String>,
enrichment_time_ms: u64,
}
#[derive(serde::Serialize)]
struct BusinessResult {
success: bool,
data: EnrichedData,
summary: ResultSummary,
}
#[derive(serde::Serialize)]
struct ResultSummary {
total_items: usize,
processing_stages: usize,
total_processing_time_ms: u64,
}
#[post]
async fn profiled_business_endpoint(ctx: Context) {
let request_body: Vec<u8> = ctx.get_request_body().await;
let business_request: BusinessRequest = serde_json::from_slice(&request_body).unwrap();
// Start performance analysis
PROFILER.start_profiling();
let start_time = Instant::now();
// Execute business logic
let result = complex_business_logic(business_request.data_size).await;
let total_duration = start_time.elapsed();
// Stop performance analysis
PROFILER.stop_profiling();
// Generate flame graph data
let flame_graph_data = PROFILER.generate_flame_graph_data();
let response = ProfiledBusinessResponse {
business_result: result,
performance_analysis: PerformanceAnalysis {
total_execution_time_ms: total_duration.as_millis() as u64,
flame_graph_data,
optimization_suggestions: generate_optimization_suggestions(&flame_graph_data),
},
};
ctx.set_response_status_code(200)
.await
.set_response_header(CONTENT_TYPE, APPLICATION_JSON)
.await
.set_response_body(serde_json::to_string(&response).unwrap())
.await;
}
#[derive(serde::Deserialize)]
struct BusinessRequest {
data_size: usize,
}
#[derive(serde::Serialize)]
struct ProfiledBusinessResponse {
business_result: BusinessResult,
performance_analysis: PerformanceAnalysis,
}
#[derive(serde::Serialize)]
struct PerformanceAnalysis {
total_execution_time_ms: u64,
flame_graph_data: FlameGraphData,
optimization_suggestions: Vec<OptimizationSuggestion>,
}
#[derive(serde::Serialize)]
struct OptimizationSuggestion {
function_name: String,
issue_type: String,
description: String,
potential_improvement: String,
}
fn generate_optimization_suggestions(flame_graph_data: &FlameGraphData) -> Vec<OptimizationSuggestion> {
let mut suggestions = Vec::new();
for node in &flame_graph_data.nodes {
if node.percentage > 30.0 {
suggestions.push(OptimizationSuggestion {
function_name: node.function_name.clone(),
issue_type: "High CPU Usage".to_string(),
description: format!("Function {} consumes {:.2}% of total execution time",
node.function_name, node.percentage),
potential_improvement: "Consider optimizing algorithm or adding caching".to_string(),
});
}
if node.call_count > 1000 {
suggestions.push(OptimizationSuggestion {
function_name: node.function_name.clone(),
issue_type: "High Call Frequency".to_string(),
description: format!("Function {} is called {} times",
node.function_name, node.call_count),
potential_improvement: "Consider batching operations or memoization".to_string(),
});
}
if node.average_time_ms > 100 {
suggestions.push(OptimizationSuggestion {
function_name: node.function_name.clone(),
issue_type: "Slow Function".to_string(),
description: format!("Function {} has average execution time of {}ms",
node.function_name, node.average_time_ms),
potential_improvement: "Consider asynchronous processing or algorithm optimization".to_string(),
});
}
}
suggestions
}
#[get]
async fn flame_graph_visualization_endpoint(ctx: Context) {
let flame_graph_data = PROFILER.generate_flame_graph_data();
let visualization_data = FlameGraphVisualization {
svg_data: generate_flame_graph_svg(&flame_graph_data),
interactive_data: flame_graph_data,
analysis_summary: AnalysisSummary {
hottest_functions: get_hottest_functions(&PROFILER.generate_flame_graph_data(), 5),
performance_bottlenecks: identify_bottlenecks(&PROFILER.generate_flame_graph_data()),
optimization_priority: calculate_optimization_priority(&PROFILER.generate_flame_graph_data()),
},
};
ctx.set_response_status_code(200)
.await
.set_response_header(CONTENT_TYPE, APPLICATION_JSON)
.await
.set_response_body(serde_json::to_string(&visualization_data).unwrap())
.await;
}
#[derive(serde::Serialize)]
struct FlameGraphVisualization {
svg_data: String,
interactive_data: FlameGraphData,
analysis_summary: AnalysisSummary,
}
#[derive(serde::Serialize)]
struct AnalysisSummary {
hottest_functions: Vec<HotFunction>,
performance_bottlenecks: Vec<PerformanceBottleneck>,
optimization_priority: Vec<OptimizationPriority>,
}
#[derive(serde::Serialize)]
struct HotFunction {
function_name: String,
percentage: f64,
total_time_ms: u64,
}
#[derive(serde::Serialize)]
struct PerformanceBottleneck {
function_name: String,
bottleneck_type: String,
severity: String,
impact_description: String,
}
#[derive(serde::Serialize)]
struct OptimizationPriority {
function_name: String,
priority_score: f64,
expected_improvement: String,
}
fn generate_flame_graph_svg(data: &FlameGraphData) -> String {
// Simplified SVG generation logic
let mut svg = String::from(r#"<svg width="800" height="600" xmlns="http://www.w3.org/2000/svg">"#);
let mut y_offset = 50;
for (index, node) in data.nodes.iter().enumerate() {
let width = (node.percentage / 100.0 * 700.0) as i32;
let color = match node.percentage {
p if p > 20.0 => "#ff4444",
p if p > 10.0 => "#ffaa44",
p if p > 5.0 => "#ffff44",
_ => "#44ff44",
};
svg.push_str(&format!(
r#"<rect x="50" y="{}" width="{}" height="30" fill="{}" stroke="#000" stroke-width="1"/>"#,
y_offset, width, color
));
svg.push_str(&format!(
r#"<text x="55" y="{}" font-family="Arial" font-size="12" fill="#000">{} ({:.2}%)</text>"#,
y_offset + 20, node.function_name, node.percentage
));
y_offset += 35;
if index >= 15 { // Limit display count
break;
}
}
svg.push_str("</svg>");
svg
}
fn get_hottest_functions(data: &FlameGraphData, count: usize) -> Vec<HotFunction> {
data.nodes.iter()
.take(count)
.map(|node| HotFunction {
function_name: node.function_name.clone(),
percentage: node.percentage,
total_time_ms: node.total_time_ms,
})
.collect()
}
fn identify_bottlenecks(data: &FlameGraphData) -> Vec<PerformanceBottleneck> {
data.nodes.iter()
.filter(|node| node.percentage > 15.0 || node.average_time_ms > 50)
.map(|node| PerformanceBottleneck {
function_name: node.function_name.clone(),
bottleneck_type: if node.percentage > 15.0 { "CPU Intensive" } else { "Slow Execution" }.to_string(),
severity: if node.percentage > 30.0 { "High" } else { "Medium" }.to_string(),
impact_description: format!("Consumes {:.2}% of total time with {} calls",
node.percentage, node.call_count),
})
.collect()
}
fn calculate_optimization_priority(data: &FlameGraphData) -> Vec<OptimizationPriority> {
let mut priorities: Vec<_> = data.nodes.iter()
.map(|node| {
let priority_score = node.percentage * 0.6 + (node.call_count as f64 / 1000.0) * 0.4;
OptimizationPriority {
function_name: node.function_name.clone(),
priority_score,
expected_improvement: if priority_score > 20.0 {
"High impact optimization potential"
} else if priority_score > 10.0 {
"Medium impact optimization potential"
} else {
"Low impact optimization potential"
}.to_string(),
}
})
.collect();
priorities.sort_by(|a, b| b.priority_score.partial_cmp(&a.priority_score).unwrap());
priorities.into_iter().take(10).collect()
}
Performance Optimization Principles Taught by Flame Graphs
Through intensive use of flame graphs, I summarized several important performance optimization principles:
Data-Driven Decisions: Don't optimize based on feelings, use data to speak
Focus on Hot Functions: Optimizing functions that consume the most time brings the greatest benefits
Consider Call Frequency: High-frequency called functions are worth optimizing even if single execution time is short
Balance Complexity: Optimization should consider code complexity and maintenance costs
Flame graphs are not just a tool, but a transformation of thinking. They taught me to analyze performance problems scientifically rather than blindly guessing and trying.
This article records my deep learning of flame graphs and performance analysis as a junior student. Through practical code practice and tool usage, I deeply experienced the importance of data-driven performance optimization. I hope my experience can provide some reference for other students.
For more information, please visit Hyperlane GitHub page or contact the author: [email protected]
SOCIAL SHARE CARD GENERATOR