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

10.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.)

10.2. Event Types

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

10.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);
}

10.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 1 always runs before event 2.
  • event 3 always runs before event 4.
  • However, event 1 + event 2 and event 3 + event 4 are 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);
}

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

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

10.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 within the timer handler

If a new event is created while the preceding event is being handled, it inherits the tag of the event in progress. An exception is the Timer, which is assigned a random event tag.

Since Timer events 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
// HandlerRegstiry::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
// HandlerRegstiry.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().
  ...
}

10.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);
    });
  }
}

10.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);
  }
}

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

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

DebugSetEventName()
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() {
  DebugSetEventName("my_event1");
  ...
}

// User-defined event generated by Event::Invoke().
auto my_event2 = []() {
  DebugSetEventName("my_event2");
  ...
};

// Timer event
void OnTimer(const Timer::Id &, const WallClock::Value &) {
  DebugSetEventName("my timer event");
  ...
};

// Otherwise, you can leverage the compiler macro to automatically give a name.
void my_event3() {
  DebugSetEventName(__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");
  ...
};

Important

Names must be assigned to all events in functions explained from now on in order to enable usage.

10.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}

10.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) {
    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.

10.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=...

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

GET http://{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 executed
  • execution_time_mean_in_sec: Average execution time
  • execution_time_stdev_in_sec: Standard deviation in execution time
  • execution_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 time
  • io_wait_time_max_in_sec: Maximum wait time

Event queue:

  • queue_time_mean_in_sec: Average time held in event queue
  • queue_time_stdev_in_sec: Standard deviation for time held in event queue
  • queue_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
    }
}

10.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:

GET http://{ip}:{api-service-port}/v1/counters/funapi/event_profiling

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 frequency
  • rollback_count_mean: Average rollback frequency
  • rollback_count_max: Maximum rollback frequency
  • execution_time_mean_in_sec: Average execution time
  • execution_time_stdev_in_sec: Standard deviation in execution time
  • execution_time_max_in_sec: Maximum execution time
  • timeout_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 time
  • io_wait_time_max_in_sec: Maximum wait time

Event queue:

  • queue_time_mean_in_sec: Average time held in event queue
  • queue_time_stdev_in_sec: Standard deviation for time held in event queue
  • queue_time_max_in_sec: Maximum time held in event queue

ORM:

  • object_create_count_mean: Average number of objects generated

  • object_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 IO

    Higher 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 by kReadCopyNoLock (nonexistent fetched objects excluded)

  • object_lease_rate_mean: Rate of objects leased from other servers through RPC rather than the DB or cache

    Lower 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
        }
    },
    ...
}

10.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 and enable_inherit_event_tag is 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)