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