~whereswaldon/gioprofiler

ref: 3217a891140d285d2ffe1461e2beec3b71cb4ddf gioprofiler/profiling.go -rw-r--r-- 5.3 KiB
3217a891Chris Waldon doc: add pkg.go.dev link 4 months ago
                                                                                
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
/*
Package gioprofiler provides tools for recording frame timings for later analysis.

The simplest usage is to construct a profilier at the start of your event loop
function and to defer stopping it until the window is closed. Something like:

    func loop(w *app.Window) error {
        // log to a CSV file with a randomly-chosen name. The file's path will be
        // logged to stderr.
        recorder, err := NewRecorder(nil)
        if err != nil {
            // handle
        }
        defer recorder.Stop()

        var ops op.Ops

        for event := range window.Events() {
            switch event := event.(type) {
                case system.DestroyEvent:
                    // returning will execute the deferred call to Stop(), which
                    // flushes the CSV file.
                    return event.Err
                case system.FrameEvent:
                    gtx := layout.NewContext(&ops, event)

                    // record the last frame's timing info and prepare the next one
                    recorder.profile(gtx)

                    // lay out your UI here
            }
        }
    }

The actual disk I/O is performed by a different goroutine and will not block the UI unless it gets more than 60 frames behind.
*/
package gioprofiler

import (
	"encoding/csv"
	"fmt"
	"io/ioutil"
	"log"
	"os"
	"strconv"
	"time"

	"gioui.org/io/profile"
	"gioui.org/layout"
)

// Timings holds frame timing information
type Timings struct {
	// When is the timestamp of the frame that this struct describes
	When          time.Time
	Total         time.Duration
	FrameDuration time.Duration
	GPUTime       time.Duration
	ZT            time.Duration
	ST            time.Duration
	CovT          time.Duration
}

func (t Timings) CSVRow() []string {
	out := []string{}
	toString := func(d time.Duration) string {
		return strconv.Itoa(int(d.Milliseconds()))
	}
	out = append(out, strconv.Itoa(int(t.When.UnixNano()/1e6)))
	out = append(out, toString(t.Total))
	out = append(out, toString(t.FrameDuration))
	out = append(out, toString(t.GPUTime))
	out = append(out, toString(t.ZT))
	out = append(out, toString(t.ST))
	out = append(out, toString(t.CovT))
	return out
}

func decode(e timedEvent) Timings {
	out := Timings{}
	var tot, fd, gpu, zt, st, covt string
	fmt.Sscanf(e.Timings, "tot: %s draw: %s gpu: %s zt: %s st: %s cov: %s", &tot, &fd, &gpu, &zt, &st, &covt)
	out.When = e.when
	out.Total, _ = time.ParseDuration(tot)
	out.FrameDuration, _ = time.ParseDuration(fd)
	out.GPUTime, _ = time.ParseDuration(gpu)
	out.ZT, _ = time.ParseDuration(zt)
	out.ST, _ = time.ParseDuration(st)
	out.CovT, _ = time.ParseDuration(covt)
	return out
}

func header() []string {
	return []string{"when(unix ms)", "tot(ms)", "draw(ms)", "gpu(ms)", "zt(ms)", "st(ms)", "cov(ms)"}
}

type timedEvent struct {
	profile.Event
	when time.Time
}

// CSVTimingRecorder captures frame timing information into a CSV file
type CSVTimingRecorder struct {
	nextEventTime time.Time
	file          *os.File
	csvWriter     *csv.Writer
	listener      chan timedEvent
	errChan       chan error
}

// NewRecorder creates a CSVTimingRecorder that will record to a CSV file
// with the provided name. If the name is nil, a temporary file will be used.
func NewRecorder(filename *string) (*CSVTimingRecorder, error) {
	var (
		err  error
		file *os.File
	)
	if filename == nil {
		file, err = ioutil.TempFile("", "profile-*.csv")
	} else {
		file, err = os.Create(*filename)
	}
	if err != nil {
		return nil, fmt.Errorf("failed opening csv file: %w", err)
	}
	recorder := &CSVTimingRecorder{}
	recorder.file = file
	recorder.csvWriter = csv.NewWriter(recorder.file)
	recorder.listener = make(chan timedEvent, 60)
	recorder.errChan = make(chan error)

	go recorder.consume()
	return recorder, nil
}

func (c *CSVTimingRecorder) consume() {
	defer close(c.errChan)
	log.Printf("Logging csv profiling to %v", c.file.Name())
	c.csvWriter.Write(header())
	for e := range c.listener {
		timing := decode(e)
		err := c.csvWriter.Write(timing.CSVRow())
		if err != nil {
			c.errChan <- err
		}
	}
	c.csvWriter.Flush()
	c.errChan <- c.csvWriter.Error()
}

// Stop shuts down the recording process and flushes all data to the
// CSV file.
func (c *CSVTimingRecorder) Stop() error {
	close(c.listener)
	err := <-c.errChan
	if err != nil {
		return fmt.Errorf("failed to flush writer: %w", err)
	}
	err = c.file.Close()
	if err != nil {
		return fmt.Errorf("failed to close csv: %w", err)
	}
	log.Printf("CSV profiling data written to %s", c.file.Name())
	return nil
}

// Profile records profiling data from the last frame and prepares the
// capture of the next frame. Calling this method every frame is sufficient
// to profile all frames.
func (c *CSVTimingRecorder) Profile(gtx layout.Context) {
	var lastEventTime time.Time
	lastEventTime, c.nextEventTime = c.nextEventTime, gtx.Now
	profile.Op{Tag: c}.Add(gtx.Ops)
	for _, e := range gtx.Events(c) {
		switch e := e.(type) {
		case profile.Event:
			c.Write(lastEventTime, e)
		}
	}
}

// Write is a lower-level way to capture a single profile event. It should
// be used instead of the Profile method if more granular profiling control
// is desired.
func (c *CSVTimingRecorder) Write(when time.Time, e profile.Event) error {
	var err error
	select {
	case err = <-c.errChan:
	default:
	}
	select {
	case c.listener <- timedEvent{Event: e, when: when}:
	default:
		err = fmt.Errorf("recorder already stopped")
	}
	return err
}