Logfile Analysis

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

• Unless you substantially change the core of the sample broker, the broker log will contains all the xml messages sent or received by the broker. Note that outgoing messages from the broker are prepended with a "key" that is used to prevent 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 a 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 unmarshaling 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 parst 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.