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.

[trumpets]

This would be awesome! What's the procedure on getting it in? I think I could help with it :)

[mzaks]

I am not sure yet :)

First just wanted to see how much interest there is for such a feature.

Let's meditate on it for a couple more days and than flesh out a plan.

[SvDvorak]

It sounds pretty interesting. Would it be possible to also see which system did the action?

[mzaks]

This is what I meant by Logical events. Combined with state events you would see something like

2015-12-26T09:56:21Z game1 user1 session1 InitSystem1 startExecution
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 InitSystem1 finishExecution
2015-12-26T09:56:21Z game1 user1 session1 SystemA startExecution
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 SystemA finishExecution

This might get chatty, but I think it worth a try. We can also adjust the log levels.

[SvDvorak]

Ah, ok, was looking at the examples. Then I'm all for it as I've been wishing for a way to see what systems use what components (in an easier way than searching around in the code).

[kartalguner]

Hello,
I was just wondering what the benefits of having a logging system integrated with Entitas are. If you just provide the events and contexts then we are free to choose our own logging framework. I have previously gotten nlog and log4net to work in my experiments.

[mzaks]

That was actually what I planned to do. Figuring out all the hooks and maybe providing a few classes, which will make it easy to use those.

[sschmid]

An integrated logging system could also make sense to use it as a foundation for visualization tools. A consistent logging output across projects could enable visualizing behaviour over time (e.g creating, changing and removing entities) which might help find some bugs.

[kicholen]

It might help finding some bugs but as @mzaks said it would be useful only in dev state. The log output would be insane. If done I would like to see it as kind of plugin that is not built in to framework. I agree with @SvDvorak checking for system-component dependencies is troublesome. Similar thing to Artemis-odb Component-Dependency-Matrix could resolve that issue quite nicely.

[sschmid]

@kicholen I agree. It should be very easy to deactivate the logging. In the future I can imagine that we can build all kinds of visualization tools etc based on this data

[JamesMcMahon]

One of the major problems with Unity development is there is no standard easy to extend logging interface. There have been attempts to replace the built in logger with something better but nothing that the entire community is using.

I think whatever solution you guys come up with needs to be easily extendable / modifiable to use 3rd party loggers.

[sschmid]

Yes, I don't plan to add a logging framework (I already did one, it's open source NLog) I plan to provide sth to plug into with any logging tool you like

[sschmid]

@mzaks what's the state with this?

[mzaks]

@sschmid Can add it to the new Plugins structure. Schools I clone develop or wait until the release and make PR on master?

[sschmid]

Might be safer to wait for the next release. PR on develop please (default branch) Does it require changes in entitas? or is it a Plugin?

[mzaks]

It is a Plugin. Sending the system will/did execute event schools be figured out though. But it will still be a Plugin

[sschmid]

It's been a while :) I saw a working prototype ages ago. Shall finalize this? Whats the state with the web UI?