Skip to content

Commit 2f18b83

Browse files
jsternbergjsternberg
committed
solver: move scheduler debug statements to their own functions
Move scheduler debug statements to their own functions and in their own file so that scheduler debug statements don't make the scheduler logic more complex to follow. Some of the scheduler logs can be quite long and can make it difficult to follow the code logic. This changes these log statements to `debugSchedulerXXX` where `XXX` is the message that would be printed. Signed-off-by: Jonathan A. Sternberg <[email protected]>
1 parent 1e0f685 commit 2f18b83

File tree

3 files changed

+331
-245
lines changed

3 files changed

+331
-245
lines changed

‎solver/debug.go

Lines changed: 312 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,312 @@
1+
package solver
2+
3+
import (
4+
"context"
5+
"os"
6+
"strings"
7+
"sync"
8+
9+
"github.com/moby/buildkit/solver/internal/pipe"
10+
"github.com/moby/buildkit/util/bklog"
11+
"github.com/tonistiigi/go-csvvalue"
12+
)
13+
14+
var (
15+
debugScheduler = false // TODO: replace with logs in build trace
16+
debugSchedulerSteps = sync.OnceValue(parseSchedulerDebugSteps)
17+
)
18+
19+
func init() {
20+
if os.Getenv("BUILDKIT_SCHEDULER_DEBUG") == "1" {
21+
debugScheduler = true
22+
}
23+
}
24+
25+
func parseSchedulerDebugSteps() []string {
26+
if s := os.Getenv("BUILDKIT_SCHEDULER_DEBUG_STEPS"); s != "" {
27+
fields, err := csvvalue.Fields(s, nil)
28+
if err != nil {
29+
return nil
30+
}
31+
return fields
32+
}
33+
return nil
34+
}
35+
36+
// debugSchedulerCheckEdge determines if this edge should be debugged
37+
// depending on the set environment variables.
38+
func debugSchedulerCheckEdge(e *edge) bool {
39+
if debugScheduler {
40+
return true
41+
}
42+
43+
if steps := debugSchedulerSteps(); len(steps) > 0 {
44+
withParents := strings.HasSuffix(steps[0], "^")
45+
name := strings.TrimSuffix(steps[0], "^")
46+
for _, v := range steps {
47+
if strings.Contains(name, v) {
48+
return true
49+
}
50+
}
51+
52+
if withParents {
53+
for _, vtx := range e.edge.Vertex.Inputs() {
54+
name := strings.TrimSuffix(vtx.Vertex.Name(), "^")
55+
for _, v := range steps {
56+
if strings.Contains(name, v) {
57+
return true
58+
}
59+
}
60+
}
61+
}
62+
}
63+
return false
64+
}
65+
66+
func debugSchedulerSkipMergeDueToDependency(e, origEdge *edge) {
67+
bklog.G(context.TODO()).
68+
WithField("edge_vertex_name", e.edge.Vertex.Name()).
69+
WithField("edge_vertex_digest", e.edge.Vertex.Digest()).
70+
WithField("edge_index", e.edge.Index).
71+
WithField("origEdge_vertex_name", origEdge.edge.Vertex.Name()).
72+
WithField("origEdge_vertex_digest", origEdge.edge.Vertex.Digest()).
73+
WithField("origEdge_index", origEdge.edge.Index).
74+
Debug("skip merge due to dependency")
75+
}
76+
77+
func debugSchedulerSwapMergeDueToOwner(e, origEdge *edge) {
78+
bklog.G(context.TODO()).
79+
WithField("edge_vertex_name", e.edge.Vertex.Name()).
80+
WithField("edge_vertex_digest", e.edge.Vertex.Digest()).
81+
WithField("edge_index", e.edge.Index).
82+
WithField("origEdge_vertex_name", origEdge.edge.Vertex.Name()).
83+
WithField("origEdge_vertex_digest", origEdge.edge.Vertex.Digest()).
84+
WithField("origEdge_index", origEdge.edge.Index).
85+
Debug("swap merge due to owner")
86+
}
87+
88+
func debugSchedulerMergingEdges(src, dest *edge) {
89+
bklog.G(context.TODO()).
90+
WithField("source_edge_vertex_name", src.edge.Vertex.Name()).
91+
WithField("source_edge_vertex_digest", src.edge.Vertex.Digest()).
92+
WithField("source_edge_index", src.edge.Index).
93+
WithField("dest_vertex_name", dest.edge.Vertex.Name()).
94+
WithField("dest_vertex_digest", dest.edge.Vertex.Digest()).
95+
WithField("dest_index", dest.edge.Index).
96+
Debug("merging edges")
97+
}
98+
99+
func debugSchedulerMergingEdgesSkipped(src, dest *edge) {
100+
bklog.G(context.TODO()).
101+
WithField("source_edge_vertex_name", src.edge.Vertex.Name()).
102+
WithField("source_edge_vertex_digest", src.edge.Vertex.Digest()).
103+
WithField("source_edge_index", src.edge.Index).
104+
WithField("dest_vertex_name", dest.edge.Vertex.Name()).
105+
WithField("dest_vertex_digest", dest.edge.Vertex.Digest()).
106+
WithField("dest_index", dest.edge.Index).
107+
Debug("merging edges skipped")
108+
}
109+
110+
func debugSchedulerPreUnpark(e *edge, inc []pipeSender, updates, allPipes []pipeReceiver) {
111+
if e.debug {
112+
debugSchedulerPreUnparkSlow(e, inc, updates, allPipes)
113+
}
114+
}
115+
116+
func debugSchedulerPreUnparkSlow(e *edge, inc []pipeSender, updates, allPipes []pipeReceiver) {
117+
log := bklog.G(context.TODO()).
118+
WithField("edge_vertex_name", e.edge.Vertex.Name()).
119+
WithField("edge_vertex_digest", e.edge.Vertex.Digest()).
120+
WithField("edge_index", e.edge.Index)
121+
122+
log.
123+
WithField("edge_state", e.state).
124+
WithField("req", len(inc)).
125+
WithField("upt", len(updates)).
126+
WithField("out", len(allPipes)).
127+
Debug(">> unpark")
128+
129+
for i, dep := range e.deps {
130+
des := edgeStatusInitial
131+
if dep.req != nil {
132+
des = dep.req.Request().desiredState
133+
}
134+
log.
135+
WithField("dep_index", i).
136+
WithField("dep_vertex_name", e.edge.Vertex.Inputs()[i].Vertex.Name()).
137+
WithField("dep_vertex_digest", e.edge.Vertex.Inputs()[i].Vertex.Digest()).
138+
WithField("dep_state", dep.state).
139+
WithField("dep_desired_state", des).
140+
WithField("dep_keys", len(dep.keys)).
141+
WithField("dep_has_slow_cache", e.slowCacheFunc(dep) != nil).
142+
WithField("dep_preprocess_func", e.preprocessFunc(dep) != nil).
143+
Debug(":: dep")
144+
}
145+
146+
for i, in := range inc {
147+
req := in.Request()
148+
log.
149+
WithField("incoming_index", i).
150+
WithField("incoming_pointer", in).
151+
WithField("incoming_desired_state", req.Payload.desiredState).
152+
WithField("incoming_canceled", req.Canceled).
153+
Debug("> incoming")
154+
}
155+
156+
for i, up := range updates {
157+
if up == e.cacheMapReq {
158+
log.
159+
WithField("update_index", i).
160+
WithField("update_pointer", up).
161+
WithField("update_complete", up.Status().Completed).
162+
Debug("> update cacheMapReq")
163+
} else if up == e.execReq {
164+
log.
165+
WithField("update_index", i).
166+
WithField("update_pointer", up).
167+
WithField("update_complete", up.Status().Completed).
168+
Debug("> update execReq")
169+
} else {
170+
st, ok := up.Status().Value.(*edgeState)
171+
if ok {
172+
index := -1
173+
if dep, ok := e.depRequests[up]; ok {
174+
index = int(dep.index)
175+
}
176+
log.
177+
WithField("update_index", i).
178+
WithField("update_pointer", up).
179+
WithField("update_complete", up.Status().Completed).
180+
WithField("update_input_index", index).
181+
WithField("update_keys", len(st.keys)).
182+
WithField("update_state", st.state).
183+
Debugf("> update edgeState")
184+
} else {
185+
log.
186+
WithField("update_index", i).
187+
Debug("> update unknown")
188+
}
189+
}
190+
}
191+
}
192+
193+
func debugSchedulerPostUnpark(e *edge, inc []pipeSender) {
194+
if e.debug {
195+
debugSchedulerPostUnparkSlow(e, inc)
196+
}
197+
}
198+
199+
func debugSchedulerPostUnparkSlow(e *edge, inc []pipeSender) {
200+
log := bklog.G(context.TODO())
201+
for i, in := range inc {
202+
log.
203+
WithField("incoming_index", i).
204+
WithField("incoming_pointer", in).
205+
WithField("incoming_complete", in.Status().Completed).
206+
Debug("< incoming")
207+
}
208+
log.
209+
WithField("edge_vertex_name", e.edge.Vertex.Name()).
210+
WithField("edge_vertex_digest", e.edge.Vertex.Digest()).
211+
WithField("edge_index", e.edge.Index).
212+
WithField("edge_state", e.state).
213+
Debug("<< unpark")
214+
}
215+
216+
func debugSchedulerNewPipe(e *edge, p *pipe.Pipe[*edgeRequest, any], req *edgeRequest) {
217+
if e.debug {
218+
bklog.G(context.TODO()).Debugf("> newPipe %s %p desiredState=%s", e.edge.Vertex.Name(), p, req.desiredState)
219+
}
220+
}
221+
222+
func debugSchedulerNewFunc(e *edge, p pipeReceiver) {
223+
if e.debug {
224+
bklog.G(context.TODO()).Debugf("> newFunc %p", p)
225+
}
226+
}
227+
228+
func debugSchedulerInconsistentGraphState(ee Edge) {
229+
bklog.G(context.TODO()).
230+
WithField("edge_vertex_name", ee.Vertex.Name()).
231+
WithField("edge_vertex_digest", ee.Vertex.Digest()).
232+
WithField("edge_index", ee.Index).
233+
Error("failed to get edge: inconsistent graph state")
234+
}
235+
236+
func debugSchedulerFinishIncoming(e *edge, err error, req pipeSender) {
237+
if e.debug {
238+
bklog.G(context.TODO()).Debugf("finishIncoming %s %v %#v desired=%s", e.edge.Vertex.Name(), err, e.edgeState, req.Request().Payload.desiredState)
239+
}
240+
}
241+
242+
func debugSchedulerUpdateIncoming(e *edge, req pipeSender) {
243+
if e.debug {
244+
bklog.G(context.TODO()).Debugf("updateIncoming %s %#v desired=%s", e.edge.Vertex.Name(), e.edgeState, req.Request().Payload.desiredState)
245+
}
246+
}
247+
248+
func debugSchedulerUpgradeCacheSlow(e *edge) {
249+
if e.debug {
250+
bklog.G(context.TODO()).Debugf("upgrade to cache-slow because no open keys")
251+
}
252+
}
253+
254+
func debugSchedulerRespondToIncomingStatus(e *edge, allIncomingCanComplete bool) {
255+
if e.debug {
256+
bklog.G(context.TODO()).Debugf("status state=%s cancomplete=%v hasouts=%v noPossibleCache=%v depsCacheFast=%v keys=%d cacheRecords=%d", e.state, allIncomingCanComplete, e.hasActiveOutgoing, e.noCacheMatchPossible, e.allDepsCompletedCacheFast, len(e.keys), len(e.cacheRecords))
257+
}
258+
}
259+
260+
func debugSchedulerCancelInputRequest(e *edge, dep *dep, desiredStateDep edgeStatusType) {
261+
if e.debug {
262+
bklog.G(context.TODO()).
263+
WithField("edge_vertex_name", e.edge.Vertex.Name()).
264+
WithField("edge_vertex_digest", e.edge.Vertex.Digest()).
265+
WithField("dep_index", dep.index).
266+
WithField("dep_req_desired_state", dep.req.Request().desiredState).
267+
WithField("dep_desired_state", desiredStateDep).
268+
WithField("dep_state", dep.state).
269+
Debug("cancel input request")
270+
}
271+
}
272+
273+
func debugSchedulerSkipInputRequestBasedOnExistingRequest(e *edge, dep *dep, desiredStateDep edgeStatusType) {
274+
if e.debug {
275+
bklog.G(context.TODO()).
276+
WithField("edge_vertex_name", e.edge.Vertex.Name()).
277+
WithField("edge_vertex_digest", e.edge.Vertex.Digest()).
278+
WithField("dep_index", dep.index).
279+
WithField("dep_req_desired_state", dep.req.Request().desiredState).
280+
WithField("dep_desired_state", desiredStateDep).
281+
WithField("dep_state", dep.state).
282+
Debug("skip input request based on existing request")
283+
}
284+
}
285+
286+
func debugSchedulerAddInputRequest(e *edge, dep *dep, desiredStateDep edgeStatusType) {
287+
if e.debug {
288+
bklog.G(context.TODO()).
289+
WithField("edge_vertex_name", e.edge.Vertex.Name()).
290+
WithField("edge_vertex_digest", e.edge.Vertex.Digest()).
291+
WithField("dep_index", dep.index).
292+
WithField("dep_desired_state", desiredStateDep).
293+
WithField("dep_state", dep.state).
294+
WithField("dep_vertex_name", e.edge.Vertex.Inputs()[dep.index].Vertex.Name()).
295+
WithField("dep_vertex_digest", e.edge.Vertex.Inputs()[dep.index].Vertex.Digest()).
296+
Debug("add input request")
297+
}
298+
}
299+
300+
func debugSchedulerSkipInputRequestBasedOnDepState(e *edge, dep *dep, desiredStateDep edgeStatusType) {
301+
if e.debug {
302+
bklog.G(context.TODO()).
303+
WithField("edge_vertex_name", e.edge.Vertex.Name()).
304+
WithField("edge_vertex_digest", e.edge.Vertex.Digest()).
305+
WithField("dep_index", dep.index).
306+
WithField("dep_desired_state", desiredStateDep).
307+
WithField("dep_state", dep.state).
308+
WithField("dep_vertex_name", e.edge.Vertex.Inputs()[dep.index].Vertex.Name()).
309+
WithField("dep_vertex_digest", e.edge.Vertex.Inputs()[dep.index].Vertex.Digest()).
310+
Debug("skip input request based on dep state")
311+
}
312+
}

0 commit comments

Comments
 (0)