Profiling a C++ game server with perf and Tracy

Intro

0:00 Hello and welcome back to episode eight, where we're going to find out how many players our server can take, and what slows it down. We're going to measure it, profile it, and fix what we find. Let's begin with a quick look at where we're going to be by the end of the episode.

0:16 Two thousand bots are playing on our server, each with a connection of its own. And the server keeps up with its twenty ticks a second, while at the start of this episode, it fell behind at around a thousand.

0:29 On the website of the series you can find more information about the project. The code for the project is open source on GitHub, tagged at each step of each episode so that you can follow along.

Last time

0:40 Now, before we get to today's work, let's quickly go over what we did last time, when our cubes became characters. We took two characters and three clips from Mixamo, and kept the files out of our public repo, as Mixamo's terms ask. FBX2glTF converts them to glTF, in Docker, and a small tool of ours merges them into what raylib expects: one skin, the walk and the run in place, and a tenth of the triangles. The server decides which way each player faces, and whether it walks or runs. The client follows the server smoothly between ticks, blends from one clip into the next, and skins the characters on the GPU. And the bots now run a third of the time, so that our load tests move the way players do. All right, now that we're caught up on episode seven, let's get started.

Today

1:28 In episode four, the dashboard showed us that what we send grows with the square of the players. And I said that before changing anything, I wanted to push the server until it struggles, and measure where that happens, which is what we're going to do today. First, a benchmark, which is a measurement we can repeat, here of how the server copes as players arrive, so that we know where it falls behind. Then a profile, which tells us where the server's time goes, and for that, perf, flame graphs and Tracy come into play. Then we fix what the profile shows us, which isn't necessarily what we'd have guessed. And guessing is how a lot of time goes into optimising code that wasn't slow. And then we run the benchmark again, so that we know whether the fix helped, and by how much.

A benchmark

2:16 Here's the plan for the benchmark, where we add bots two hundred and fifty at a time. Each batch is a swarm of its own, a process with its own thread, so that the bots don't run out of CPU before the server does. We give each batch twenty seconds to log in and arrive, then let them play for thirty, and measure the last twenty-five of those, once they've settled. The numbers we need are in Prometheus already, from episode four. So the script asks Prometheus, over its HTTP API, for the players online, the ticks per second, the tick's p50 and p99, and the bytes sent each second. The ticks per second tell us whether the server keeps up, as while it manages twenty, each tick fits in its fifty milliseconds. Each step gives us a line of JSON, and then the next two hundred and fifty bots join. These numbers depend on the machine, and mine is an M4 Pro, with Docker Desktop's virtual machine running all of it, the bots too. So we compare runs on one machine, and the shape of the numbers matters more than their values.

3:18 Before we write the benchmark, the server's metrics need to tell us more about slow ticks. In metrics dot c c, the comment over the tick histogram goes first, as it says the buckets stop at the whole tick, fifty milliseconds, and that's what we're changing. A tick that took longer than that landed in plus infinity, which is what Prometheus calls the bucket with no upper bound. Today, we're going past the budget on purpose, and in plus infinity, a tick of sixty milliseconds and a tick of six hundred look alike. And histogram quantile can't see past the last bucket either, so a p99 over the budget would have come out as fifty milliseconds, however slow the ticks were. So the buckets now go up to a whole second, and a slow tick lands in a bucket of its own. Up to ten milliseconds, they're as before, and then twenty, thirty, forty and fifty are ten milliseconds apart around the budget, as that's where we look the closest. Then seventy-five, a hundred, two hundred and fifty, half a second, and a second. Each bucket is a time series of its own in Prometheus. So we don't want hundreds of them, and sixteen is plenty, as long as they sit where the answers matter to us. We could have added a counter for the ticks over the budget, too. However, the histogram sees each tick already, so its buckets answer that as well. In metrics test, a new test pins this down: keeps ticks over the budget apart. It observes a tick of sixty milliseconds and one of three hundred, which would both have landed in plus infinity before. Then it scrapes the metrics, with the helper from episode four that gives us the text Prometheus would read. A bucket counts all the ticks up to its boundary, so the counts add up as they go. The fifty-millisecond bucket has none of them, while the seventy-five has the sixty, and by half a second, both of them are in. If someone trims the buckets later, say to save on time series, this test fails. Then the dashboard, which is JSON that Grafana exports for us, so I'm pasting it in. Next to the players online, a new panel shows the ticks per second, from the rate of the histogram's count, which is how many ticks the server observed each second. It's a stat panel, like players online, with a small graph under the number, so that we can tell at a glance whether the server keeps up. It's red below nineteen and a half and green above, as a rate over fifteen seconds wobbles a little, and we don't want it red while the server is fine. The tick duration panel makes room for it, and draws the fifty-millisecond budget as a dashed line.

5:49 Next, the script that adds the bots in steps, and before that, the bots need a small change. As each step of the benchmark starts a swarm of its own, which numbers its bots from one, a second swarm's bot1 would be refused, as bot1 is already playing. In the bot's main file, the swarm's constructor takes first, the number of its first bot, and keeps it in first underscore. When the swarm adds a bot, the bot's number now counts from first, where it used to count from one. The member goes after count, and in main, first starts at one, so that a single swarm behaves as it did. It comes from the fifth argument, and Abseil's simple a to i parses it, like the count and the ramp. If any of them isn't a number, the bot stops, with a message that now names the first bot's number too. The line we print at the start says which bot the swarm starts from, which helps when we read the logs of several swarms, and main passes first on to the swarm. In compose dot yaml, the bots service takes how many bots from BOTS, and the ramp from RAMP. Dollar, brace, BOTS, colon, dash, three hundred is Compose's way of saying the BOTS variable from the shell, or three hundred if it isn't set. So docker compose up bots still starts three hundred, while BOTS equals twelve hundred and fifty in front of it starts that many, which is how we're going to profile. Then a new folder, bench, for the benchmark, with load dot s h, a bash script. It starts containers, waits, and asks Prometheus for numbers, which is the kind of work a shell is good at, with nothing to compile. Its first line, hash bang, user bin env bash, has it run by bash, wherever bash is installed. Set dash e u stops at the first failure, like in episode seven. And pipefail counts a pipeline as failed when any command in it fails, as by default, the last command decides. Without these, a benchmark can carry on after a step went wrong, and hand us numbers that look fine and aren't. Per step and steps come from the script's two arguments, and colon dash gives them defaults, like in compose dot yaml: two hundred and fifty bots and eight steps. Ramp and hold are the twenty and thirty seconds from the plan. Query is a bash function, which asks Prometheus for a single number, with dollar one, its first argument, as the PromQL to run. Curl, which we used in episode four, sends it to Prometheus's HTTP API, and dash dash data urlencode encodes our PromQL, so that its brackets and quotes survive the trip. Then jq, which reads and writes JSON, picks the value out of the answer. That value is a pair of a time and the number, and the number comes as a string, so tonumber turns it into a number. We ask Prometheus, and don't read the server's metrics page directly, as Prometheus keeps the history, and can work out rates and quantiles over a window for us. Then stop, a second function, removes the bots this script started, and leaves any other containers alone. Docker ps lists the running containers with our label, nanommo dot bench, and xargs passes their ids to docker rm dash f, which stops and removes them. And trap stop EXIT runs stop when the script exits, however that happens, Control C halfway through as well. Without it, a run we stop early would leave hundreds of bots playing, and the next run would start with them still there. Then docker compose build bots builds the bots from this checkout, as docker compose run starts whatever bots image it finds, and that could be one from an earlier episode. Window is the hold less five seconds, the twenty-five we measure over. And quantile is the sum of the bucket rates by l e, the bucket's upper bound, like the tick duration panel on our dashboard. So histogram quantile can turn it into the p50 and the p99. Now the loop, where seq counts from one up to the number of steps. First is the number of this step's first bot, one, then two hundred and fifty-one, and so on. And the dollar and the double parentheses around it are bash's arithmetic. Docker compose run starts a one-off container of the bots service, with our arguments instead of the ones in compose dot yaml. Dash d and dash dash rm run it in the background and remove it once it stops, and dash dash label puts our label on it, for stop to find. Then we sleep for the ramp and the hold together, fifty seconds a step. Result is an object that jq builds without reading any input, which is what dash n is for. Its five numbers come in through dash dash argjson, which passes each one as JSON, so it arrives as a number and not a string. Players is the gauge, nanommo players online, read as it is, with no rate around it. Ticks is the rate of the histogram's count over the window, so the ticks per second. P50 and p99 come from histogram quantile, times a thousand for milliseconds. And sent is the rate of the server's byte counter, divided by a million, for megabytes a second. The filter puts them into an object, with names that carry their units. And map values rounds each number to one decimal place, as more digits than that would be noise. The next jq prints a line with the players, the ticks per second and the p99, as plain text, which is what dash r is for. Three less-than signs hand it the result as its input, and greater than ampersand two sends that line to standard error. So the line shows up in the terminal as we go, while echo sends the object to standard output, which we're going to send to a file. After the loop, jq dash s, for slurp, collects the objects into one array, which is the file we keep and chart. Last, bench slash results goes into dot gitignore, as results belong to the machine they were measured on. And it goes into dot dockerignore, so that a new result doesn't make Docker build the server again.

11:44 Let's run it, and docker compose up dash d dash dash build starts the game server, along with the MySQL and Redis it needs, and Prometheus and Grafana. The login server starts later, with the first swarm of bots. Dash dash wait waits until they're all up, and as the first build compiles everything, that part is sped up. Mkdir dash p makes the results folder, and load dot s h runs ten steps of two hundred and fifty bots, with the JSON going into before dot json. Each step takes close to a minute, so this is sped up too. Up to a thousand players, the server manages its twenty ticks a second, while the p99 climbs from around nineteen milliseconds to forty. At twelve hundred and fifty, it manages eighteen point six, at fifteen hundred, thirteen point eight, and with twenty-five hundred players, it's down to five point four ticks a second.

12:37 The charts read before dot json, which our first run just wrote. On the left, the tick's p50 and p99 as the players arrive, with the fifty-millisecond budget as a dashed line. The p50 grows faster than the players do: five point eight milliseconds with two hundred and fifty players, thirty-five with a thousand, and past the budget before twelve hundred and fifty. That's the curve we'd expect from work that grows with the square of the players. On the right are the ticks per second, against the twenty the server aims for. Once a tick takes longer than its fifty milliseconds, the next one starts late, and the world runs slower than real time. So players would see everyone around them moving in slow motion. So on my machine, our server keeps up with a thousand players, and somewhere between a thousand and twelve hundred and fifty, it stops keeping up.

13:28 The dashboard shows it too, here with fifteen hundred bots, and ticks per second, the new panel, is red, well under its twenty. The tick duration is above the dashed line, the budget, most of the time. And what we send has stopped growing, as each tick sends more, and there are fewer ticks a second to send it in.

Profiling

13:48 Next, we want to know why the server falls behind past a thousand players, which is what a profiler tells us. There are two kinds, and we're going to use one of each. A sampling profiler interrupts the program a thousand times a second or so, and writes down its call stack. The call stack is the function it was in, and the functions that called it. Over ten seconds, that's ten thousand stacks, and the functions that show up in most of them are where the time goes. Sampling needs no changes to our code, and it sees all of it, our code, the libraries and the kernel. On Linux, that's perf, which is developed along with the kernel, in the kernel's own source tree. An instrumenting profiler works the other way round: we mark the parts of our code we care about, and each one records when it starts and when it ends. That gives us a timeline of each tick, with nothing averaged away, so a single slow tick shows up as a slow tick. For that, we're going to use Tracy, which a lot of games use.

14:46 perf gives us a lot of stacks, and the usual way to read them is a flame graph. Flame graphs are Brendan Gregg's idea, and these are his scripts. Each box is a function, and the boxes on top of it are the functions it called. A box's width is how many samples had that function on their stack, so the wide boxes are where the time goes. Left to right is alphabetical, not time, and the colours are there to tell the boxes apart. The README goes over the three steps we're going to use. Perf record, with dash g for the call stacks, and perf script, which prints the stacks as text. Then stackcollapse perf, which folds them into a line for each distinct stack, with a count, and flamegraph dot p l, which draws the SVG from those lines.

15:33 To run the server with perf next to it, we're going to use a compose override. Compose can merge several compose files into one, so that a second file can change a few things in the first. Compose picks up a file called compose dot override dot yaml automatically. So ours has another name, as we want the profiling setup when we ask for it, and not otherwise. We name the files with dash f, or in the COMPOSE FILE variable, and Compose merges them in that order. A later file adds to the services of an earlier one, and where both set something, the later one wins. So compose dot yaml stays as it is, and a small second file changes what profiling needs.

16:14 For perf to walk the call stack, our code needs frame pointers. With them, a register points at the current function's frame, and each frame keeps the address of its caller's frame. So following those from one frame to the next gives the call stack, cheaply. Optimising compilers leave them out by default, as that frees the register for other work, and then perf can't tell who called whom. There are other ways to unwind a stack, such as from DWARF debug information. However, perf then copies a chunk of the stack with each sample, and the files get big and slow to process. So in the top-level CMakeLists, add compile options, dash f no omit frame pointer. It goes above the FetchContent calls, so that Abseil, protobuf, Asio and the other libraries we fetch get it too. And a stack that stops at the first library frame wouldn't tell us much. It costs a register, and around a percent of speed, which Ubuntu, Fedora and Meta pay too, as they build their code with frame pointers for profiling. And we keep them on in all our builds, so that what we profile is what we run. In the Dockerfile, after the bot's stage, a new stage, profile, for the server with perf next to it. It starts from runtime, like the server's image, so it has the libraries the server needs. The comment over it reads: Ubuntu's perf wants a build for the running kernel, and Docker Desktop's kernel isn't Ubuntu's, so we put the generic build on the path. So apt installs linux tools generic, which has perf, along with perl, which the flame graph scripts are written in. The generic build works, as perf talks to the kernel through an interface that stays stable from one kernel to the next. And l n dash s links it into user local bin, as Ubuntu's perf command is a wrapper that gives up when there's no perf built for the running kernel. ADD fetches a file with a checksum, like FBX2glTF's in episode seven, and here, it's an archive of the flame graph scripts from GitHub, pinned to a commit. The next RUN makes a folder for them, opt slash flamegraph, and tar unpacks the scripts into it, where strip components one drops the folder the archive wraps them in. Then it removes the download, and ENV puts that folder on the path, so the scripts run by name. Then comes the server, from the test stage, so it's the binary our tests passed with, and profile dot s h, which we write next. It exposes the server's ports, and starts the server, like the server's image does. However, there's no USER line, so here the server runs as root, which keeps it simple for perf. Running as root is fine for a container we start for profiling, on our own machine, and nowhere else. Profile dot s h goes into bench, next to load dot s h, as a plain shell script, hash bang bin s h, with set dash e u like before. Name and seconds are its two arguments, server and ten by default, and the name ends up in the file names. So a profile from before a change and one from after can sit side by side. Perf record dash capital F nine nine seven samples nine hundred and ninety-seven times a second. That's a little off a round thousand, so that the samples don't line up with something in the server that runs on a timer, such as our tick. And lined up, they'd keep landing on one part of it. Dash g records the call stacks, which is what the frame pointers are for, and pidof finds the server's process id for dash p. After the double dash, sleep is what perf runs while it records, so it records for that many seconds, and stops. Then perf script turns the data into text, and dash capital F minus period leaves out how long each sample stands for, so that the flame graph counts samples. Stackcollapse perf dot p l folds the stacks into the folded file, which we keep, as it's small, and we can draw it again, or compare two of them. And flamegraph dot p l draws the SVG from it, with the name in its title, and the last line says where the flame graph went. Then the override, compose dot profile dot yaml, which changes the server service and nothing else. Image gives the profile image a name of its own, so that building it doesn't replace the normal server's image. And build, target profile builds it from the stage we just wrote. Cap add gives the container two Linux capabilities, which are pieces of root's powers. Docker drops most of them for a container, and perf needs these two back. PERFMON lets perf sample the server, and the kernel along with it. SYSLOG lets it read where the kernel's functions are, so that kernel frames get their names. We could run the container as privileged instead, which hands it all of root's powers, and that's a lot more than perf needs. And volumes mounts a profile folder from the repo at slash profile, so that the flame graphs end up on our machine. That folder goes into dot gitignore, like the benchmark's results, and into dot dockerignore, along with the override, like compose dot yaml. And CI builds the profile image too, without running it. So a change that breaks it shows up on the pull request, and not on the day we want to profile something.

21:29 Exported, COMPOSE FILE makes each compose command in this terminal read both files, listed with colons between them, the override after the base. Up dash d dash dash build starts the server from the profile image, with MySQL and Redis. Then twelve hundred and fifty bots, in a single swarm, which is about where the server started falling behind. And as they take a minute or two to log in, I've skipped ahead. Docker compose exec runs profile dot s h inside the server's container, named before, for ten seconds. perf took around ten thousand samples, a thousand a second for ten seconds, so the server's thread was busy all of that time.

22:09 The flame graph starts from main, with the event loop's own frames merged away, so that it fits. Ninety-five percent of the samples are in the server's Tick, and nearly all of those are in Broadcast. Two thirds of the time goes into Frame, our function that serialises a message and puts its size in front of it. Inside it, serialize as string is protobuf writing out the world, and that's about half of all the server's time. Most of it is writing each player, and a quarter of it is checking that each player's name is valid UTF-8, which protobuf does for each string field it writes. Next to it, do mem abort is a page fault. Frame copies the bytes into a new string, and the kernel hands fresh memory over page by page, before we can write to it. Handing over those pages takes another tenth of the server's time, on top of the serialising. And Session Write, a quarter of the time, is the kernel sending the bytes over TCP. So, for each of the twelve hundred and fifty clients, the server serialises all twelve hundred and fifty players, copies the result, and sends it. The serialising and the copying are the work that grows with the square of the players.

Tracy

23:19 Tracy is by Bartosz Taudul, and it's a frame profiler, with nanosecond resolution. A program marks its frames, and the parts of a frame we want to see, which Tracy calls zones. And Tracy draws them on a timeline while the program runs. It comes from games, where a frame is what's drawn on screen, sixteen milliseconds or so apart, and our frames are going to be ticks. It comes in two parts, and the first is a small client library that goes into our server, and sends what it records over the network. The second is the profiler, a separate program that connects to it, and draws the timeline, with statistics and a lot more.

24:02 Tracy's client comes into the build like our other libraries, in the top-level CMakeLists, after Asio. Before it, we set TRACY ON DEMAND to on, as Tracy reads its options when it's made available. Without on demand, Tracy's client records from the moment the server starts, and keeps all of it in memory until a profiler connects. And in a server that runs for days, that's a lot of memory. The comment over it reads: Tracy's macros compile to nothing without dash D TRACY ENABLE equals ON, and on demand, it records nothing until a profiler connects. The first part is why we can leave Tracy's macros in our code, as a normal build, like the server's image, doesn't pay for them at all. Then FetchContent declare tracy, from its release, zero point fourteen point one, marked SYSTEM like before, and make available adds it to the build. In the server's CMakeLists, the core library links Tracy colon colon TracyClient, publicly, like the rest. So the server and its tests get Tracy's header through the core library, and with TRACY ENABLE off, the macros are empty there too. Now we mark the parts of the tick we want to see. In world dot c c, we include tracy slash Tracy dot h p p, the header with Tracy's macros. At the top of Step, zone scoped is a macro that creates an object on the stack. And the object records the time when it's created, and again when it goes out of scope, at the end of the function. Tying the work to an object's lifetime like that is called R A I I in C++, and it means the zone ends whichever way the function returns. So it times the whole function, and names the zone after it, Step. In server dot c c, we include Tracy's header again, and Tick gets zone scoped at the top. So the timeline has the whole tick, with Step and Broadcast inside it. After the metrics, Tracy plot, players, draws the number of players as a graph under the timeline. So we can see a slow tick next to how many players there were. The size gets a static cast to a sixty-four-bit integer, as Tracy plot comes in versions for integers and for floating point. And a size t would be ambiguous between those two versions. Then frame mark tells Tracy that a frame ends here, so it shows our ticks as frames, and we can hold each one up against its fifty milliseconds. Broadcast gets zone scoped too, and the serialising gets a zone of its own, which takes a block around the call to frame. So we declare bytes on its own line first, before the block. Inside it, zone scoped N, serialize, where N is for named, as a zone inside a function needs a name of its own. Then bytes gets what frame returns, and as it was declared outside the block, it lives on after it. The closing brace ends the zone as soon as frame returns, so serialize times frame, and stops there. In session dot c c, the header, and zone scoped at the top of Send, which is where each client's bytes are queued and handed to the socket. So we can see what sending costs next to serialising. In the Dockerfile, a new stage, profile build, starts from the build stage, where the project is configured and built already. It configures CMake again with TRACY ENABLE on, and builds the server's target. As CMake keeps its cache from the first build, this recompiles the server's own files and Tracy's client, and nothing else. The tests and the server's image keep coming from the build without Tracy, so what we ship doesn't change. The profile image now copies the server from the new stage, and exposes eight zero eight six, Tracy's port. And the override publishes that port, so that the profiler on our machine can connect to it. The profiler has to be the client's release, zero point fourteen point one, as Tracy's network protocol changes between releases. On a Mac, brew install tracy gives you that release of the profiler.

28:01 With the profile image running, and twelve hundred and fifty bots playing, Tracy's profiler connects to the server, on port eight zero eight six. Along the top, each bar is a tick, and its height is how long that tick took. I've set Tracy's target to twenty frames a second, our tick rate. So the ticks that took longer than fifty milliseconds show up in yellow, and the ones that took more than twice that in red, and nearly all of them are one or the other. Let's close the connection box, and pause, so that the timeline stays still. Each tick here is a frame of fifty-five to seventy milliseconds, and the red shading is the part of it past the budget. In each one, there's Tick, and under it, Broadcast, which takes almost all of the tick. Hovering over a Broadcast shows that this one took around sixty-five milliseconds. Zooming in with the wheel, the row under Broadcast is serialize, then Send, then serialize again, twelve hundred and fifty times over. The statistics window adds up the time in each zone, over all the ticks it has recorded. Serialize is two thirds of the time, and Send about a third, which is close to what perf told us, from the other side.

The fix

29:11 So the fix is to stop serialising the players for each client. Right now, that happens twelve hundred and fifty times each tick, with a copy each time. The players are identical for all of them, so we can serialise them once a tick, and all the sessions write those bytes, without a copy each. What differs from one client to the next is you, the client's own player id. So after the players, each client gets a tiny message of its own, a World with nothing but you set. On the wire, that's the size, the players' bytes, and the few bytes of you. Protobuf reads two messages back to back as one message, with the fields of both. That comes from how its encoding works: each field carries its number, and a parser reads fields until the bytes run out. So the clients read what they read before, and their code doesn't change. Another way would be to send your id once, when you join, which changes the protocol and the client. This way keeps both as they are, for two or three bytes a message.

30:12 We start with a test, for the protobuf behaviour the fix relies on. If protobuf didn't read two messages as one, we'd want to find out now, and not from a client that reads garbage. In protocol test, reads messages back to back as one. Players is a World with a single player, whose id is seven, and you is a World with nothing but you set, also to seven. Bytes is the one serialised, followed by the other, which is what the server is going to send. Received parses them, and parse from string has to succeed, so it's an assert. Then we expect you to be seven, and a single player, with id seven, so one World comes back, with the fields of both. Then framing, as the session is going to put the header in front of the players' bytes directly, without frame. So in framing dot h, k header size moves here from the source file, as the server needs it too, to count the bytes it sends. It's a constexpr, like the largest message size under it. And a new function, header, gives the four bytes that go in front of a message of a given size. And it's the part of frame that writes the size, on its own. In framing dot c c, the unnamed namespace with k header size goes, as it's in the header now. Header turns the size into a thirty-two-bit unsigned value first, as that's what goes on the wire, whatever size type the machine has. Then it returns a string of those four bytes, most significant first, with the shifts that frame's push backs used in episode three. A cast to char keeps the lowest byte of each shifted value, so each shift picks out one byte of the size. Frame serialises the body as before, and returns the header for its size, followed by the body. So frame and the session's new send both write the size through header. In framing test, a test for header, writes the size most significant byte first. Until now, no test looked at the header's bytes in order. The other framing tests write with frame and read with the frame reader, so if both had the order backwards, they'd still agree with each other. A client written by someone else wouldn't, and from now on, the session writes the header without frame. So we pass two hundred and fifty-eight, which is one times two hundred and fifty-six, plus two, and we expect zero, zero, one and two. The string is built with its length, four, as it starts with zero bytes, and a string from a plain literal would stop at the first of them. Now the session, which has to send a message that comes in two parts. In session dot h, send still takes a string, for a whole message, such as the login server's reply. A second send takes a message in two parts, for the broadcast: a shared pointer to a const string, for bytes that other sessions write too, and the client's own bytes. Two functions with one name and different parameters are called overloads, and the compiler picks one by the arguments we pass. With a shared pointer, the players' bytes live until the last session has written them, however slow its client is. And the string is const, as no session may change bytes that the others are about to send. In the private part, a struct, Outgoing, is a message waiting to go out. Head is bytes of its own, shared is the bytes it shares with other sessions, which can be empty, and tail is more of its own. A private send takes an Outgoing, and both public sends hand their message to it, so the queueing stays in one place. And the outbox, the queue of messages waiting to go out, holds Outgoings now, instead of strings. In session dot c c, we include array, for the buffers further down. The first send wraps its bytes into an Outgoing that's all head, with a null pointer for shared, and an empty tail. The second puts the header for the size of both parts into the head. The shared pointer goes in the middle, moved, so there's no extra owner to count, and the client's own bytes go into the tail. Then the private send, which takes over what send used to do, with zone scoped still at its top, so Tracy keeps calling it Send. It queues the message, and starts writing if no write is under way, like before. Write takes a const reference to the message at the front of the outbox, so the message isn't copied, and makes an array of three buffers. We don't write the array's type or its size, as the compiler works them out from the three values, which is called class template argument deduction. The buffers are the head, then the shared bytes, or an empty buffer if there aren't any, and the tail. They point into the message at the front of the outbox, which stays there until the write is done, so the bytes can't go away under it. Async write takes all three, and writes them in order, as one stream of bytes, which is called a gathered write. The kernel takes the bytes from the three places they're in, so we don't copy the shared bytes into a new string for each client. Last comes the broadcast, in server dot c c, where the message with the players is built as before, with you left unset. Then players, a shared pointer to a const string, for the serialised players. Over it goes the reason: the players are identical for everyone, so we serialise them once, and all the sessions share the bytes until each has written them. Then a block with the serialize zone, which now runs once a tick. In it, make shared builds the string from what serialize as string returns, in one allocation with its count of owners. Then for each session, you is a World with nothing but the client's id, and own is its bytes, a handful of them. The bytes sent add up the header, the players and own, so the metric still counts what goes out on the wire. And session send gets the shared pointer, which adds an owner, and the client's own bytes, moved. So the serialising, these few lines, runs once a tick now, however many players there are. And what's left in the loop for each client is a message of two or three bytes.

36:10 Once it's built, we run the protocol's tests, and all seven of them pass. And the two new ones are among them: the header's four bytes in order, and two messages read back to back as one.

36:22 Tracy again, on the new server, with twelve hundred and fifty bots. The bars along the top are short now, and none of them is red. Let's close the box, and pause, so that the timeline stays still again. Each tick takes around seventeen milliseconds now, and for the rest of its fifty, the server waits for the next one. Zooming in, serialize is a single sliver at the start of Broadcast, and after it, it's Send after Send. And in the statistics, Send is now nearly all of the time.

Measuring again

36:53 Now we run the benchmark again, on a stack built from the new code. Load dot s h runs ten steps of two hundred and fifty bots, into after dot json. This time, the server manages its twenty ticks a second at each step, all the way to twenty-five hundred players.

37:15 Let's put before and after together, starting with the tick's p50, on the left. With a thousand players, it was thirty-five milliseconds before, and it's eight point four now. With twelve hundred and fifty, it was fifty-six, past the budget, and it's fourteen point one now. On the right, the ticks per second show that before, the server fell behind after a thousand players. Now it keeps up all the way to twenty-five hundred players, the most we tried, on this machine. At twenty-five hundred, the p99 is around thirty-nine milliseconds, so the slowest ticks use seventy-eight percent of the budget already.

37:51 And a profile of the new server, with the profile image and twelve hundred and fifty bots again, named after. This time, perf took around nineteen hundred samples in ten seconds, a fifth of before. The server's thread sits idle for four fifths of the time, waiting for the next tick.

38:08 Broadcast is still most of the tick, and nearly all of it is the kernel's TCP send now, while serialising is too small to show up. Inside the send, copy from user is the kernel copying our bytes into each client's socket, about a tenth of the time. And tcp write xmit, more than half of the time, is the packets going out. On Docker's network, the bots' end of each connection is on this machine too. So the kernel does a lot of their side of the work while we send, along with Docker's tracking of each connection. Those are costs of running it all on one machine, and on a real network, the receiving side would be somebody else's computer.

38:48 So, as for what's left, the serialising happens once a tick, and it's out of the way. However, each client still gets all of the players, twenty times a second. So each tick sends N clients N players' worth of bytes, and that still grows with the square of the players, in the kernel now, not in our code. Games deal with that through interest management, which we touched on in episode four: each player gets the players near it. On our twelve by twelve board, everyone is near everyone, so it wouldn't help until the world grows. The other way is smaller updates, such as positions in fewer bytes, or a player sent when it has changed, and not otherwise. And whichever we try, we'd go about it like today, measuring before and after a single change.

Docs

39:37 Last, the README, where the bots' section covers the first bot's number, and BOTS and RAMP for the bots service. A new section covers benchmarking and profiling: load dot s h and what it measures, with a warning to compare runs on one machine, with nothing else busy. Then the commands for the profile image, with COMPOSE FILE and why it's needed, profile dot s h and where its flame graph goes, and the two capabilities perf needs. And Tracy, whose profiler has to be the release the server is built with, zero point fourteen point one.

Wrap-up

40:10 So, today we wrote a benchmark that steps the bots up, and reads the server's own metrics from Prometheus at each step. On my machine, the server fell behind past a thousand players. perf, in Docker, with frame pointers and two capabilities, showed us where its time went, as a flame graph. And Tracy showed us what perf found, tick by tick, from inside our code. Both pointed at the broadcast, which serialised the whole world for each client. Now it serialises the players once a tick, and the sessions share the bytes, with protobuf reading the players and each client's id as one message. And the server keeps up with twice the players, on this machine, at twenty ticks a second. What's left is the kernel sending the bytes, which still grow with the square of the players.

Playing it

41:50 Let me know in the comments what you'd like to see next, and what you'd like to measure. And if you want to follow along with the series, subscribe to the channel. I hope you find this useful, and thanks for watching.