Lab 9.2 — Analyze a Performance Regression

Lab type: Research & Benchmark Estimated time: 4–6 hours Tez modules: tez-dag, tez-common, tez-examples, tez-runtime-library

Background

A performance patch without numbers is a guess. Tez's entire reason to exist is that it is faster than chaining MapReduce jobs — container reuse, pipelined shuffle, a single long-lived AM. So a performance regression in Tez is not a nice-to-have bug; it is an attack on the project's core value proposition. A 10% slowdown in the sort/shuffle path or a per-task allocation in the AM dispatcher compounds across every task in every DAG on every cluster, and it costs real money at scale.

Regressions are also the hardest bugs to handle well, because "it got slower" is unfalsifiable without measurement. This lab teaches the full maintainer-grade workflow: dissect a real perf fix as a case study, build a repeatable benchmark DAG, bisect a regression to a single commit with git bisect run, profile the AM and tasks with async-profiler and JFR, isolate a hot path with a JMH microbenchmark, and write the perf JIRA with evidence a committer can reproduce.

This lab is the hands-on counterpart to Stage 10: Performance Improvements; read that stage for the issue-finding workflow and the policy framing.

Three rules, drilled until they are reflex:

1. Never optimize un-profiled code. Find the hot path with a profiler or a benchmark, not intuition. Most "obvious" optimizations target cold code.
2. Micro proves the mechanism; macro proves it matters. A JMH win that does not move a benchmark-DAG wall-clock is noise — and you must say so.
3. One change, one number. Bundle two optimizations and you cannot attribute the delta, and one may quietly regress.

Why This Lab Matters for Contributors

Performance patches are held to a higher review bar than correctness patches, for two reasons. First, "faster" is unverifiable without a benchmark — a committer cannot approve a claim they cannot reproduce. Second, an optimization that helps one DAG shape often hurts another, and the cost of shipping a regression is paid by every user, not just the one whose case you optimized. Learning to produce micro + macro numbers, to bisect a regression precisely, and to read them honestly (including "this JMH win does not move any real DAG") is what lets a committer trust your perf work — and what lets you, as a reviewer, gate others'.

Prerequisites

• You can build Tez (mvn install -DskipTests -Dmaven.javadoc.skip=true) and run a DAG in local mode (Level 1, Lab 3).
• You have read Stage 10: Performance Improvements.
• You understand at least one hot path — the shuffle & sort deep dive or the scheduler deep dive.
• JMH basics: @Benchmark, @BenchmarkMode, @State, @Param, Blackhole, warmup vs measurement iterations. (You will install JMH in Step 4 — Tez has no JMH module of its own.)
• async-profiler downloaded (or a JDK with JFR — every JDK 11+ has it). Tez master targets Java 21 (maven.compiler.release in the root pom.xml).

The Measurement Loop

   profile (async-profiler / JFR)        find the hot path, don't guess
            |
            v
   baseline: JMH micro + benchmark-DAG macro
            |
            v
   make ONE change  ------------------>  re-measure identical JMH + identical DAG
            |                                        |
            |                                        v
            |                            delta real AND no regression?
            |                              /                      \
            +---------- no --------------                          yes --> JIRA w/ before/after

Step-by-Step Tasks

Step 1 — Dissect a real perf fix as a case study

Do not invent a hypothetical. Tez's git history is full of real, reviewed performance fixes; find and read them.

cd ~/src/oss-repos/tez
git log --oneline -i --grep="optimi\|performance\|speed up\|slow\|regression" | head -40

You will see fixes like TEZ-4250 (TaskImpl counters), TEZ-1526 (TezTaskID interning), TEZ-4580 (slow preemption), TEZ-3709 (TezMerger slow for many segments), TEZ-2731 (GenericCounter bottleneck). Pick one and read the commit before you describe it — the house rule.

The cleanest case study is TEZ‑4250, Optimise TaskImpl::getCounters (commit 9aeb17b4b, Ayush Saxena, reviewed by Rajesh Balamohan):

git show 9aeb17b4b -- tez-dag/src/main/java/org/apache/tez/dag/app/dag/impl/TaskImpl.java

The mechanism, straight from the diff: the old getCounters() unconditionally did

// BEFORE (TEZ-4250) — allocates + copies on every call
TezCounters counters = new TezCounters();
counters.incrAllCounters(this.counters);
...
counters.incrAllCounters(bestAttempt.getCounters());
return counters;

getCounters() is called frequently (progress reporting, the dispatcher, the web UI), so allocating a fresh TezCounters and deep-copying every counter group on each call is pure churn. The fix only does that aggregation when speculation is actually enabled — otherwise it returns the best attempt's counters directly:

// AFTER (TEZ-4250) — no allocation/copy unless speculation needs the merged view
if (getVertex().isSpeculationEnabled()) {
  tezCounters = new TezCounters();
  tezCounters.incrAllCounters(this.counters);
}
...
TezCounters taskCounters =
    (bestAttempt != null) ? bestAttempt.getCounters() : TaskAttemptImpl.EMPTY_COUNTERS;
if (getVertex().isSpeculationEnabled()) {
  tezCounters.incrAllCounters(taskCounters);
  return tezCounters;
}
return taskCounters;

This is the archetype of a Tez perf fix: an allocation + copy on a per-task, frequently-called path, removed for the common case. Note what the patch is not — it is not a rewrite, it does not change behavior when speculation is on, and it is one change. Write a one-paragraph analysis of your chosen commit in these terms: what path, how hot, what was allocated/copied, and why the fix is safe.

Step 2 — Build a repeatable benchmark DAG

To measure macro impact you need a DAG you can run at scale, deterministically, in local mode (single JVM — easiest to profile). tez-examples ships OrderedWordCount, a shuffle-heavy two-stage DAG (tokenize → sort), perfect for this.

cd ~/src/oss-repos/tez
mvn package -DskipTests -pl tez-examples -am -q
ls tez-examples/target/tez-examples-*.jar | grep -v sources | grep -v tests

Generate an input large enough that wall-clock is dominated by real work, not JVM startup:

mkdir -p /tmp/tez-bench/input
# ~200MB of repeated text so the sort/shuffle stage does meaningful work.
for i in $(seq 1 2000); do
  cat >> /tmp/tez-bench/input/words.txt <<'EOF'
the quick brown fox jumps over the lazy dog while the industrious ant carries a crumb
a distributed acyclic graph engine reuses containers to avoid the shuffle to hdfs tax
EOF
done
wc -l /tmp/tez-bench/input/words.txt

Run OrderedWordCount in local mode with counters printed (-local -counter come from TezExampleBase):

TEZ_HOME=~/src/oss-repos/tez
CP=$(echo $TEZ_HOME/tez-*/target/tez-*.jar | tr ' ' ':'):$(hadoop classpath)

rm -rf /tmp/tez-bench/output
java -cp "$CP" org.apache.tez.examples.OrderedWordCount \
  -local -counter \
  /tmp/tez-bench/input /tmp/tez-bench/output 4

The -counter flag makes the AM print the aggregated TezCounters at the end (OUTPUT_RECORDS, SHUFFLE_BYTES, OUTPUT_BYTES, wall-clock via the DAG's start/finish times). Confirm the counter names against the real enum so your report cites them correctly:

rg -n "OUTPUT_RECORDS|SHUFFLE_BYTES|OUTPUT_BYTES|SPILLED_RECORDS" \
  tez-api/src/main/java/org/apache/tez/common/counters/TaskCounter.java

Step 3 — Measure properly: warmup, repetitions, variance

A single run is not a measurement. JIT warmup, filesystem cache, and GC make the first run an outlier and every run noisy. Wrap the DAG in a script that discards a warmup run and reports the mean and spread of several timed runs.

cat > /tmp/tez-bench/run.sh <<'EOF'
#!/usr/bin/env bash
set -euo pipefail
TEZ_HOME=~/src/oss-repos/tez
CP=$(echo $TEZ_HOME/tez-*/target/tez-*.jar | tr ' ' ':'):$(hadoop classpath)
IN=/tmp/tez-bench/input
REPS=${1:-5}

run_once() {
  rm -rf /tmp/tez-bench/output
  local start end
  start=$(date +%s.%N)
  java -cp "$CP" org.apache.tez.examples.OrderedWordCount \
    -local "$IN" /tmp/tez-bench/output 4 >/dev/null 2>&1
  end=$(date +%s.%N)
  echo "$end - $start" | bc
}

echo "warmup: $(run_once) s (discarded)"
times=()
for i in $(seq 1 "$REPS"); do
  t=$(run_once); times+=("$t"); echo "run $i: $t s"
done
printf '%s\n' "${times[@]}" | awk '
  { s+=$1; ss+=$1*$1; n++ }
  END { m=s/n; printf "mean=%.3fs stddev=%.3fs n=%d\n", m, sqrt(ss/n - m*m), n }'
EOF
chmod +x /tmp/tez-bench/run.sh
/tmp/tez-bench/run.sh 5

Record mean and stddev. The rule: a delta smaller than a couple of standard deviations is not a result. If stddev is large relative to mean, increase the input size or the repetition count until the signal is clean — you cannot bisect noise.

Step 4 — Isolate a hot path with a JMH microbenchmark

The benchmark DAG proves impact but cannot tell you which line. For that, isolate the suspect method in JMH. Tez has no JMH module, so you build a tiny standalone project that depends on the Tez artifacts you just installed.

# Install the Tez artifacts to your local Maven repo so the benchmark can depend on them.
cd ~/src/oss-repos/tez
mvn install -DskipTests -Dmaven.javadoc.skip=true -q

# Generate a JMH project from the official archetype (JMH 1.37).
cd /tmp
mvn -q archetype:generate \
  -DinteractiveMode=false \
  -DarchetypeGroupId=org.openjdk.jmh \
  -DarchetypeArtifactId=jmh-java-benchmark-archetype \
  -DarchetypeVersion=1.37 \
  -DgroupId=org.apache.tez.bench -DartifactId=tez-jmh -Dversion=1.0

Add a dependency on tez-common (where the ID classes live) to /tmp/tez-jmh/pom.xml, inside <dependencies>:

<dependency>
  <groupId>org.apache.tez</groupId>
  <artifactId>tez-common</artifactId>
  <version>1.0.0-SNAPSHOT</version>
</dependency>

Now benchmark a real, verifiable hot path: TezTaskID.getInstance(...), which interns every task ID through a weak interner. This was itself the subject of a real perf fix (TEZ-1526, LoadingCache for TezTaskID slow for large jobs, git show 57c857d26) — large jobs create millions of these IDs, so the interning cost is real. Confirm the code before benchmarking it:

rg -n "getInstance|tezTaskIDCache|Interners" \
  tez-common/src/main/java/org/apache/tez/dag/records/TezTaskID.java
# public static TezTaskID getInstance(TezVertexID vertexID, int id) {
#   return tezTaskIDCache.intern(new TezTaskID(vertexID, id));
# }

Write the benchmark at /tmp/tez-jmh/src/main/java/org/apache/tez/bench/TezTaskIDBenchmark.java:

package org.apache.tez.bench;

import java.util.concurrent.TimeUnit;

import org.apache.hadoop.yarn.api.records.ApplicationId;
import org.apache.tez.dag.records.TezDAGID;
import org.apache.tez.dag.records.TezVertexID;
import org.apache.tez.dag.records.TezTaskID;

import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Fork;
import org.openjdk.jmh.annotations.Measurement;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.annotations.Param;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.Setup;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.annotations.Warmup;
import org.openjdk.jmh.infra.Blackhole;

@Fork(value = 2)
@Warmup(iterations = 5, time = 1)
@Measurement(iterations = 10, time = 1)
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@State(Scope.Thread)
public class TezTaskIDBenchmark {

  // Number of DISTINCT task ids to cycle through. Small => the weak interner mostly
  // hits; large => it mostly misses and constructs. Both are real regimes.
  @Param({"1", "1024", "65536"})
  public int distinctIds;

  private TezVertexID vertexId;
  private int cursor;

  @Setup
  public void setup() {
    // Build a real vertex id: ApplicationId -> TezDAGID -> TezVertexID.
    ApplicationId appId = ApplicationId.newInstance(System.currentTimeMillis(), 1);
    TezDAGID dagId = TezDAGID.getInstance(appId, 1);
    vertexId = TezVertexID.getInstance(dagId, 1);
    cursor = 0;
  }

  /**
   * Measures the interned construction path. The id varies each invocation (from
   * @State, not a constant) so the JIT cannot constant-fold, and the result is
   * consumed via Blackhole so dead-code elimination cannot delete the call.
   */
  @Benchmark
  public void getInstance(Blackhole bh) {
    int id = (cursor++ % distinctIds);
    TezTaskID taskId = TezTaskID.getInstance(vertexId, id);
    bh.consume(taskId);
  }
}

Read the two comments carefully — they are the entire JMH discipline:

• Dead-code elimination: if you did not bh.consume(taskId), the JIT could prove the call has no observable effect and delete it. You would measure an empty loop and see an impossible ~0 ns/op.
• Constant folding: if you passed a literal id (getInstance(vertexId, 42)), the JIT could hoist the whole call out of the loop and compute it once. The id must come from mutable @State (here cursor), and inputs must be handed in through @Param/@State, never constants.

Build and run, scoped to your class:

cd /tmp/tez-jmh
mvn -q clean package
# Run with the GC profiler on — allocation is usually the real story on hot paths.
java -jar target/benchmarks.jar "TezTaskIDBenchmark" -prof gc

Read the output as a committer reads it — two numbers matter, not one: the Score ± Error (mean time per op and its confidence interval; the intervals must not overlap for a delta to be real) and gc.alloc.rate.norm (bytes allocated per op, which predicts GC pressure at scale). Watch how both scale with distinctIds — a cost that is flat when the interner hits and explosive when it misses tells you the interner, not the constructor, dominates.

Alternative hot path. If you would rather benchmark I/O, target IFile.Writer.append(Object key, Object value) in tez-runtime-library/.../common/sort/impl/IFile.java — the per-record write path of the sort/shuffle output. Verify the signature first (rg -n "public void append" tez-runtime-library/.../sort/impl/IFile.java); it needs a tez-runtime-library dependency and a real serializer, so it is more setup than the ID benchmark, but it is closer to a genuine hot loop.

Step 5 — Profile the AM and tasks with async-profiler / JFR

The JMH benchmark isolates a method you already suspect. To find the hot method in a running DAG, profile local mode — because -local runs the AM and all tasks in one JVM, a single profiler attach captures everything.

Get the local-mode JVM's pid and attach async-profiler for a wall-clock flame graph:

# Launch the benchmark DAG in the background, capture its pid.
java -cp "$CP" org.apache.tez.examples.OrderedWordCount \
  -local /tmp/tez-bench/input /tmp/tez-bench/output 4 & PID=$!

# Attach async-profiler for 30s, CPU mode, HTML flame graph.
asprof -d 30 -e cpu -f /tmp/tez-bench/flame-cpu.html $PID
# Allocation flame graph — the one that finds per-task/per-record churn like TEZ-4250:
asprof -d 30 -e alloc -f /tmp/tez-bench/flame-alloc.html $PID

Or use JFR, which ships with every modern JDK — start the DAG with a recording and open the .jfr in JDK Mission Control:

java -cp "$CP" \
  -XX:StartFlightRecording=duration=60s,filename=/tmp/tez-bench/rec.jfr,settings=profile \
  org.apache.tez.examples.OrderedWordCount \
  -local /tmp/tez-bench/input /tmp/tez-bench/output 4

Reading a flame graph: width is time (or bytes, for the alloc graph), not call count. Look for a wide frame you did not expect — a TezCounters.incrAllCounters under getCounters (the TEZ‑4250 smell), a HashMap/TreeMap resize inside a sort, or a serializer allocating per record. That wide frame is your hot path; then you write the JMH benchmark for it.

Step 6 — Bisect a regression with git bisect run

When you know a DAG got slower between two versions but not why, bisect it automatically. Write a script that builds Tez, runs the benchmark DAG, and exits 0 (good / fast) or 1 (bad / slow) against a threshold you set from your baseline.

cat > /tmp/tez-bench/bisect.sh <<'EOF'
#!/usr/bin/env bash
# git bisect run script: exit 0 = good (fast), 1 = bad (slow), 125 = skip (won't build).
set -uo pipefail
cd ~/src/oss-repos/tez

# Rebuild only what the benchmark touches; skip the commit if it won't compile.
mvn install -q -DskipTests -Dmaven.javadoc.skip=true -pl tez-common,tez-dag,tez-runtime-library,tez-runtime-internals,tez-api,tez-mapreduce,tez-examples -am \
  || exit 125

TEZ_HOME=~/src/oss-repos/tez
CP=$(echo $TEZ_HOME/tez-*/target/tez-*.jar | tr ' ' ':'):$(hadoop classpath)
THRESHOLD_S=${THRESHOLD_S:-30.0}   # set from your baseline: ~1.5x the good mean

rm -rf /tmp/tez-bench/output
start=$(date +%s.%N)
java -cp "$CP" org.apache.tez.examples.OrderedWordCount \
  -local /tmp/tez-bench/input /tmp/tez-bench/output 4 >/dev/null 2>&1 || exit 125
end=$(date +%s.%N)
elapsed=$(echo "$end - $start" | bc)

echo "commit $(git rev-parse --short HEAD): ${elapsed}s (threshold ${THRESHOLD_S}s)"
awk -v e="$elapsed" -v t="$THRESHOLD_S" 'BEGIN { exit (e > t) ? 1 : 0 }'
EOF
chmod +x /tmp/tez-bench/bisect.sh

# Drive the bisection: known-good older tag, known-bad newer ref.
cd ~/src/oss-repos/tez
git bisect start
git bisect bad  HEAD                       # current is slow
git bisect good rel/release-0.10.3         # this release was fast
git bisect run /tmp/tez-bench/bisect.sh
# ... git prints "<sha> is the first bad commit"
git bisect reset

Two disciplines that keep a bisection honest: pick a THRESHOLD_S with real daylight between the good and bad means (use the stddev from Step 3 — if good is 20s±1 and bad is 28s±1, threshold 24s is safe), and exit 125 on any commit that will not build so git bisect skips it instead of mislabeling it. The output is a single SHA you can then git show and read like the TEZ‑4250 case study.

Step 7 — Write the perf JIRA with evidence

The deliverable a committer wants is a report they can reproduce. Use this template — it is deliberately marked as a template, with <...> placeholders you fill from your runs. Do not paste example numbers; measured numbers or none.

========================= JIRA PERF REPORT TEMPLATE =========================
Summary: <ClassName>.<method>() allocates/copies on a per-<task|record|call>
         path; <describe the cheaper alternative>

Component: <tez-dag | tez-runtime-library | tez-common>
Priority:  <Minor | Major>   (Major if it moves a real DAG's wall-clock)

Environment:
  Tez:    <git sha / branch>          e.g. master @ <sha>
  JDK:    <version>                   e.g. Temurin 21.0.x
  Hadoop: <hadoop.version from pom>   e.g. 3.4.2
  Host:   <cpu / cores / RAM / OS>

Hot path (why it matters):
  <ClassName>.<method>() is called <how often — per task? per record? per
  heartbeat?>. Flame graph (attached: flame-alloc.html) shows <frame> at
  <N>% of samples. Confirmed with: rg -n "<symbol>" <path>

Micro-benchmark (JMH 1.37, isolates the mechanism):
  Benchmark          (param)   Mode  Cnt   Score            Units
  <name>.before      <p>       avgt  <n>   <mean> ± <err>   ns/op
  <name>.after       <p>       avgt  <n>   <mean> ± <err>   ns/op
  gc.alloc.rate.norm before    <p>                          <B/op>
  gc.alloc.rate.norm after     <p>                          <B/op>
  Confidence intervals do NOT overlap: <yes/no>

Macro (benchmark DAG, proves it matters):
  OrderedWordCount, <input size>, local mode, <REPS> reps + warmup discarded
  before: mean=<m>s stddev=<s>s
  after:  mean=<m>s stddev=<s>s
  delta:  <-X%>   (or: "within noise — micro win does NOT move the DAG")

Regression bisected to: <first-bad sha>  (git bisect run, threshold <T>s)

Patch: <one-sentence description of the single change>
Compatibility: <none | note any tez-api / proto / config-default impact>
=============================================================================

The honesty clause is not optional: if the micro win does not move the benchmark DAG, say so in the macro line. "This JMH improvement does not move any real DAG's wall-clock" is a valid, respected result — and reporting it is what earns you the trust to have your next perf claim believed.

Deliverables

• A one-paragraph written dissection of one real perf commit (read via git show), naming the hot path, what was allocated/copied, and why the fix is safe and minimal.
• A repeatable benchmark DAG (run.sh) that discards a warmup run and reports mean + stddev over ≥5 reps.
• A git bisect run script that builds Tez, times the DAG, and exits 0/1/125 correctly — and one bisection you actually drove to a single SHA (may be a synthetic slow-down you introduce on a scratch branch).
• A CPU and an allocation flame graph of a local-mode DAG run, with the hottest unexpected frame identified and tied to a class.
• One correct JMH microbenchmark against a real Tez class (TezTaskID or IFile.Writer), run with -prof gc, with non-overlapping confidence intervals between two variants (e.g. cache-hit vs cache-miss regimes).
• A filled-in JIRA perf report from the template — with measured numbers, or an explicit "micro win does not move the macro" honesty line.

Troubleshooting

Stretch Goals

• Reproduce a real fix's benefit: check out the commit before TEZ‑4250, run a DAG with speculation disabled under the allocation profiler, then check out the fix and show TezCounters allocations under getCounters disappear from the flame graph.
• Benchmark IFile.Writer.append for real: build a tez-runtime-library-backed JMH that writes N key/value records through the writer, and measure ns/record and B/record as record size scales.
• Turn the interner regime into an A/B: parameterize distinctIds across two orders of magnitude and show where the weak-interner miss cost overtakes the raw constructor cost.
• Take a real, merged perf JIRA, revert only its production change on a scratch branch, and use your git bisect script to confirm it re-detects the regression — the ultimate proof your benchmark actually measures the thing.

Validation / Self-check

Answer all of these before marking the lab complete:

1. Why is a JMH microbenchmark insufficient on its own to justify a Tez perf patch, and what does the benchmark DAG add that JMH cannot?
2. Explain the TEZ‑4250 fix in one sentence from the diff: what path, what allocation, and what condition now gates it.
3. Your @Benchmark reports 0.3 ns/op. Name the two classic causes and the fix for each.
4. Why must a git bisect run script exit 125 (not 1) when a commit fails to build?
5. Why is local mode (-local) the right target for profiling a DAG, and what does that let a single async-profiler attach capture?
6. Your JMH shows a 40% time improvement but the benchmark DAG mean does not move outside its stddev. What do you write in the JIRA, and why is that the honest and career-correct answer?
7. Given a wide TezCounters.incrAllCounters frame in an allocation flame graph, describe the regression mechanism (allocation → GC → dispatcher latency) and one way to confirm it is on a hot path before you touch it.