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       System.out.println( "usage: <coreprof.dat file> <trace out file> [-2txt]\n"+
  74                           "\nThe -2txt option will take the raw binary events and spit\n"+
  75                           "out every event as text in events.txt, useful for debugging\n"+
  76                           "event mis-matches." );
  77       System.exit( 0 );
  78     }
  79     String inputfile=null;
  80     String outputfile=null;
  81     boolean events=false;
  82     HashSet<Integer> eventset=new HashSet<Integer>();
  83     boolean hasinput=false;
  84     long maxtime=-1;
  85     long mintime=0;
  86     long scale=1;
  87
  88     for(int i=0; i<args.length; i++) {
  89       if (args[i].equals("-2txt")) {
  90         events=true;
  91       } else if (args[i].equals("-event")) {
  92         eventset.add(Integer.parseInt(args[i+1]));
  93         i++;
  94       } else if (args[i].equals("-maxtime")) {
  95         maxtime=Long.parseLong(args[i+1]);
  96         i++;
  97       } else if (args[i].equals("-mintime")) {
  98         mintime=Long.parseLong(args[i+1]);
  99         i++;
 100       } else if (args[i].equals("-scale")) {
 101         scale=Long.parseLong(args[i+1]);
 102         i++;
 103       } else {
 104         if (hasinput) {
 105           outputfile=args[i];
 106         } else {
 107           hasinput=true;
 108           inputfile=args[i];
 109         }
 110       }
 111     }
 112
 113     Trace t = new Trace(events, inputfile, outputfile, eventset, mintime, maxtime,scale);
 114   }
 115
 116
 117
 118   // event IDs are a word, timestamps are long ints
 119   public static final int WORD_SIZE      = 4;
 120   public static final int EVENT_SIZE     = WORD_SIZE;
 121   public static final int TIMESTAMP_SIZE = WORD_SIZE*2;
 122
 123   int          numThreads;
 124   ThreadData[] threadData;
 125   HashSet<Integer> eventset;
 126
 127   boolean        convert2txt;
 128   BufferedWriter txtStream;
 129
 130   boolean             convert2plot;
 131   BufferedWriter      bwPlot;
 132   long                tSysZero;
 133   long maxtime;
 134   long mintime;
 135   long scale;
 136
 137   public Trace( boolean c2txt, String inFile, String outFile,  HashSet<Integer> eventset, long mintime, long maxtime, long scale) {
 138     this.eventset=eventset;
 139     this.maxtime=maxtime;
 140     this.mintime=mintime;
 141     this.scale=scale;
 142     convert2txt  = c2txt;
 143     convert2plot = true;
 144
 145     openInputStreams( inFile );
 146
 147     initNames();
 148
 149     if (convert2plot) {
 150       printPlotCmd();
 151     }
 152
 153     for( int i = 0; i < numThreads; i++ ) {
 154       readThread( i );
 155     }
 156
 157     printStats( outFile );
 158
 159     if( convert2plot ) {
 160       try {
 161         bwPlot.write("plot [0:"+(globendtime/scale)+"] [-1:"+(numThreads+1)+"] -3\n");
 162         bwPlot.close();
 163       } catch (IOException e) {
 164         e.printStackTrace();
 165       }
 166     }
 167   }
 168
 169
 170   public static int readInt( InputStream is ) {
 171     try {
 172       int b1 = is.read();
 173       int b2 = is.read();
 174       int b3 = is.read();
 175       int b4 = is.read();
 176
 177       int retval = (b4<<24)|(b3<<16)|(b2<<8)|b1;
 178
 179       if( retval < 0 ) {
 180         throw new Error();
 181       }
 182       return retval;
 183
 184     } catch( Exception e ) {
 185       throw new Error();
 186     }
 187   }
 188
 189
 190   public static long readLong( InputStream is ) {
 191     try {
 192       long b1 = is.read();
 193       long b2 = is.read();
 194       long b3 = is.read();
 195       long b4 = is.read();
 196       long b5 = is.read();
 197       long b6 = is.read();
 198       long b7 = is.read();
 199       long b8 = is.read();
 200
 201       long retval =
 202         (b8<<56)|(b7<<48)|(b6<<40)|(b5<<32)|
 203         (b4<<24)|(b3<<16)|(b2<< 8)|b1;
 204
 205       if( retval < 0 ) {
 206         throw new Error();
 207       }
 208       return retval;
 209
 210     } catch( Exception e ) {
 211       throw new Error();
 212     }
 213   }
 214
 215
 216   protected void openInputStreams( String filename ) {
 217
 218     BufferedInputStream bis    = null;
 219     int                 offset = 0;
 220
 221     try {
 222       bis    = new BufferedInputStream( new FileInputStream( filename ) );
 223       offset = readHeader( bis );
 224       bis.close();
 225
 226     } catch( Exception e ) {
 227       e.printStackTrace();
 228       System.exit( -1 );
 229     }
 230
 231     for( int i = 0; i < numThreads; ++i ) {
 232       try {
 233         // point a thread's event stream to the
 234         // beginning of its data within the input file
 235         threadData[i].dataStream =
 236           new BufferedInputStream( new FileInputStream( filename ) );
 237
 238         int skip = offset;
 239         while( skip > 0 ) {
 240           skip -= threadData[i].dataStream.skip( skip );
 241         }
 242         threadData[i].dataStream.mark(20);
 243         int eventRaw = readInt ( threadData[i].dataStream );
 244         long Stamp    = readLong( threadData[i].dataStream );
 245         threadData[i].dataStream.reset();
 246
 247         if (globalstarttime==-1||globalstarttime>Stamp)
 248           globalstarttime=Stamp;
 249
 250
 251         offset += WORD_SIZE*threadData[i].numDataWords;
 252
 253       } catch( Exception e ) {
 254         e.printStackTrace();
 255         System.exit( -1 );
 256       }
 257     }
 258   }
 259
 260
 261   int readHeader( BufferedInputStream bis ) {
 262
 263     // check version
 264     int version = readInt( bis );
 265     if( version != 0 ) {
 266       throw new Error( "Unsupported Version" );
 267     }
 268     int offset = WORD_SIZE;
 269
 270     // read number of threads
 271     numThreads = readInt( bis );
 272     offset += WORD_SIZE;
 273
 274     threadData = new ThreadData[numThreads];
 275
 276     // read number of words used for all events, per thread
 277     for( int i = 0; i < numThreads; ++i ) {
 278       threadData[i] = new ThreadData();
 279       threadData[i].numDataWords = readInt( bis );
 280       offset += WORD_SIZE;
 281     }
 282     return offset;
 283   }
 284
 285
 286   public void readThread( int tNum ) {
 287
 288     System.out.print( "Reading thread "+tNum );
 289
 290     if( convert2txt ) {
 291       try {
 292         txtStream = new BufferedWriter( new FileWriter( "events.txt" ) );
 293
 294         txtStream.write( "\n\n\n\n" );
 295         txtStream.write( "*************************************************\n" );
 296         txtStream.write( "**  Thread "+tNum+"\n" );
 297         txtStream.write( "*************************************************\n" );
 298       } catch( IOException e ) {
 299         e.printStackTrace();
 300         System.exit( -1 );
 301       }
 302     }
 303
 304
 305     ThreadData tdata = threadData[tNum];
 306     tdata.stackDepth = 0;
 307     long timeStamp   = 0;
 308     int  i           = 0;
 309     int numProgress  = 10;
 310
 311     int progressChunk = tdata.numDataWords / numProgress;
 312     int j;
 313     boolean[] progress = new boolean[numProgress];
 314     for( j = 0; j < numProgress; ++j ) {
 315       progress[j] = false;
 316     }
 317     j = 0;
 318
 319     long lasttime=-1;
 320     while( i < tdata.numDataWords ) {
 321
 322       if( !progress[j] && i > j*progressChunk ) {
 323         System.out.print( "." );
 324         progress[j] = true;
 325         if( j < numProgress - 1 ) {
 326           ++j;
 327         }
 328       }
 329
 330       int eventRaw = readInt ( tdata.dataStream );
 331       timeStamp    = readLong( tdata.dataStream );
 332       i += 3;
 333
 334       int eventType = eventRaw &  CP_EVENT_MASK;
 335       int eventID   = eventRaw >> CP_EVENT_BASESHIFT;
 336
 337       if (eventset.isEmpty()||eventset.contains(eventID))
 338         switch( eventType ) {
 339
 340         case CP_EVENTTYPE_BEGIN: {
 341           if( eventID == CP_EVENTID_MAIN ) {
 342             tSysZero = timeStamp;
 343           }
 344           if( tdata.stackDepth>0 && convert2plot ) {
 345             EventSummary esParent = tdata.eventStack.get( tdata.stackDepth - 1 );
 346             long starttime=lasttime>esParent.timeStampBeginLatestInstance?lasttime:esParent.timeStampBeginLatestInstance;
 347             addPointToPlot( tNum, esParent.eventID, starttime, timeStamp);
 348           }
 349
 350           pushEvent( tdata, eventID, timeStamp );
 351         } break;
 352
 353         case CP_EVENTTYPE_END: {
 354           if( convert2plot ) {
 355             EventSummary esParent = tdata.eventStack.get( tdata.stackDepth - 1 );
 356             long starttime=lasttime>esParent.timeStampBeginLatestInstance?lasttime:esParent.timeStampBeginLatestInstance;
 357
 358             addPointToPlot( tNum, esParent.eventID, starttime, timeStamp);
 359             lasttime=timeStamp;
 360           }
 361           popEvent( tdata, eventID, timeStamp );
 362         } break;
 363         }
 364     }
 365
 366     System.out.println( "" );
 367
 368     while( tdata.stackDepth > 0 ) {
 369       // worker threads currently do not exit gracefully, and therefore
 370       // may not register END events, so supply them with whatever the
 371       // latest known timestamp is
 372       EventSummary eventSummary = tdata.eventStack.get( tdata.stackDepth);
 373
 374       if( eventSummary == null ) {
 375         // if there is no previous event it means there are no children
 376         // events with a timestamp for the workaround, so just punt
 377         break;
 378       }
 379
 380       popEvent( tdata, eventSummary.eventID, timeStamp );
 381
 382       --tdata.stackDepth;
 383     }
 384
 385   }
 386
 387
 388   protected void pushEvent( ThreadData tdata,
 389                             int        eventID,
 390                             long       timeStamp ) {
 391
 392     EventSummary eventSummary = null;
 393
 394     if( tdata.stackDepth == 0 ) {
 395       // there are no parents, so look in the rootEvents
 396       // for an existing EventSummary of this type
 397       for( Iterator<EventSummary> itr = tdata.rootEvents.iterator();
 398            itr.hasNext();
 399            ) {
 400         EventSummary es = itr.next();
 401         if( es.eventID == eventID ) {
 402           eventSummary = es;
 403           break;
 404         }
 405       }
 406       if( eventSummary == null ) {
 407         // there is no summary for this event type yet,
 408         // so add it
 409         eventSummary = new EventSummary( eventID );
 410         tdata.rootEvents.add( eventSummary );
 411       }
 412
 413     } else {
 414       // look through the parent's children for an existing
 415       // EventSummary of this type
 416       EventSummary esParent = tdata.eventStack.get( tdata.stackDepth - 1 );
 417       for( Iterator<EventSummary> itr = esParent.children.iterator();
 418            itr.hasNext();
 419            ) {
 420         EventSummary es = itr.next();
 421         if( es.eventID == eventID ) {
 422           eventSummary = es;
 423           break;
 424         }
 425       }
 426       if( eventSummary == null ) {
 427         // there is no summary for this event type yet,
 428         // under this parent, so add it
 429         eventSummary = new EventSummary( eventID );
 430         esParent.children.add( eventSummary );
 431         eventSummary.parent = esParent;
 432       }
 433     }
 434
 435     eventSummary.timeStampBeginLatestInstance = timeStamp;
 436
 437     eventSummary.instanceCount++;
 438
 439     if( tdata.eventStack.size() <= tdata.stackDepth ) {
 440       tdata.eventStack.setSize( 2*tdata.stackDepth + 20 );
 441     }
 442
 443     tdata.eventStack.set( tdata.stackDepth, eventSummary );
 444
 445
 446     // print to the event text file (if needed) before
 447     // updating the stack depth to get tabs right
 448     if( convert2txt ) {
 449       try {
 450         for( int tabs = 0; tabs < tdata.stackDepth; ++tabs ) {
 451           txtStream.write( "  " );
 452         }
 453         txtStream.write( "begin "+getEventName( eventID )+"@"+timeStamp+"\n" );
 454       } catch( IOException e ) {
 455         e.printStackTrace();
 456         System.exit( -1 );
 457       }
 458     }
 459
 460
 461     tdata.stackDepth++;
 462   }
 463
 464
 465   protected void popEvent( ThreadData tdata,
 466                            int        eventID,
 467                            long       timeStamp ) {
 468     tdata.stackDepth--;
 469
 470
 471     // print to the event text file (if needed) after
 472     // updating the stack depth to get tabs right
 473     if( convert2txt ) {
 474       try {
 475         for( int tabs = 0; tabs < tdata.stackDepth; ++tabs ) {
 476           txtStream.write( "  " );
 477         }
 478         txtStream.write( "end   "+getEventName( eventID )+"@"+timeStamp+"\n" );
 479       } catch( IOException e ) {
 480         e.printStackTrace();
 481         System.exit( -1 );
 482       }
 483     }
 484
 485
 486     if( tdata.stackDepth < 0 ) {
 487       throw new Error( "Event stack underflow\n" );
 488     }
 489
 490     EventSummary eventSummary = tdata.eventStack.get( tdata.stackDepth );
 491     assert eventSummary != null;
 492
 493     if( eventSummary.eventID != eventID ) {
 494       System.out.println( "Warning: event begin("+
 495                           getEventName( eventSummary.eventID )+
 496                           ") end("+
 497                           getEventName( eventID )+
 498                           ") mismatch!\n" );
 499     }
 500
 501     long elapsedTime =
 502       timeStamp - eventSummary.timeStampBeginLatestInstance;
 503
 504     eventSummary.totalTime_ticks += elapsedTime;
 505     eventSummary.selfTime_ticks  += elapsedTime;
 506
 507     if( tdata.stackDepth - 1 >= 0 ) {
 508       EventSummary esParent = tdata.eventStack.get( tdata.stackDepth-1 );
 509       esParent.selfTime_ticks -= elapsedTime;
 510     }
 511   }
 512
 513   long globalstarttime=-1;
 514   long globendtime=-1;
 515
 516   public void addPointToPlot( int thread, int eventID, long starttime, long endtime) {
 517     try {
 518       long nstart=starttime-globalstarttime-mintime;
 519       long nend=endtime-globalstarttime-mintime;
 520       if ((maxtime==-1 || (endtime-globalstarttime)<maxtime)&&(nend>0)) {
 521         if (nend>globendtime)
 522           globendtime=nend;
 523         if (nstart<0)
 524           nstart=0;
 525         bwPlot.write( "set arrow from "+(nstart/scale)+","+thread+" to "+(nend/scale)+","+thread+" lt "+eventID+" nohead\n");
 526       }
 527     } catch( IOException e ) {
 528       e.printStackTrace();
 529       System.exit( -1 );
 530     }
 531   }
 532
 533
 534
 535   public void printStats( String filename ) {
 536
 537     System.out.println( "Printing..." );
 538
 539     try {
 540       BufferedWriter bw =
 541         new BufferedWriter( new FileWriter( filename ) );
 542
 543       for( int i = 0; i < numThreads; ++i ) {
 544
 545         ThreadData tdata = threadData[i];
 546
 547         bw.write( "----------------------------------\n" );
 548         bw.write( "Thread "+i+"\n" );
 549
 550         for( Iterator<EventSummary> itr = tdata.rootEvents.iterator();
 551              itr.hasNext();
 552              ) {
 553           EventSummary es = itr.next();
 554           printEventSummary( bw, es, 0 );
 555         }
 556
 557         bw.write( "\n" );
 558       }
 559
 560       bw.close();
 561     } catch( IOException e ) {
 562       e.printStackTrace();
 563       System.exit( -1 );
 564     }
 565   }
 566
 567
 568   public String getEventName( int eventID ) {
 569     return
 570       eid2name.containsKey( eventID ) ?
 571       eid2name.get        ( eventID ) :
 572       Integer.toString    ( eventID );
 573   }
 574
 575
 576   public void printEventSummary( BufferedWriter bw,
 577                                  EventSummary   es,
 578                                  int            depth )
 579     throws IOException {
 580
 581     String strIndent = "";
 582     for( int i = 0; i < depth; ++i ) {
 583       strIndent += "--";
 584     }
 585
 586     String strEventName = getEventName( es.eventID );
 587
 588     float tOfParent_perc;
 589     String strPercParent = "";
 590     if( es.parent != null ) {
 591       float divisor = new Long( es.parent.totalTime_ticks ).floatValue();
 592       if( divisor <= 0.00001f ) {
 593         divisor = 0.00001f;
 594       }
 595
 596       tOfParent_perc =
 597         100.0f *
 598         new Long( es.totalTime_ticks        ).floatValue() /
 599         divisor;
 600
 601       strPercParent = String.format( " %%ofParent=%5.1f",
 602                                      tOfParent_perc );
 603     }
 604
 605     float tSelf_perc =
 606       100.0f *
 607       new Long( es.selfTime_ticks  ).floatValue() /
 608       new Long( es.totalTime_ticks ).floatValue();
 609
 610     String strSelfStats =
 611       String.format( " total(ticks)=%12dK, %%self=%5.1f, count=%d, avgTicks=%d",
 612                      es.totalTime_ticks/1000,
 613                      tSelf_perc,
 614                      es.instanceCount,
 615                      (int)((float)es.totalTime_ticks/(float)es.instanceCount) );
 616
 617     bw.write( strIndent+
 618               strEventName+
 619               strPercParent+
 620               strSelfStats+
 621               "\n" );
 622
 623     for( Iterator<EventSummary> itr = es.children.iterator();
 624          itr.hasNext();
 625          ) {
 626       EventSummary esChild = itr.next();
 627       printEventSummary( bw, esChild, depth + 1 );
 628     }
 629   }
 630
 631
 632   public void printPlotCmd() {
 633     try {
 634       bwPlot =
 635         new BufferedWriter( new FileWriter( "plot.cmd" ) );
 636     } catch( IOException e ) {
 637       e.printStackTrace();
 638       System.exit( -1 );
 639     }
 640   }
 641 }