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