12. Events¶
iFun Engine is an event-driven framework. In other words, most code written with iFun Engine runs as events.
This chapter will explain how events work.
12.1. What is an event?¶
Broadly speaking, events are divided into engine events and user-defined events. Engine events are executed with handlers registered to run when internal engine events such as network or timer events take place. (Please refer to
Receiving Packets from a Session and Timer, respectively.)
Event::Invoke() is used to generate user events.
Events are handled by one or more event threads. Each event has tags added, as explained in Event order and event tags, and events with the same tag are handled sequentially while events with different tags are handled in parallel.
Changes to ORM objects occurring in a single event are handled as a batch transaction when the event function ends. (For more details, see the section in ORM Part 1: Overview and Transaction.)
12.2. Event Types¶
12.2.1. Engine events¶
Events generated by the engine pertain to the inventory, network message handler, timer handler, and callbacks for engine functions (Leaderboard, Authenticator, Biller, HttpClient, Redis, etc.)
When a handler or callback is registered for an event, the engine runs that function when needed.
Important
Rpc::Call() and callbacks when using Mariadb::ExecuteQuery() are excluded from events.
12.2.2. 사용자 정의 이벤트¶
Event::Invoke() can be used to generate events whenever needed. The handler sent by these functions is invoked by the event thread, just as with engine events. User-defined events are used for convenience during development or to improve performance.
Function object passed to Event::Invoke() will be treated as an event.
#include <funapi.h>
void event_function_a() {
LOG(INFO) << "event_function_a";
...
}
void event_function_b(int param1, string param2) {
LOG(INFO) << "event_function_b";
...
}
void some_function() {
...
// Example 1
Event::Invoke(&event_function_a);
...
// Example 2
// Please refer to boost::bind()
Event::Invoke(bind(&event_function_b, 1234, "hello?"));
...
// Example 3
// Lambda is allowed if you use C++ 1x.
auto event_function_c = []() {
LOG(INFO) << "event_function_c";
...;
};
Event::Invoke(event_function_c);
// Example 4
// Another lambda form.
Event::Invoke([]() {
LOG(INFO) << "event_function_d";
...;
});
}
Function object passed to Event::Invoke() will be treated as an event.
using funapi;
...
public void EventFunctionA()
{
Log.Info ("EventFunctionA");
}
public void EventFunctionB(int param1, string param2)
{
Log.Info ("EventFunctionB");
}
public void SomeFunction()
{
...
// Example 1
Event.Invoke (EventFunctionA);
// Example 2
// This example uses a lambda function.
Event.Invoke (() => {
int integer_value = 1;
string hello_string = "hello";
EventFunctionB(integer_value, hello_string);
});
// Example 3
// You can use delegate to use a lambda function.
Event.EventFunction lambda_function = () => {
Log.Info ("lambda function");
};
Event.Invoke (lambda_function);
}
12.3. Event order and event tags¶
By default, events are queued in the order they are generated. However, as there is generally more than one thread managing events, events are run in parallel. (For more on changing the number of event threads, see Event parameters.)
This can cause problems in environments in which the event handling order must be guaranteed. For this reason, iFun Engine supports a feature to bundle events where the processing order must be guaranteed with the same tag. When event tags are assigned, events with the same tag are in a guaranteed sequence, and events with different tags are run in parallel.
For example, independent tags for each session are automatically used for network events so the message handling sequence is guaranteed in a session, but run in parallel with other sessions.
In the code below, tag1 is assigned to event 1 and event 2, tag2 is assigned to event 3 and event 4.
event 1always runs beforeevent 2.event 3always runs beforeevent 4.However,
event 1 + event 2andevent 3 + event 4are processed in parallel, so there is no way of knowing which will be run first.
#include <funapi.h>
EventTag my_tag_1 = RandomGenerator::GenerateUuid();
EventTag my_tag_2 = RandomGenerator::GenerateUuid();
function<void(string)> my_event = [](string event_msg) {
LOG(INFO) << event_msg;
};
// tag 1
Event::Invoke(bind(my_event, "event1"), my_tag_1); // event 1
Event::Invoke(bind(my_event, "event2"), my_tag_1); // event 2
// tag 2
Event::Invoke(bind(my_event, "event3"), my_tag_2); // event 3
Event::Invoke(bind(my_event, "event4"), my_tag_2); // event 4
using funapi;
public void MyEvent(string event_msg)
{
Log.Info ("my_event called. " + event_msg);
};
public void Example()
{
System.Guid my_tag_1 = RandomGenerator.GenerateUuid();
System.Guid my_tag_2 = RandomGenerator.GenerateUuid();
// tag 1
Event.Invoke (() => { MyEvent ("event1"); }, my_tag_1);
Event.Invoke (() => { MyEvent ("event2"); }, my_tag_1);
// tag 2
Event.Invoke (() => { MyEvent ("event3"); }, my_tag_2);
Event.Invoke (() => { MyEvent ("event4"); }, my_tag_2);
}
12.3.1. Engine event tags¶
Network: Each network session is run with session id as an event tag. Thus, each session is independent, and sequence within one session is guaranteed.
Timer: All run with one event tag. This guarantees that timer handlers are invoked in chronological order.
Misc.: Other engine handlers or callbacks are run in parallel with randomly generated tags.
12.3.2. Rules for automatic assigning of event tags¶
If an event tag parameter is omitted when an event is run using Event::Invoke(), the engine allocates a tag. The following rules are applied depending on where the event was generated.
12.3.2.1. When new events are generated during event handling¶
If a new event is created during event handling, it inherits the tag from a running event. For example, if a new event is created within the network message handler, it inherits the network message handler tag. Assuming the session ID was used as an event tag in this network’s case, the session ID becomes the new event’s tag.
Important
When a new event is generated in the `Timer` and `ApiService` handler
If a new event is created while the preceding event is being handled, it inherits the tag of the event in progress. Exceptions are the Timer and Server management part 1: Adding RESTful APIs, which are assigned a random event tag.
Since the events of Timer and Server management part 1: Adding RESTful APIs are assigned the same event tag, if a newly created event inherits the tag, it will be serialized with timer events even if it has nothing to do with them, thus creating a problem.
If the newly created event in the timer handler is a new timer, a fixed tag is assigned to the timer.
The 4 event functions in the following code sample all inherit network event tags, session id for the session which received the message. They are thus guaranteed to be handled in this order: OnMessage -> MessageProcess1 -> MessageProcess2 -> MessageProcess3.
// OnMessage() below is a functor registered by
// HandlerRegistry::Register(..., OnMessage) in the server's Install() method.
void OnMessage(const Ptr<Session> &session, const Json &message) {
...
// Case of omitting an event tag argument.
Event::Invoke(bind(MessageProcess1, session, message));
Event::Invoke(bind(MessageProcess2, session, message));
}
void MessageProcess1(const Ptr<Session> &session, const Json &message) {
// This event is tagged by session->id().
...
// Case of omitting an event tag argument.
Event::Invoke(bind(MessageProcess3, session, message));
}
void MessageProcess2(const Ptr<Session> &session, const Json &message) {
// This event is tagged by session->id().
...
}
void MessageProcess3(const Ptr<Session> &session, const Json &message) {
// This event is tagged by session->id().
...
}
// OnMessage() below is a functor registered by
// HandlerRegistry.Register(..., OnMessage) in the server's Install() method.
public static void OnMessage(Session session, JObject message)
{
...
// Case of omitting an event tag argument.
Event.Invoke (() => {
MessageProcess1 (session, message);
});
Event.Invoke (() => {
MessageProcess2 (session, message);
});
}
public static void MessageProcess1(Session session, JObject message)
{
// This event is tagged by session->id().
...
// Case of omitting an event tag argument.
Event.Invoke (() => {
MessageProcess3 (session, message);
});
}
public static void MessageProcess2(Session session, JObject message)
{
// This event is tagged by session->id().
...
}
public static void MessageProcess3(Session session, JObject message)
{
// This event is tagged by session->id().
...
}
12.3.2.2. When new events are generated from outside the event handler¶
In this case, a randomly generated event tag is assigned. As explained previously, random event tags mean events can be processed in parallel.
Tip
Some examples of functions that are not events are the server’s Install and Start function,
Rpc::Call() and Mariadb::ExecuteQuery() callback as well as code run from threads intentionally generated by users.
The following example shows randomly generated event tags inherited because 100 events are created in non-event locations. Since each event has a random event tag, they are processed in parallel and the order is not guaranteed.
1 2 3 4 5 6 7 8 9 10 11 | // Start() below invoked after the server's Install(), for a purpose of initialization.
// It's not an event.
bool Start() {
for (size_t i = 0; i < 100; ++i) {
auto my_event = [i]() {
LOG(INFO) << i;
};
Event::Invoke(my_event);
}
}
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 | delegate void MyEvent(int idx);
...
bool Start()
{
MyEvent my_event = (int number) => {
Log.Info (number.ToString());
};
for (int i = 0; i < 100; ++i) {
int idx = i;
Event.Invoke (() => {
my_event(idx);
});
}
}
|
12.3.3. (Example) Serializing using event tags¶
Since the order of events with the same event tag is guaranteed, they can be serialized without a lock. This is how lock usage is minimized to increase server performance. For more details, please see Guideline on How to Build MO Game Server.
An example below updates a shared, global varaible. Since accessing a shared variable by multiple threads can cause a race condition, we use an event tag to serialize updates.
// Global variables.
int64_t the_counter = 0;
EventTag the_counter_tag;
// Initializes the global variables.
bool Start() {
// Randomly generates a event tag to be used when accessing the_counter.
the_counter_tag = RandomGenerator::GenerateUuid();
return true;
}
void UpdateCounter() {
// ++ is not atomic in the multi-threaded environment.
// So, the_counter can be smaller than expected if operations are not serialized.
++the_counter;
}
// Let's assume OnXXX() is called by other code..
void OnXXX(...) {
// Tag events with the_counter_tag.
Event::Invoke(UpdateCounter, the_counter_tag);
}
An example below updates a shared, global varaible. Since accessing a shared variable by multiple threads can cause a race condition, we use an event tag to serialize updates.
public class SomeClass
{
static int TheCounter = 0;
static System.Guid TheCounterTag;
bool Start()
{
// Randomly generates a event tag to be used when accessing the_counter.
SomeClass.TheCounterTag = RandomGenerator.GenerateUuid ();
return true;
}
void UpdateCounter()
{
// ++ is not atomic in the multi-threaded environment.
// So, TheCounter can be smaller than expected if operations are not serialized.
SomeClass.TheCounter++;
}
// Let's assume OnXXX() is called by other code..
void OnXXX()
{
// Tag events with the_counter_tag.
Event.Invoke (UpdateCounter, SomeClass.TheCounterTag);
}
}
12.4. Event profiling and debugging¶
iFun Engine provides convenient features to optimize and debug events.
Note
Please refer to CPU profiling for CPU performance analysis.
12.4.1. Assigning names to events for debugging¶
You can assign event names using the function below. When you assign an event name, a log is output together with the event name, which is convenient for debugging.
Tip
Network events can be omitted as the engine automatically assigns their names using message (packet) type.
SetEventName()
Event.SetEventName()
It is best to give names in the very first row of the function to be run as the event, as in the example below.
// User-defined event generated by Event::Invoke().
void my_event1() {
SetEventName("my_event1");
...
}
// User-defined event generated by Event::Invoke().
auto my_event2 = []() {
SetEventName("my_event2");
...
};
// Timer event
void OnTimer(const Timer::Id &, const WallClock::Value &) {
SetEventName("my timer event");
...
};
// Otherwise, you can leverage the compiler macro to automatically give a name.
void my_event3() {
SetEventName(__func__);
...
}
delegate void MyEvent();
// User-defined event generated by Event::Invoke().
void MyEvent1()
{
Event.SetEventName ("my_event1");
...
}
Event.EventFunction my_event2 = () => {
Event.SetEventName ("my_event2");
...
};
Event::Invoke 를 이용하여 함수를 이벤트로 실행할 때는 아래처럼 이름을 지어줄
수 있습니다.
Event::Invoke(my_event, "my_event1");
Event.Invoke (MyEvent1, "my_event1");
이름이 있는 이벤트 함수에서 Event::Invoke 함수를 이용하여 새 이벤트를 만들면
기본적으로 "{부모이벤트의이름}_#{생성순서}" 를 이름으로 갖습니다. 예를 들어
이름이 "my_event1" 인 이벤트 함수에서 Event::Invoke 를 3 번 호출했다면
3 번째 이벤트의 이름은 "my_event1_#3" 이 됩니다.
Important
Names must be assigned to all events in functions explained from now on in order to enable usage.
12.4.2. Detecting bottleneck events¶
If it takes longer than slow_event_log_threshold_in_ms in Event parameters to handle events, a log is output with the following path. When this log is output, you should check the implementation of the relevant event handler.
Slow event: event_name={event_name}, event_id={event_id}, execution_time={handling_time}
12.4.3. Suspending serious bottleneck events¶
To prevent some events from slowing down the entire system, a log is output with the following path if the event takes longer than event_timeout_in_ms in Event parameters to handle, and handling of that event as well as all other events with the same tag is stopped.
Event timeout: event_name={event_name}, event_id={event_id}, event_tag={event_tag}
If the event is forcibly suspended, the following notification may be received through the handler.
// The server's Install method().
static bool Install(const ArgumentMap &arguments) {
...
Event::RegisterTimeoutHandler(OnEventTimeout);
return true;
}
void OnEventTimeout(const string &event_name, const EventId &event_id,
const EventTag &event_tag,
const Ptr<Session> &associated_session) {
// If the event in question is derived from a session message handler,
// the impacted session is passed as associated_session.
if (associated_session) {
// MANIFEST/SessionService 항목의 close_session_when_event_timeout 값이
// true 이면 이벤트 타임아웃 핸들러 이후에 세션 닫힘 핸들러가 실행되는데,
// 아래 로그아웃 처리를 세션 닫힘 핸들러에서 처리하는 것이 더 좋습니다.
Event::Invoke(bind(OnLogout, associated_session));
}
}
void OnLogout(const Ptr<Session> &session) {
...
}
C# version will be available soon.
Important
The timeout handler is dealt with in a separate thread from the event thread to prevent the effects of bottleneck events. However, if it must be dealt with in the event thread, Event::Invoke must be used.
Tip
If this event has to do with a session, all messages coming from that session are affected by the rules for adding event tags. This means that session will no longer work, so forced logout must be dealt with in the event timeout handler. (If the value of close_session_when_event_timeout of MANIFEST/SessionService is true, exceptionally, the session close handler will be executed. thus, forced logout can also be there.)
12.4.4. Detecting hung event threads¶
If enable_event_thread_checker in Event parameters is set to true, the following log is output at 1-minute intervals when the event thread is stopped for 30 seconds or more for any reason. We recommend checking for deadlocks, infinite loops, or unusually lengthy processes in the relevant event handler’s implementation at such times.
event thread hang: event_thread_index=..., event_name={event_name}, event_id={event_id}, event_tag={event_tag}, elapsed_time_in_sec=...
12.4.5. Event profiling: summary¶
Important
This function works when enable_event_profiler in Event parameters is true and ApiService is enabled.
iFun Engine provides processing time statistics for the entire event system. Events stopped due to timeout are excluded from this.
To view these statistics, invoke the following API.
-
GEThttp://{ip}:{api-service-port}/v1/counters/funapi/event/profiling/summary/¶
When this API is invoked, JSON is returned, and all_time within JSON properties means the cumulative value. last1min means statistics for the past 1 minute. The following items are included in both results.
Execution time:
count: Total number of events executedexecution_time_mean_in_sec: Average execution timeexecution_time_stdev_in_sec: Standard deviation in execution timeexecution_time_max_in_sec: Maximum execution time
I/O wait time:
io_wait_time_mean_in_sec: Average wait time (due to DB, Zookeeper, lock contention, etc.)io_wait_time_stdev_in_sec: Standard deviation in wait timeio_wait_time_max_in_sec: Maximum wait time
Event queue:
queue_time_mean_in_sec: Average time held in event queuequeue_time_stdev_in_sec: Standard deviation for time held in event queuequeue_time_max_in_sec: Maximum time held in event queue
Note
execution_time = queue_time + io_wait_time + Event handler processing time
{
"all_time": {
"count": 8814,
"execution_time_mean_in_sec": 0.007857,
"execution_time_stdev_in_sec": 0.023191,
"execution_time_max_in_sec": 0.309402,
"io_wait_time_mean_in_sec": 0.005639,
"io_wait_time_stdev_in_sec": 0.017964,
"io_wait_time_max_in_sec": 0.247697,
"queue_time_mean_in_sec": 0.000953,
"queue_time_stdev_in_sec": 0.005887,
"queue_time_max_in_sec": 0.106234
},
"last1min": {
"count": 5882,
"execution_time_mean_in_sec": 0.009843,
"execution_time_stdev_in_sec": 0.028,
"execution_time_max_in_sec": 0.309402,
"io_wait_time_mean_in_sec": 0.007114,
"io_wait_time_stdev_in_sec": 0.021708,
"io_wait_time_max_in_sec": 0.247697,
"queue_time_mean_in_sec": 0.001377,
"queue_time_stdev_in_sec": 0.007167,
"queue_time_max_in_sec": 0.106234
}
}
12.4.6. Event profiling: details¶
Important
This function works when enable_event_profiler in Event parameters is true and ApiService is enabled.
iFun Engine also provides statistics for ORM and processing time for each event.
To see statistics, go to the following URL:
-
GEThttp://{ip}:{api-service-port}/v1/counters/funapi/event/profiling/all¶
JSON is returned as the results and events are classified by name in the JSON and include statistics. Properties called all_time and last1min are included for each event name and respectively indicate all cumulative statistics, and statistics for the last 1 minute. The meanings of each statistic are as follows:
Execution time:
execution_count: Execution frequencyrollback_count_mean: Average rollback frequencyrollback_count_max: Maximum rollback frequencyexecution_time_mean_in_sec: Average execution timeexecution_time_stdev_in_sec: Standard deviation in execution timeexecution_time_max_in_sec: Maximum execution timetimeout_count: How many timeouts were handled
I/O wait time:
io_wait_time_mean_in_sec: Average wait time (due to DB, Zookeeper, lock contention, etc.)io_wait_time_stdev_in_sec: Standard deviation in wait timeio_wait_time_max_in_sec: Maximum wait time
Event queue:
queue_time_mean_in_sec: Average time held in event queuequeue_time_stdev_in_sec: Standard deviation for time held in event queuequeue_time_max_in_sec: Maximum time held in event queue
ORM:
object_create_count_mean: Average number of objects generatedobject_count_mean: Number of fetched objects (nonexistent fetched objects excluded)object_cache_hit_rate_mean: Rate of objects fetched from the in-memory cache without IOHigher values of this are better. This value includes objects that were fetched but don’t exist, and thus may be a negative number. If this value is low, please refer to the explanation in DB caching. Objects need to stay in the cache for longer.
object_nolock_rate_mean: Rate of objects fetched bykReadCopyNoLock(nonexistent fetched objects excluded)object_lease_rate_mean: Rate of objects leased from other servers through RPC rather than the DB or cacheLower values are better for this. (Nonexistent fetched objects excluded)
Note
execution_time = queue_time + io_wait_time + Event handler processing time
예)
{
"OnGameServerLogin": {
"all_time": {
"execution_count": 1926,
"rollback_count_mean": 1.0,
"rollback_count_max": 4,
"execution_time_mean_in_sec": 0.025312,
"execution_time_stdev_in_sec": 0.07749,
"execution_time_max_in_sec": 0.404292,
"io_wait_time_mean_in_sec": 0.018308,
"io_wait_time_stdev_in_sec": 0.057154,
"io_wait_time_max_in_sec": 0.290297,
"queue_time_mean_in_sec": 0.005993,
"queue_time_stdev_in_sec": 0.022505,
"queue_time_max_in_sec": 0.156082,
"object_count_mean": 104.0,
"object_cache_hit_rate_mean": 0.824,
"object_nolock_rate_mean": 0.0,
"object_lease_rate_mean": 0.175,
"object_create_count_mean": 0.0,
"timeout_count": 0
},
"last1min": {
"execution_count": 56,
"rollback_count_mean": 1.0,
"rollback_count_max": 2,
"execution_time_mean_in_sec": 0.001889,
"execution_time_stdev_in_sec": 0.000936,
"execution_time_max_in_sec": 0.007396,
"io_wait_time_mean_in_sec": 0.000792,
"io_wait_time_stdev_in_sec": 0.00048,
"io_wait_time_max_in_sec": 0.004086,
"queue_time_mean_in_sec": 0.000052,
"queue_time_stdev_in_sec": 0.00002,
"queue_time_max_in_sec": 0.000108,
"object_count_mean": 97.0,
"object_cache_hit_rate_mean": 0.965,
"object_nolock_rate_mean": 0.0,
"object_lease_rate_mean": 0.035,
"object_create_count_mean": 0.0
}
},
"OnListFriend": {
"all_time": {
"execution_count": 12136,
"rollback_count_mean": 2.0,
"rollback_count_max": 3,
"execution_time_mean_in_sec": 0.000958,
"execution_time_stdev_in_sec": 0.004036,
"execution_time_max_in_sec": 0.321312,
"io_wait_time_mean_in_sec": 0.0003,
"io_wait_time_stdev_in_sec": 0.003198,
"io_wait_time_max_in_sec": 0.319272,
"queue_time_mean_in_sec": 0.000143,
"queue_time_stdev_in_sec": 0.002402,
"queue_time_max_in_sec": 0.086365,
"object_count_mean": 11.9,
"object_cache_hit_rate_mean": 0.899,
"object_nolock_rate_mean": 0.837,
"object_lease_rate_mean": 0.1,
"object_create_count_mean": 0.0,
"timeout_count": 0
},
"last1min": {
"execution_count": 408,
"rollback_count_mean": 2.0,
"rollback_count_max": 3,
"execution_time_mean_in_sec": 0.00053,
"execution_time_stdev_in_sec": 0.00019,
"execution_time_max_in_sec": 0.002214,
"io_wait_time_mean_in_sec": 0.0,
"io_wait_time_stdev_in_sec": 0.0,
"io_wait_time_max_in_sec": 0.0,
"queue_time_mean_in_sec": 0.000043,
"queue_time_stdev_in_sec": 0.000082,
"queue_time_max_in_sec": 0.001559,
"object_count_mean": 11.9,
"object_cache_hit_rate_mean": 1.0,
"object_nolock_rate_mean": 0.838,
"object_lease_rate_mean": 0.0,
"object_create_count_mean": 0.0
}
},
...
}
12.5. Event parameters¶
Please read the following and refer to Configuration file (MANIFEST.json) and Configuration file (MANIFEST.json) details to learn about EventDispatcher.
event_threads_size: Number of main event threads. (type=uint64, default=4)
enable_event_profiler: Whether event profiler is enabled (type=bool, default=true)
Parameters with configurations that are almost never changed manually
slow_event_log_threshold_in_ms: Sets whether to maintain a log of somewhat slow events (type=uint64, default=300)
event_timeout_in_ms: Milliseconds until events timeout (type=uint64, default=30000)
enable_inheriting_event_tag: Whether to inherit event tags for invoked events if separate event tags are not assigned when invoking
Event::Invoke(). (type=bool, default=true)enable_random_event_tag: Whether to randomly generate and add event tags when
Event::Invoke()is invoked with no event tag andenable_inherit_event_tagis not activated. If false, null event tag added (type=bool, default=true)enable_event_thread_checker: Check once per second whether there has been blocking during event thread processing if true (type=bool, default=true)
enable_outstanding_event_profiler: Whether to profile currently running events (type=bool, default=true)