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