Bash Profiling

Key Profiling Techniques

time ls -la

SECONDS=0
# commands
echo $SECONDS

PS4='+ $(date +%s.%N) '

start=$(date +%s.%N)

🔹 Using the time Command

The time command measures script execution with three metrics: real time (wall clock), user time (CPU in user mode), and system time (CPU in kernel mode). This helps identify whether scripts are CPU-bound or I/O-bound by comparing real vs. CPU time. Understanding these metrics guides optimization efforts toward the actual bottlenecks rather than assumptions about performance issues.

#!/bin/bash

# Time a single command
time sleep 1

# Time multiple commands
time {
    echo "Processing..."
    sleep 2
    echo "Done"
}

# Time entire script
time ./myscript.sh

real    0m1.002s
user    0m0.001s
sys     0m0.001s

Processing...
Done

real    0m2.005s
user    0m0.002s
sys     0m0.001s

🔹 SECONDS Variable

Bash's built-in SECONDS variable automatically counts seconds since script start and can be reset to zero for timing specific sections. Set SECONDS=0 before operations you want to time, then check $SECONDS afterward. This provides lightweight, built-in timing without external commands, perfect for measuring function performance or specific code blocks within scripts.

#!/bin/bash

# Reset timer
SECONDS=0

echo "Starting long operation..."
sleep 3
echo "Operation took $SECONDS seconds"

# Reset for another measurement
SECONDS=0
for i in {1..5}; do
    sleep 1
done
echo "Loop took $SECONDS seconds"

Starting long operation...
Operation took 3 seconds
Loop took 5 seconds

🔹 Precise Timing with date

Use date +%s.%N for nanosecond-precision timing essential for profiling fast operations where second-level resolution is insufficient. Capture start and end timestamps, then calculate differences using bc for floating-point arithmetic. This approach provides microsecond accuracy for performance analysis of individual functions, commands, or tight loops where small improvements matter.

#!/bin/bash

# Start timer
start=$(date +%s.%N)

# Operation to measure
for i in {1..1000}; do
    echo "Processing $i" > /dev/null
done

# End timer
end=$(date +%s.%N)

# Calculate duration
duration=$(echo "$end - $start" | bc)
echo "Duration: $duration seconds"

Duration: 0.234567 seconds

🔹 Profiling with PS4

Set PS4 to include timestamps in debug output, creating a detailed execution trace that shows exactly when each command runs. Enhanced PS4 variables like export PS4='+ $(date +%s.%N) [${LINENO}] ' provide high-resolution timing information alongside line numbers. This helps identify slow operations and understand the precise timing relationships between different parts of your script's execution flow.

#!/bin/bash

# Add timestamp to debug output
export PS4='+ $(date "+%H:%M:%S.%N") ${BASH_SOURCE}:${LINENO}: '

set -x

echo "Step 1"
sleep 1
echo "Step 2"
sleep 2
echo "Step 3"

set +x

+ 14:23:45.123456789 script.sh:8: echo 'Step 1'
Step 1
+ 14:23:45.125678901 script.sh:9: sleep 1
+ 14:23:46.127890123 script.sh:10: echo 'Step 2'
Step 2
+ 14:23:46.129012345 script.sh:11: sleep 2
+ 14:23:48.131234567 script.sh:12: echo 'Step 3'
Step 3

🔹 Function Profiling

Create timing wrapper functions that measure execution time of any command or function using SECONDS or date commands. These reusable profilers can capture multiple metrics including execution time, memory usage, and call counts. Consistent profiling across different script sections provides comparable performance data for identifying optimization priorities and measuring improvement effectiveness.

#!/bin/bash

# Timing function
time_function() {
    local start=$(date +%s.%N)
    "$@"  # Execute the command
    local end=$(date +%s.%N)
    local duration=$(echo "$end - $start" | bc)
    echo "[TIMING] '$*' took $duration seconds" >&2
}

# Example functions
slow_function() {
    sleep 2
    echo "Slow function completed"
}

fast_function() {
    echo "Fast function completed"
}

# Profile functions
time_function slow_function
time_function fast_function

Slow function completed
[TIMING] 'slow_function' took 2.003456 seconds
Fast function completed
[TIMING] 'fast_function' took 0.001234 seconds

🔹 Memory Profiling

Monitor script memory usage by reading /proc/self/status or using ps -o pid,rss,cmd to track resident set size over time. This identifies memory leaks, excessive consumption, and unusual allocation patterns. For scripts processing large datasets or running extended periods, memory profiling is crucial for stability and efficient resource utilization.

#!/bin/bash

# Function to get memory usage
get_memory() {
    ps -o rss= -p $$ | awk '{print $1/1024 " MB"}'
}

echo "Initial memory: $(get_memory)"

# Allocate memory
big_array=()
for i in {1..100000}; do
    big_array+=("Item $i")
done

echo "After allocation: $(get_memory)"

# Clear array
unset big_array

echo "After cleanup: $(get_memory)"

Initial memory: 2.5 MB
After allocation: 15.3 MB
After cleanup: 3.1 MB

🔹 Profiling Report Generator

Create comprehensive profiling reports that aggregate execution time, memory usage, command counts, and other performance metrics. These reports provide complete performance overviews for analysis, highlighting bottlenecks, resource trends, and optimization opportunities. Automated profiling with formatted output makes performance analysis repeatable and comparable across script versions.

#!/bin/bash

# Profiling report
echo "=== Performance Report ==="
echo "Script: $0"
echo "Started: $(date)"
echo ""

SECONDS=0
start_mem=$(ps -o rss= -p $$)

# Your script operations here
sleep 2
echo "Processing data..."

end_mem=$(ps -o rss= -p $$)
duration=$SECONDS

echo ""
echo "=== Results ==="
echo "Duration: $duration seconds"
echo "Memory start: $((start_mem/1024)) MB"
echo "Memory end: $((end_mem/1024)) MB"
echo "Memory delta: $(((end_mem-start_mem)/1024)) MB"

=== Performance Report ===
Script: ./profile.sh
Started: Fri Jan 10 14:30:00 UTC 2025

Processing data...

=== Results ===
Duration: 2 seconds
Memory start: 2 MB
Memory end: 3 MB
Memory delta: 1 MB