Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-38536

Execution time of parallel blocks of in-flight jobs wrong

    XMLWordPrintable

    Details

    • Similar Issues:

      Description

      Desired behaviour

      • Duration should be 20s for the whole pipeline.
      • ed1 node duration should be 20s
      • ed2 node duration should be 10s

      Undesired behaviour

      • Duration should be 20s for the whole pipeline.
      • ed1 node duration should be 20s
      • ed2 node duration should be 10s but is reported as 20s

      Example

      def map = [:]
      
      map['ed1'] = {
          node() {
              sleep 20
          }
      }
      
      map['ed2'] = {
          node() {
              sleep 10
          }
      }
      
      stage('Stage 1') {
          parallel map
      }
      

      Original request
      Hi,

      the execution time of a stage containing two parallel jobs shows, after the first job has finished, only the execution time of the first job, as long as the second job is running.
      After the second job has finished, the displayed time is updated to the right runtime.

      It would be nice if the time could be right during the execution of the job as well.

        Attachments

          Issue Links

            Activity

            Hide
            svanoort Sam Van Oort added a comment - - edited

            Cornelius Riemenschneider You are correct, I have reproduced this. It appears we have a small bug with the handling of partially-completed parallels: we explore branches in order of declaration (the next update to workflow-api reverses this behavior to be consistent with the order of iteration).

            Dense implementation details following:

            I think the fix is a subtle one in the workflow-api visitSimpleChunk method (which stage view consumes downstream) or in stage view itself: for the last stage, if there are multiple heads (currently in-scope nominally running FlowNodes, i.e. branches of a parallel), set the last node to whichever of the nodes is really still executing (not just the BlockEndNode denoting the end of the parallel). Then status & timing computations for the stage will use the right end node and return correct timing.

            Show
            svanoort Sam Van Oort added a comment - - edited Cornelius Riemenschneider You are correct, I have reproduced this. It appears we have a small bug with the handling of partially-completed parallels: we explore branches in order of declaration (the next update to workflow-api reverses this behavior to be consistent with the order of iteration). Dense implementation details following: I think the fix is a subtle one in the workflow-api visitSimpleChunk method (which stage view consumes downstream) or in stage view itself: for the last stage, if there are multiple heads (currently in-scope nominally running FlowNodes, i.e. branches of a parallel), set the last node to whichever of the nodes is really still executing (not just the BlockEndNode denoting the end of the parallel). Then status & timing computations for the stage will use the right end node and return correct timing.
            Hide
            scm_issue_link SCM/JIRA link daemon added a comment -

            Code changed in jenkins
            User: Sam Van Oort
            Path:
            pom.xml
            src/main/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScanner.java
            src/test/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScannerTest.java
            http://jenkins-ci.org/commit/workflow-api-plugin/2ac612a4de00f0cf26bcad66bd2fd3a6eb5c120e
            Log:
            Test and fix for wrong order for in-progress parallels JENKINS-38536

            Show
            scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Sam Van Oort Path: pom.xml src/main/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScanner.java src/test/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScannerTest.java http://jenkins-ci.org/commit/workflow-api-plugin/2ac612a4de00f0cf26bcad66bd2fd3a6eb5c120e Log: Test and fix for wrong order for in-progress parallels JENKINS-38536
            Hide
            scm_issue_link SCM/JIRA link daemon added a comment -

            Code changed in jenkins
            User: Sam Van Oort
            Path:
            pom.xml
            src/main/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScanner.java
            src/test/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScannerTest.java
            http://jenkins-ci.org/commit/workflow-api-plugin/eca21af30bcf90e4a7ae29c14747ebdfedd8d84b
            Log:
            Merge pull request #20 from jenkinsci/final-parallel-branch-ordering

            Ensure that for SimpleBlockVisitor we find the REAL last branch for a parallel JENKINS-38536

            Compare: https://github.com/jenkinsci/workflow-api-plugin/compare/92ab59a0cff1...eca21af30bcf

            Show
            scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Sam Van Oort Path: pom.xml src/main/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScanner.java src/test/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScannerTest.java http://jenkins-ci.org/commit/workflow-api-plugin/eca21af30bcf90e4a7ae29c14747ebdfedd8d84b Log: Merge pull request #20 from jenkinsci/final-parallel-branch-ordering Ensure that for SimpleBlockVisitor we find the REAL last branch for a parallel JENKINS-38536 Compare: https://github.com/jenkinsci/workflow-api-plugin/compare/92ab59a0cff1...eca21af30bcf
            Hide
            svanoort Sam Van Oort added a comment -

            Another fix yielded the full solution (combined with this one). Ready for release now.

            Show
            svanoort Sam Van Oort added a comment - Another fix yielded the full solution (combined with this one). Ready for release now.
            Hide
            svanoort Sam Van Oort added a comment -

            Pending release as v2.8

            Show
            svanoort Sam Van Oort added a comment - Pending release as v2.8
            Hide
            jamesdumay James Dumay added a comment -

            Sam Van Oort if its not too much trouble are you able to verify that this fixes JENKINS-39158 ?

            Show
            jamesdumay James Dumay added a comment - Sam Van Oort if its not too much trouble are you able to verify that this fixes JENKINS-39158 ?
            Hide
            svanoort Sam Van Oort added a comment -

            released as workflow-api 2.8

            Show
            svanoort Sam Van Oort added a comment - released as workflow-api 2.8
            Hide
            jochenafuerbacher Jochen A. Fürbacher added a comment -

            Even with workflow-api 2.8 the problem still occurs.

            Show
            jochenafuerbacher Jochen A. Fürbacher added a comment - Even with workflow-api 2.8 the problem still occurs.
            Hide
            jamesdumay James Dumay added a comment - - edited

            Jochen A. Fürbacher would you be able to provide a sample Jenkinsfile that exercises the behaviour you are seeing?

            Show
            jamesdumay James Dumay added a comment - - edited Jochen A. Fürbacher would you be able to provide a sample Jenkinsfile that exercises the behaviour you are seeing?
            Hide
            jochenafuerbacher Jochen A. Fürbacher added a comment -
            node() {
                
                stage('Stage 1') {
                    
                    parallel (
                        el1: { sleep 20 },
                        el2: { sleep 10 }
                    )
                }
            }
            
            Show
            jochenafuerbacher Jochen A. Fürbacher added a comment - node() { stage( 'Stage 1' ) { parallel ( el1: { sleep 20 }, el2: { sleep 10 } ) } }
            Hide
            scm_issue_link SCM/JIRA link daemon added a comment -

            Code changed in jenkins
            User: Sam Van Oort
            Path:
            rest-api/pom.xml
            rest-api/src/main/java/com/cloudbees/workflow/rest/external/ChunkVisitor.java
            rest-api/src/main/java/com/cloudbees/workflow/rest/external/ErrorExt.java
            rest-api/src/test/java/com/cloudbees/workflow/rest/endpoints/JobAndRunAPITest.java
            http://jenkins-ci.org/commit/pipeline-stage-view-plugin/ead4a5d7542f31929e401b743c060721e38b33b1
            Log:
            Merge pull request #38 from jenkinsci/fix-incomplete-parallel-final-order

            Fix finding the end of the fhinal chunk in the presence of incomplete parallel branches JENKINS-38536

            Compare: https://github.com/jenkinsci/pipeline-stage-view-plugin/compare/0045b78dc3fc...ead4a5d7542f

            Show
            scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Sam Van Oort Path: rest-api/pom.xml rest-api/src/main/java/com/cloudbees/workflow/rest/external/ChunkVisitor.java rest-api/src/main/java/com/cloudbees/workflow/rest/external/ErrorExt.java rest-api/src/test/java/com/cloudbees/workflow/rest/endpoints/JobAndRunAPITest.java http://jenkins-ci.org/commit/pipeline-stage-view-plugin/ead4a5d7542f31929e401b743c060721e38b33b1 Log: Merge pull request #38 from jenkinsci/fix-incomplete-parallel-final-order Fix finding the end of the fhinal chunk in the presence of incomplete parallel branches JENKINS-38536 Compare: https://github.com/jenkinsci/pipeline-stage-view-plugin/compare/0045b78dc3fc...ead4a5d7542f
            Hide
            svanoort Sam Van Oort added a comment -

            Fixed with explicit test coverage in workflow-api 2.12 + pipeline-stage-view 2.26 – this should be dead, for good.

            Show
            svanoort Sam Van Oort added a comment - Fixed with explicit test coverage in workflow-api 2.12 + pipeline-stage-view 2.26 – this should be dead, for good.
            Hide
            bth Bruno Thomsen added a comment -

            I can still reproduce this bug when using the parallel map construct.
            Jenkinsfile that can reproduce behaviour:

            #!/usr/bin/env groovy
            
            def map = [:]
            
            map['ed1'] = {
                node() {
                    sleep 20
                }
            }
            
            map['ed2'] = {
                node() {
                    sleep 10
                }
            }
            
            stage('Stage 1') {
                parallel map
            }
            

             
            It looks like "ed2"-step text is updated from "Passed in 10s" to "Passed in 20s" when "ed1"-step completes.

            Show
            bth Bruno Thomsen added a comment - I can still reproduce this bug when using the parallel map construct. Jenkinsfile that can reproduce behaviour: #!/usr/bin/env groovy def map = [:] map['ed1'] = {     node() {         sleep 20     } } map['ed2'] = {     node() {         sleep 10     } } stage('Stage 1') {     parallel map }   It looks like "ed2"-step text is updated from "Passed in 10s" to "Passed in 20s" when "ed1"-step completes.
            Hide
            bth Bruno Thomsen added a comment -

            The parallel step execution time is shown wrong both in classic Jenkins Stage View and in Blue Ocean pipeline view.

            "ed1"-step execution time is shown correct:

            "ed2"-step execution time is shown wrong:

            Show
            bth Bruno Thomsen added a comment - The parallel step execution time is shown wrong both in classic Jenkins Stage View and in Blue Ocean pipeline view. "ed1"-step execution time is shown correct: "ed2"-step execution time is shown wrong:
            Hide
            jamesdumay James Dumay added a comment -

            Bruno Thomsen could you please provide an example Jenkinsfile to reproduce that problem? I can then take this to pipeline developers for investigation

            Show
            jamesdumay James Dumay added a comment - Bruno Thomsen could you please provide an example Jenkinsfile to reproduce that problem? I can then take this to pipeline developers for investigation
            Hide
            bth Bruno Thomsen added a comment -

            This Jenkinsfile example can reproduce the issue shown by the screenshots:

            #!/usr/bin/env groovy
            
            def map = [:]
            
            map['ed1'] = {
                node() {
                    sleep 20
                }
            }
            
            map['ed2'] = {
                node() {
                    sleep 10
                }
            }
            
            stage('Stage 1') {
                parallel map
            }

            It was also posted in this comment:

            https://issues.jenkins-ci.org/browse/JENKINS-38536?focusedCommentId=297557&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-297557

            Show
            bth Bruno Thomsen added a comment - This Jenkinsfile example can reproduce the issue shown by the screenshots: #!/usr/bin/env groovy def map = [:] map['ed1'] = {     node() {         sleep 20     } } map['ed2'] = {     node() {         sleep 10     } } stage('Stage 1') {     parallel map } It was also posted in this comment: https://issues.jenkins-ci.org/browse/JENKINS-38536?focusedCommentId=297557&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-297557
            Hide
            jamesdumay James Dumay added a comment -

            Thanks Bruno Thomsen ill have someone take a look

            Show
            jamesdumay James Dumay added a comment - Thanks Bruno Thomsen ill have someone take a look
            Hide
            jamesdumay James Dumay added a comment - - edited

            Bruno Thomsen I just ran this locally on my instance (using Blue Ocean 1.1.0-beta4) and I had both parallels for the example Jenkinsfile you provided have their duration reported as 20 seconds.

            Yes, there is a bug here.

            There is a bug that will mean you will have to refresh Blue Ocean to get update durations but we will fix that in JENKINS-43746.

            Show
            jamesdumay James Dumay added a comment - - edited Bruno Thomsen I just ran this locally on my instance (using Blue Ocean 1.1.0-beta4) and I had both parallels for the example Jenkinsfile you provided have their duration reported as 20 seconds. Yes, there is a bug here. There is a bug that will mean you will have to refresh Blue Ocean to get update durations but we will fix that in JENKINS-43746 .
            Hide
            svanoort Sam Van Oort added a comment -

            I've been working on this again for a while, but just making sure the status tracks that now.

            Show
            svanoort Sam Van Oort added a comment - I've been working on this again for a while, but just making sure the status tracks that now.
            Hide
            scm_issue_link SCM/JIRA link daemon added a comment -

            Code changed in jenkins
            User: Sam Van Oort
            Path:
            pom.xml
            src/test/java/org/jenkinsci/plugins/workflow/pipelinegraphanalysis/NoOpChunkFinder.java
            src/test/java/org/jenkinsci/plugins/workflow/pipelinegraphanalysis/StatusAndTimingTest.java
            src/test/java/org/jenkinsci/plugins/workflow/pipelinegraphanalysis/TestVisitor.java
            http://jenkins-ci.org/commit/pipeline-graph-analysis-plugin/1bcd313fad5b721ea8f2dbefb68e8e8d01f0e35e
            Log:
            Verify fix for timing of parallels with single long steps JENKINS-38536

            Show
            scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Sam Van Oort Path: pom.xml src/test/java/org/jenkinsci/plugins/workflow/pipelinegraphanalysis/NoOpChunkFinder.java src/test/java/org/jenkinsci/plugins/workflow/pipelinegraphanalysis/StatusAndTimingTest.java src/test/java/org/jenkinsci/plugins/workflow/pipelinegraphanalysis/TestVisitor.java http://jenkins-ci.org/commit/pipeline-graph-analysis-plugin/1bcd313fad5b721ea8f2dbefb68e8e8d01f0e35e Log: Verify fix for timing of parallels with single long steps JENKINS-38536
            Hide
            scm_issue_link SCM/JIRA link daemon added a comment -

            Code changed in jenkins
            User: Sam Van Oort
            Path:
            pom.xml
            src/main/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScanner.java
            src/test/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScannerTest.java
            http://jenkins-ci.org/commit/workflow-api-plugin/c591aef1002b6fc3a4313e99dc5e2861338250d8
            Log:
            Merge pull request #39 from jenkinsci/fix-bismuth-long-parallelbranch-JENKINS-38536

            Fix finding the last node of a parallel with one long-running step JENKINS-38536

            Compare: https://github.com/jenkinsci/workflow-api-plugin/compare/af2aec2bc46e...c591aef1002b

            Show
            scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Sam Van Oort Path: pom.xml src/main/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScanner.java src/test/java/org/jenkinsci/plugins/workflow/graphanalysis/ForkScannerTest.java http://jenkins-ci.org/commit/workflow-api-plugin/c591aef1002b6fc3a4313e99dc5e2861338250d8 Log: Merge pull request #39 from jenkinsci/fix-bismuth-long-parallelbranch- JENKINS-38536 Fix finding the last node of a parallel with one long-running step JENKINS-38536 Compare: https://github.com/jenkinsci/workflow-api-plugin/compare/af2aec2bc46e...c591aef1002b
            Hide
            scm_issue_link SCM/JIRA link daemon added a comment -

            Code changed in jenkins
            User: Sam Van Oort
            Path:
            pom.xml
            src/main/java/org/jenkinsci/plugins/workflow/pipelinegraphanalysis/StatusAndTiming.java
            src/test/java/org/jenkinsci/plugins/workflow/pipelinegraphanalysis/StatusAndTimingTest.java
            http://jenkins-ci.org/commit/pipeline-graph-analysis-plugin/7d58d361764f8b71c2ca17a22aa560feb31fc6ce
            Log:
            Merge pull request #10 from jenkinsci/verify-timing-for-incomplete-parallels

            Further verify timing for incomplete parallels fix from JENKINS-38536

            Compare: https://github.com/jenkinsci/pipeline-graph-analysis-plugin/compare/63866931892a...7d58d361764f

            Show
            scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Sam Van Oort Path: pom.xml src/main/java/org/jenkinsci/plugins/workflow/pipelinegraphanalysis/StatusAndTiming.java src/test/java/org/jenkinsci/plugins/workflow/pipelinegraphanalysis/StatusAndTimingTest.java http://jenkins-ci.org/commit/pipeline-graph-analysis-plugin/7d58d361764f8b71c2ca17a22aa560feb31fc6ce Log: Merge pull request #10 from jenkinsci/verify-timing-for-incomplete-parallels Further verify timing for incomplete parallels fix from JENKINS-38536 Compare: https://github.com/jenkinsci/pipeline-graph-analysis-plugin/compare/63866931892a...7d58d361764f
            Hide
            svanoort Sam Van Oort added a comment -

            Finally resolved with workflow-api 2.17 

            James Dumay   Vivek Pandey Cornelius Riemenschneider

            Show
            svanoort Sam Van Oort added a comment - Finally resolved with workflow-api 2.17  James Dumay   Vivek Pandey   Cornelius Riemenschneider
            Hide
            svanoort Sam Van Oort added a comment -

            Closing since the fix has been released

            Show
            svanoort Sam Van Oort added a comment - Closing since the fix has been released
            Hide
            jamesdumay James Dumay added a comment -

            Sam Van Oort nice one We are going to upgrade to that version for 1.2 in this PR.

            Show
            jamesdumay James Dumay added a comment - Sam Van Oort nice one We are going to upgrade to that version for 1.2 in this PR .
            Hide
            jamesdumay James Dumay added a comment -

            Sam Van Oort I am going to backport this dependency upgrade to our 1.1 branch so we don't have people confused about it.

            Show
            jamesdumay James Dumay added a comment - Sam Van Oort I am going to backport this dependency upgrade to our 1.1 branch so we don't have people confused about it.
            Hide
            svanoort Sam Van Oort added a comment -

            Sounds good to me

            Show
            svanoort Sam Van Oort added a comment - Sounds good to me
            Hide
            jiangty_addepar Damien Jiang added a comment -

            This problem seems to be occurring for us on a newer version of Blue Ocean (Jenkins Core 2.73.3, Blue Ocean 1.4.2 + dependencies, Pipeline 2.5, Pipeline: API 2.26).

            We have a parallel step where each of the individual nodes has a clearly different runtime, but Blue Ocean (and the Blue Ocean API) report all the parallel nodes as having roughly the same runtime (+/- a few ms).

            Show
            jiangty_addepar Damien Jiang added a comment - This problem seems to be occurring for us on a newer version of Blue Ocean (Jenkins Core 2.73.3, Blue Ocean 1.4.2 + dependencies, Pipeline 2.5, Pipeline: API 2.26). We have a parallel step where each of the individual nodes has a clearly different runtime, but Blue Ocean (and the Blue Ocean API) report all the parallel nodes as having roughly the same runtime (+/- a few ms).
            Hide
            jiangty_addepar Damien Jiang added a comment -

            See above comment; this issue is happening for us on the latest version of Blue Ocean.

            Show
            jiangty_addepar Damien Jiang added a comment - See above comment; this issue is happening for us on the latest version of Blue Ocean.
            Hide
            jiangty_addepar Damien Jiang added a comment -

            I created a new ticket to track my issue, which may be different from this one.

            Show
            jiangty_addepar Damien Jiang added a comment - I created a new ticket to track my issue, which may be different from this one.

              People

              • Assignee:
                svanoort Sam Van Oort
                Reporter:
                cri Cornelius Riemenschneider
              • Votes:
                4 Vote for this issue
                Watchers:
                11 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: