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