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

Each postBuildStep block takes 1 second to evaluate, DSL seed jobs went up from 10mins to 1 hour

    Details

    • Similar Issues:

      Description

      We were using post build script old version, and just upgraded to the new version which looks great. Thanks!

      We're using postBuildScript with Job DSL. Each "postBuildStep" in the postBuildScripts takes 1 full second just to evaluate (note: not the generation, just the evaluation of this single block takes 1s). We are generating around 1500 jobs, each with 3 post build steps, and the Seed jobs are now taking more than an hour to run.

      Sample DSL and output below.

      println "    ${ZonedDateTime.now()} postbuildscript start"
      postBuildScript {
        markBuildUnstable(true)
        buildSteps {
          postBuildStep {
            results(Arrays.asList("SUCCESS", "UNSTABLE", "FAILURE", "NOT_BUILT", "ABORTED"))
            role("SLAVE")
            buildSteps {
              scriptBuildStep {
                buildStepId("[redacted]")
                scriptBuildStepArgs {
                  defineArgs(false)
                  tokenized(false)
                }
              }
            }
          }
          postBuildStep {
            results(Arrays.asList("SUCCESS"))
            role("SLAVE")
            buildSteps {
              shell {
                command("[redacted]")
              }
            }
          }
          postBuildStep {
            results(Arrays.asList("FAILURE"))
            role("SLAVE")
            buildSteps {
              shell {
                command("[redacted]")
              }
            }
          }
        }
      }
      println "    ${ZonedDateTime.now()} postbuildscript end"
      

      Output:

      2018-01-25T23:13:38.246+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:13:41.355+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:13:41.597+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:13:44.180+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:13:44.561+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:13:48.403+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:13:48.592+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:13:51.224+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:13:51.405+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:13:53.573+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:13:53.688+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:13:55.221+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:13:55.333+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:13:56.841+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:13:56.982+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:13:59.251+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:13:59.410+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:14:01.732+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:14:01.886+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:14:04.231+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:14:04.375+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:14:06.656+01:00[Europe/Berlin] postbuildscript end
      2018-01-25T23:14:06.797+01:00[Europe/Berlin] postbuildscript start
      2018-01-25T23:14:09.167+01:00[Europe/Berlin] postbuildscript end
      

      During this time, Jenkins master is found to use constant 25% of CPU as well. We tested this after putting Jenkins on maintenance mode, so only this job takes 25% of CPU on master.

      We have confirmed after multiple attempts that each postBuildStep takes 1 second to evaluate. If we have two postBuildSteps, the logs are printed 2s apart. 1 step and logs take 1s, etc.

      Any ideas what can be going wrong?

        Attachments

          Activity

          Hide
          fm4zyqnfbbfpim Subhas Dandapani added a comment -

          Hi Daniel Heid thanks

          I have a simple "shell" example also above with same 1second response times.

          I see the same with not just scriptBuildStep (which is "config file" plugin) - but basically any buildStep inside postBuildScripts, hence the type of the buildStep doesn't seem to change anything Would you like me to post results with any other buildStep other than "shell" to cross check?

          Show
          fm4zyqnfbbfpim Subhas Dandapani added a comment - Hi Daniel Heid thanks I have a simple "shell" example also above with same 1second response times. I see the same with not just scriptBuildStep (which is "config file" plugin) - but basically any buildStep inside postBuildScripts, hence the type of the buildStep doesn't seem to change anything Would you like me to post results with any other buildStep other than "shell" to cross check?
          Hide
          fm4zyqnfbbfpim Subhas Dandapani added a comment - - edited

          I'd also like to align the code with the example - but would you recommend the example provided by Daniel Spilker, or to reproduce the way you have in the PR like this: https://github.com/dheid/job-dsl-plugin/blob/093cf534d2e46ca7a8dd7005e97002aecc434fc3/job-dsl-core/src/main/groovy/javaposse/jobdsl/dsl/helpers/publisher/PublisherContext.groovy#L1313

          Which one would you believe would resolve the 1s delays in postbuildsteps...

          Show
          fm4zyqnfbbfpim Subhas Dandapani added a comment - - edited I'd also like to align the code with the example - but would you recommend the example provided by Daniel Spilker, or to reproduce the way you have in the PR like this: https://github.com/dheid/job-dsl-plugin/blob/093cf534d2e46ca7a8dd7005e97002aecc434fc3/job-dsl-core/src/main/groovy/javaposse/jobdsl/dsl/helpers/publisher/PublisherContext.groovy#L1313 Which one would you believe would resolve the 1s delays in postbuildsteps...
          Hide
          dheid Daniel Heid added a comment -

          Thank you for the input. Shell is so basic, this should be calculated in a very short time. I'm not very deep into the Job DSL functionallity, so I currently don't really know, why this is taking so long.

          Both ways, the automatically generated DSL and the old way should be fast in my opinion. In addition: The old way does not support some of the features you use in your example. And it generates the old configuration, which will be converted in the format on the fly each time, the job will be executed. So I recommend the automatically generated DSL in your case.

          I have two assumptions:

          1. Since the build steps reference to other, more general kinds of steps, this could have something to with the loading of all these step types. Could be, that every plugin is checked here and this takes much time.

          2. Could have something to with the way, the plugin configuration is structured. The tree is more complex than usual trees.

          I will investigate a litte bit more further to have more information.

          Show
          dheid Daniel Heid added a comment - Thank you for the input. Shell is so basic, this should be calculated in a very short time. I'm not very deep into the Job DSL functionallity, so I currently don't really know, why this is taking so long. Both ways, the automatically generated DSL and the old way should be fast in my opinion. In addition: The old way does not support some of the features you use in your example. And it generates the old configuration, which will be converted in the format on the fly each time, the job will be executed. So I recommend the automatically generated DSL in your case. I have two assumptions: 1. Since the build steps reference to other, more general kinds of steps, this could have something to with the loading of all these step types. Could be, that every plugin is checked here and this takes much time. 2. Could have something to with the way, the plugin configuration is structured. The tree is more complex than usual trees. I will investigate a litte bit more further to have more information.
          Hide
          fm4zyqnfbbfpim Subhas Dandapani added a comment -

          Daniel Heid thank you so much for your inputs and time Actually I am using the auto-generated DSL in the example above, so as a short recap:

          • Using automatic DSL "postBuildScript" with  a "shell" build step takes 1 second per step
          • Same "shell" build step in the regular job scripts (i.e. not postbuildscript but main job build step) executes fast

          We'll also continue to investigate, and I'm trying to generate the configuration using regular XML instead of the DSL to see if that helps as well. Will keep you posted and thank you so much!

          Show
          fm4zyqnfbbfpim Subhas Dandapani added a comment - Daniel Heid thank you so much for your inputs and time Actually I am using the auto-generated DSL in the example above, so as a short recap: Using automatic DSL "postBuildScript" with  a "shell" build step takes 1 second per step Same "shell" build step in the regular job scripts (i.e. not postbuildscript but main job build step) executes fast We'll also continue to investigate, and I'm trying to generate the configuration using regular XML instead of the DSL to see if that helps as well. Will keep you posted and thank you so much!
          Hide
          dheid Daniel Heid added a comment -

          I'm closing the issue, since I cannot do anything at the moment.

          Show
          dheid Daniel Heid added a comment - I'm closing the issue, since I cannot do anything at the moment.

            People

            • Assignee:
              dheid Daniel Heid
              Reporter:
              fm4zyqnfbbfpim Subhas Dandapani
            • Votes:
              1 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: