State logging - Pyosch/powertac-server GitHub Wiki
A critical requirement of the Power TAC server is that its state is recorded as it runs, to enable ex post analysis of various sorts. The original design of the server relies on the relational database to record server state, and the audit-logging plugin is used to record changes to mutable domain objects. Some server state is not recorded in domain objects, due to mapping difficulties, although much of that is derived data, such as the map in TariffRateService used to map clock time to rates, or the expiration map in TariffSubscriptionService. These "services" exist only to keep data around without needing to map it into the database; the server would arguably be simpler and easier to understand if this data were not kept aside in this way.
What needs to be logged?
So what should the recorded data look like? The database is actually not the ideal approach to data recording; it can contain current state at any time, but it's not the ideal method to recording events. If we record events rather than state, we should be able to reconstruct state at any time in a completed simulation. In the current server, there are three kinds of events:
- passage of time and the processing phases within each timeslot.
- incoming messages from brokers
- method calls, some of which change server state and some of which result in outgoing messages to brokers.
For completeness, we could add outgoing messages to brokers.
Since passage of time is also represented as method calls, and since all incoming and outgoing messages either produce or arise from method calls, it seems enough to just record selected method calls, with their arguments.
Format and naming of log files
The SCM server uses a binary format for its .slg files, but it's not serialized objects; instead it's events (method calls in many cases) and their associated data. A typical SCM logfile is 5-6 Mb. There has been some discussion between John and Prashant about the idea of merging the "trace" log and the "data" log, because trace information could be informative in understanding the data. The downside is that we are then potentially stuck with huge logfiles for each game, when all most researchers would need is the data.
It is important that log files for particular simulations be saved in a predictable location with predictable names. The Grails prototype uses the GUID from the Competition instance to name log and database dump files, but these are opaque tags that convey no information other than uniqueness. The SCM server stores a trace file and a state-log file with fixed names in a directory tree named for the host and competition, and competition names are simply numbers from a sequence kept in a simple on-disk database (along with agent registrations and a few other items). The Power TAC server could keep a sequence number in its file environment, or we could use the current time and hostname as a filename prefix.
Log entries will be formatted as a series of lines in a text file, each line formatted as
r:c:id:method:args
where r is a timestamp, c is the classname, method is the method name or "new" for a constructor call, and the args are colon-separated list of method arguments. The r value is generated by the logging infrastructure, so actual calls to the logger should generate messages of the form c:id:method:args
.
Annotation-based logging
There a relatively easy way to record certain method calls using AOP, by annotating selected classes and method calls, which are then "wrapped" with state-recording code. In this way, the only intrusion into server code is the annotations. For immutable types, the only annotation is on the class. For mutable types, annotations are also needed for state-changing method calls.
This is far simpler than the current method, which requires mapping cleverness and Hibernate session and transaction management, and the resulting difficulties with stale objects.
Process
- Develop the logging mechanism for constructors and for mutator methods.
- For all types that are referred to by other types (in Hiberenate these often show up as hasMany and belongsTo notation), we record object id rather than the object. Types that currently lack an explicit id field will need one, generated with
IdGenerator.createId()
. - Transition domain types from Hibernate/Groovy to Java/AOP logging, taking care to note which types are mutable and which are not. All terminal domain types (types for which actual instances are created) are annotated with
@Domain
. For mutable types, such asTariff
, all state-changing methods are annotated with@StateChange
. - Fold in externalized data like the tariff rate maps and subscription expiration maps as we convert the domain types.