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.


 * The detailed format of "new" entries in the state log depends on whether the object was created by calling a constructor, or by the read-resolve 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. Once the logtool is further along, new state logs will use '-rr' instead of 'new' for read-resolve entries, but for now you just 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.