Proposal for logging infrastructure in Entitas

[mzaks]

Motivation:

There are two main reasons why one would consider introducing logging in a game.

1. Finding and fixing bugs
2. Gathering data for analytic purposes

Logging for Bug finding and fixing

It is fairly easy to unit test a system and therefore write robust code which transforms state in a expected manner. This however doesn't mean that one will not run into bugs. There are always a possibility for a behaviour which we do not expect. The unknown unknowns. For this type of situations it is crucial to have a logging infrastructure which can provide us with context and historical development of the state which lead to the bug. It helps us to understand and reproduce unexpected behaviours.

Gathering User Data

There are multiple reasons for gathering user data:

• Understanding how many people play your game and how often
• Understanding which parts of the game logic are executed
• Analyse User input

This data than can be used for refining game design decisions, UI decisions and even for a creation of interactive agents and NPCs.

Hoover this kind of logic is very game specific and can already be achieved with smart use of reactive systems.

Therefore this proposal will concentrate on the Logging for Bug finding and fixing starting from here.

General Context

In order to analyse the logging data every logging statement has to be provided with context.

Time and order related context

• Time (time stamp), it is the local time of device running the game. It reflects the time when the logging statement was created.
• Current tick. As Entitas systems are executed on every tick. This can be considered as an additional information to time. Giving us an FPS agnostic view on execution.
• Log Statement Index. This provides an additional information if we chose to select a time stamp format which is not fine granular enough. (e.g. multiple log statement have the same time stamp)

Time seems to be the important data point for this context. Two other data points can be seen as optional.

Identification context

• GameId. This can be a static id for the game but it could also contain the game version and device information, because a game compiled for a different platform is technically not the same game.
• UserId. Can be left blank or set to placeholder value if you want to protect the privacy of your users. However it can be helpful for contacting a user who happened to get all this bugs and crashes.
• SessionId. If you have a logical concept of a game session.

Entitas specific events

I see two types of events which can help developers in finding and fixing Bugs

1. State Events:
   • Entity Created
   • Entity Destroyed
   • Component Added
   • Component Removed
   • Component Replaced
   • Pool Cleared
2. Logical events
   • Initialise System Executed
   • System Executed
   • Reactive SubSystem Executed
   • Event Listener executed (On Entity or on Group)
   • System crashed

This events also need context which is Entitas specific:

Entitas state context

• Pool Type. Reflects pool the pool which manages the entities which were involved in state events and event listener / reactive sub system execution
• Pool instance ID. We could potentially have multiple instances of the same pool type. In this case logging the instance id would be very helpful.
• Entity Creation Index. Gives us a possibility to aggregate all changes happening to an entity during it's life cycle.
• Entity instance ID. As an entity is pooled and reincarnated after destruction. This gives us a possibility for spotting bugs happening because of bad memory management. (Usage of Retain Release methods)

For component related events it would be nice to see the data the component was storing. Something like:

• PositionComponent x:45, y:13 was added
• PositionComponent x:45, y:13 was replaced with x:45, y:12
• Position component x:45, y:12 was removed

This would be hard to achieve automatically because a component can store any kind of data. Therefore I suggest to introduce a ILoggableInterface:

interface ILoggable {
   public string LogString {get;}
}

Which when implemented by a component class will lead to a more verbose log statement.

Examples of Log Statements:

2015-12-26T09:56:21Z game1 user1 session1 CorePool 34526 45673 1 e_created
2015-12-26T09:56:21Z game1 user1 session1 CorePool 34526 45673 1 c_added PositionComponent(5,4)
2015-12-26T09:56:21Z game1 user1 session1 CorePool 34526 45673 1 c_replaced PositionComponent(5,4) PositionComponent(5,5)
2015-12-26T09:56:21Z game1 user1 session1 CorePool 34526 45673 1 e_destroyed

Which can be decode as following

Time | GameId | UserId | SessionID | PoolType | PoolInstanceID | EntityInstanceID | EntityCreationIndex | EventName | ComponentRelatedData

Now by searching for game1 user1 session1 CorePool 34526 45673 1 we can find out the whole history of entity with creation index 1. By excluding the creation index game1 user1 session1 CorePool 34526 45673 we can see how and when this entity instance was reused during the whole session1.

Logging BackEnd infrastructure

Logging all the events that I have described in Entitas specific events means that every instance of the game will generate a massive amount of data. This is why I would suggest using such high level logging only during development and maybe internal beta releases. However even for this controlled scenarios we would need to have a Log receiving part which can handle so much data.

Without trying it out my self, I would suggest to use Papertrail and see how much load it can handle. Papertrail provides a nice infrastructure for storing and querying Log statements.