timja
commented
6 years ago In all provided stacktraces Fingerprinting I/O comes from the Maven plugin which generates heavy fingerprinting load.
I will reassign the issue to the plugin maintainer, so far I do not see issue in the core implementation (although there are some discussions about changing the fingerprint storage in long-term).
java.lang.Thread.State: BLOCKED (on object monitor) at hudson.model.Fingerprint.add(Fingerprint.java:1014) - waiting to lock <0x00007f6124c61050> (a hudson.model.Fingerprint) at hudson.maven.reporters.MavenFingerprinter$1.call(MavenFingerprinter.java:125) at hudson.maven.reporters.MavenFingerprinter$1.call(MavenFingerprinter.java:112) at hudson.maven.MavenBuild$ProxyImpl.execute(MavenBuild.java:452) at hudson.maven.MavenBuild$ProxyImpl2.execute(MavenBuild.java:584) at sun.reflect.GeneratedMethodAccessor1033.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at hudson.model.Executor$2.call(Executor.java:911) at hudson.util.InterceptingProxy$1.invoke(InterceptingProxy.java:23) at com.sun.proxy.$Proxy117.execute(Unknown Source) at hudson.maven.MavenBuildProxy$Filter$AsyncInvoker.call(MavenBuildProxy.java:294) at hudson.remoting.UserRequest.perform(UserRequest.java:210) at hudson.remoting.UserRequest.perform(UserRequest.java:53) at hudson.remoting.Request$2.run(Request.java:364) at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:72) at org.jenkinsci.remoting.CallableDecorator.call(CallableDecorator.java:19) at hudson.remoting.CallableDecoratorList$1.call(CallableDecoratorList.java:21) at jenkins.util.ContextResettingExecutorService$2.call(ContextResettingExecutorService.java:46) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)
We have several heavily loaded instances of Jenkins. The most biggest of them builds around 30 000 jobs per day (two others - around 6000).
After upgrade to Jenkins 2.107.3 on the most heavily loaded instance we see a hight CPU sys time consumption. For users this looks like that the Jenkins works fast, but jobs build slow and the last step "Waiting for Jenkins to finish collecting data" takes a very long time (very similar to https://issues.jenkins-ci.org/browse/JENKINS-19712).
Moreover, some jobs simply looped at random steps:
After some investigation we have found that the processes, who consume CPU sys time most of all, are hanging on "futex" system call:
In strace output for such processes we can see something like that:
futex(0x7fc42800ba54, FUTEX_WAIT_BITSET_PRIVATE, 1, {5161981, 228340395}, ffffffff) = -1 ETIMEDOUT (Connection timed out) futex(0x7fc42800ba28, FUTEX_WAKE_PRIVATE, 1) = 0 futex(0x7fc42800ba54, FUTEX_WAIT_BITSET_PRIVATE, 1, {5161981, 278655215}, ffffffff) = -1 ETIMEDOUT (Connection timed out) futex(0x7fc42800ba28, FUTEX_WAKE_PRIVATE, 1) = 0 futex(0x7fc42800ba54, FUTEX_WAIT_BITSET_PRIVATE, 1, {5161981, 328848067}, ffffffff) = -1 ETIMEDOUT (Connection timed out) futex(0x7fc42800ba28, FUTEX_WAKE_PRIVATE, 1) = 0 futex(0x7fc42800ba54, FUTEX_WAIT_BITSET_PRIVATE, 1, {5161981, 379185329}, ffffffff) = -1 ETIMEDOUT (Connection timed out)corresponding Java-process:
or that:
clock_gettime(CLOCK_THREAD_CPUTIME_ID, {10, 798549532}) = 0 stat("/var/cache/jenkins/war/WEB-INF/classes/hudson/maven/MavenModuleSet.class", 0x7f4168ac8540) = -1 ENOENT (No such file or directory) stat("/var/cache/jenkins/war/WEB-INF/classes/hudson/maven/MavenModuleSet.class", 0x7f4168ac8560) = -1 ENOENT (No such file or directory) lstat("/u01", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0Environment: RHEL 7.5 with the latest updates (except of kernel). DRBD+ext4. OpenStack KVM. 32 CPU 64 GB RAM.
JENKINS_JAVA_OPTIONS="-Djava.awt.headless=true -Dgroovy.use.classvalue=true -Xms32g -Xmx32g -XX:MaxGCPauseMillis=200 -XX:ParallelGCThreads=20 -XX:ConcGCThreads=5 -XX:InitiatingHeapOccupancyPercent=75 -XX:MaxMetaspaceSize=3024m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/u01/jenkins -XX:+UnlockDiagnosticVMOptions -Djenkins.model.Jenkins.logStartupPerformance=true -Dhudson.plugins.git.GitStatus.allowNotifyCommitParameters=true -Dhudson.model.ParametersAction.keepUndefinedParameters=true -Dhudson.model.DirectoryBrowserSupport.CSP=\"default-src 'self'; img-src 'self'; script-src 'self' 'unsafe-inline' 'unsafe-eval'; style-src 'self' 'unsafe-inline'; child-src 'self'; frame-src 'self';\" -Djenkins.model.DirectoryBrowserSupport.CSP=\"default-src 'self'; img-src 'self'; script-src 'self' 'unsafe-inline' 'unsafe-eval'; style-src 'self' 'unsafe-inline'; child-src 'self'; frame-src 'self';\" -Dorg.apache.commons.jelly.tags.fmt.timeZone=\"Europe/Moscow\" -Dhudson.model.User.SECURITY_243_FULL_DEFENSE=false -Dcom.cloudbees.workflow.rest.external.ChangeSetExt.resolveCommitAuthors=false -server -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent -XX:+ParallelRefProcEnabled -XX:+UseStringDeduplication -Xloggc:${JENKINS_HOME}/gc_logs/gc-%t.log -XX:NumberOfGCLogFiles=5 -XX:+UseGCLogFileRotation -XX:GCLogFileSize=20m -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+PrintAdaptiveSizePolicy -Dcom.sun.management.jmxremote.port=3333 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Djava.io.tmpdir=/u01/jenkins/tmp -Dhudson.remoting.ClassFilter=org.jenkinsci.lib.xtrigger.AbstractTrigger"More diagnostic information in the attachments (we have created screenshots and ThreadDumps not at the same time, but at a time when we have seen the problem).
Originally reported by dkoryavov, imported from: High CPU sys time consumption after upgrade to 2.107.3