github.com/grailbio/bigslice@v0.0.0-20230519005545-30c4c12152ad/cmd/slicetrace/main.go (about)

     1  // Copyright 2020 GRAIL, Inc. All rights reserved.
     2  // Use of this source code is governed by the Apache 2.0
     3  // license that can be found in the LICENSE file.
     4  
     5  package main
     6  
     7  import (
     8  	"flag"
     9  	"fmt"
    10  	"log"
    11  	"os"
    12  	"text/tabwriter"
    13  	"time"
    14  
    15  	"github.com/grailbio/bigslice/internal/trace"
    16  )
    17  
    18  func main() {
    19  	flag.Usage = func() {
    20  		fmt.Fprintf(os.Stderr, `usage: slicetrace <trace-file>
    21  
    22  slicetrace prints out summary diagnostics read from trace-file, a Chrome trace
    23  event format file generated by a bigslice program.
    24  
    25  It shows the following reports for each invocation:
    26  
    27    summary
    28      A summary of the invocation, i.e. call location and arguments.
    29  
    30    slice
    31      The (pipelined) slice operations that compose the invocation. The table has
    32      the following columns:
    33        op
    34          The name slice operation.
    35        shards
    36          The number of shards used to compute the slice.
    37        start
    38          The start time of the operation, given as the offset in time from the
    39          start of the job.
    40        duration
    41          The duration of the operation, measured as the span between the start
    42          time of the first task and the end time of the last task of the tasks
    43          composing the operation.
    44  
    45    task:io
    46      A breakdown of task computation duration. The table has the following
    47      columns:
    48        op
    49          The name slice operation.
    50        total
    51          The sum of the durations of total running time of the tasks composing
    52          the slice.
    53        read
    54          The sum of the durations of time spent reading and decoding dependee
    55          task data of the tasks composing the slice. This includes data transfer
    56          time for data pulled from other workers.
    57        write
    58          The sum of the durations of time spent encoding and writing task output
    59          to disk of the tasks composing the slice.
    60  
    61    task:quartile
    62      A distribution of task durations. The table has the following columns:
    63        op
    64          The name slice operation.
    65        min
    66          The minimum duration of a task composing the slice.
    67        q1
    68          The first quartile duration of a task composing the slice.
    69        q2
    70          The median duration of a task composing the slice.
    71        q3
    72          The third quartile duration of a task composing the slice.
    73        max
    74          The maximum duration of a task composing the slice.
    75  
    76  `)
    77  		flag.PrintDefaults()
    78  		os.Exit(2)
    79  	}
    80  	flag.Parse()
    81  	if flag.NArg() == 0 {
    82  		flag.Usage()
    83  	}
    84  
    85  	path := flag.Arg(0)
    86  	f, err := os.Open(path)
    87  	if err != nil {
    88  		log.Fatalf("opening trace file: %v", err)
    89  	}
    90  	defer f.Close()
    91  
    92  	t := trace.T{}
    93  	if err := t.Decode(f); err != nil {
    94  		log.Fatalf("decoding %q: %v", path, err)
    95  	}
    96  	sess := newSession(t.Events)
    97  	for _, inv := range sess.Invs() {
    98  		printInvSummary(inv)
    99  		printInvSlice(sess, inv)
   100  		printInvTaskIO(sess, inv)
   101  		printInvTaskQuartiles(sess, inv)
   102  	}
   103  }
   104  
   105  func printInvSummary(inv invocation) {
   106  	fmt.Printf("# inv%d:summary\n", inv.index)
   107  	w := makeTabWriter()
   108  	fmt.Fprintf(w, "location\t%s\t\n", inv.location)
   109  	fmt.Fprintf(w, "args\t%s\t\n", inv.args)
   110  	w.Flush()
   111  	fmt.Println("")
   112  }
   113  
   114  func printInvSlice(sess *session, inv invocation) {
   115  	fmt.Printf("# inv%d:slice\n", inv.index)
   116  	w := makeTabWriter()
   117  	fmt.Fprintf(w, "op\tshards\tstart\tduration\t\n")
   118  	for _, stats := range sess.OpStats(inv.index) {
   119  		fmt.Fprintf(w, "%s\t%d\t%s\t%s\t\n",
   120  			stats.op,
   121  			stats.shards,
   122  			formatDuration(stats.start),
   123  			formatDuration(stats.duration))
   124  	}
   125  	w.Flush()
   126  	fmt.Println("")
   127  }
   128  
   129  func printInvTaskIO(sess *session, inv invocation) {
   130  	fmt.Printf("# inv%d:task:io\n", inv.index)
   131  	w := makeTabWriter()
   132  	fmt.Fprintf(w, "op\ttotal\tread\twrite\t\n")
   133  	for _, stats := range sess.OpStats(inv.index) {
   134  		fmt.Fprintf(w, "%s\t%s\t%s\t%s\t\n",
   135  			stats.op,
   136  			formatDuration(stats.total),
   137  			formatDuration(stats.read),
   138  			formatDuration(stats.write))
   139  	}
   140  	w.Flush()
   141  	fmt.Println("")
   142  }
   143  
   144  func printInvTaskQuartiles(sess *session, inv invocation) {
   145  	fmt.Printf("# inv%d:task:quartile\n", inv.index)
   146  	w := makeTabWriter()
   147  	fmt.Fprintf(w, "op\tmin\tq1\tq2\tq3\tmax\t\n")
   148  	for _, stats := range sess.OpStats(inv.index) {
   149  		fmt.Fprintf(w, "%s\t%s\t%s\t%s\t%s\t%s\t\n",
   150  			stats.op,
   151  			formatDuration(stats.min),
   152  			formatDuration(stats.q1),
   153  			formatDuration(stats.q2),
   154  			formatDuration(stats.q3),
   155  			formatDuration(stats.max))
   156  	}
   157  	w.Flush()
   158  	fmt.Println("")
   159  }
   160  
   161  func makeTabWriter() *tabwriter.Writer {
   162  	return tabwriter.NewWriter(os.Stdout, 0, 0, 4, ' ', tabwriter.AlignRight)
   163  }
   164  
   165  func formatDuration(d time.Duration) string {
   166  	totalSeconds := int64(d.Seconds())
   167  	seconds := totalSeconds % 60
   168  	minutes := (totalSeconds / 60) % 60
   169  	hours := (totalSeconds / (60 * 60))
   170  	return fmt.Sprintf("%02d:%02d:%02d", hours, minutes, seconds)
   171  }