Find the bottleneck

What you will be able to do

Split one ticket’s 2.2 seconds into its parts, and check each resource that could limit the service. Find what stopped four users from doubling the throughput. Then you know which change can help before Black Friday, and which cannot.

Before you startWhat to know and to have readyAbout 50 minutes

What you need to know

• Percentiles, Little’s law, queues and the baseline, from Latency and capacity.
• Transactions and the connection pool, from Connection management.

What you need on your computer

• Your project from the last lesson: python -m pytest prints 128 passed. The small data is loaded.
• PostgreSQL and Azurite running. You start the simulator and the API in the guided practice.

The narrow neck of a bottle

Turn a full bottle upside down. The water does not leave as fast as the bottle is wide. It leaves as fast as the neck lets it. A wider bottle with the same neck empties no faster.

A motorway works in the same way. Four lanes narrow to one lane at a road repair. The traffic on the whole road now moves at the speed of that one lane. Adding a fifth lane before the repair changes nothing.

The narrow part is the bottleneck: the one part that limits the whole system. Any work on another part is wasted until the bottleneck changes.

The problem: fixing the wrong part

In the last lesson, four users did not double the throughput of two users. Tomás has a fix ready: “The API is too slow. Let’s give it a bigger computer with more CPUs.”

Amira checks one number first. During the baseline with four users, the API process used 2.2% of one CPU. With one user, it used 0.6%. The API is not computing: it is waiting. A computer with twice as many CPUs would wait at the same speed, and it would cost twice as much.

This is the most common mistake in scaling work: a change to a part that is not the bottleneck. It costs money and time, and the next measurement shows no change. You find the bottleneck first, with two questions:

1. Where does one request spend its time? This finds what makes each request slow.
2. Which resource runs out when many requests arrive? This finds what limits the throughput.

The two answers can differ. A part can be slow without being full, and a part can be fast but have a hard limit.

The idea: split the time, then check the resources

To answer the first question, the API measures itself. ticket_api/timing.py has a small timer. The code wraps each part of the request in it, and the API sends the parts back in a standard response header, Server-Timing:

server-timing: db;dur=10.3, classify;dur=787.0, draft_reply;dur=1167.7, embed;dur=222.6

You saw this header in the setup lesson. Browsers show it in their developer tools. scripts.breakdown sends tickets, reads the header of each answer, and takes the median of each part. Whatever the header does not cover is “other”: the web framework, the JSON and the network between the script and the API.

To answer the second question, you check each resource that a request uses: the CPU, the memory, the network, the database and the provider. For each one, you ask whether it is close to a limit.

A tiny example: one ticket in five parts

The course sent 10 tickets, one at a time, on a quiet computer, with the simulated provider. These are the medians of the parts:

Part	Median ms	Share of the total
db	9.5	0%
classify	914.5	43%
draft_reply	946.9	44%
embed	249.9	12%
other	7.6	0%
total	2,146.6

The three provider calls together take 2,111 ms of the 2,147 ms. The database work, about 10 ms, is under half a percent. The medians of the parts do not add up exactly to the median total, because each median comes from a different ticket. They are close enough to show where the time goes.

The median of each part of a new ticket, from the Server-Timing header: 10 tickets, one at a time, Module 1's design, simulated provider, a quiet computer. The provider's three calls are almost all of the time.

Text description of the chart

Median milliseconds per part of a new ticket: db 9.5, classify 914.5, draft a reply 946.9, embed 249.9, other 7.6. The median total is 2,146.6 ms. The three provider calls take about 98% of it.

What this tells us. To make one ticket faster, only the provider calls matter. A faster database could save at most 10 ms per ticket. Faster Python could save less. The calls could get faster in only three ways: a faster provider, fewer calls, or calls that run at the same time instead of one after the other.

Larkfield’s resources, one by one

The breakdown answers the first question. Now the second: what runs out when many tickets arrive? Go through the resources in order. For each one, the evidence comes from a measurement, not from a guess.

• CPU. The API used 0.6% of one CPU with one user and 2.2% with four (the baseline passes). Not the limit. On another service, such as one that runs a model on its own CPU, this could be the first limit.
• Memory. In the author’s run, the API process used about 51 MB after a first load test, and still 51 MB after a second one. It did not grow from test to test. Not the limit.
• Network. The “other” part, 7.6 ms, includes the network between the script and the API on the same computer. Not the limit here. Between real data centres, it adds tens of milliseconds.
• Database work. About 10 ms per ticket. Not the limit for time. But look again at the request diagram of the setup lesson. The transaction keeps its connection for the whole 2.1 seconds, while it waits for the provider. The pool has 10 connections. Module 2 measures what happens with more than 10 tickets at once.
• Provider time. 98% of each ticket. The limit for the latency of one ticket.
• Provider quota. 100 chat calls per minute for the whole account. Each ticket needs 2, so the account can finish at most 0.83 tickets per second. Four users ask for more than that, as the next section shows.

Larkfield's bottleneck map for Module 1's design. The two thick boxes are the limits; the database is the next one to watch.

Text description of the diagram

One ticket takes 2,147 ms at the median. Six resources could limit it. The API’s CPU (0.6 to 2.2%), its memory (about 51 MB, flat) and the network (7.6 ms) are far from any limit. The database work is short, 9.5 ms, but each ticket holds a connection for the whole 2.1 seconds. The provider’s time is 98% of a ticket: it limits the latency. The provider’s quota, 100 chat calls per minute, limits the throughput: with four users, the provider refused between 41 and 115 calls per pass. The database pool and the quota are what limit the next design.

The quota under load

Now see the second bottleneck yourself.

1. In ~/projects/ticket-api, with the virtual environment active, copy the script of this lesson from the snapshot end-of-m01. Your project then matches the snapshot.

   macOS / Linux

   cp ../nextia-learning-labs/C21/snapshots/end-of-m01/scripts/breakdown.py scripts/

   Windows (PowerShell)

   Copy-Item ..\nextia-learning-labs\C21\snapshots\end-of-m01\scripts\breakdown.py scripts\

2. Start a fresh simulator in terminal 1 (python -m simulator) and the API in terminal 2 (fastapi run). A fresh simulator has a full quota and counts from zero.

3. In terminal 3, break down 10 tickets, one at a time:

   python -m scripts.breakdown --tickets 10

   The course’s run on a quiet computer printed the table of the tiny example, and then this line. Your times will differ:

   Provider (simulated): 30 calls, 0 refused with 429, at most 1 at the same time

4. Break down 10 tickets again, four at a time:

   python -m scripts.breakdown --tickets 10 --concurrency 4

   The parts stay about the same, because the simulator does not slow down when calls overlap. The author’s run of these 10 tickets, four at a time, gave a median total of 2,260 ms and at most 4 at the same time. The real provider would be a little slower here.

5. Now send load with four users for 60 seconds:

   locust -f loadtest/locustfile.py --host http://127.0.0.1:8000 --headless -u 4 -r 4 -t 60s

6. When Locust stops, ask the simulator what it counted: curl http://127.0.0.1:8300/admin/stats.

The author’s run of steps 5 and 6 printed this, shortened to the final table and the error report. Your numbers will differ:

Type     Name                  # reqs      # fails |    Avg     Min     Max    Med |   req/s  failures/s
--------|---------------------|-------|-------------|-------|-------|-------|-------|--------|-----------
POST     POST /v1/tickets         158   62(39.24%) |   1511     139    3080   2100 |    2.64        1.03

Error report
# occurrences      Error
------------------|-----------------------------------
62                 POST POST /v1/tickets: 503

{"mode":"normal","in_flight":1,"max_in_flight":4,"calls":{"classify":{"200":102,"429":58},"draft_reply":{"200":96,"429":6},"embed":{"200":96}},"tokens":41314,"simulated":true}

62 of 158 tickets failed with status 503. Locust says req/s 2.64, but that counts the failures. Only 96 tickets were saved: 96 embed calls, one per saved ticket. The Min 139 ms is a failed request: a refusal comes back fast. The course measured the same test five times on a quiet computer. The provider refused between 41 and 115 calls per pass, and between 41 and 115 customers per pass got a 503.

Look at the six refused draft replies. Each of those tickets had already paid for a classify call, and it still failed. A refusal can waste work that was already done.

What a refusal looks like

When the quota is used up, the simulator answers like the real provider. The author’s run caught this answer, after a burst of 110 calls at once:

HTTP/1.1 429 Too Many Requests
retry-after: 30
retry-after-ms: 266
x-simulated: true

{"error":{"code":"rate_limit_exceeded","type":"too_many_requests","message":"Your requests to chat-small have exceeded the request rate limit (simulated)."}}

Status 429 Too Many Requests means “over the limit, try later”. A limit of this kind, a number of requests per time window, is a rate limit. The answer has two hints about when to try again, and they disagree. Retry-After: 30 says 30 seconds. retry-after-ms: 266 says 266 milliseconds. The real provider sent both too: Retry-After was 30 every time, and retry-after-ms was between 12 and a few hundred. The project’s client reads retry-after-ms first, as the provider’s own Python library does, because it is more exact.

The API turns the refusal into its own answer for the customer:

HTTP/1.1 503 Service Unavailable
retry-after: 1
server-timing: db;dur=4.4, classify;dur=133.2

{"error":{"code":"ai_busy","message":"The AI provider is busy. Try again in 1 second.","request_id":"4badc55650e3","fields":[]}}

The classify part took 133 ms: the refusal itself. The transaction rolled back, so the ticket was not saved. On Black Friday, this customer sees an error, and the help desk never sees the ticket. That is a lost ticket, not only a slow one.

What the real provider did

The course team saw the same pattern with the real provider. With 16 calls in flight, 114 chat calls passed in about 8 seconds, and then the provider answered 429. Twenty seconds later, a burst of 160 calls got only 34 through. So the limit counts the calls of about the last minute. A burst can use a whole minute’s quota in a few seconds, and then it must wait. That is why the quota is a limit on throughput, not on speed: 100 calls per minute, however fast you send them.

Four users need about 1.7 tickets per second, so about 3.4 chat calls per second, or 206 per minute. The quota gives 100. The bottleneck under load is the quota.

When to look for the bottleneck

Look for it before every change that is meant to make the service faster or bigger. Split the time, and check each resource with a measurement. Then change only the bottleneck, and measure again, because the bottleneck moves. When the quota stops being the limit, the database pool may be next.

Do not trust a single sign. A high CPU number can be another program on the same computer. A long “db” part can be a wait for a free connection, not slow SQL. Check the evidence from both sides: the request’s parts and the resource’s use.

The tools cost something too. A timer around each part adds a little code to each request. The Server-Timing header also tells every client how your service works inside, for example that it calls an AI provider. In a real service, send it only to your own staff, or remove it at the edge of your network.

Tomás has a last idea: “Then let’s run four copies of the API. Four times the throughput!” Sam asks the right question: “Does each copy get its own quota?” No. The quota belongs to the account. Four copies would share the same 100 calls per minute, and they would only reach the limit sooner. Module 2 runs several copies anyway, and it shows what they can and cannot change.

Common mistakes

Common mistake

The breakdown says 'at most 4 at the same time' for one ticket at a time

Symptom: you run python -m scripts.breakdown --tickets 10, one at a time, and the last line says at most 4 at the same time.

Cause: the simulator counts the most calls in flight since it started, not in this run. An earlier test with four users set it to 4. The author’s run showed exactly this.

Fix: restart the simulator before each measurement, or reset its counts:

curl -X POST http://127.0.0.1:8300/admin/reset

On Windows, type curl.exe instead of curl. A reset also fills the quota again and sets the mode back to normal.

Common mistake

Locust's req/s looks good, but tickets are lost

Symptom: with more users, Locust’s req/s goes up, for example 2.64. But the # fails column is not zero.

Cause: Locust’s req/s counts every answer, including the fast 503s. A failed request is not useful work.

Diagnose: read # fails and the error report. Count the saved tickets: one embed call per saved ticket in /admin/stats, or scripts.percentiles on a SAMPLES_CSV file, which counts only the 2xx answers.

Fix: report successful requests per second. In the author’s run, that was 96 tickets in 60 seconds, not 158.

Your turn: a smaller quota

Change one condition: the quota. The simulator has a quota mode with a quota ten times smaller, 10 chat calls per minute. It is made up for practice. Stop the simulator, start it with python -m simulator --mode quota, and predict what python -m scripts.breakdown --tickets 10 prints: how many tickets succeed, and does the breakdown of the successful ones change?

Show the answer

The quota holds about 10 chat calls, so about 5 tickets get both their chat calls, and the rest get 503. The successful tickets look the same as before: the quota decides how many tickets pass, not how fast each one is. The author’s run printed:

10 tickets, 1 at a time: status codes {201: 5, 503: 5}
part          median ms   share
db                 23.7      1%
classify          913.4     42%
draft_reply       955.1     44%
embed             223.7     10%
other               7.5      0%
total            2179.0
Provider (simulated): 22 calls, 5 refused with 429, at most 1 at the same time

The simulator counted 7 successful classify calls and only 5 saved tickets: two tickets paid for classify, and then lost their draft reply to the quota. Start the simulator again without --mode quota when you finish.

Knowledge check

Check your understanding

Tomás says: 'The API is slow, so we need a bigger computer.' Use two measurements from this module to answer him.

Show the answer

The provider’s three calls take about 2,111 ms of a 2,147 ms ticket (98%). The database and “other” take about 17 ms. The API’s CPU was only 0.6 to 2.2% in the baseline. The API is waiting, not computing, so a bigger computer would wait just as long. Under load, the limit is the provider’s quota (100 chat calls per minute): with 4 users, it refused 41 to 115 calls per pass. Neither depends on the size of the API’s computer.

Check your understanding

Predict: the quota grows to 1,000 chat calls per minute, and nothing else changes. What happens to the latency of one ticket, and to the throughput with 4 users?

Show the answer

The latency of one ticket does not change: about 2.2 seconds, because the quota does not make a call faster. The throughput with 4 users rises to about 4 ÷ 2.3 = 1.7 tickets per second. That is about 206 chat calls per minute, well inside the new quota, so no 503s. The quota stops being the bottleneck. Then the next limit shows, for example the database pool of 10 when more than 10 tickets wait at once.

Check your understanding

Module completion check: pick three numbers from this module (for example the 1-user baseline, the breakdown and the 4-user run). For each one, state the workload and the hardware behind it.

Show the answer

For example. The baseline, 0.43 tickets per second and p95 2,995 ms: Module 1’s design, loadtest/locustfile.py, 1 user, no pause, 60 s, 10 s warm-up left out, 5 passes (median); small data; simulated provider with the recorded quota; Apple M4, 10 cores, 16 GB, load under 3. The breakdown, provider calls 98% of 2,147 ms: scripts.breakdown, 10 tickets one at a time, simulated provider, the same quiet computer. The 4-user run, 41 to 115 refused calls per pass: the same locustfile with 4 users, the same computer, 5 passes, quota on. Your own numbers need your own computer, your load average and your number of passes. None of them is a production capacity.

Recap

• The bottleneck is the one part that limits the whole system. Change anything else, and nothing improves.
• Split the time with Server-Timing and scripts.breakdown: the provider takes about 98% of a ticket’s 2.1 to 2.2 seconds; the database about 10 ms.
• Check each resource with a measurement: CPU 0.6 to 2.2%, memory flat, network a few milliseconds. The provider quota of 100 chat calls per minute limits the throughput to 0.83 tickets per second.
• Over the quota, the provider answers 429 with two hints, Retry-After: 30 and a much shorter retry-after-ms. The API answers 503 ai_busy, and the ticket is lost.
• The database work is short, but each ticket holds a connection for the whole wait. That is the next limit to watch.

Module 1 in one paragraph. You run the AI workload on your computer, with a simulated provider that copies real times and the real quota. You describe Black Friday as a workload: 0.28 tickets per second in the busiest hour, 90 tickets in the busiest minute. You record a baseline with its workload and its computer: 0.43 tickets per second, p95 2,995 ms. And you know the two limits: the provider’s time for each ticket, and its quota for many tickets. Every number has its workload and its computer next to it.

Next, Module 2 lets the API do more at once, and you see where more concurrency stops helping.

Next: I/O versus CPU work