Linux Basic — Profiling with time

Profiling with time

Before optimising, measure. The time command shows where your script spends its time.

---

Basic Usage

time ./script.sh

Output:

real    0m2.345s
user    0m1.234s
sys     0m0.567s

Metric	Meaning
real	wall-clock time (what you experience)
user	CPU time in user mode (your code)
sys	CPU time in kernel mode (system calls)

---

Interpreting the Numbers

• user + sys ≈ real → CPU-bound (computation, loops)
• user + sys ≪ real → I/O-bound or waiting (network, disk, sleep)
• High sys → lots of forks, file opens, or syscalls

---

/usr/bin/time (More Detail)

The time builtin is minimal. Use /usr/bin/time -v for detailed stats (Linux only):

/usr/bin/time -v ./script.sh

Shows:

• Max memory usage
• Page faults
• Context switches
• Number of system calls

---

Per-Function Timing

Wrap functions:

time_func() {
    local start end
    start=$(date +%s%N)
    "$@"
    end=$(date +%s%N)
    echo "[$*] took $(( (end - start) / 1000000 )) ms" >&2
}

time_func process_large_file

Or use SECONDS:

SECONDS=0
heavy_function
echo "took $SECONDS seconds" >&2

---

Per-Line Profiling with PS4

Enable tracing with timestamps:

PS4='+ $(date +%s.%N)\011 '
set -x
# ... script body
set +x

Each traced line gets a timestamp. Pipe stderr to a file and awk the deltas to find slow lines.

Automated version:

#!/usr/bin/env bash
exec 3>&2 2> >(tee /tmp/trace.log)
PS4='+ $(date +%s.%N)\011 '
set -x

# script body
for i in {1..100}; do
    slow_command
done

set +x
exec 2>&3 3>&-

# analyse
awk '{print $2, $0}' /tmp/trace.log | sort -n

The slowest lines bubble to the top.

---

When to Profile

1. Script takes > 5 seconds
2. Script runs frequently (cron, loop)
3. Before and after optimisation to verify gains

---

Next → xargs & GNU Parallel