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 namedhello
.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.