3232import java .util .Set ;
3333import java .util .regex .Matcher ;
3434import java .util .regex .Pattern ;
35+ import javax .annotation .Nullable ;
3536
3637/**
3738 * A {@link DataProvider} that supplies the duration spent queuing for remote execution within the
@@ -64,85 +65,90 @@ CriticalPathQueuingDuration getCriticalPathQueuingDuration()
6465 if (bazelProfile .getCriticalPath ().isEmpty ()) {
6566 return new CriticalPathQueuingDuration (EMPTY_REASON );
6667 }
67- bazelProfile
68- .getCriticalPath ()
69- .get ()
70- .getCompleteEvents ()
71- .forEach (
72- (criticalPathEvent ) -> {
73- Matcher m = CRITICAL_PATH_TO_EVENT_NAME .matcher (criticalPathEvent .name );
74- if (m .matches ()) {
75- String eventNameToFind = m .group (1 );
76- bazelProfile
77- .getThreads ()
78- .flatMap ((thread ) -> thread .getCompleteEvents ().stream ())
79- // Name should match, and event interval should be contained in
80- // criticalPathEvent interval.
81- .filter (
82- (event ) ->
83- BazelProfileConstants .CAT_ACTION_PROCESSING .equals (event .category )
84- && eventNameToFind .equals (event .name )
85- // If "action processing" is the first event, the timestamp
86- // may be slightly out of sync with the critical path event.
87- && (criticalPathEvent .start .almostEquals (event .start )
88- ||
89- // It may not be the first event, e.g.
90- // "action dependency checking" may be reported before
91- criticalPathEvent .start .compareTo (event .start ) > 0 )
92- // Keep this always-true-condition for documentation purposes!
93- // We have found cases where the end time of the critical path
94- // event is less than the end time of the processing event.
95- // This might be a bug / inconsistency in Bazel profile writing.
96- && (true
97- || criticalPathEvent .end .almostEquals (event .end )
98- || criticalPathEvent .end .compareTo (event .end ) > 0 ))
99- // We expect to find just one event, but this may not be true for more
100- // generic action names. Sort all thus far matching events to find the best
101- // match.
102- .sorted (
103- (a , b ) -> {
104- boolean aWithinBounds =
105- criticalPathEvent .end .almostEquals (a .end )
106- || criticalPathEvent .end .compareTo (a .end ) > 0 ;
107- boolean bWithinBounds =
108- criticalPathEvent .end .almostEquals (b .end )
109- || criticalPathEvent .end .compareTo (b .end ) > 0 ;
110- if (aWithinBounds && bWithinBounds ) {
111- // Both events within bounds, prefer the longer one.
112- return b .duration .compareTo (a .duration );
113- }
114- // If one of the events is within the bounds, prefer it.
115- if (aWithinBounds ) {
116- return -1 ;
117- }
118- if (bWithinBounds ) {
119- return 1 ;
120- }
121- // Neither event within bounds, prefer the one that extends the bounds
122- // least.
123- return a .end .compareTo (b .end );
124- })
125- .limit (1 )
126- .forEach (
127- e -> {
128- // As we could not check the end boundary above, adjust the duration here,
129- // so that we can ensure queuing events do not exceed the boundaries of
130- // the critical path entry.
131- Timestamp end =
132- Timestamp .ofMicros (
133- Math .min (e .end .getMicros (), criticalPathEvent .end .getMicros ()));
134- criticalPathEventsInThreads .add (
135- new CompleteEvent (
136- e .name ,
137- e .category ,
138- e .start ,
139- TimeUtil .getDurationBetween (e .start , end ),
140- e .threadId ,
141- e .processId ,
142- e .args ));
143- });
144- }
145- });
68+ for (var cPathEvent : bazelProfile .getCriticalPath ().get ().getCompleteEvents ()) {
69+ Matcher m = CRITICAL_PATH_TO_EVENT_NAME .matcher (cPathEvent .name );
70+ if (!m .matches ()) {
71+ continue ;
72+ }
73+ var eventNameToFind = m .group (1 );
74+ @ Nullable CompleteEvent found = null ;
75+ var foundWithinBounds = false ;
76+ for (var thread : bazelProfile .getThreadList ()) {
77+ for (var event : thread .getCompleteEvents ()) {
78+ // Name should match, and event interval should be contained in cPathEvent interval.
79+ if (!BazelProfileConstants .CAT_ACTION_PROCESSING .equals (event .category )) {
80+ continue ;
81+ }
82+ if (!eventNameToFind .equals (event .name )) {
83+ continue ;
84+ }
85+ // If "action processing" is the first event, the timestamp
86+ // may be slightly out of sync with the critical path event.
87+ //
88+ // It may not be the first event, e.g.
89+ // "action dependency checking" may be reported before
90+ if (!cPathEvent .start .almostEquals (event .start )
91+ && cPathEvent .start .compareTo (event .start ) <= 0 ) {
92+ continue ;
93+ }
94+ // We have found cases where the end time of the critical path event is less than the end
95+ // time of the processing event. This might be a bug / inconsistency in Bazel profile
96+ // writing.
97+ if (!cPathEvent .end .almostEquals (event .end ) && cPathEvent .end .compareTo (event .end ) <= 0 ) {
98+ continue ;
99+ }
100+
101+ if (found == null ) {
102+ found = event ;
103+ foundWithinBounds =
104+ cPathEvent .end .almostEquals (found .end ) || cPathEvent .end .compareTo (found .end ) > 0 ;
105+ continue ;
106+ }
107+
108+ // We expect to find just one event, but this may not be true for more generic action
109+ // names. Sort all thus far matching events to find the best match.
110+ var eventWithinBounds =
111+ cPathEvent .end .almostEquals (event .end ) || cPathEvent .end .compareTo (event .end ) > 0 ;
112+
113+ if (foundWithinBounds && eventWithinBounds ) {
114+ // Both events within bounds, prefer the longer one.
115+ if (event .duration .compareTo (found .duration ) > 0 ) {
116+ found = event ;
117+ foundWithinBounds = true ;
118+ }
119+ continue ;
120+ }
121+ // If one of the events is within the bounds, prefer it.
122+ if (eventWithinBounds ) {
123+ found = event ;
124+ foundWithinBounds = true ;
125+ continue ;
126+ }
127+ // Neither event within bounds, prefer the one that extends the bounds
128+ // least.
129+ if (found .end .compareTo (event .end ) < 0 ) {
130+ found = event ;
131+ foundWithinBounds = false ;
132+ }
133+ }
134+ }
135+ if (found != null ) {
136+ // As we could not check the end boundary above, adjust the duration here,
137+ // so that we can ensure queuing events do not exceed the boundaries of
138+ // the critical path entry.
139+ Timestamp end =
140+ Timestamp .ofMicros (Math .min (found .end .getMicros (), cPathEvent .end .getMicros ()));
141+ criticalPathEventsInThreads .add (
142+ new CompleteEvent (
143+ found .name ,
144+ found .category ,
145+ found .start ,
146+ TimeUtil .getDurationBetween (found .start , end ),
147+ found .threadId ,
148+ found .processId ,
149+ found .args ));
150+ }
151+ }
146152 Duration duration =
147153 bazelProfile
148154 .getThreads ()
@@ -161,7 +167,7 @@ CriticalPathQueuingDuration getCriticalPathQueuingDuration()
161167 && cpEvent .processId == event .processId
162168 && (cpEvent .start .compareTo (event .start ) <= 0 )
163169 && (event .end .almostEquals (cpEvent .end )
164- || (event .end .compareTo (cpEvent .end ) <= 0 ))))
170+ || (event .end .compareTo (cpEvent .end ) <= 0 ))))
165171 .map ((event ) -> event .duration )
166172 .reduce (Duration .ZERO , Duration ::plus );
167173 return new CriticalPathQueuingDuration (duration );
0 commit comments