Skip to content

Commit ad0c36c

Browse files
tonistiigitonistiigi
authored
Merge pull request moby#5328 from jsternberg/debug-scheduler-refactor
solver: move scheduler debug statements to their own functions
2 parents 9837185 + 2f18b83 commit ad0c36c

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)