1// Copyright 2017 Google Inc. All rights reserved.
2//
3// Licensed under the Apache License, Version 2.0 (the "License");
4// you may not use this file except in compliance with the License.
5// You may obtain a copy of the License at
6//
7//     http://www.apache.org/licenses/LICENSE-2.0
8//
9// Unless required by applicable law or agreed to in writing, software
10// distributed under the License is distributed on an "AS IS" BASIS,
11// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12// See the License for the specific language governing permissions and
13// limitations under the License.
14
15// This package implements a trace file writer, whose files can be opened in
16// chrome://tracing.
17//
18// It implements the JSON Array Format defined here:
19// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit
20package tracer
21
22import (
23	"bytes"
24	"compress/gzip"
25	"encoding/json"
26	"fmt"
27	"io"
28	"os"
29	"strings"
30	"sync"
31	"time"
32
33	"android/soong/ui/logger"
34	"android/soong/ui/status"
35)
36
37type Thread uint64
38
39const (
40	MainThread     = Thread(iota)
41	MaxInitThreads = Thread(iota)
42)
43
44type Tracer interface {
45	Begin(name string, thread Thread)
46	End(thread Thread)
47	Complete(name string, thread Thread, begin, end uint64)
48
49	ImportMicrofactoryLog(filename string)
50
51	StatusTracer() status.StatusOutput
52
53	NewThread(name string) Thread
54}
55
56type tracerImpl struct {
57	lock sync.Mutex
58	log  logger.Logger
59
60	buf  bytes.Buffer
61	file *os.File
62	w    io.WriteCloser
63
64	firstEvent bool
65	nextTid    uint64
66}
67
68var _ Tracer = &tracerImpl{}
69
70type viewerEvent struct {
71	Name  string      `json:"name,omitempty"`
72	Phase string      `json:"ph"`
73	Scope string      `json:"s,omitempty"`
74	Time  uint64      `json:"ts"`
75	Dur   uint64      `json:"dur,omitempty"`
76	Pid   uint64      `json:"pid"`
77	Tid   uint64      `json:"tid"`
78	ID    uint64      `json:"id,omitempty"`
79	Arg   interface{} `json:"args,omitempty"`
80}
81
82type nameArg struct {
83	Name string `json:"name"`
84}
85
86type nopCloser struct{ io.Writer }
87
88func (nopCloser) Close() error { return nil }
89
90// New creates a new Tracer, storing log in order to log errors later.
91// Events are buffered in memory until SetOutput is called.
92func New(log logger.Logger) *tracerImpl {
93	ret := &tracerImpl{
94		log: log,
95
96		firstEvent: true,
97		nextTid:    uint64(MaxInitThreads),
98	}
99	ret.startBuffer()
100
101	return ret
102}
103
104func (t *tracerImpl) startBuffer() {
105	t.w = nopCloser{&t.buf}
106	fmt.Fprintln(t.w, "[")
107
108	t.defineThread(MainThread, "main")
109}
110
111func (t *tracerImpl) close() {
112	if t.file != nil {
113		fmt.Fprintln(t.w, "]")
114
115		if err := t.w.Close(); err != nil {
116			t.log.Println("Error closing trace writer:", err)
117		}
118
119		if err := t.file.Close(); err != nil {
120			t.log.Println("Error closing trace file:", err)
121		}
122		t.file = nil
123		t.startBuffer()
124	}
125}
126
127// SetOutput creates the output file (rotating old files).
128func (t *tracerImpl) SetOutput(filename string) {
129	t.lock.Lock()
130	defer t.lock.Unlock()
131
132	t.close()
133
134	// chrome://tracing requires that compressed trace files end in .gz
135	if !strings.HasSuffix(filename, ".gz") {
136		filename += ".gz"
137	}
138
139	f, err := logger.CreateFileWithRotation(filename, 5)
140	if err != nil {
141		t.log.Println("Failed to create trace file:", err)
142		return
143	}
144	// Save the file, since closing the gzip Writer doesn't close the
145	// underlying file.
146	t.file = f
147	t.w = gzip.NewWriter(f)
148
149	// Write out everything that happened since the start
150	if _, err := io.Copy(t.w, &t.buf); err != nil {
151		t.log.Println("Failed to write trace buffer to file:", err)
152	}
153	t.buf = bytes.Buffer{}
154}
155
156// Close closes the output file. Any future events will be buffered until the
157// next call to SetOutput.
158func (t *tracerImpl) Close() {
159	t.lock.Lock()
160	defer t.lock.Unlock()
161
162	t.close()
163}
164
165func (t *tracerImpl) writeEvent(event *viewerEvent) {
166	t.lock.Lock()
167	defer t.lock.Unlock()
168
169	t.writeEventLocked(event)
170}
171
172func (t *tracerImpl) writeEventLocked(event *viewerEvent) {
173	bytes, err := json.Marshal(event)
174	if err != nil {
175		t.log.Println("Failed to marshal event:", err)
176		t.log.Verbosef("Event: %#v", event)
177		return
178	}
179
180	if !t.firstEvent {
181		fmt.Fprintln(t.w, ",")
182	} else {
183		t.firstEvent = false
184	}
185
186	if _, err = t.w.Write(bytes); err != nil {
187		t.log.Println("Trace write error:", err)
188	}
189}
190
191func (t *tracerImpl) defineThread(thread Thread, name string) {
192	t.writeEventLocked(&viewerEvent{
193		Name:  "thread_name",
194		Phase: "M",
195		Pid:   0,
196		Tid:   uint64(thread),
197		Arg: &nameArg{
198			Name: name,
199		},
200	})
201}
202
203// NewThread returns a new Thread with an unused tid, writing the name out to
204// the trace file.
205func (t *tracerImpl) NewThread(name string) Thread {
206	t.lock.Lock()
207	defer t.lock.Unlock()
208
209	ret := Thread(t.nextTid)
210	t.nextTid += 1
211
212	t.defineThread(ret, name)
213	return ret
214}
215
216// Begin starts a new Duration Event. More than one Duration Event may be active
217// at a time on each Thread, but they're nested.
218func (t *tracerImpl) Begin(name string, thread Thread) {
219	t.writeEvent(&viewerEvent{
220		Name:  name,
221		Phase: "B",
222		Time:  uint64(time.Now().UnixNano()) / 1000,
223		Pid:   0,
224		Tid:   uint64(thread),
225	})
226}
227
228// End finishes the most recent active Duration Event on the thread.
229func (t *tracerImpl) End(thread Thread) {
230	t.writeEvent(&viewerEvent{
231		Phase: "E",
232		Time:  uint64(time.Now().UnixNano()) / 1000,
233		Pid:   0,
234		Tid:   uint64(thread),
235	})
236}
237
238// Complete writes a Complete Event, which are like Duration Events, but include
239// a begin and end timestamp in the same event.
240func (t *tracerImpl) Complete(name string, thread Thread, begin, end uint64) {
241	t.writeEvent(&viewerEvent{
242		Name:  name,
243		Phase: "X",
244		Time:  begin / 1000,
245		Dur:   (end - begin) / 1000,
246		Pid:   0,
247		Tid:   uint64(thread),
248	})
249}
250