Fully featured low overhead profiler for Java EE and Java SE platforms.
Ultimate profiling and monitoring solution for Gradle, Maven, Ant, JUnit and TestNG.
Easy to use performance and memory profiler for .NET framework.

Capturing Snapshot extremely slow

Moderators: Vladimir Kondratyev, Anton Katilin

Capturing Snapshot extremely slow

Postby lemke » Wed Nov 25, 2015 10:51 am

Hi all,

the "Capturing Snapshot" feature is currently quite unusable on my Ubuntu 15.10 box. It proceeds very fast until the progress bar reaches 50~60% and then it takes about an hour or longer to complete the snapshot.
I'm using YourKit 2015 build 15078 (64bit)

I need to profile a java process at a certain state. I started the process with the following JVM options:
-agentpath:/opt/yourkit/bin/linux-x86-64/libyjpagent.so
-Xdebug
-Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=5005

Then I connect with IDEA and wait until a breakpoint is reached (only the current thread is suspended) and start capturing snapshot in yourkit.
lemke
 
Posts: 3
Joined: Wed Nov 25, 2015 10:35 am

Re: Capturing Snapshot extremely slow

Postby Anton Katilin » Wed Nov 25, 2015 1:37 pm

Hi,

It's a new issue, we're investigating.

Perhaps stopping the JVM at the breakpoint is the cause of the problem.

Could you please:

1. Provide the profiler agent log file ~/.yjp/log/<session name>-<pid>.log

2. Try capturing the same kind of snapshot when the application is not stopped at a breakpoint, to compare capture times.

What kind of snapshot is this? If it's a memory snapshot, you may consider using the JVM's built-in dumper as a workaround:
https://www.yourkit.com/docs/java/help/ ... pshots.jsp

Best regards,
Anton
Anton Katilin
 
Posts: 5575
Joined: Wed Aug 11, 2004 8:37 am

Re: Capturing Snapshot extremely slow

Postby lemke » Thu Nov 26, 2015 6:48 am

Hi Anton,

thank your for your quick reply and the workaround! Yes, it's a memory snapshot.

I noticed that I can't even (re)connect to the process when I stopped at a breakpoint and captured a mem snapshot. When I choose the process from yourkit welcom screen, the message "Connecting to Application..." appears but gets stuck at 0%.

I killed the process and restarted yourkit. Then I could connect but snapshot capturing was slow as before. After a reboot, snapshot capturing is really fast again (few seconds). It seems you're right and the stop at the breakpoint is the cause for the problem.

Here the log file content:
15078 0.032: Command line:
/opt/yjp-2015-build-15078/bin/../jre64/bin/java
-Xmx4G
-XX:+HeapDumpOnOutOfMemoryError
-XX:OnError=/opt/yjp-2015-build-15078/bin/../bin/yjp.sh -on_error %p
-jar
/opt/yjp-2015-build-15078/bin/../lib/yjp.jar
15078 0.032: Executable: /opt/yjp-2015-build-15078/jre64/bin/java
15078 0.032: uname:
sysname: Linux
release: 4.2.0-18-generic
version: #22-Ubuntu SMP Fri Nov 6 18:25:50 UTC 2015
machine: x86_64
15078 0.032: Linux; fast_thread_cpu_time=1; 64-bit process
15078 0.032: hid: 3602291148UY33ZW9831Z0857UU681Y6VV 64-bit machine
15078 0.032: Today is 20151125
15078 0.032: full_build_stamp: 15078 201511161426
15078 0.032: Agent library path: /opt/yjp-2015-build-15078/bin/linux-x86-64/libyjpagent.so
15078 0.032:
---------------------------------------------------------------------
Product: YourKit Java Profiler 2015 build 15078
Build: 15078 on 201511161343
JDK: 1.8.0_65
VM: Java HotSpot(TM) 64-Bit Server VM
Vendor: Oracle Corporation
OS: Linux
OS version: 4.2.0-18-generic
OS arch: amd64
Date and time: Wed Nov 25 08:40:42 CET 2015
Properties:
awt.toolkit=sun.awt.X11.XToolkit
file.encoding.pkg=sun.io
file.encoding=UTF-8
file.separator=/
java.awt.graphicsenv=sun.awt.X11GraphicsEnvironment
java.awt.printerjob=sun.print.PSPrinterJob
java.class.path=/opt/yjp-2015-build-15078/bin/../lib/yjp.jar
java.class.version=52.0
java.endorsed.dirs=/opt/yjp-2015-build-15078/jre64/lib/endorsed
java.ext.dirs=/opt/yjp-2015-build-15078/jre64/lib/ext:/usr/java/packages/lib/ext
java.home=/opt/yjp-2015-build-15078/jre64
java.io.tmpdir=/tmp
java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
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=Linux
os.version=4.2.0-18-generic
path.separator=:
sun.arch.data.model=64
sun.awt.enableExtraMouseButtons=true
sun.boot.class.path=/opt/yjp-2015-build-15078/jre64/lib/resources.jar:/opt/yjp-2015-build-15078/jre64/lib/rt.jar:/opt/yjp-2015-build-15078/jre64/lib/sunrsasign.jar:/opt/yjp-2015-build-15078/jre64/lib/jsse.jar:/opt/yjp-2015-build-15078/jre64/lib/jce.jar:/opt/yjp-2015-build-15078/jre64/lib/charsets.jar:/opt/yjp-2015-build-15078/jre64/lib/jfr.jar:/opt/yjp-2015-build-15078/jre64/classes
sun.boot.library.path=/opt/yjp-2015-build-15078/jre64/lib/amd64
sun.cpu.endian=little
sun.cpu.isalist=
sun.desktop=gnome
sun.font.fontmanager=sun.awt.X11FontManager
sun.io.unicode.encoding=UnicodeLittle
sun.java.command=/opt/yjp-2015-build-15078/bin/../lib/yjp.jar
sun.java.launcher=SUN_STANDARD
sun.jnu.encoding=UTF-8
sun.management.compiler=HotSpot 64-Bit Tiered Compilers
sun.os.patch.level=unknown
user.country=CH
user.dir=/home/lemke
user.home=/home/lemke
user.language=de
user.name=lemke
user.timezone=Europe/Zurich
Environment:
CLUTTER_IM_MODULE=xim
COMPIZ_BIN_PATH=/usr/bin/
COMPIZ_CONFIG_PROFILE=ubuntu
DBUS_SESSION_BUS_ADDRESS=unix:abstract=/tmp/dbus-V63wjvUwur
DEFAULTS_PATH=/usr/share/gconf/ubuntu.default.path
DESKTOP_SESSION=ubuntu
DISPLAY=:0
GDMSESSION=ubuntu
GDM_LANG=de_DE
GIO_LAUNCHED_DESKTOP_FILE=/home/lemke/.local/share/applications/yourkit.desktop
GIO_LAUNCHED_DESKTOP_FILE_PID=9909
GNOME_DESKTOP_SESSION_ID=this-is-deprecated
GNOME_KEYRING_CONTROL=
GNOME_KEYRING_PID=
GPG_AGENT_INFO=/tmp/gpg-sQc5sL/S.gpg-agent:4298:1
GTK2_MODULES=overlay-scrollbar
GTK_IM_MODULE=ibus
GTK_MODULES=unity-gtk-module
HOME=/home/lemke
IM_CONFIG_PHASE=1
INSTANCE=
JOB=unity-settings-daemon
LANG=de_CH.UTF-8
LANGUAGE=de_CH:de
LOGNAME=lemke
MANDATORY_PATH=/usr/share/gconf/ubuntu.mandatory.path
NLSPATH=/usr/dt/lib/nls/msg/%L/%N.cat
PATH=/home/lemke/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games
PWD=/home/lemke
QT4_IM_MODULE=xim
QT_IM_MODULE=ibus
QT_QPA_PLATFORMTHEME=appmenu-qt5
SESSION=ubuntu
SESSIONTYPE=gnome-session
SHELL=/bin/bash
SHLVL=0
SSH_AUTH_SOCK=/run/user/1000/keyring/ssh
UPSTART_EVENTS=xsession started
UPSTART_INSTANCE=
UPSTART_JOB=unity7
UPSTART_SESSION=unix:abstract=/com/ubuntu/upstart-session/1000/4158
USER=lemke
XAUTHORITY=/home/lemke/.Xauthority
XDG_CONFIG_DIRS=/etc/xdg/xdg-ubuntu:/usr/share/upstart/xdg:/etc/xdg
XDG_CURRENT_DESKTOP=Unity
XDG_DATA_DIRS=/usr/share/ubuntu:/usr/share/gnome:/usr/local/share/:/usr/share/
XDG_GREETER_DATA_DIR=/var/lib/lightdm-data/lemke
XDG_RUNTIME_DIR=/run/user/1000
XDG_SEAT=seat0
XDG_SEAT_PATH=/org/freedesktop/DisplayManager/Seat0
XDG_SESSION_DESKTOP=ubuntu
XDG_SESSION_ID=c3
XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0
XDG_SESSION_TYPE=x11
XDG_VTNR=7
XFILESEARCHPATH=/usr/dt/app-defaults/%L/Dt
XMODIFIERS=@im=ibus
http_proxy=http://proxy:8080/
https_proxy=https://proxy:8080/
---------------------------------------------------------------------


15078 0.032: com.yourkit.Main1: starting...
15078 0.032: com.yourkit.Main1: number of args: 0
15078 0.121: com.yourkit.Main1: oomeDumperStatus: 1
15078 0.321: com.yourkit.g.f.a.a: FYI: native (current) LAF font: javax.swing.plaf.FontUIResource[family=Ubuntu,name=Ubuntu,style=plain,size=15]
15078 0.321: com.yourkit.g.f.a.a: FYI: metal font: javax.swing.plaf.FontUIResource[family=Dialog,name=Dialog,style=bold,size=12]
15078 0.321: com.yourkit.g.f.a.a: FYI: default font preference for this system: metal
15078 0.321: com.yourkit.g.f.a.a: font: using metal
15078 0.321: com.yourkit.g.f.a.a: general font: javax.swing.plaf.FontUIResource[family=Dialog,name=Dialog,style=plain,size=12]
15078 0.756: com.yourkit.g.i.c.c: ParallelExecutor: pool size 12
15078 0.802: shmem 4234148E: OK
15078 0.804: shmem 42341490: OK
15078 0.962: com.yourkit.g.b6: marker: created /tmp/.yjp_20071015_ui40383
15078 3.197: com.yourkit.h.f$b: LWS-activate: code=200 text: payload=AM... result=ok
15078 344.022: com.yourkit.d.a5: snapshot_outer: starting: null
15078 344.022: com.yourkit.d.a5: controller telemetry limit: 3600
15078 344.025: com.yourkit.d.a5: snapshot_outer: done in 0 sec: null
15078 620.194: com.yourkit.d.a5: snapshot_outer: starting: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems.snapshot size=299 MB
15078 620.195: com.yourkit.d.a5: Loader for YourKit snapshot (v2014+): /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems.snapshot
15078 620.197: com.yourkit.d.c.a.c: hprof_magic_string: YOURKIT_FILE_60000
15078 620.205: com.yourkit.d.c.a.c: pass1: skipping
15078 620.205: com.yourkit.d.c.a.c: hprof_info: big_oids=false compressed=false record_order=normal
15078 620.211: [m: 9534 377] createStorage: objectCount=6449191
15078 620.255: [m: 9706 549] createStorage: result=140179880833312
15078 620.259: com.yourkit.d.c.a.c: pass2: starting
15078 623.859: com.yourkit.d.c.a.c: pass2: finished
15078 623.860: com.yourkit.d.c.f: flush_all:
oids: 0/0
crc: 50/6439684
prim: 27/3441959
refs: 3604/6815474
15078 624.416: com.yourkit.d.a5: probes_to_j2ee_records: with all events: startNs=0
15078 624.752: com.yourkit.d.c.am: initMemPart: 0
15078 624.755: com.yourkit.d.c.am: initMemPart: 1
15078 625.571: com.yourkit.d.c.am: initMemPart: 2
15078 625.571: com.yourkit.d.c.am: initMemPart: 3
15078 625.573: [m: 9894 881] dc: 0
15078 625.573: [m: 9894 881] dc: input creation: starting...
N=6449192 roots=6504
/tmp/yjp_dc_7570838146943501472.dc_input -> /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems.snapshot.idom
15078 625.573: [m: 9894 881] NewDominatorSupport::createInput: /tmp/yjp_dc_7570838146943501472.dc_input
15078 625.595: [m: 9919 905] NewDominatorSupport::createInput: o2c created
15078 625.604: NewDominatorSupport::createInput: roots=6504
N=6449192
NC=4976731
15078 625.941: [m: 9919 907] NewDominatorSupport::createInput: all_refs=16425404 not_null_refs=11738671 written_refs=8253214
15078 625.946: [m: 9919 906] NewDominatorSupport::createInput: done
15078 625.946: [m: 9894 881] dc: input creation: ended, NC=4976731
15078 625.946: [m: 9894 881] dc: runnable...
15078 625.947: com.yourkit.d.c.ar: DC_process: to run:
/opt/yjp-2015-build-15078/bin/linux-x86-64/yjp_dc
/tmp/yjp_dc_7570838146943501472.dc_input
/media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems.snapshot.idom
snca

15078 627.787: com.yourkit.d.c.ar: DC_process: output:
exit code: 0
stdout:
yjp_dc: trying to load /opt/yjp-2015-build-15078/bin/linux-x86-64/libyjpagent.so
stderr:
15078 0.000: [m: 40 5] Reading input: /tmp/yjp_dc_7570838146943501472.dc_input
15078 0.001: N = 4976731
15078 0.367: refs: 8253214
15078 0.367: roots: 6504
15078 0.367: [m: 109 75] creating idom...
15078 0.387: [m: 128 94] starting DominatorComputer3 (SNCA)...
15078 0.428: [m: 166 132] _dcc: enter: N=4976731
15078 0.456: [m: 186 151] _dcc: dfsd: 1
15078 0.688: [m: 186 151] _dcc: dfsd: 2
15078 0.689: [m: 167 132] _dcc: 1: n=4976731
15078 0.691: [m: 167 132] _dcc: 2
15078 1.170: [m: 236 202] _dcc: 3
15078 1.173: [m: 166 132] _dcc: 4
15078 1.229: [m: 204 170] _dcc: 5
15078 1.449: [m: 204 170] _dcc: 6: stack size (bytes): 4104
15078 1.455: [m: 166 132] _dcc: 7
15078 1.460: [m: 166 132] _dcc: 8
15078 1.469: [m: 166 132] _dcc: exit
15078 1.473: [m: 58 24] Writing output: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems.snapshot.idom
15078 1.605: [m: 59 25] OK

15078 627.787: [m: 10024 878] dc: reading...
15078 627.787: NewDominatorSupport::read: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems.snapshot.idom
N=6449192
NC=4976731
15078 627.879: NewDominatorSupport::read: done
15078 627.880: [m: 10024 878] dc: reading done
15078 628.072: [m: 10024 878] dc: 3
15078 628.072: [m: 10024 878] dc: end
15078 628.072: com.yourkit.d.c.am: initMemPart: 5
15078 628.077: com.yourkit.d.c.am: initMemPart: task 2/5
15078 628.216: com.yourkit.d.c.am: WebApplicationHelper: starting...
15078 628.324: com.yourkit.d.c.am: WebApplicationHelper: done
15078 628.324: com.yourkit.d.c.am: initMemPart: task 3/5
15078 628.868: com.yourkit.d.c.am: initMemPart: task 4/5
15078 628.905: com.yourkit.d.c.am: initMemPart: task 5/5
15078 629.211: [m: 10026 918] depth_to_gc_roots: maxFrontSize: 1537234
15078 629.213: com.yourkit.d.c.am: initMemPart: done; storage stats:
CLASS : 9505
OBJ : 5818160
OBJ_ARRAY : 134896
PRIM_ARRAY : 486630
ARRAY_EXT : 0
REFS : 14366346

SS: 6449192 0
RS: 6449192 0

15078 629.224: com.yourkit.d.a5: Loader finished:
db stats:
string 98081 / 98082
thread 50 / 51
tfi
capacity: 1049600
size: 50
i_chunks: 0 of -1
l_chunks: 1 of 1026
estimated size: 0 MB
method 102948 / 105026
monitor 0 / 0
cpu(time)
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB
cpu(count)
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB
instance_count 9496 / 9497
frame 18061 / 18061
table_gen 0 / 0
snapshot 0 / 0
alloc_info 0 / 0
generation 2 / 3
properties 185 / 186
tele 1878 [ 0; 1878)
ext values length: total=522084 avg=278 max=278
values ext size: 1 MB

values size: 0 MB

states length: total=44762 avg=23 max=30
states size: 0 MB

exception 2119 / 2120
event 7222 / 7223
values length: total=43277 avg=5 max=7
values size: 0 MB

code_point 2910 / 2911
call_count
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB
alloc_point
capacity: 1049600
size: 55255
i_chunks: 0 of -1
l_chunks: 54 of 1026
estimated size: 0 MB
alloc_object_count
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB

15078 629.224: com.yourkit.d.a5: snapshot_outer: done in 9 sec: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems.snapshot
15078 2528.410: com.yourkit.d.a5: snapshot_outer: starting: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems_afterGC.snapshot size=227 MB
15078 2528.411: com.yourkit.d.a5: Loader for YourKit snapshot (v2014+): /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems_afterGC.snapshot
15078 2528.411: com.yourkit.d.c.a.c: hprof_magic_string: YOURKIT_FILE_60000
15078 2528.412: com.yourkit.d.c.a.c: pass1: skipping
15078 2528.412: com.yourkit.d.c.a.c: hprof_info: big_oids=false compressed=false record_order=normal
15078 2528.708: [m: 10026 885] createStorage: objectCount=5079725
15078 2528.768: [m: 10128 1021] createStorage: result=140179746591776
15078 2528.772: com.yourkit.d.c.a.c: pass2: starting
15078 2531.574: com.yourkit.d.c.a.c: pass2: finished
15078 2531.577: com.yourkit.d.c.f: flush_all:
oids: 0/0
crc: 39/5070218
prim: 20/2616673
refs: 3604/6812781
15078 2532.129: com.yourkit.d.a5: probes_to_j2ee_records: with all events: startNs=0
15078 2532.381: com.yourkit.d.c.am: initMemPart: 0
15078 2532.413: com.yourkit.d.c.am: initMemPart: 1
15078 2532.965: com.yourkit.d.c.am: initMemPart: 2
15078 2532.965: com.yourkit.d.c.am: initMemPart: 3
15078 2532.966: [m: 10256 1230] dc: 0
15078 2532.966: [m: 10256 1230] dc: input creation: starting...
N=5079726 roots=6345
/tmp/yjp_dc_2697550725811566722.dc_input -> /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems_afterGC.snapshot.idom
15078 2532.966: [m: 10256 1230] NewDominatorSupport::createInput: /tmp/yjp_dc_2697550725811566722.dc_input
15078 2532.976: [m: 10276 1249] NewDominatorSupport::createInput: o2c created
15078 2532.982: NewDominatorSupport::createInput: roots=6345
N=5079726
NC=4976737
15078 2533.308: [m: 10276 1251] NewDominatorSupport::createInput: all_refs=16425255 not_null_refs=11738727 written_refs=8261725
15078 2533.313: [m: 10276 1250] NewDominatorSupport::createInput: done
15078 2533.313: [m: 10276 1249] dc: input creation: ended, NC=4976737
15078 2533.313: [m: 10276 1249] dc: runnable...
15078 2533.313: com.yourkit.d.c.ar: DC_process: to run:
/opt/yjp-2015-build-15078/bin/linux-x86-64/yjp_dc
/tmp/yjp_dc_2697550725811566722.dc_input
/media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems_afterGC.snapshot.idom
snca

15078 2535.010: com.yourkit.d.c.ar: DC_process: output:
exit code: 0
stdout:
yjp_dc: trying to load /opt/yjp-2015-build-15078/bin/linux-x86-64/libyjpagent.so
stderr:
15078 0.001: [m: 40 5] Reading input: /tmp/yjp_dc_2697550725811566722.dc_input
15078 0.002: N = 4976737
15078 0.362: refs: 8261725
15078 0.362: roots: 6345
15078 0.362: [m: 109 75] creating idom...
15078 0.373: [m: 128 94] starting DominatorComputer3 (SNCA)...
15078 0.394: [m: 166 132] _dcc: enter: N=4976737
15078 0.407: [m: 186 151] _dcc: dfsd: 1
15078 0.631: [m: 186 151] _dcc: dfsd: 2
15078 0.632: [m: 167 132] _dcc: 1: n=4976737
15078 0.634: [m: 167 132] _dcc: 2
15078 1.058: [m: 236 202] _dcc: 3
15078 1.059: [m: 166 132] _dcc: 4
15078 1.087: [m: 204 170] _dcc: 5
15078 1.286: [m: 204 170] _dcc: 6: stack size (bytes): 4104
15078 1.290: [m: 166 132] _dcc: 7
15078 1.295: [m: 166 132] _dcc: 8
15078 1.303: [m: 166 132] _dcc: exit
15078 1.305: [m: 58 24] Writing output: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems_afterGC.snapshot.idom
15078 1.483: [m: 59 25] OK

15078 2535.010: [m: 10276 1249] dc: reading...
15078 2535.010: NewDominatorSupport::read: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems_afterGC.snapshot.idom
N=5079726
NC=4976737
15078 2535.088: NewDominatorSupport::read: done
15078 2535.088: [m: 10276 1249] dc: reading done
15078 2535.252: [m: 10288 1254] dc: 3
15078 2535.252: [m: 10288 1254] dc: end
15078 2535.252: com.yourkit.d.c.am: initMemPart: 5
15078 2535.259: com.yourkit.d.c.am: initMemPart: task 2/5
15078 2535.301: com.yourkit.d.c.am: WebApplicationHelper: starting...
15078 2535.354: com.yourkit.d.c.am: WebApplicationHelper: done
15078 2535.354: com.yourkit.d.c.am: initMemPart: task 3/5
15078 2535.978: com.yourkit.d.c.am: initMemPart: task 4/5
15078 2536.008: com.yourkit.d.c.am: initMemPart: task 5/5
15078 2536.302: [m: 10292 1262] depth_to_gc_roots: maxFrontSize: 1537223
15078 2536.302: com.yourkit.d.c.am: initMemPart: done; storage stats:
CLASS : 9505
OBJ : 4742994
OBJ_ARRAY : 81994
PRIM_ARRAY : 245232
ARRAY_EXT : 0
REFS : 11599867

SS: 5079726 0
RS: 5079726 0

15078 2536.307: com.yourkit.d.a5: Loader finished:
db stats:
string 98065 / 98082
thread 51 / 52
tfi
capacity: 1049600
size: 51
i_chunks: 0 of -1
l_chunks: 1 of 1026
estimated size: 0 MB
method 102948 / 105026
monitor 0 / 0
cpu(time)
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB
cpu(count)
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB
instance_count 9496 / 9497
frame 18067 / 18067
table_gen 0 / 0
snapshot 1 / 2
alloc_info 0 / 0
generation 3 / 4
properties 185 / 186
tele 1934 [ 0; 1934)
ext values length: total=537652 avg=278 max=278
values ext size: 2 MB

values size: 0 MB

states length: total=44762 avg=23 max=30
states size: 0 MB

exception 2119 / 2120
event 7755 / 7756
values length: total=46473 avg=5 max=7
values size: 0 MB

code_point 2910 / 2911
call_count
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB
alloc_point
capacity: 1049600
size: 55255
i_chunks: 0 of -1
l_chunks: 54 of 1026
estimated size: 0 MB
alloc_object_count
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB

15078 2536.307: com.yourkit.d.a5: snapshot_outer: done in 7 sec: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_products_before_setMaxItems_afterGC.snapshot
15078 22692.532: com.yourkit.d.a5: snapshot_outer: starting: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_p23777_c10259_l6500_hit.snapshot size=268 MB
15078 22692.533: com.yourkit.d.a5: Loader for YourKit snapshot (v2014+): /media/Daten/Profiling/Snapshots/O1342-Hasler-all_p23777_c10259_l6500_hit.snapshot
15078 22692.533: com.yourkit.d.c.a.c: hprof_magic_string: YOURKIT_FILE_60000
15078 22692.533: com.yourkit.d.c.a.c: pass1: skipping
15078 22692.533: com.yourkit.d.c.a.c: hprof_info: big_oids=false compressed=false record_order=normal
15078 22692.567: [m: 10294 1231] createStorage: objectCount=5820196
15078 22692.844: [m: 10466 1386] createStorage: result=140179880904560
15078 22692.848: com.yourkit.d.c.a.c: pass2: starting
15078 22696.248: com.yourkit.d.c.a.c: pass2: finished
15078 22696.250: com.yourkit.d.c.f: flush_all:
oids: 0/0
crc: 45/5810083
prim: 22/2872016
refs: 4030/3699355
15078 22696.746: com.yourkit.d.a5: probes_to_j2ee_records: with all events: startNs=0
15078 22696.955: com.yourkit.d.c.am: initMemPart: 0
15078 22696.974: com.yourkit.d.c.am: initMemPart: 1
15078 22697.297: com.yourkit.d.c.am: initMemPart: 2
15078 22697.297: com.yourkit.d.c.am: initMemPart: 3
15078 22697.297: [m: 10594 1626] dc: 0
15078 22697.298: [m: 10594 1626] dc: input creation: starting...
N=5820197 roots=6675
/tmp/yjp_dc_8146900231480436458.dc_input -> /media/Daten/Profiling/Snapshots/O1342-Hasler-all_p23777_c10259_l6500_hit.snapshot.idom
15078 22697.298: [m: 10594 1626] NewDominatorSupport::createInput: /tmp/yjp_dc_8146900231480436458.dc_input
15078 22697.301: [m: 10594 1626] NewDominatorSupport::createInput: o2c created
15078 22697.307: NewDominatorSupport::createInput: roots=6675
N=5820197
NC=2486645
15078 22697.487: [m: 10594 1628] NewDominatorSupport::createInput: all_refs=8725264 not_null_refs=6128198 written_refs=4255927
15078 22697.490: [m: 10594 1627] NewDominatorSupport::createInput: done
15078 22697.490: [m: 10594 1626] dc: input creation: ended, NC=2486645
15078 22697.490: [m: 10594 1626] dc: runnable...
15078 22697.541: com.yourkit.d.c.ar: DC_process: to run:
/opt/yjp-2015-build-15078/bin/linux-x86-64/yjp_dc
/tmp/yjp_dc_8146900231480436458.dc_input
/media/Daten/Profiling/Snapshots/O1342-Hasler-all_p23777_c10259_l6500_hit.snapshot.idom
snca

15078 22698.434: com.yourkit.d.c.ar: DC_process: output:
exit code: 0
stdout:
yjp_dc: trying to load /opt/yjp-2015-build-15078/bin/linux-x86-64/libyjpagent.so
stderr:
15078 0.006: [m: 40 5] Reading input: /tmp/yjp_dc_8146900231480436458.dc_input
15078 0.006: N = 2486645
15078 0.229: refs: 4255927
15078 0.229: roots: 6675
15078 0.229: [m: 78 44] creating idom...
15078 0.246: [m: 88 53] starting DominatorComputer3 (SNCA)...
15078 0.276: [m: 107 72] _dcc: enter: N=2486645
15078 0.291: [m: 117 82] _dcc: dfsd: 1
15078 0.413: [m: 117 82] _dcc: dfsd: 2
15078 0.414: [m: 107 73] _dcc: 1: n=2486645
15078 0.415: [m: 107 73] _dcc: 2
15078 0.664: [m: 146 111] _dcc: 3
15078 0.666: [m: 107 72] _dcc: 4
15078 0.696: [m: 126 91] _dcc: 5
15078 0.803: [m: 126 91] _dcc: 6: stack size (bytes): 4104
15078 0.806: [m: 107 72] _dcc: 7
15078 0.809: [m: 107 72] _dcc: 8
15078 0.813: [m: 107 72] _dcc: exit
15078 0.815: [m: 49 15] Writing output: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_p23777_c10259_l6500_hit.snapshot.idom
15078 0.884: [m: 50 15] OK

15078 22698.434: [m: 10594 1626] dc: reading...
15078 22698.434: NewDominatorSupport::read: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_p23777_c10259_l6500_hit.snapshot.idom
N=5820197
NC=2486645
15078 22698.473: NewDominatorSupport::read: done
15078 22698.473: [m: 10594 1626] dc: reading done
15078 22698.606: [m: 10601 1633] dc: 3
15078 22698.606: [m: 10601 1633] dc: end
15078 22698.606: com.yourkit.d.c.am: initMemPart: 5
15078 22698.609: com.yourkit.d.c.am: initMemPart: task 2/5
15078 22698.656: com.yourkit.d.c.am: WebApplicationHelper: starting...
15078 22698.707: com.yourkit.d.c.am: WebApplicationHelper: done
15078 22698.707: com.yourkit.d.c.am: initMemPart: task 3/5
15078 22699.231: com.yourkit.d.c.am: initMemPart: task 4/5
15078 22699.272: com.yourkit.d.c.am: initMemPart: task 5/5
15078 22699.512: [m: 10601 1633] depth_to_gc_roots: maxFrontSize: 542836
15078 22699.512: com.yourkit.d.c.am: initMemPart: done; storage stats:
CLASS : 10113
OBJ : 5161370
OBJ_ARRAY : 210147
PRIM_ARRAY : 438566
ARRAY_EXT : 0
REFS : 10813334

SS: 5820197 0
RS: 5820197 0

15078 22699.516: com.yourkit.d.a5: Loader finished:
db stats:
string 102588 / 102589
thread 158 / 159
tfi
capacity: 1049600
size: 103
i_chunks: 0 of -1
l_chunks: 1 of 1026
estimated size: 0 MB
method 107538 / 109112
monitor 0 / 0
cpu(time)
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB
cpu(count)
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB
instance_count 10105 / 10106
frame 19436 / 19436
table_gen 0 / 0
snapshot 2 / 3
alloc_info 0 / 0
generation 4 / 5
properties 185 / 186
tele 3600 [ 4921; 8521)
ext values length: total=1000800 avg=278 max=278
values ext size: 3 MB

values size: 0 MB

states length: total=0 avg=0 max=0
states size: 0 MB

exception 2119 / 2121
event 13031 / 13032
values length: total=78021 avg=5 max=7
values size: 0 MB

code_point 3085 / 3086
call_count
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB
alloc_point
capacity: 1049600
size: 59223
i_chunks: 0 of -1
l_chunks: 58 of 1026
estimated size: 0 MB
alloc_object_count
capacity: 1049600
size: 0
i_chunks: 0 of -1
l_chunks: 0 of -1
estimated size: 0 MB

15078 22699.516: com.yourkit.d.a5: snapshot_outer: done in 6 sec: /media/Daten/Profiling/Snapshots/O1342-Hasler-all_p23777_c10259_l6500_hit.snapshot
15078 26307.484: com.yourkit.e.bc: exiting now...

Kind Regards,
Bastian
lemke
 
Posts: 3
Joined: Wed Nov 25, 2015 10:35 am

Re: Capturing Snapshot extremely slow

Postby Anton Katilin » Thu Nov 26, 2015 12:10 pm

Hi Bastian

The log you've sent is from the profiler UI (yjp.sh), but we need the log of the profiled application. The profiler UI only triggers the snapshot, but all real work is done in the agent, so we need to know whether anything goes wrong on the agent side.

By the way, we tried to reproduce the problem but didn't manage to.

Are other threads, i.e. those non-stopped at the breakpoint, active? Do they perform any active computations or are more or less idle? The profiler tries to stop all threads during a memory snapshot capture, but it is not always possible. For example, when the profiled application runs with the debugger, the agent cannot stop threads at all (that's a JVM's limitation). So, if other threads are active during the snapshot capture they may interfere.

Best regards,
Anton
Anton Katilin
 
Posts: 5575
Joined: Wed Aug 11, 2004 8:37 am

Re: Capturing Snapshot extremely slow

Postby Anton Katilin » Thu Nov 26, 2015 12:18 pm

Another possible workaround is to trigger the snapshot automatically.

If you set the breakpoint to catch the first entrance to a given method, you can add a trigger on method invocation, with a single command to capture a snapshot:
https://www.yourkit.com/docs/java/help/triggers.jsp

If the breakpoint's condition is more complicated and you can modify the profiled program's source code, you can use the profiler API ( https://www.yourkit.com/docs/java/help/api.jsp ), e.g:
Code: Select all
        try {
          new com.yourkit.api.Controller().captureMemorySnapshot();
        }
        catch (Exception e) {
          e.printStackTrace();
        }

To let this compile, please add <Profiler Installation Directory>/lib/yjp-controller-api-redist.jar to the classpath.
Anton Katilin
 
Posts: 5575
Joined: Wed Aug 11, 2004 8:37 am

Re: Capturing Snapshot extremely slow

Postby Anton Katilin » Thu Nov 26, 2015 12:28 pm

Update 2:

Another idea, unrelated with the breakpoint:

According to the log file, your snapshots are located in /media/Daten/Profiling/Snapshots/

Is this the directory where the snapshots are captured to?

What kind of file system is this? /media usually corresponds to a removable media mounted by the system.

Snapshot capture maps the result file to memory at some stages. It is desirable that the snapshot directories' file system is fast enough to support this operation.

If possible, please try setting the snapshot directory to a local drive which is presumably fast (hdd or sdd):
https://www.yourkit.com/docs/java/help/snapshot_dir.jsp
Anton Katilin
 
Posts: 5575
Joined: Wed Aug 11, 2004 8:37 am

Re: Capturing Snapshot extremely slow

Postby lemke » Fri Nov 27, 2015 7:51 am

Hi Anton,

the workaround with the method invocation trigger seems to be the best solution for my case to avoid stopping at the breakpoint. The HPROF dump also works fine.

There are several other threads running. They *should* not perform any computations but I am not sure. It's a quite complex application and not my code ;-)

/media/Daten is an internal HDD that was used for a windows installation before. It's formatted with NTFS :x
I also have an internal SSD (ext4) - but not enough space for all snapshots.
I just changed the snapshot directory to the ssd and cannot reproduce the problem anymore. It seems the NTFS disk was the reason. Sry - I did not remember that the partition was formatted with NTFS ... I should have tried another snapshot directory sooner.

Thank you very much for your really fast and competent help!!!

Kind Regards,
Bastian
lemke
 
Posts: 3
Joined: Wed Nov 25, 2015 10:35 am


Return to Java Profiler

Who is online

Users browsing this forum: No registered users and 13 guests

cron