TeamCity 8.1.2 on OSX - consuming a lot of CPU while idle

Avatar
Taylor Steil
Created

I have a barebones TeamCity 8.1.2 installation on my MacbookPro (OSX 10.9.2 Java 1.6 / 1.7), it's functioning as the server + agent. I setup 1 project with 1 build (bash script) using Github (no commit hooks though) to do Unity3d command line builds.

After I configured my project & build steps I noticed that the java process from teamcity was using 50-70% CPU while idling. I did some googling and nothing came up so I decided to post here.

start command output:
Taylors-MacBook-Pro:TeamCity taylor$ ./bin/runAll.sh start
Using CATALINA_BASE:   /Applications/TeamCity
Using CATALINA_HOME:   /Applications/TeamCity
Using CATALINA_TMPDIR: /Applications/TeamCity/temp
Using JRE_HOME:        /System/Library/Frameworks/JavaVM.framework/Home
Using CLASSPATH:       /Applications/TeamCity/bin/bootstrap.jar:/Applications/TeamCity/bin/tomcat-juli.jar
Starting TeamCity build agent...
Java executable is found in '/System/Library/Frameworks/JavaVM.framework/Home'.
Starting TeamCity Build Agent Launcher...
Agent home directory is /Applications/TeamCity/buildAgent
Current Java runtime version is 1.7
Lock file: /Applications/TeamCity/buildAgent/logs/buildAgent.properties.lock
Using no lock
Done [81064], see log at /Applications/TeamCity/buildAgent/logs/teamcity-agent.log


this is the process that is using the cpu:

  501 81052     1   0  1:51PM ttys003    1:56.88 /System/Library/Frameworks/JavaVM.framework/Home/bin/java -Djava.util.logging.config.file=/Applications/TeamCity/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -server -Xmx512m -XX:MaxPermSize=270m -Dlog4j.configuration=file:/Applications/TeamCity/bin/../conf/teamcity-server-log4j.xml -Dteamcity_logs=../logs/ -Djava.awt.headless=true -Djava.endorsed.dirs=/Applications/TeamCity/endorsed -classpath /Applications/TeamCity/bin/bootstrap.jar:/Applications/TeamCity/bin/tomcat-juli.jar -Dcatalina.base=/Applications/TeamCity -Dcatalina.home=/Applications/TeamCity -Djava.io.tmpdir=/Applications/TeamCity/temp org.apache.catalina.startup.Bootstrap start

the start and stop logs from /Applications/TeamCity/buildAgent/logs/* and /Applications/TeamCity/logs/*
https://gist.github.com/tayl0r/11398005

I'm assuming this is not supposed to happen. Any ideas what it might be? How can I debug this further?
I tried switching my JRE_HOME to java 1.7 (from java 1.6) but there was no change.
I'm a programmer but have never done anything with Java so I don't quite know where to start debugging this. The misbehaving process seems to be Tomcat, which I know is the java application server, but I don't know how to dig deeper.

Votes

0

Share

17 comments
Avatar
Sergey Pak
Created

Please attach thread dump (Administration->Diagnostics)

0
Avatar
Taylor Steil
Created

Attached.



Attachment(s):
threadDump-2014-04-29_19.08.22.txt.zip
0
Avatar
Sergey Pak
Created

According to thread dump, TC is idle. However, it takes time for TC to start and load all dependencies, etc (like 1-2 minutes). How long did it work before you stopped it?

0
Avatar
Taylor Steil
Created

I wait 10+ minutes because I assumed it did some stuff at startup.

http://screencast.com/t/Faa7FvAa4z

It's definitely doing *something*. With TC running, OSX says I have 3 hours 10 minutes battery life remaining. When I stop TC, the battery life jumps to 4 hours. The CPU temps also go up while TC is running. So it must be doing something!

0
Avatar
Sergey Pak
Created

As far as I can see, one thread is really doing something. Please do the following:
1) Enable debug-all logging under Administration-Diagnostics and let it work for couple of minutes after server is completely started. And then send the whole log folder (zipped) to us.
2) Do several thread dumps (via save thread dump) with interval of 10-15 seconds.

Please don't forget to turn off debug logging after that - otherwise it will flood the log.

Thanks!

0
Avatar
Taylor Steil
Created

Thanks a lot for your help btw. Here you go!



Attachment(s):
buildAgent_logs.zip
teamCity_logs.zip
0
Avatar
Sergey Pak
Created

I suspect there's something with system thread "AWT-AppKit", but I need to be sure.

Can you please do the following:
1) Start TC and let it run for a couple of minutes
2) clone https://github.com/silvansky/threadmon and compile it via make
3) sudo ./threadmon <tc_pid>
// this will print cpu usage per thread.
4) jstack <tc_pid> >> td_java.txt
// this will give us real thread PIDs, not TC fake ones.

Also, did all these problems happen, when TC installation was clean (i.e. no projects, etc.)?

0
Avatar
Taylor Steil
Created
Also, did all these problems happen, when TC installation was clean (i.e. no projects, etc.)?



Unfortunately I can't answer that question. I only noticed the CPU usage after I added the project. Can I "archive" and then delete the project to test this?

I looked at the threadmon & jstack output but I can't make sense of it. The threadmon thread ids dont seem to match anything from jstack. Supposedly the "nid" field should be the hex encoded thread id, but those don't seem to match anything from threadmon.
Here's the output:

Taylors-MacBook-Pro:bin taylor$ ps -ef | grep -i TeamCity
  501 20052     1   0  1:02PM ttys001   15:23.99 /System/Library/Frameworks/JavaVM.framework/Home/bin/java -Djava.util.logging.config.file=/Applications/TeamCity/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -server -Xmx512m -XX:MaxPermSize=270m -Dlog4j.configuration=file:/Applications/TeamCity/bin/../conf/teamcity-server-log4j.xml -Dteamcity_logs=../logs/ -Djava.awt.headless=true -Djava.endorsed.dirs=/Applications/TeamCity/endorsed -classpath /Applications/TeamCity/bin/bootstrap.jar:/Applications/TeamCity/bin/tomcat-juli.jar -Dcatalina.base=/Applications/TeamCity -Dcatalina.home=/Applications/TeamCity -Djava.io.tmpdir=/Applications/TeamCity/temp org.apache.catalina.startup.Bootstrap start
  501 20064     1   0  1:02PM ttys001    0:02.00 /System/Library/Frameworks/JavaVM.framework/Home/bin/java -ea -cp ../launcher/lib/launcher.jar jetbrains.buildServer.agent.Launcher -ea -Xmx384m -Dteamcity_logs=../logs/ -Dlog4j.configuration=file:../conf/teamcity-agent-log4j.xml jetbrains.buildServer.agent.AgentMain -file ../conf/buildAgent.properties
  501 20069 20064   0  1:02PM ttys001    0:21.14 /System/Library/Java/JavaVirtualMachines/1.6.0.jdk/Contents/Home/bin/java -ea -Xmx384m -Dteamcity_logs=../logs/ -Dlog4j.configuration=file:../conf/teamcity-agent-log4j.xml -classpath /Applications/TeamCity/buildAgent/lib/agent-configurator.jar:/Applications/TeamCity/buildAgent/lib/agent-launcher.jar:/Applications/TeamCity/buildAgent/lib/agent-openapi.jar:/Applications/TeamCity/buildAgent/lib/agent-upgrade.jar:/Applications/TeamCity/buildAgent/lib/agent.jar:/Applications/TeamCity/buildAgent/lib/agentInstaller-UI.jar:/Applications/TeamCity/buildAgent/lib/agentInstaller.jar:/Applications/TeamCity/buildAgent/lib/annotations.jar:/Applications/TeamCity/buildAgent/lib/buildAgent-updates-applying.jar:/Applications/TeamCity/buildAgent/lib/common-impl.jar:/Applications/TeamCity/buildAgent/lib/common-runtime.jar:/Applications/TeamCity/buildAgent/lib/common.jar:/Applications/TeamCity/buildAgent/lib/commons-beanutils-core.jar:/Applications/TeamCity/buildAgent/lib/commons-codec-1.3.jar:/Applications/TeamCity/buildAgent/lib/commons-collections-3.2.1.jar:/Applications/TeamCity/buildAgent/lib/commons-compress-1.5.jar:/Applications/TeamCity/buildAgent/lib/commons-httpclient-3.1.jar:/Applications/TeamCity/buildAgent/lib/commons-io-1.3.2.jar:/Applications/TeamCity/buildAgent/lib/commons-logging.jar:/Applications/TeamCity/buildAgent/lib/coverage-agent-common.jar:/Applications/TeamCity/buildAgent/lib/coverage-report.jar:/Applications/TeamCity/buildAgent/lib/duplicator-util.jar:/Applications/TeamCity/buildAgent/lib/ehcache-1.6.0-patch.jar:/Applications/TeamCity/buildAgent/lib/ehcache-1.6.0.jar:/Applications/TeamCity/buildAgent/lib/freemarker.jar:/Applications/TeamCity/buildAgent/lib/idea-settings.jar:/Applications/TeamCity/buildAgent/lib/inspections-util.jar:/Applications/TeamCity/buildAgent/lib/jaxen-1.1.1.jar:/Applications/TeamCity/buildAgent/lib/jdk-searcher.jar:/Applications/TeamCity/buildAgent/lib/jdom.jar:/Applications/TeamCity/buildAgent/lib/joda-time-1.5.2.jar:/Applications/TeamCity/buildAgent/lib/launcher-api.jar:/Applications/TeamCity/buildAgent/lib/launcher.jar:/Applications/TeamCity/buildAgent/lib/log4j-1.2.12.jar:/Applications/TeamCity/buildAgent/lib/messages.jar:/Applications/TeamCity/buildAgent/lib/openapi.jar:/Applications/TeamCity/buildAgent/lib/patches-impl.jar:/Applications/TeamCity/buildAgent/lib/patches.jar:/Applications/TeamCity/buildAgent/lib/processesTerminator.jar:/Applications/TeamCity/buildAgent/lib/resources_en.jar:/Applications/TeamCity/buildAgent/lib/runtime-util.jar:/Applications/TeamCity/buildAgent/lib/server-logging.jar:/Applications/TeamCity/buildAgent/lib/serviceMessages.jar:/Applications/TeamCity/buildAgent/lib/slf4j-api-1.7.5.jar:/Applications/TeamCity/buildAgent/lib/slf4j-log4j12-1.7.5.jar:/Applications/TeamCity/buildAgent/lib/spring.jar:/Applications/TeamCity/buildAgent/lib/trove4j.jar:/Applications/TeamCity/buildAgent/lib/util.jar:/Applications/TeamCity/buildAgent/lib/xercesImpl.jar:/Applications/TeamCity/buildAgent/lib/xml-rpc-wrapper.jar:/Applications/TeamCity/buildAgent/lib/xmlrpc-2.0.1.jar:/Applications/TeamCity/buildAgent/lib/xpp3-1.1.4c.jar:/Applications/TeamCity/buildAgent/lib/xstream-1.4.1.jar jetbrains.buildServer.agent.AgentMain -file ../conf/buildAgent.properties -launcher.version 29993

  501 20634   345   0  1:32PM ttys001    0:00.00 grep -i TeamCity

// 20052 is the pid

Taylors-MacBook-Pro:threadmon taylor$ sudo ./threadmon 20052
Starting threadmon for PID 20052
Thread 7695: CPU 0%
Thread 7939: CPU 0%
Thread 8195: CPU 0%
Thread 8451: CPU 0%
Thread 8707: CPU 0%
Thread 8963: CPU 0%
Thread 9219: CPU 0%
Thread 9475: CPU 0%
Thread 9731: CPU 0%
Thread 9987: CPU 0%
Thread 10243: CPU 0%
Thread 10499: CPU 0%
Thread 10755: CPU 0%
Thread 11011: CPU 0%
Thread 11267: CPU 0%
Thread 11523: CPU 0%
Thread 11779: CPU 0%
Thread 12035: CPU 0%
Thread 12291: CPU 0%
Thread 12547: CPU 0%
Thread 12803: CPU 0%
Thread 13059: CPU 0%
Thread 13315: CPU 1%
Thread 13571: CPU 0%
Thread 13827: CPU 0%
Thread 14083: CPU 0%
Thread 14339: CPU 0%
Thread 14595: CPU 0%
Thread 14851: CPU 0%
Thread 15107: CPU 0%
Thread 15363: CPU 0%
Thread 15619: CPU 33%
Thread 15875: CPU 36%
Thread 16131: CPU 34%
Thread 16387: CPU 31%
Thread 16643: CPU 33%
Thread 16899: CPU 34%
Thread 17155: CPU 33%
Thread 17411: CPU 36%
Thread 17667: CPU 33%
Thread 17923: CPU 34%
Thread 18179: CPU 34%
Thread 18435: CPU 33%
Thread 18691: CPU 33%
Thread 18947: CPU 35%
Thread 19203: CPU 31%
Thread 19459: CPU 0%
Thread 19715: CPU 0%
Thread 19971: CPU 0%
Thread 20227: CPU 0%
Thread 20483: CPU 0%
Thread 20739: CPU 0%
Thread 20995: CPU 0%
Thread 21251: CPU 0%
Thread 21507: CPU 0%
Thread 21763: CPU 0%
Thread 22019: CPU 0%
Thread 22275: CPU 0%
Thread 22531: CPU 0%
Thread 22787: CPU 0%
Thread 23043: CPU 0%
Thread 23299: CPU 0%
Thread 23555: CPU 0%
Thread 23811: CPU 0%
Thread 24067: CPU 0%
Thread 24323: CPU 0%
Thread 24579: CPU 0%
Thread 24835: CPU 0%
Thread 25091: CPU 3%
Thread 25347: CPU 0%
Thread 25603: CPU 0%
Thread 25859: CPU 0%
Thread 26115: CPU 0%
Thread 26371: CPU 0%
Thread 26627: CPU 0%
Thread 26883: CPU 0%
Thread 27139: CPU 0%
Thread 27395: CPU 0%
Thread 27651: CPU 0%
Thread 27907: CPU 0%
Thread 28163: CPU 0%
Thread 28419: CPU 0%
Thread 28675: CPU 0%
Thread 28931: CPU 0%
Thread 29187: CPU 0%
Thread 29443: CPU 0%
Thread 29699: CPU 0%
Thread 29955: CPU 0%
Thread 30211: CPU 0%
Thread 30467: CPU 0%
Thread 30723: CPU 0%
Thread 30979: CPU 0%
Thread 31235: CPU 0%
Thread 31491: CPU 0%
Thread 31747: CPU 0%
Thread 32003: CPU 0%
Thread 32259: CPU 0%
Thread 32515: CPU 0%
Thread 32771: CPU 0%

jstack 20052 > ~/Desktop/td_java.txt

// take a thread id that was consuming cpu and convert it to hex
Taylors-MacBook-Pro:threadmon taylor$ printf "0x%x\n" 15619
0x3d03

// search for it in the jstack output
Taylors-MacBook-Pro:threadmon taylor$ grep 3d03 ~/Desktop/td_java.txt

// nothing =(

// AWT-AppKit section from jstack:
"AWT-AppKit" daemon prio=5 tid=7fae188d6000 nid=0x7fff779f1310 runnable [00000000]
   java.lang.Thread.State: RUNNABLE

// how do you get the thread id from tid=7fae188d6000 or nid=0x7fff779f1310 ??


Attachment(s):
td_java.txt.zip
0
Avatar
Sergey Pak
Created

It turns out, there's no direct matching between tid and nid generated by jstack and OS pids and tids. This is sad. Let me find a way to get these TIDs.

0
Avatar
Taylor Steil
Created

That was my conclusion as well after doing some googling. I guess on linux you can match it up but not OSX.

0
Avatar
Sergey Pak
Created

I was unable to find an easier way rather than asking you to run a profiler. Luckily, it comes with JDK and called jvisualvm. Please start it, attach to TC process and go to Sampler tab.

Then, please, click on CPU button and let it grab some information. There are two tabs - CPU samples (methods) and Thread CPU time. I would need information from both. I haven't found a way to dump the information to txt file, so screenshots would be enough

Thanks!

0
Avatar
Taylor Steil
Created

No problem. Here are the screenshots. It seems like it's the "Agent messages processing threads". Maybe they're just tuned too aggressively for non-production applications.



Attachment(s):
visualvm-sampler-cpu_samples.png
visualvm-sampler-thread_cpu_time.png
0
Avatar
Sergey Pak
Created

Thanks. Please try replacing TC/webapps/ROOT/WEB-INF/lib/server.jar with the one from the link: ftp://ftp.labs.intellij.net/pub/.teamcity/mac-cpu-try/server.jar and let me if it changes anything.

0
Avatar
Taylor Steil
Created

Wow, looks like that fixed it. Now's its using about the same amount of CPU as a normal running & idle app.

0
Avatar
Sergey Pak
Created

Thank you for your help on the issue. That was a useful knowledge for us.

0
Avatar
Sergey Pak
Created

By the way, it's not the final fix, but a workaround and try to understand the problem (for us). Most likely, the final fix would be included into 8.1.3.

0
Avatar
Taylor Steil
Created

Understood. I'll be happy to try out new server jar files or give you additional debug info if you want.

Thanks again! Jetbrains is the best! Now if you guys would make a proper C# editor that worked with Unity =)

0

Please sign in to leave a comment.