How to produce debug information in the Jenkins console log when using Job DSL

[John Wadleigh]

We are using the Job DSL to generate our jobs but in the Jenkins console log, there is not much information showing as it is generating each of the jobs.

I would like to understand what exactly it is doing. One reason is because the performance is really bad and we are only generating 30 jobs.

Here is what I see while the job is running...

10:42:06 Started by an SCM change
10:42:06 [EnvInject] - Loading node environment variables.
10:42:06 [EnvInject] - Preparing an environment for the build.
10:42:06 [EnvInject] - Keeping Jenkins system variables.
10:42:06 [EnvInject] - Keeping Jenkins build variables.
10:42:06 [EnvInject] - Injecting as environment variables the properties content 
10:42:06 environment=dev1
10:42:06 group=pbdel
10:42:06 
10:42:06 [EnvInject] - Variables injected successfully.
10:42:06 [EnvInject] - Injecting contributions.
10:42:06 Building remotely on SERVER in workspace /opt/deploy/work/jenkins-slave/workspace/DevOps-SeedJob-Generator-dev1
10:42:06 Cleaning up /opt/deploy/work/jenkins-slave/workspace/DevOps-SeedJob-Generator-dev1/.
10:42:06 Updating http://svn/DEVOPS/jenkins/trunk at revision '2015-09-25T10:42:06.243 +0200'
10:42:06 U         jobs/TestafterDeployment.groovy
10:42:06 At revision 223086

Please help... 

Also, separate question - how can I see the PID for a specific build of Jenkins? I want to see process info on the server for that build.

Thanks,

John

[Victor Martinez]

Hi John,

 Off the top of my head, you can debug Jenkins plugin using the logs options:

  - https://wiki.jenkins-ci.org/display/JENKINS/Logging

Loggers:

- javaposse.jobdsl.plugin.*
- javaposse.jobdsl.dsl.*

- javaposse.jobdsl.*

Regarding the pid of a specific build, I'm not sure whether its part of the API. Have you already asked in the Jenkins Dev groups?

I hope it helps.

[John Wadleigh]

Hi Victor, thanks for the information - that helped.

Regarding PIDs, it seems I can only see that Jenkins can be configured with max executors for each node, but beyond that I see no way to monitor these builds from an OS-level.

[John Wadleigh]

So I am still not sure how I can get the details behind what is taking so long for the plugin to complete. See this console log - it has a step at 09:46:13 and then next one is at 10:11:57. This is a long time to build about 30 jobs. 

How can I determine what is taking so long?

09:46:12 Started by upstream project "DevOps-misc-Generator" build number 387
09:46:12 originally caused by:
09:46:12  Started by an SCM change
09:46:12 [EnvInject] - Loading node environment variables.
09:46:12 [EnvInject] - Preparing an environment for the build.
09:46:12 [EnvInject] - Keeping Jenkins system variables.
09:46:12 [EnvInject] - Keeping Jenkins build variables.
09:46:12 [EnvInject] - Injecting as environment variables the properties content 
09:46:12 environment=spg
09:46:12 group=pbdel
09:46:12 
09:46:12 [EnvInject] - Variables injected successfully.
09:46:12 [EnvInject] - Injecting contributions.
09:46:12 Building remotely on muc-opsce-03 in workspace /opt/deploy/work/jenkins-slave/workspace/DevOps-SeedJob-Generator-spg
09:46:12 Cleaning up /opt/deploy/work/jenkins-slave/workspace/DevOps-SeedJob-Generator-spg/.
09:46:12 Updating http://svn.com/repos/DEVOPS/jenkins/branches/jenkins-9.14 at revision '2015-09-28T09:46:12.585 +0200'
09:46:12 A         jobs/Deploy-LMSDB.groovy
09:46:12 A         jobs/Deploy-APIPROXY.groovy
09:46:12  U        .
09:46:12 At revision 223163
09:46:13 no change for http://svn.com/repos/DEVOPS/jenkins/branches/jenkins-9.14 since the previous build
10:11:57 Existing Templates: 
10:11:57 New Templates: 
10:11:57 Unreferenced Templates: 
10:11:57 Removing items: 
10:11:57 Adding views: 
10:11:57 Existing views: GeneratedJob{viewName='SPG'}
10:11:57 Removing views: 
10:11:57 Adding config files: 
10:11:57 Existing config files: 
10:11:57 Removing config files: 
10:11:58 Finished: SUCCESS

[Victor Martinez]

Hi John,

 You could add some verbose output:

  - https://github.com/jenkinsci/job-dsl-plugin/wiki/Job-DSL-Commands#logging

 Have you tried to run those dsl files individually? What version do you use? I have not seen anything related to Performance issues/fixes in:

- https://github.com/jenkinsci/job-dsl-plugin/wiki

- https://issues.jenkins-ci.org/browse/JENKINS-30621?jql=project%20%3D%20JENKINS%20AND%20status%20in%20(Open%2C%20%22In%20Progress%22%2C%20Reopened%2C%20Resolved)%20AND%20component%20%3D%20job-dsl-plugin

Cheers

[Daniel Spilker]

John, which version of the Job DSL plugin are you using?

Newer version will log the name of DSL script which is being processed, e.g.

Processing DSL script projectA.groovy
Processing DSL script projectB.groovy
Processing DSL script projectB.groovy

So you can see which file takes a long time.

You can also take a JVM thread dump (http://localhost:8080/threadDump) to see what's happening in the seed job executor's thread.

Regards,
Daniel

--
You received this message because you are subscribed to the Google Groups "job-dsl-plugin" group.
To unsubscribe from this group and stop receiving emails from it, send an email to job-dsl-plugi...@googlegroups.com.
To post to this group, send email to job-dsl...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/job-dsl-plugin/862e79b5-6b61-4124-b6a3-55ea56eb6ee2%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[John Wadleigh]

Hi Daniel,

Thank you for the response and info. We are not on the latest version because I believe the newest version has various API changes, which would require us to re-write our Groovy code, so it is at the moment a lower priority.  However there must be a way to understand why it is taking so long for JobDSL to process all of these jobs. Is this the general performance of JobDSL? Or are we doing something wrong?

I use Gradlew to test locally on my machine, but this also takes a long time and I do not feel its the same as what happens when Jenkins build is kicked off and JobDSL is processing the jobs.

Thanks,

John

[Ingo Rissmann]

Hi John

Have you found why the JobDSL is taking so long to generate your jobs? It seems we have a similar issue here. On a fresh Jenkins instance the seed job is running very fast (~90 seconds for more than 1700 jobs) but on our old instance the runtime is increasing more and more. At the moment it needs more than an hour :(

Regards,

Ingo

[Rob Fagen]

You may have already looked at the machine's performance, but something you might want to consider is installing the monitoring plugin to get some insight into JVM heap usage, etc. https://wiki.jenkins-ci.org/display/JENKINS/Monitoring

I'm thinking this because you're saying a fresh instance runs quickly but a long running instance takes 60x as long. If there's something with a memory leak and the heap is constantly being garbage collected, then that can severely affect performance.

If so, then finding the leak and fixing it is an exercise left to the reader :)

[Ingo Rissmann]

Hi

I found the problem for our environment. We are using the Job Configuration History Plugin and the content in the config-history folder was grown over the time. It seems that the dsl plugin scans this folder for some reasons. After I deleted this folder the generation is very fast again.

Regards,

Ingo