Robust/CoreProf/Trace.java

   1 import java.io.*;
   2 import java.util.*;
   3
   4 public class Trace {
   5
   6   // everything defined here should match coreprof.h
   7   // definitions exactly
   8   public static final int CP_EVENT_MASK           = 3;
   9   public static final int CP_EVENT_BASESHIFT      = 8;
  10
  11   public static final int CP_EVENTTYPE_BEGIN      = 1;
  12   public static final int CP_EVENTTYPE_END        = 2;
  13   public static final int CP_EVENTTYPE_ONEOFF     = 3;
  14
  15   public static final int CP_EVENTID_MAIN             = 0x04;
  16   public static final int CP_EVENTID_RUNMALLOC        = 0x10;
  17   public static final int CP_EVENTID_RUNFREE          = 0x11;
  18   public static final int CP_EVENTID_POOLALLOC        = 0x14;
  19   public static final int CP_EVENTID_COUNT_POOLALLOC  = 0x15;
  20   public static final int CP_EVENTID_COUNT_POOLREUSE  = 0x16;
  21   public static final int CP_EVENTID_WORKSCHEDGRAB    = 0x20;
  22   public static final int CP_EVENTID_TASKDISPATCH     = 0x30;
  23   public static final int CP_EVENTID_PREPAREMEMQ      = 0x31;
  24   public static final int CP_EVENTID_TASKEXECUTE      = 0x40;
  25   public static final int CP_EVENTID_TASKRETIRE       = 0x50;
  26   public static final int CP_EVENTID_TASKSTALLVAR     = 0x60;
  27   public static final int CP_EVENTID_TASKSTALLMEM     = 0x61;
  28   public static final int CP_EVENTID_DEBUG_A          = 0x180;
  29   public static final int CP_EVENTID_DEBUG_B          = 0x181;
  30   public static final int CP_EVENTID_DEBUG_C          = 0x182;
  31   public static final int CP_EVENTID_DEBUG_D          = 0x183;
  32   public static final int CP_EVENTID_DEBUG_E          = 0x184;
  33   public static final int CP_EVENTID_DEBUG_F          = 0x185;
  34   public static final int CP_EVENTID_DEBUG_G          = 0x186;
  35   public static final int CP_EVENTID_DEBUG_H          = 0x187;
  36   public static final int CP_EVENTID_DEBUG_I          = 0x188;
  37   public static final int CP_EVENTID_DEBUG_J          = 0x189;
  38
  39
  40   void initNames() {
  41     eid2name = new Hashtable<Integer, String>();
  42     eid2name.put( CP_EVENTID_MAIN,              "MAIN         " );
  43     eid2name.put( CP_EVENTID_RUNMALLOC,         "RUNMALLOC    " );
  44     eid2name.put( CP_EVENTID_RUNFREE,           "RUNFREE      " );
  45     eid2name.put( CP_EVENTID_POOLALLOC,         "POOLALLOC    " );
  46     eid2name.put( CP_EVENTID_COUNT_POOLALLOC,   "POOLALLOC CNT" );
  47     eid2name.put( CP_EVENTID_COUNT_POOLREUSE,   "POOLREUSE CNT" );
  48     eid2name.put( CP_EVENTID_WORKSCHEDGRAB,     "WORKSCHEDGRAB" );
  49     eid2name.put( CP_EVENTID_TASKDISPATCH,      "TASKDISPATCH " );
  50     eid2name.put( CP_EVENTID_PREPAREMEMQ,       "PREPAREMEMQ  " );
  51     eid2name.put( CP_EVENTID_TASKEXECUTE,       "TASKEXECUTE  " );
  52     eid2name.put( CP_EVENTID_TASKRETIRE,        "TASKRETIRE   " );
  53     eid2name.put( CP_EVENTID_TASKSTALLVAR,      "TASKSTALLVAR " );
  54     eid2name.put( CP_EVENTID_TASKSTALLMEM,      "TASKSTALLMEM " );
  55     eid2name.put( CP_EVENTID_DEBUG_A,           "DEBUG A      " );
  56     eid2name.put( CP_EVENTID_DEBUG_B,           "DEBUG B      " );
  57     eid2name.put( CP_EVENTID_DEBUG_C,           "DEBUG C      " );
  58     eid2name.put( CP_EVENTID_DEBUG_D,           "DEBUG D      " );
  59     eid2name.put( CP_EVENTID_DEBUG_E,           "DEBUG E      " );
  60     eid2name.put( CP_EVENTID_DEBUG_F,           "DEBUG F      " );
  61     eid2name.put( CP_EVENTID_DEBUG_G,           "DEBUG G      " );
  62     eid2name.put( CP_EVENTID_DEBUG_H,           "DEBUG H      " );
  63     eid2name.put( CP_EVENTID_DEBUG_I,           "DEBUG I      " );
  64     eid2name.put( CP_EVENTID_DEBUG_J,           "DEBUG J      " );
  65   }
  66
  67   Hashtable<Integer, String> eid2name;
  68
  69
  70
  71   public static void main( String args[] ) {
  72     if( args.length < 2 ||
  73         args.length > 3 ) {
  74       System.out.println( "usage: [-2txt] <coreprof.dat file> <trace out file>" );
  75       System.out.println( "The -2txt option will take the raw binary events and spit\n"+
  76                           "out every event as text in events.txt, useful for debugging\n"+
  77                           "event mis-matches." );
  78       System.exit( 0 );
  79     }
  80
  81     Trace t;
  82     if( args[0].equals( "-2txt" ) ) {
  83       t = new Trace( true,  args[1], args[2] );
  84     } else {
  85       t = new Trace( false, args[0], args[1] );
  86     }
  87   }
  88
  89
  90
  91   // event IDs are a word, timestamps are long ints
  92   public static final int WORD_SIZE      = 4;
  93   public static final int EVENT_SIZE     = WORD_SIZE;
  94   public static final int TIMESTAMP_SIZE = WORD_SIZE*2;
  95
  96   int          numThreads;
  97   ThreadData[] threadData;
  98
  99   boolean        convert2txt;
 100   BufferedWriter txtStream;
 101
 102
 103
 104   public Trace( boolean c2txt, String inFile, String outFile ) {
 105
 106     convert2txt = c2txt;
 107
 108     openInputStreams( inFile );
 109
 110     initNames();
 111
 112     for( int i = 0; i < numThreads; i++ ) {
 113       readThread( i );
 114     }
 115
 116     printStats( outFile );
 117   }
 118
 119
 120   public static int readInt( InputStream is ) {
 121     try {
 122       int b1 = is.read();
 123       int b2 = is.read();
 124       int b3 = is.read();
 125       int b4 = is.read();
 126
 127       int retval = (b4<<24)|(b3<<16)|(b2<<8)|b1;
 128
 129       if( retval < 0 ) {
 130         throw new Error();
 131       }
 132       return retval;
 133
 134     } catch( Exception e ) {
 135       throw new Error();
 136     }
 137   }
 138
 139
 140   public static long readLong( InputStream is ) {
 141     try {
 142       long b1 = is.read();
 143       long b2 = is.read();
 144       long b3 = is.read();
 145       long b4 = is.read();
 146       long b5 = is.read();
 147       long b6 = is.read();
 148       long b7 = is.read();
 149       long b8 = is.read();
 150
 151       long retval =
 152         (b8<<56)|(b7<<48)|(b6<<40)|(b5<<32)|
 153         (b4<<24)|(b3<<16)|(b2<< 8)|b1;
 154
 155       if( retval < 0 ) {
 156         throw new Error();
 157       }
 158       return retval;
 159
 160     } catch( Exception e ) {
 161       throw new Error();
 162     }
 163   }
 164
 165
 166   protected void openInputStreams( String filename ) {
 167
 168     BufferedInputStream bis    = null;
 169     int                 offset = 0;
 170
 171     try {
 172       bis    = new BufferedInputStream( new FileInputStream( filename ) );
 173       offset = readHeader( bis );
 174       bis.close();
 175
 176       if( convert2txt ) {
 177         txtStream = new BufferedWriter( new FileWriter( "events.txt" ) );
 178       }
 179
 180     } catch( Exception e ) {
 181       e.printStackTrace();
 182       System.exit( -1 );
 183     }
 184
 185     for( int i = 0; i < numThreads; ++i ) {
 186       try {
 187         // point a thread's event stream to the
 188         // beginning of its data within the input file
 189         threadData[i].dataStream =
 190           new BufferedInputStream( new FileInputStream( filename ) );
 191
 192         int skip = offset;
 193         while( skip > 0 ) {
 194           skip -= threadData[i].dataStream.skip( skip );
 195         }
 196
 197         offset += WORD_SIZE*threadData[i].numDataWords;
 198
 199       } catch( Exception e ) {
 200         e.printStackTrace();
 201         System.exit( -1 );
 202       }
 203     }
 204   }
 205
 206
 207   int readHeader( BufferedInputStream bis ) {
 208
 209     // check version
 210     int version = readInt( bis );
 211     if( version != 0 ) {
 212       throw new Error( "Unsupported Version" );
 213     }
 214     int offset = WORD_SIZE;
 215
 216     // read number of threads
 217     numThreads = readInt( bis );
 218     offset += WORD_SIZE;
 219
 220     threadData = new ThreadData[numThreads];
 221
 222     // read number of words used for all events, per thread
 223     for( int i = 0; i < numThreads; ++i ) {
 224       threadData[i] = new ThreadData();
 225       threadData[i].numDataWords = readInt( bis );
 226       offset += WORD_SIZE;
 227     }
 228     return offset;
 229   }
 230
 231
 232   public void readThread( int tNum ) {
 233
 234     System.out.print( "Reading thread "+tNum );
 235
 236     if( convert2txt ) {
 237       try {
 238         txtStream.write( "\n\n\n\n" );
 239         txtStream.write( "*************************************************\n" );
 240         txtStream.write( "**  Thread "+tNum+"\n" );
 241         txtStream.write( "*************************************************\n" );
 242       } catch( IOException e ) {
 243         e.printStackTrace();
 244         System.exit( -1 );
 245       }
 246     }
 247
 248     ThreadData tdata = threadData[tNum];
 249     tdata.stackDepth = 0;
 250     long timeStamp   = 0;
 251     int  i           = 0;
 252     int numProgress  = 10;
 253
 254     int progressChunk = tdata.numDataWords / numProgress;
 255     int j;
 256     boolean[] progress = new boolean[numProgress];
 257     for( j = 0; j < numProgress; ++j ) {
 258       progress[j] = false;
 259     }
 260     j = 0;
 261
 262     while( i < tdata.numDataWords ) {
 263
 264       if( !progress[j] && i > j*progressChunk ) {
 265         System.out.print( "." );
 266         progress[j] = true;
 267         if( j < numProgress - 1 ) {
 268           ++j;
 269         }
 270       }
 271
 272       int eventRaw = readInt ( tdata.dataStream );
 273       timeStamp    = readLong( tdata.dataStream );
 274       i += 3;
 275
 276       int eventType = eventRaw &  CP_EVENT_MASK;
 277       int eventID   = eventRaw >> CP_EVENT_BASESHIFT;
 278
 279       switch( eventType ) {
 280
 281         case CP_EVENTTYPE_BEGIN: {
 282           pushEvent( tdata, eventID, timeStamp );
 283         } break;
 284
 285         case CP_EVENTTYPE_END: {
 286           popEvent( tdata, eventID, timeStamp );
 287         } break;
 288
 289       }
 290     }
 291
 292     System.out.println( "" );
 293
 294     while( tdata.stackDepth > 0 ) {
 295       // worker threads currently do not exit gracefully, and therefore
 296       // may not register END events, so supply them with whatever the
 297       // latest known timestamp is
 298       EventSummary eventSummary = tdata.eventStack.get( tdata.stackDepth );
 299
 300       if( eventSummary == null ) {
 301         // if there is no previous event it means there are no children
 302         // events with a timestamp for the workaround, so just punt
 303         break;
 304       }
 305
 306       popEvent( tdata, eventSummary.eventID, timeStamp );
 307
 308       --tdata.stackDepth;
 309     }
 310   }
 311
 312
 313   protected void pushEvent( ThreadData tdata,
 314                             int        eventID,
 315                             long       timeStamp ) {
 316
 317     EventSummary eventSummary = null;
 318
 319     if( tdata.stackDepth == 0 ) {
 320       // there are no parents, so look in the rootEvents
 321       // for an existing EventSummary of this type
 322       for( Iterator<EventSummary> itr = tdata.rootEvents.iterator();
 323            itr.hasNext();
 324            ) {
 325         EventSummary es = itr.next();
 326         if( es.eventID == eventID ) {
 327           eventSummary = es;
 328           break;
 329         }
 330       }
 331       if( eventSummary == null ) {
 332         // there is no summary for this event type yet,
 333         // so add it
 334         eventSummary = new EventSummary( eventID );
 335         tdata.rootEvents.add( eventSummary );
 336       }
 337
 338     } else {
 339       // look through the parent's children for an existing
 340       // EventSummary of this type
 341       EventSummary esParent = tdata.eventStack.get( tdata.stackDepth - 1 );
 342       for( Iterator<EventSummary> itr = esParent.children.iterator();
 343            itr.hasNext();
 344            ) {
 345         EventSummary es = itr.next();
 346         if( es.eventID == eventID ) {
 347           eventSummary = es;
 348           break;
 349         }
 350       }
 351       if( eventSummary == null ) {
 352         // there is no summary for this event type yet,
 353         // under this parent, so add it
 354         eventSummary = new EventSummary( eventID );
 355         esParent.children.add( eventSummary );
 356         eventSummary.parent = esParent;
 357       }
 358     }
 359
 360     eventSummary.timeStampBeginLatestInstance = timeStamp;
 361
 362     eventSummary.instanceCount++;
 363
 364     if( tdata.eventStack.size() <= tdata.stackDepth ) {
 365       tdata.eventStack.setSize( 2*tdata.stackDepth + 20 );
 366     }
 367
 368     tdata.eventStack.set( tdata.stackDepth, eventSummary );
 369
 370
 371     // print to the event text file (if needed) before
 372     // updating the stack depth to get tabs right
 373     if( convert2txt ) {
 374       try {
 375         for( int tabs = 0; tabs < tdata.stackDepth; ++tabs ) {
 376           txtStream.write( "  " );
 377         }
 378         txtStream.write( "begin "+getEventName( eventID )+"@"+timeStamp+"\n" );
 379       } catch( IOException e ) {
 380         e.printStackTrace();
 381         System.exit( -1 );
 382       }
 383     }
 384
 385
 386     tdata.stackDepth++;
 387   }
 388
 389
 390   protected void popEvent( ThreadData tdata,
 391                            int        eventID,
 392                            long       timeStamp ) {
 393     tdata.stackDepth--;
 394
 395
 396     // print to the event text file (if needed) after
 397     // updating the stack depth to get tabs right
 398     if( convert2txt ) {
 399       try {
 400         for( int tabs = 0; tabs < tdata.stackDepth; ++tabs ) {
 401           txtStream.write( "  " );
 402         }
 403         txtStream.write( "end   "+getEventName( eventID )+"@"+timeStamp+"\n" );
 404       } catch( IOException e ) {
 405         e.printStackTrace();
 406         System.exit( -1 );
 407       }
 408     }
 409
 410
 411     if( tdata.stackDepth < 0 ) {
 412       throw new Error( "Event stack underflow\n" );
 413     }
 414
 415     EventSummary eventSummary = tdata.eventStack.get( tdata.stackDepth );
 416     assert eventSummary != null;
 417
 418     if( eventSummary.eventID != eventID ) {
 419       System.out.println( "Warning: event begin("+
 420                           getEventName( eventSummary.eventID )+
 421                           ") end("+
 422                           getEventName( eventID )+
 423                           ") mismatch!\n" );
 424     }
 425
 426     long elapsedTime =
 427       timeStamp - eventSummary.timeStampBeginLatestInstance;
 428
 429     eventSummary.totalTime_ticks += elapsedTime;
 430     eventSummary.selfTime_ticks  += elapsedTime;
 431
 432     if( tdata.stackDepth - 1 >= 0 ) {
 433       EventSummary esParent = tdata.eventStack.get( tdata.stackDepth-1 );
 434       esParent.selfTime_ticks -= elapsedTime;
 435     }
 436   }
 437
 438
 439
 440   public void printStats( String filename ) {
 441
 442     System.out.println( "Printing..." );
 443
 444     try {
 445       BufferedWriter bw =
 446         new BufferedWriter( new FileWriter( filename ) );
 447
 448       for( int i = 0; i < numThreads; ++i ) {
 449
 450         ThreadData tdata = threadData[i];
 451
 452         bw.write( "----------------------------------\n" );
 453         bw.write( "Thread "+i+"\n" );
 454
 455         for( Iterator<EventSummary> itr = tdata.rootEvents.iterator();
 456              itr.hasNext();
 457              ) {
 458           EventSummary es = itr.next();
 459           printEventSummary( bw, es, 0 );
 460         }
 461
 462         bw.write( "\n" );
 463       }
 464
 465       bw.close();
 466     } catch( IOException e ) {
 467       e.printStackTrace();
 468       System.exit( -1 );
 469     }
 470   }
 471
 472
 473   public String getEventName( int eventID ) {
 474     return
 475       eid2name.containsKey( eventID ) ?
 476       eid2name.get        ( eventID ) :
 477       Integer.toString    ( eventID );
 478   }
 479
 480
 481   public void printEventSummary( BufferedWriter bw,
 482                                  EventSummary   es,
 483                                  int            depth )
 484     throws IOException {
 485
 486     String strIndent = "";
 487     for( int i = 0; i < depth; ++i ) {
 488       strIndent += "--";
 489     }
 490
 491     String strEventName = getEventName( es.eventID );
 492
 493     float tOfParent_perc;
 494     String strPercParent = "";
 495     if( es.parent != null ) {
 496       float divisor = new Long( es.parent.totalTime_ticks ).floatValue();
 497       if( divisor <= 0.00001f ) {
 498         divisor = 0.00001f;
 499       }
 500
 501       tOfParent_perc =
 502         100.0f *
 503         new Long( es.totalTime_ticks        ).floatValue() /
 504         divisor;
 505
 506       strPercParent = String.format( " %%ofParent=%5.1f",
 507                                      tOfParent_perc );
 508     }
 509
 510     float tSelf_perc =
 511       100.0f *
 512       new Long( es.selfTime_ticks  ).floatValue() /
 513       new Long( es.totalTime_ticks ).floatValue();
 514
 515     String strSelfStats =
 516       String.format( " total(ticks)=%12dK, %%self=%5.1f, count=%d, avgTicks=%d",
 517                      es.totalTime_ticks/1000,
 518                      tSelf_perc,
 519                      es.instanceCount,
 520                      (int)((float)es.totalTime_ticks/(float)es.instanceCount) );
 521
 522     bw.write( strIndent+
 523               strEventName+
 524               strPercParent+
 525               strSelfStats+
 526               "\n" );
 527
 528     for( Iterator<EventSummary> itr = es.children.iterator();
 529          itr.hasNext();
 530          ) {
 531       EventSummary esChild = itr.next();
 532       printEventSummary( bw, esChild, depth + 1 );
 533     }
 534   }
 535 }