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 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 javadocs include a description of the state log fields.