Logfile Analysis

Pointers on what's in the logfiles and how to work with them.

Overview

• Unless you substantially change the core of the sample broker, the broker log will contain all the xml messages sent or received by the broker. Note that outgoing messages from the broker are prepended with a "key" that prevents cross-broker spoofing in a tournament situation.

• As the simulation server runs, it generates two log files: a "trace" log (usually named log/powertac-sim-n.trace) and a "state" log (usually named log/powertac-sim-n.state). Both the trace log and state log from the simulator have the current process time in msec in the first field; this can be used to cross-correlate events from the trace log with new and updated domain instances in the state log.

Here's a sample of output from the trace log:

3594487 INFO  auctioneer.AuctionService: Activate
3594487 INFO  auctioneer.AuctionService: Timeslot 953: Clearing 1 asks and 2 bids
3594487 INFO  auctioneer.AuctionService: market clears at 90.0 with null bid price
3596542 INFO  auctioneer.AuctionService: ClearedTrade 74.10475889226022@90.0

and here's a sample of output from the state log:

3594487:org.powertac.common.MarketTransaction::321469::new::378::2009-11-18T17:00:00.000Z::308191::-74.10475889226022::90.0
3594487:org.powertac.common.MarketTransaction::321470::new::601::2009-11-18T17:00:00.000Z::308191::74.10475889226022::-90.0
3594487:org.powertac.common.Orderbook::321471::new::308191::90.0::2009-11-18T17:00:00.000Z
3594488:org.powertac.common.OrderbookOrder::321472::new::113.51840915098781::-4.404571943348531
3594488:org.powertac.common.Orderbook::321471::addBid::321472
3594488:org.powertac.common.OrderbookOrder::321473::new::-17087.49925354737::75.0
3594488:org.powertac.common.Orderbook::321471::addAsk::321473

As an aside, note the 2-second "gap" in the trace between 3594487 and 3596542. You should seldom see this behavior; these logs came from a session where we were tracking down a performance problem.

• the general format of the state log is described in more detail in this wiki and in the developer's wiki on github.

• Entries correspond to method calls. For all methods other than new(), the record contains the class name, the id of the target object, the name of the method, and the arguments to the method. The methods and their arguments can be found in the javadocs.

• In older log files, the detailed format of "new" entries in the state log depends on whether the object was created by calling a constructor, or by the readResolve mechanism used by XStream when marshaling an incoming message. For non-trivial types, the @Domain annotation is decorated with field names that match the types and sequence of fields. To correctly parse the older logs, you have to know whether the instance is generated in the simulator or by an external broker. The simplest clue is the id values - each broker has a prefix on its id values that is intended to keep them unique. Since Release 0.6.3 in December 2012, state logs use '-rr' instead of 'new' for readResolve entries.

• For the readResolve case, the state log fields are specified in the @Domain annotation on the class.

Tools

In the powertac-tools repo on github is a set of tools for pulling apart and analyzing log files and collections of logs.

• In logtool-examples are a number of Java classes that extract information from state log files (and a few also pull data from the accompanying trace logs). Instructions for building and running these are in logtool-examples/README.md. Most of them produce csv files. They all share a common structure, and once you understand that structure new ones are fairly easy to write.
• In python-scripts are tools for plotting, and for iterating the tools in logtool-examples over collections of games. The TournamentLogtoolProcessor.py script iterates over games listed in a csv file produced by the tournament scheduler. You can see an example of how it's used in BrokerAccounting.py.