Improve support bundle data for running Pipelines, update support bundle component names and file paths, and update log warning for a particular type of error during step completion #916

dwnusbaum · 2024-08-08T20:21:15Z

Relates to #892, jenkinsci/workflow-api-plugin#347, and jenkinsci/workflow-api-plugin#349.

Recently I have seen two cases where the CPS VM thread task queue is either very backed up or completely stuck for some builds, leading to various problems. It is currently difficult to detect this state without either running Groovy scripts that use reflection to access internal state of SingleLaneExecutorService or analyzing a heap dump. I think it is worth tracking both the amount of time that a build spends waiting for queued tasks to start as well as the current number of queued tasks.

Here is an example of pipeline-thread-dump.txt with the data from this PR:

Build: p #39
Started: 2024-08-12T20:08:44.701Z
Duration: PT7.651134S
Timings:
  classLoad	33ms
  flowNode	69ms
  parse	69ms
  run	177ms
  runQueue	417ms
  saveProgram	50ms
Active operations:
  run	1	7326ms
  runQueue	7	51535ms
Approximate graph size: 11
Thread #5
	at DSL.sleep(sleeping for another 52 sec)
	at WorkflowScript.run(WorkflowScript:3)
	at DSL.parallel(Native Method)
	at WorkflowScript.run(WorkflowScript:1)
Thread #6
	at WorkflowScript.run(WorkflowScript:5)
Thread #7
	at WorkflowScript.run(WorkflowScript:7)
Thread #8
	at WorkflowScript.run(WorkflowScript:9)

Testing done

Submitter checklist

Make sure you are opening from a topic/feature/bugfix branch (right side) and not your main branch!
Ensure that the pull request title represents the desired changelog entry
Please describe what you did
Link to relevant issues in GitHub or Jira
Link to relevant pull requests, esp. upstream and downstream changes
Ensure you have provided tests - that demonstrates feature works or fixes the issue

plugin/src/main/java/org/jenkinsci/plugins/workflow/cps/CpsVmExecutorService.java

…f in progress operations

…r to reflect its severity

dwnusbaum · 2024-08-12T20:13:36Z

plugin/src/main/java/org/jenkinsci/plugins/workflow/cps/CpsStepContext.java

+            // TODO: If the problem is with the FlowNode and not the CpsFlowExecution, should we try to call
+            // CpsVmExecutorService.reportProblem or CpsFlowExecution.croak to kill the build right away?
+            LOGGER.log(Level.WARNING, "Unable to load FlowNode or CpsFlowExecution when completing " + this + ", which is likely to cause its execution to hang indefinitely", x);


We do not have any tests in this plugin which enter this catch block, and the only case where I ever saw it was while manually creating broken Pipelines while investigating jenkinsci/workflow-api-plugin#349. I think for now it is good enough to just update the log message, and if we see it come up when investigating stuck Pipelines in the future, then it might be worth investigating further.

dwnusbaum · 2024-08-12T20:19:51Z

plugin/src/main/java/org/jenkinsci/plugins/workflow/cps/CpsFlowExecution.java

+    /** instances of {@link Timing} which have not yet completed for reporting counts and durations in support bundles. Never persisted. */
+    transient @NonNull Set<Timing> liveIncompleteTimings = ConcurrentHashMap.newKeySet();


I considered a few different approaches, like using metrics or refactoring liveTimings, but in the end this seemed like the best way to report useful information about ongoing operations while keeping things simple and similar to what we already do. I don't see any benefit to persisting this data since it only applies to actively running tasks - once the build completes it should be empty, barring any cleanup-related bugs.

dwnusbaum · 2024-08-12T20:23:32Z

plugin/src/main/java/org/jenkinsci/plugins/workflow/cps/CpsThreadDumpAction.java

@@ -108,13 +118,47 @@ public CpsThreadDump getThreadDump() {

        @Override public void addContents(Container container) {
            container.add(new Content("nodes/master/pipeline-thread-dump.txt") {


Is it worth updating the display name and file name to be more generic, and/or moving this to a distinct class, or should we just keep it? Users may be used to the current display name, and there may be some CloudBees-internal automation which expects the current file name, but I am not sure.

Unclear to me how this related to the existing pipeline-timings.txt. Should we consolidate?

One is for completed builds, one is for running builds. If I was going to rename both of them, I would do this:

"Timing data about recently completed Pipeline builds"/pipeline-timings.txt would become "Recently completed Pipeline builds"/pipeline-recent-builds.txt

"Thread dumps of running Pipeline builds"/pipeline-thread-dump.txt would become "Running Pipeline builds"/pipeline-running-builds.txt

We could combine them into a single "Pipeline builds"/pipelines.txt component, but I think keeping running and completed builds separate seems clearest.

I would do this

Seems reasonable. Anyway, this is fine as is, just trying to clarify.

I did some GitHub searches for usage of these exact strings and checked with CloudBees support about support bundle automation and didn't find anything problematic, so I will go ahead and update the names here.

EDIT: Also, the IDs that keep track of which Components are active are based on the simple class name of the Component by default, so I will just leave the class names as-is and keep them where they are.

See e8af1ac.

jglick · 2024-08-13T00:35:54Z

plugin/src/main/java/org/jenkinsci/plugins/workflow/cps/CpsThreadDumpAction.java

@@ -108,13 +118,47 @@ public CpsThreadDump getThreadDump() {

        @Override public void addContents(Container container) {
            container.add(new Content("nodes/master/pipeline-thread-dump.txt") {


Unclear to me how this related to the existing pipeline-timings.txt. Should we consolidate?

jglick · 2024-08-13T00:36:51Z

plugin/src/main/java/org/jenkinsci/plugins/workflow/cps/CpsThreadDumpAction.java

+                                var started = Instant.ofEpochMilli(run.getStartTimeInMillis());
+                                pw.println("Started: " + started);
+                                var duration = Duration.between(started, Instant.now());
+                                pw.print("Duration: " + duration);


Not very legible; consider Util.getTimeSpanString (IIRC).

Yes, this is subjective (personally I like ISO 8601 in contexts like this). Mainly I did not use getTimeSpanString to avoid localization.

… generic

jglick

Clearer, thanks.

Track CPS VM thread queue size and task execution times

936f2bc

dwnusbaum commented Aug 8, 2024

View reviewed changes

dwnusbaum mentioned this pull request Aug 8, 2024

Prevent StepExecutionIterator from leaking memory in cases where a single processed execution has a stuck CPS VM thread jenkinsci/workflow-api-plugin#347

Merged

6 tasks

dwnusbaum added 3 commits August 12, 2024 15:15

Track time spent waiting in the CPS VM thread as well as the number o…

9b277cf

…f in progress operations

Adjust log message in CpsStepContext.scheduleNextRun exception handle…

3775801

…r to reflect its severity

Merge branch 'master' into cps-vm-thread-metrics

a3db23e

dwnusbaum force-pushed the cps-vm-thread-metrics branch from e0ec99a to a3db23e Compare August 12, 2024 19:15

dwnusbaum changed the title ~~Track CPS VM thread queue size and task execution times via metrics~~ Improve support bundle data for running Pipelines and update log warning for a particular type of error during step completion Aug 12, 2024

dwnusbaum added 3 commits August 12, 2024 16:12

Track durations of active operations, not just counts

698be19

Avoid leaking this in Timing constructor

61f14f5

Revert accidental Javadoc change to minimize diff

60a014c

dwnusbaum commented Aug 12, 2024

View reviewed changes

dwnusbaum added the enhancement label Aug 12, 2024

dwnusbaum marked this pull request as ready for review August 12, 2024 20:32

dwnusbaum requested a review from a team as a code owner August 12, 2024 20:32

dwnusbaum mentioned this pull request Aug 12, 2024

Avoid infinite loops due to corrupted flow graphs in some cases and improve resumption error handling jenkinsci/workflow-api-plugin#349

Merged

6 tasks

jglick reviewed Aug 13, 2024

View reviewed changes

jglick approved these changes Aug 13, 2024

View reviewed changes

Update names of Pipeline-related support bundle components to be more…

e8af1ac

… generic

dwnusbaum requested review from jglick and a team August 13, 2024 19:24

jglick approved these changes Aug 13, 2024

View reviewed changes

dwnusbaum merged commit 3519a32 into jenkinsci:master Aug 15, 2024
16 checks passed

dwnusbaum deleted the cps-vm-thread-metrics branch August 15, 2024 16:46

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve support bundle data for running Pipelines, update support bundle component names and file paths, and update log warning for a particular type of error during step completion #916

Improve support bundle data for running Pipelines, update support bundle component names and file paths, and update log warning for a particular type of error during step completion #916

dwnusbaum commented Aug 8, 2024 •

edited

Loading

dwnusbaum Aug 12, 2024

dwnusbaum Aug 12, 2024

dwnusbaum Aug 12, 2024

jglick Aug 13, 2024

dwnusbaum Aug 13, 2024 •

edited

Loading

jglick Aug 13, 2024

dwnusbaum Aug 13, 2024 •

edited

Loading

dwnusbaum Aug 13, 2024

jglick Aug 13, 2024

jglick Aug 13, 2024

dwnusbaum Aug 13, 2024

jglick left a comment

		/** instances of {@link Timing} which have not yet completed for reporting counts and durations in support bundles. Never persisted. */
		transient @NonNull Set<Timing> liveIncompleteTimings = ConcurrentHashMap.newKeySet();

		@@ -108,13 +118,47 @@ public CpsThreadDump getThreadDump() {

		@Override public void addContents(Container container) {
		container.add(new Content("nodes/master/pipeline-thread-dump.txt") {

Improve support bundle data for running Pipelines, update support bundle component names and file paths, and update log warning for a particular type of error during step completion #916

Improve support bundle data for running Pipelines, update support bundle component names and file paths, and update log warning for a particular type of error during step completion #916

Conversation

dwnusbaum commented Aug 8, 2024 • edited Loading

Testing done

Submitter checklist

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dwnusbaum Aug 13, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dwnusbaum Aug 13, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jglick left a comment

Choose a reason for hiding this comment

dwnusbaum commented Aug 8, 2024 •

edited

Loading

dwnusbaum Aug 13, 2024 •

edited

Loading

dwnusbaum Aug 13, 2024 •

edited

Loading