Measuring Performance of Transformer Inference

When you optimize the inference performance of an LLM, you need to know how to measure it. Without measurement, it is easy to make a model more complicated without making it faster, or to improve throughput while making user-visible latency worse. An LLM service has several kinds of performance. A user cares about how long it takes to see the first token and how quickly the rest of the answer streams. An operator cares about how many requests the hardware can serve, how much memory is used, and how much each generated token costs. A researcher may care about whether an optimization changes the model’s output quality. In this chapter, you will learn about: - Latency and throughput metrics - Time to first token and time per output token - Measuring CPU and GPU inference - Using CUDA events - Benchmarking multiple requests - Thinking about multiple GPUs and multiple machines Let’s get started. Overview This chapter is divided into eight parts; they are: - Metrics for LLM Inference - Measuring a Single Request - Warmup and Synchronization - Measuring GPU Work with CUDA Events - Measuring Memory Usage - Measuring Concurrent Requests - Multiple GPUs and Multiple Machines - Cost per Token Metrics for LLM Inference The most common inference metrics are: - Latency: How long a request takes from start to finish. - Time to first token (TTFT): How long the user waits before the first output token appears. - Time per output token (TPOT): The average time between generated tokens after the first token. - Throughput: How many tokens or requests are processed per second. - Memory usage: How much CPU memory or GPU memory is used. - Utilization: How busy the accelerator is during the benchmark. - Cost per token: The hardware or service cost divided by the number of tokens processed. For LLMs, a single latency number is usually not enough. Consider two requests: - Request A: 2,000 prompt tokens and 20 output tokens - Request B: 20 prompt tokens and 2,000 output tokens Request A stresses prefill. Request B stresses decode. They may have the same total number of tokens, but they have different performance profiles. This is why you should record prompt tokens and output tokens separately. Tail latency also matters. If most requests complete in one second but a few take ten seconds, users will notice. Report high-percentile latencies such as p90, p95, and p99 in addition to the mean or median. The high percentiles describe the worst cases better. You can easily find these percentiles from a list of values using NumPy: | 1 2 3 4 5 6 7 8 9 10 11 | import numpy as np def summarize(values): values = np.asarray(values, dtype=np.float64) return { "mean": values.mean(), "median": np.percentile(values, 50), "p90": np.percentile(values, 90), "p95": np.percentile(values, 95), "p99": np.percentile(values, 99), } | These numbers are simple, but they prevent a common mistake: optimizing the average while making the worst cases slower. Measuring a Single Request The simplest measurement uses time.perf_counter() . It is a built-in high-resolution wall-clock timer suitable for measuring elapsed time in Python. It is more accurate than time.time() . The following example measures prefill and decode separately for a Hugging Face causal language model: | 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 | import time import torch from transformers import AutoModelForCausalLM, AutoTokenizer def load_model(model_name="sshleifer/tiny-gpt2", device="cpu"): tokenizer = AutoTokenizer.from_pretrained(model_name) model = AutoModelForCausalLM.from_pretrained(model_name).to(device) model.eval() return tokenizer, model @torch.no_grad() def measure_one_request(model, tokenizer, prompt, max_new_tokens=50, device="cpu"): input_ids = tokenizer(prompt, return_tensors="pt").input_ids.to(device) start = time.perf_counter() outputs = model(input_ids, use_cache=True) prefill_end = time.perf_counter() past_key_values = outputs.past_key_values next_token = outputs.logits[:, -1, :].argmax(dim=-1, keepdim=True) generated = [next_token] decode_times = [] for _ in range(max_new_tokens - 1): step_start = time.perf_counter() outputs = model( next_token, past_key_values=past_key_values, use_cache=True, ) # Note: You may need torch.cuda.synchronize() here step_end = time.perf_counter() decode_times.append(step_end - step_start) past_key_values = outputs.past_key_values next_token = outputs.logits[:, -1, :].argmax(dim=-1, keepdim=True) generated.append(next_token) if tokenizer.eos_token_id is not None: if next_token.item() == tokenizer.eos_token_id: break end = time.perf_counter() output_ids = torch.cat([input_ids] + generated, dim=1) return { "text": tokenizer.decode(output_ids[0], skip_special_tokens=True), "prompt_tokens": input_ids.size(1), "output_tokens": len(generated), "prefill_seconds": prefill_end - start, "decode_seconds": sum(decode_times), "total_seconds": end - start, "ttft_seconds": prefill_end - start, "seconds_per_output_token": ( sum(decode_times) / max(1, len(decode_times)) ), } | This function does not use the model’s generate() method. That is intentional. The goal is to expose prefill and decode so they can be measured separately. The number of output_tokens includes the tokens generated by both prefill and decode. The seconds_per_output_token is the average time per output token in the decode phase. There are two details to notice: use_cache=True asks the model to return the KV cache.- During decode, the model receives only next_token , not the whole sequence. This is the same idea as Chapter 1, but using a library model. Warmup and Synchronization When you measure performance, note that some one-time costs should not dominate the result. In Python, import of a module can be slow but subsequent import of the same module is instant. Similarly, the first execution of some code may be slower than subsequent executions due to initialization of data structures or warmup of caches. You want to measure steady-state work, not that setup overhead. Therefore, benchmarks should include warmup. The first few iterations may be slower for various reasons. Instead of measuring the total time and dividing by the number of iterations, you should measure the time for each iteration and analyze the steady-state ones. For example, if you use the model to generate multiple tokens, you will likely put the generation in a loop. Measure each iteration as follows, then ignore the first few results: | 1 2 3 4 5 6 7 8 9 10 11 12 13 | def iterations(model, tokenizer, prompt, device, steps=100, warmup=10): results = [] for _ in range(steps): result = measure_one_request( model, tokenizer, prompt, max_new_tokens=8, device=device, ) results.append(result) steady = results[warmup:] return summarize([item["total_seconds"] for item in steady]) | If you use GPU to run your LLM inference, you also need to initialize the kernels when you first run them. Unfortunately, many GPU operations are asynchronous. That is, while you launched an operation on GPU, Python may continue with your code immediately while the GPU is still working. Therefore, a naive approach to measure the time would be incorrect. Instead, you should use torch.cuda.synchronize() to wait for the GPU to finish the operation before you stop the timer: | 1 2 3 4 5 6 7 8 | def sync_if_needed(device): if device.startswith("cuda"): torch.cuda.synchronize() start = time.perf_counter() outputs = model(input_ids, use_cache=True) sync_if_needed(device) elapsed = time.perf_counter() - start | This gives a wall-clock measurement that includes the actual GPU work. For accurate prefill and per-token decode timings on GPU, call sync_if_needed(device) after each timed model(...) call in measure_one_request() , not only once at the end of the request. Measuring GPU Work with CUDA Events CUDA events measure elapsed time the GPU spent executing kernels, not the end-to-end user latency. This time does not include any Python overhead. Below is an example of how to use CUDA events to measure the time: | 1 2 3 4 5 6 7 8 9 10 11 | def cuda_event_time(fn): start = torch.cuda.Event(enable_timing=True) end = torch.cuda.Event(enable_timing=True) start.record() result = fn() end.record() torch.cuda.synchronize() milliseconds = start.elapsed_time(end) return result, milliseconds / 1000.0 | You can use it to measure one forward pass: | 1 2 3 4 5 6 | with torch.no_grad(): outputs, seconds = cuda_event_time( lambda: model(input_ids, use_cache=True) ) print(f"GPU forward time: {seconds:.6f} seconds") | CUDA event timing and wall-clock timing answer different questions: - Wall-clock timing measures what the application experiences. - CUDA event timing measures how long the GPU work took. For an inference service, wall-clock timing is usually the primary metric because users experience queues, tokenization, scheduling, network overhead, and streaming. CUDA events are useful when you are optimizing kernels or comparing model execution paths. For deeper GPU profiling, use tools such as PyTorch Profiler, Nsight Systems, Nsight Compute, or CUPTI-based monitoring. These tools can report kernel timelines, memory copies, GPU utilization, and operator-level breakdowns. They are more complex than a timer, but they are necessary when a simple benchmark says the model is slow and you need to know why. Measuring Memory Usage Memory is a different dimension to measure because it limits not speed for one user so much as how many users your system can serve. Usually the GPU memory is the bottleneck. In PyTorch, you can report allocated and reserved memory like the following: | 1 2 3 4 5 6 7 | def gpu_memory_summary(device="cuda"): torch.cuda.synchronize() return { "allocated_gb": torch.cuda.memory_allocated(device) / 1e9, "reserved_gb": torch.cuda.memory_reserved(device) / 1e9, "max_allocated_gb": torch.cuda.max_memory_allocated(device) / 1e9, } | The allocate