Profiling the Server¶

It’s not a rare event to profile the game server to address bottlenecks. In this chapter, we will walk through how to figure out problematic event handlers consuming lots of CPU time. For illustration purposes, we will assume our timer handler is the case.

 // Timer handler
 void OnTick(const Timer::Id &timer_id, const WallClock::Value &clock) {
   std::vector<int> x;
   const int N = 1000000;
   x.reserve(N);
   for (int i = 0; i < N; ++i) {
     x.push_back(fun::RandomGenerator::GenerateNumber(i, N + 100));
   }
 }

 // Starts the timer (in the server initialization code)
 // ...
 Timer::ExpireRepeatedly(boost::posix_time::seconds(1), hello::OnTick);
 // ...

Identifying Slow Event¶

You can find additional description on event profiling in Event profiling and debugging.

In short, iFun Engine treats incoming network messages, timer callbacks, and functors invoked via fun::Event::Invoke as events. And any event taking longer than a specific time is treated as a slow event. You can see such slow events in a log file like this:

W0112 18:46:58.568523 23418 object_context.h:124] Slow event: event_name=TimerHandler, event_id=dd6d99c3-a155-4ac3-9f41-0fe48f361e4f, execution_time=4109

In the example above, we can see that our timer handler took long time (4109 ms). You might wonder what if there are many timer handlers. How to point out a specific one? Fortunately, you can tag an event with a name. Please see this example.

 // We will use this function declared in <funapi/system/event.h>
 // Only for illustration purposes. You don't have to explicitly declare it.
 void SetEventName(const std::string &name);

 // Timer handler
 void OnTick(const Timer::Id &timer_id, const WallClock::Value &clock) {
   SetEventName("Generate random numbers");
   std::vector<int> x;
   const int N = 1000000;
   x.reserve(N);
   for (int i = 0; i < N; ++i) {
     x.push_back(fun::RandomGenerator::GenerateNumber(i, N + 100));
   }
 }

Please note that we used SetEventName() in the example. The function gives an event a name and the name will be used when reporting a slow event. Please see a new log message below:

W0112 18:57:43.103525 26533 object_context.h:124] Slow event: event_name=Generate random numbers, event_id=7cb189ed-63aa-4aad-a5a8-7ecb10cbad41, execution_time=4165

Also, you can set up a threshold of slow events in slow_event_log_threshold_in_ms of the EventDispatcher component in MANIFEST.json.

CPU Usage Profiling¶

Note

This feature is experimental.

Let’s see how to identify an event consuming lots of CPU without rebuilding the game server.

Required tools¶

perf utility from Linux kernel is required.

# Ubuntu
$ sudo apt-get install linux-tools-generic

# CentOS
$ sudo yum install perf

And FlameGraph script is required.

$ sudo wget -O /usr/local/bin/flamegraph.pl \
    https://raw.githubusercontent.com/brendangregg/FlameGraph/master/flamegraph.pl
$ sudo wget -O /usr/local/bin/stackcollapse-perf.pl \
    https://raw.githubusercontent.com/brendangregg/FlameGraph/master/stackcollapse-perf.pl
$ sudo chmod a+x /usr/local/bin/flamegraph.pl /usr/local/bin/stackcollapse-perf.pl

Tip

\ indicates a continuing line. So, please enter as a single line.

Important

We assumed the generic kernel and hence used linux-tools-generic in the example. If you are using a kernel distribution other than the generic, please replace linux-tools-generic to reflect your kernel distribution. (i.e., linux-tools-<name>)

Commands to run¶

Please run the game server if it has not run, yet.
```
$ ./hello-local
```

(root privilege is required) Run funapi_profile In this example, we assume a project named hello.

Tip

If you are using the Flavors: Identifying servers according to their role, append a flavor name like funapi_profile <project name> <flavor name>

$ /usr/bin/funapi_profile hello
Profiling server for activity (for 60 seconds)
[sudo] password for user:
[ perf record: Woken up 7 times to write data ]
[ perf record: Captured and wrote 1.626 MB perf.23428.data (~71057 samples) ]
Generating flamegraph
[kernel.kallsyms] with build id d7fccc433a6b698638325b755df2772c15636d04 not found, continuing without symbols
Generated: perf.hello_server.default.23428.svg

Note

Root privilege is required in the middle of execution.

Please ignore messages starting with [ perf or [kernel.]

File name at the end is a result file. (perf.hello_server.default.23428.svg in this example.) Open the file using your browser.

Note

The number in the file name indicates a process number. So, each profiling result will have different number.

We can see that hello::OnTick() has a long row in the flame graph, which means it’s a bottleneck and subject to possible optimization.

Tip

You can click on each function name to zoom in.

Tip

Search button at the top right is useful to show specific functions.

In the hello project example above, we can give a search string pattern ^hello:: to show functions in the hello namespace.

Also, CPU usage of the target function and its descendants will be displayed at the bottom when hovering over the function.