Difficulty with getting profiling to work

Questions about YourKit Java Profiler
Post Reply
dgshaver
Posts: 3
Joined: Wed Oct 28, 2015 8:50 pm

Difficulty with getting profiling to work

Post by dgshaver »

Hi,

I'm a newbie user, so apologies in advance if I'm doing something silly.

I'm trying to profile a Java service on Windows. I added the -agentpath parameter to the end of the service command line (entire command line pasted below) and restarted the service:
-Xmx1000m -Dtempleton.log.dir=C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog\logs -Dlog4j.configuration=file:C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog\etc\webhcat\webhcat-log4j.properties -Dhadoop.log.dir=C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\logs -Dhadoop.log.file=hadoop.log -Dhadoop.home.dir=C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004 -Dhadoop.id.str=HEADNODE0$ -Dhadoop.root.logger=INFO,console,DRFA,ETW,FilterLog -Djava.library.path=;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\bin -Dhadoop.policy.file=hadoop-policy.xml -Djava.net.preferIPv4Stack=true -Detwlogger.component=templeton -Dtempleton.root.logger=DEBUG,standard,ETW,FilterLog,Anonymizer -Dwhitelist.filename=core-whitelist.res,hive-whitelist.res -DlogFilter.filename=TempletonLogFilters.xml -DpatternGroup.filename=TempletonPatternGroups.xml -classpath C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog\etc\webhcat;C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog;C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog\share\webhcat\svr;C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog\conf;C:\apps\dist\hive-0.14.0.2.2.7.1-0004\conf;C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog\share\hcatalog\*;C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog\share\webhcat\svr\*;C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog\share\webhcat\svr\lib\*;C:\apps\dist\hive-0.14.0.2.2.7.1-0004\lib\*;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\etc\hadoop;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\share\hadoop\common\lib\*;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\share\hadoop\common\*;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\share\hadoop\hdfs;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\share\hadoop\hdfs\lib\*;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\share\hadoop\hdfs\*;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\share\hadoop\yarn\lib\*;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\share\hadoop\yarn\*;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\share\hadoop\mapreduce\lib\*;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\share\hadoop\mapreduce\*;C:\apps\dist\azureLogging\*;C:\apps\dist\tez-0.5.2.2.2.7.1-0004\conf\;C:\apps\dist\tez-0.5.2.2.2.7.1-0004\*;C:\apps\dist\tez-0.5.2.2.2.7.1-0004\lib\*; org.apache.hive.hcatalog.templeton.Main -agentpath:"D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win64\yjpagent.dll"

Upon restarting the service, it fails with no error message.

The load test works fine:

D:\>java -agentpath:"D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win64\yjpagent.dll"=help

[YourKit Java Profiler 2015 build 15076] Log file: D:\Users\root\.yjp\log\java-1
0032.log

YourKit Java Profiler 2015 build 15076 JVMTI agent usage: -agentpath:<path to ag
ent library>=[<option>, ...]

< . . . cut . . . >

Tried to start the service from the command line but still silent failure.

Any idea what the problem is?

Using the OpenJDK:
D:\>java -version
openjdk version "1.7.0_55"
OpenJDK Runtime Environment (Zulu 7.4.0.5-win64) (build 1.7.0_55-b13)
OpenJDK 64-Bit Server VM (Zulu 7.4.0.5-win64) (build 24.55-b03, mixed mode)

Thanks!
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Difficulty with getting profiling to work

Post by Anton Katilin »

Hi,

Could you please provide the profiler agent log file <user home>/.yjp/log/<session name>-<pid>.log

Please note that the profiler does not officially support Zulu OpenJDK.

Please try running with Sun/Oracle Java instead.

Best regards
Anton
dgshaver
Posts: 3
Joined: Wed Oct 28, 2015 8:50 pm

Re: Difficulty with getting profiling to work

Post by dgshaver »

Thanks Anton.

Looks like it's failing to attach with. Return code is 3. Here is the full log (apologies, didn't see an upload link):

15076 0.048: Command line:
D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\bin\javaw.exe
-XX:+HeapDumpOnOutOfMemoryError
-Xmx4G
-XX:PermSize=256m
-XX:MaxPermSize=256m
-jar
..\lib\yjp.jar
15076 0.048: Executable: D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\bin\javaw.exe
15076 0.048: Windows Server 2012 R2; version 6.3.9600; 64-bit process
15076 0.049: hid: 16022D999W6Z093YZU593253555186505WVUUX661Y 64-bit machine
15076 0.049: Today is 20151028
15076 0.049: full_build_stamp: 15076 201510231650
15076 0.049: Agent library path: D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win64\yjpagent.dll
15076 0.049:
---------------------------------------------------------------------
Product: YourKit Java Profiler 2015 build 15076
Build: 15076 on 201510231650
JDK: 1.8.0_65
VM: Java HotSpot(TM) 64-Bit Server VM
Vendor: Oracle Corporation
OS: Windows Server 2012 R2
OS version: 6.3
OS arch: amd64
Date and time: Wed Oct 28 19:45:27 GMT 2015
Properties:
awt.toolkit=sun.awt.windows.WToolkit
file.encoding.pkg=sun.io
file.encoding=Cp1252
file.separator=\
java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment
java.awt.printerjob=sun.awt.windows.WPrinterJob
java.class.path=..\lib\yjp.jar
java.class.version=52.0
java.endorsed.dirs=D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\lib\endorsed
java.ext.dirs=D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\lib\ext;D:\Windows\Sun\Java\lib\ext
java.home=D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64
java.io.tmpdir=D:\Users\root\AppData\Local\Temp\2\
java.library.path=D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\bin;D:\Windows\Sun\Java\bin;D:\Windows\system32;D:\Windows;C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\bin;C:\apps\dist\java\bin;D:\Windows\system32;D:\Windows;D:\Windows\System32\Wbem;D:\Windows\System32\WindowsPowerShell\v1.0\;D:\Windows\system32;D:\Windows;D:\Windows\System32\Wbem;D:\Windows\System32\WindowsPowerShell\v1.0\;;E:\base\x64;E:\base\x86;E:\diagnostics\x64;;D:\Packages\GuestAgent\GuestAgent\LegacyRuntime\x64;D:\Packages\GuestAgent\GuestAgent\LegacyRuntime\x86;;D:\python27;.
java.runtime.name=Java(TM) SE Runtime Environment
java.runtime.version=1.8.0_65-b17
java.specification.name=Java Platform API Specification
java.specification.vendor=Oracle Corporation
java.specification.version=1.8
java.vendor.url.bug=http://bugreport.sun.com/bugreport/
java.vendor.url=http://java.oracle.com/
java.vendor=Oracle Corporation
java.version=1.8.0_65
java.vm.info=mixed mode
java.vm.name=Java HotSpot(TM) 64-Bit Server VM
java.vm.specification.name=Java Virtual Machine Specification
java.vm.specification.vendor=Oracle Corporation
java.vm.specification.version=1.8
java.vm.vendor=Oracle Corporation
java.vm.version=25.65-b01
line.separator=


os.arch=amd64
os.name=Windows Server 2012 R2
os.version=6.3
path.separator=;
sun.arch.data.model=64
sun.awt.enableExtraMouseButtons=true
sun.boot.class.path=D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\lib\resources.jar;D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\lib\rt.jar;D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\lib\sunrsasign.jar;D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\lib\jsse.jar;D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\lib\jce.jar;D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\lib\charsets.jar;D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\lib\jfr.jar;D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\classes
sun.boot.library.path=D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\bin
sun.cpu.endian=little
sun.cpu.isalist=amd64
sun.desktop=windows
sun.io.unicode.encoding=UnicodeLittle
sun.java.command=..\lib\yjp.jar
sun.java.launcher=SUN_STANDARD
sun.jnu.encoding=Cp1252
sun.management.compiler=HotSpot 64-Bit Tiered Compilers
sun.os.patch.level=
user.country=US
user.dir=D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin
user.home=D:\Users\root
user.language=en
user.name=root
user.script=
user.timezone=GMT
user.variant=
Environment:
ALLUSERSPROFILE=D:\ProgramData
APPDATA=D:\Users\root\AppData\Roaming
CLIENTNAME=DANSHA1
COMPUTERNAME=HEADNODE0
ComSpec=D:\Windows\system32\cmd.exe
CommonProgramFiles(x86)=D:\Program Files (x86)\Common Files
CommonProgramFiles=D:\Program Files\Common Files
CommonProgramW6432=D:\Program Files\Common Files
DATAFU_HOME=C:\apps\dist\datafu-1.2.0.2.2.7.1-0004
DATA_LOSS_STATE=0
FC_HOME=C:\apps\dist\failovercontroller-1.0.0
FP_NO_HOST_CHECK=NO
HADOOP_CLASSPATH=C:\apps\dist\azureLogging\*
HADOOP_CLIENT_OPTS=-Xmx1000m
HADOOP_COMMON_HOME=C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004
HADOOP_CONF_DIR=C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\etc\hadoop
HADOOP_HDFS_HOME=C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004
HADOOP_HOME=C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004
HADOOP_MAPRED_HOME=C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004
HADOOP_ROOT_LOGGER=INFO,console,DRFA,ETW,FilterLog
HADOOP_YARN_HOME=C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004
HBASE_CLASSPATH=C:\apps\dist\azureLogging\*
HBASE_CONF_DIR=C:\apps\dist\hbase-0.98.4.2.2.7.1-0004-hadoop2\conf
HBASE_HOME=C:\apps\dist\hbase-0.98.4.2.2.7.1-0004-hadoop2
HBASE_ROOT_LOGGER=INFO,console,DRFA,ETW,FilterLog
HCAT_HOME=C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog
HDFS_AUDIT_LOGGER=INFO,RFAAUDIT
HIVE_CONF_DIR=C:\apps\dist\hive-0.14.0.2.2.7.1-0004\conf
HIVE_HOME=C:\apps\dist\hive-0.14.0.2.2.7.1-0004
HIVE_LIB_DIR=C:\apps\dist\hive-0.14.0.2.2.7.1-0004\lib
HIVE_OPTS= -hiveconf hive.querylog.location=C:\apps\dist\hive-0.14.0.2.2.7.1-0004\logs\history -hiveconf hive.log.dir=C:\apps\dist\hive-0.14.0.2.2.7.1-0004\logs
HIVE_REPLACED=yes
HOMEDRIVE=D:
HOMEPATH=\Users\root
JAVA_HOME=C:\apps\dist\java
LOCALAPPDATA=D:\Users\root\AppData\Local
LOGONSERVER=\\HEADNODE0
MAHOUT_HOME=C:\apps\dist\mahout-0.9.0.2.2.7.1-0004
MA_LOGGING_HASH=f26ba47d-bc15-4f47-89b2-664a9c4ba310
NUMBER_OF_PROCESSORS=4
OOZIE_ROOT=C:\apps\dist\oozie-4.1.0.2.2.7.1-0004
OOZIE_URL=http://headnodehost:11000/oozie
OS=Windows_NT
PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC
PIG_HOME=C:\apps\dist\pig-0.14.0.2.2.7.1-0004
PROCESSOR_ARCHITECTURE=AMD64
PROCESSOR_IDENTIFIER=Intel64 Family 6 Model 45 Stepping 7, GenuineIntel
PROCESSOR_LEVEL=6
PROCESSOR_REVISION=2d07
PSModulePath=D:\Windows\system32\WindowsPowerShell\v1.0\Modules\;d:\Program Files\Microsoft Security Client\MpProvider\
PUBLIC=D:\Users\Public
PYTHON_CMD=D:\python27\python.exe
PYTHON_HOME=D:\python27
Path=C:\apps\dist\hadoop-2.6.0.2.2.7.1-0004\bin;C:\apps\dist\java\bin;D:\Windows\system32;D:\Windows;D:\Windows\System32\Wbem;D:\Windows\System32\WindowsPowerShell\v1.0\;D:\Windows\system32;D:\Windows;D:\Windows\System32\Wbem;D:\Windows\System32\WindowsPowerShell\v1.0\;;E:\base\x64;E:\base\x86;E:\diagnostics\x64;;D:\Packages\GuestAgent\GuestAgent\LegacyRuntime\x64;D:\Packages\GuestAgent\GuestAgent\LegacyRuntime\x86;;D:\python27
ProgramData=D:\ProgramData
ProgramFiles(x86)=D:\Program Files (x86)
ProgramFiles=D:\Program Files
ProgramW6432=D:\Program Files
SESSIONNAME=RDP-Tcp#1
SQOOP_HOME=C:\apps\dist\sqoop-1.4.5.2.2.7.1-0004
SystemDrive=D:
SystemRoot=D:\Windows
TEMP=D:\Users\root\AppData\Local\Temp\2
TEMPLETON_HOME=C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog
TEZ_CLASSPATH=C:\apps\dist\tez-0.5.2.2.2.7.1-0004\conf\;C:\apps\dist\tez-0.5.2.2.2.7.1-0004\*;C:\apps\dist\tez-0.5.2.2.2.7.1-0004\lib\*
TEZ_HOME=C:\apps\dist\tez-0.5.2.2.2.7.1-0004
TMP=D:\Users\root\AppData\Local\Temp\2
USERDOMAIN=headnode0
USERDOMAIN_ROAMINGPROFILE=headnode0
USERNAME=root
USERPROFILE=D:\Users\root
WEBHCAT_CONF_DIR=C:\apps\dist\hive-0.14.0.2.2.7.1-0004\hcatalog\etc\webhcat
YARN_ROOT_LOGGER=INFO,console,DRFA,ETW,FilterLog
windir=D:\Windows
---------------------------------------------------------------------


15076 0.049: com.yourkit.Main1: starting...
15076 0.050: com.yourkit.Main1: number of args: 0
15076 0.181: com.yourkit.Main1: oomeDumperStatus: 1
15076 0.294: com.yourkit.g.f.a.a: FYI: native (current) LAF font: javax.swing.plaf.FontUIResource[family=Tahoma,name=Tahoma,style=plain,size=11]
15076 0.294: com.yourkit.g.f.a.a: FYI: metal font: javax.swing.plaf.FontUIResource[family=Dialog,name=Dialog,style=bold,size=12]
15076 0.300: com.yourkit.g.f.a.a: general font: javax.swing.plaf.FontUIResource[family=Segoe UI,name=Segoe UI,style=plain,size=12]
15076 0.300: com.yourkit.g.f.a.a: menu font: javax.swing.plaf.FontUIResource[family=Segoe UI,name=Segoe UI,style=plain,size=12]
15076 1.149: com.yourkit.g.i.c.c: ParallelExecutor: pool size 4
15076 1.257: shmem: Global\YOURKIT SHARE G: OK, isFirst=1
15076 1.257: shmem: Local\YOURKIT SHARE L: OK, isFirst=1
15076 1.282: shmem: Global\YOURKIT SHARE2 G: OK, isFirst=1
15076 1.282: shmem: Local\YOURKIT SHARE2 L: OK, isFirst=1
15076 1.302: shmem: Global\YOURKIT SHARE5 G: OK, isFirst=1
15076 1.303: shmem: Local\YOURKIT SHARE5 L: OK, isFirst=1
15076 1.524: com.yourkit.g.b6: marker: created D:\Users\root\.yjp\.yjp_20071015_ui55857
15076 76.176: com.yourkit.h.f$b: LWS-activate: code=200 text: payload=AM... result=ok
15076 1127.129: com.yourkit.g.u.a: Attaching agent to: PID=1604
15076 1127.174: com.yourkit.g.u.q: Process type: _BITNESS_UNKNOWN
15076 1127.183: com.yourkit.g.u.q: Process path: java.exe
15076 1127.184: com.yourkit.g.u.q: Trying to attach as to a 32-bit JVM:
D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre\bin\javaw.exe
-Xbootclasspath/a:D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\lib\tools.jar
-Dfile.encoding=UTF-8
-cp
D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\lib\yjp.jar
com.yourkit.Attach
1604
D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win32\yjpagent.dll
D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win64\yjpagent.dll

15076 1127.505: com.yourkit.g.u.q: Command failed:
exit code: 3
stdout:
PID: 1604
path_to_agent: D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win32\yjpagent.dll
startupOptions: D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win64\yjpagent.dll
com.sun.tools.attach.AttachNotSupportedException: Unable to attach to 64-bit process
at sun.tools.attach.WindowsVirtualMachine.openProcess(Native Method)
at sun.tools.attach.WindowsVirtualMachine.<init>(WindowsVirtualMachine.java:38)
at sun.tools.attach.WindowsAttachProvider.attachVirtualMachine(WindowsAttachProvider.java:52)
at com.sun.tools.attach.VirtualMachine.attach(VirtualMachine.java:195)
at com.yourkit.Attach.main(a:50)

15076 1127.506: com.yourkit.g.u.q: Trying to attach as to a 64-bit JVM:
D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\jre64\bin\javaw.exe
-Xbootclasspath/a:D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\lib\tools.jar
-Dfile.encoding=UTF-8
-cp
D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\lib\yjp.jar
com.yourkit.Attach
1604
D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win64\yjpagent.dll
D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win64\yjpagent.dll

15076 1127.915: com.yourkit.g.u.q: Command failed:
exit code: 2
stdout:
PID: 1604
path_to_agent: D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win64\yjpagent.dll
startupOptions: D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win64\yjpagent.dll
VirtualMachine: sun.tools.attach.WindowsAttachProvider@55f96302: 1604
Waiting the agent to load...
checking agent status...
Cannot attach profiler agent to JVM: AgentInitializationException, return value=3
com.sun.tools.attach.AgentInitializationException: Agent_OnAttach failed
at sun.tools.attach.HotSpotVirtualMachine.loadAgentLibrary(HotSpotVirtualMachine.java:47)
at sun.tools.attach.HotSpotVirtualMachine.loadAgentPath(HotSpotVirtualMachine.java:70)
at com.yourkit.Attach.main(a:81)

15076 1127.916: com.yourkit.g.u.a$7: com.yourkit.runtime.PresentableException: Cannot attach profiler agent to JVM as to a 32-bit process:

com.sun.tools.attach.AttachNotSupportedException: Unable to attach to 64-bit process

Cannot attach profiler agent to JVM as to a 64-bit process:

Cannot attach profiler agent to JVM: AgentInitializationException, return value=3
at com.yourkit.g.u.q.a(a:39)
at com.yourkit.g.u.a$7.a(a:3)
at com.yourkit.g.db$1.run(a:5)
at com.yourkit.g.db$b.run(a:12)

15076 1160.836: com.yourkit.e.bc: exiting now...
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Difficulty with getting profiling to work

Post by Anton Katilin »

Hello,

I think I've found the problem.

Please see the command line in your original message. It ends with:
org.apache.hive.hcatalog.templeton.Main -agentpath:"D:\Program Files (x86)\YourKit Java Profiler 2015 build 15076\bin\win64\yjpagent.dll"

-agentpath is a JVM option, and should be placed among other VM options, i.e. before the class name org.apache.hive.hcatalog.templeton.Main. You placed it after the class name, thus making it the program's parameter, i.e. a parameter of main(). As the result, it was not applied.

Best regards,
Anton
dgshaver
Posts: 3
Joined: Wed Oct 28, 2015 8:50 pm

Re: Difficulty with getting profiling to work

Post by dgshaver »

Ugh! Thanks Anton. Really appreciate the help.
Post Reply