coderplay
12/30/2017 - 7:25 AM

user space c++ method tracing

user/kernel space c++ method tracing

Trace the 2nd argument of JNIEXPORT jint JNICALL Agent_OnAttach(JavaVM* vm, char *args, void * reserved)

download perf-tools from https://github.com/brendangregg/perf-tools/

$ sudo bin/uprobe 'p:/usr/java/jdk1.8.0_144/jre/lib/amd64/libinstrument.so:Agent_OnAttach args=+0(%si):string'
Tracing uprobe Agent_OnAttach (p:Agent_OnAttach /usr/java/jdk1.8.0_144/jre/lib/amd64/libinstrument.so:0x27b0 args=+0(%si):string). Ctrl-C to end.
           <...>-61491 [012] d... 8823844.123721: Agent_OnAttach: (0x7f0f63df87b0) args="/home/ec2-user/.greys/lib/1.7.6.6/greys/greys-agent.jar=/home/ec2-user/.greys/lib/1.7.6.6/greys/greys-core.jar;;targetIp=127.0.0.1;greysCore=/home/ec2-user/.greys/lib/1.7.6.6/greys/greys-core.jar;greysAgent=/home/ec2-user/.greys/lib/1.7.6.6/greys/greys-agent.jar;connectTimeout=6000;targetPort=3658;javaPid=61228;"

For more complex parameters, like struct pointer, object pointer. Dumping the object layout first, this can be done through clang. https://eli.thegreenplace.net/2012/12/17/dumping-a-c-objects-memory-layout-with-clang

$ objdump -tTC  $JAVA_HOME/jre/lib/amd64/server/libjvm.so | grep GCCause::to_string
00000000005d2fd0 l     F .text	00000000000001c9              .hidden GCCause::to_string(GCCause::Cause)

$ sudo perf probe -x $JAVA_HOME/jre/lib/amd64/server/libjvm.so '0x00000000005d2fd0%return +0($retval):string'
Added new event:
  probe_libjvm:abs_5d2fd0 (on 0x00000000005d2fd0%return in $omit_java_home/jre/lib/amd64/server/libjvm.so with +0($retval):string)

You can now use it in all perf tools, such as:

	perf record -e probe_libjvm:abs_5d2fd0 -aR sleep 1
 
$ sudo perf record -e probe_libjvm:abs_5d2fd0 -a

$ sudo perf script
            java  5260 [000] 2190542.672893: probe_libjvm:abs_5d2fd0: (7f0ce8c4ffd0 <- 7f0ce9144f4d) arg1="No GC"
            java  5260 [000] 2190542.672898: probe_libjvm:abs_5d2fd0: (7f0ce8c4ffd0 <- 7f0ce9144f61) arg1="Allocation Failure"
            java  5260 [000] 2190542.672903: probe_libjvm:abs_5d2fd0: (7f0ce8c4ffd0 <- 7f0ce8b0464d) arg1="Allocation Failure"
            java  5260 [000] 2190542.672906: probe_libjvm:abs_5d2fd0: (7f0ce8c4ffd0 <- 7f0ce8b04663) arg1="Allocation Failure"
            java  5260 [000] 2190542.672930: probe_libjvm:abs_5d2fd0: (7f0ce8c4ffd0 <- 7f0ce8c6825c) arg1="Allocation Failure"
            java  5260 [000] 2190542.672962: probe_libjvm:abs_5d2fd0: (7f0ce8c4ffd0 <- 7f0ce8fbf214) arg1="Allocation Failure"
            java  5260 [000] 2190542.692693: probe_libjvm:abs_5d2fd0: (7f0ce8c4ffd0 <- 7f0ce8b046bf) arg1="Allocation Failure"
            java  5260 [000] 2190542.692697: probe_libjvm:abs_5d2fd0: (7f0ce8c4ffd0 <- 7f0ce8b046d3) arg1="Allocation Failure"
            java  5260 [000] 2190542.692699: probe_libjvm:abs_5d2fd0: (7f0ce8c4ffd0 <- 7f0ce9144f9f) arg1="Allocation Failure"
            java  5260 [000] 2190542.692701: probe_libjvm:abs_5d2fd0: (7f0ce8c4ffd0 <- 7f0ce9144fb3) arg1="No GC"

Oracle hotspot jvm 1.8.0u144

$ sudo perf probe -v  -x /usr/java/jdk1.8.0_144/jre/lib/amd64/server/libjvm.so --funcs | head -n 10
(anonymous namespace)::get_global()
ASConcurrentMarkSweepGeneration::cms_size_policy() const
ASConcurrentMarkSweepGeneration::gc_adaptive_policy_counters()
ASConcurrentMarkSweepGeneration::kind()
ASConcurrentMarkSweepGeneration::resize(unsigned long, unsigned long)
ASConcurrentMarkSweepGeneration::short_name() const
ASConcurrentMarkSweepGeneration::shrink_by(unsigned long)
ASConcurrentMarkSweepGeneration::update_counters()
ASConcurrentMarkSweepGeneration::update_counters(unsigned long)
ASConcurrentMarkSweepPolicy::initialize_gc_policy_counters()

function to be traced -- jint JvmtiExport::load_agent_library(AttachOperation* op, outputStream* st)

Check existence

$ sudo perf probe -v  -x /usr/java/jdk1.8.0_144/jre/lib/amd64/server/libjvm.so --funcs | grep load_agent
JvmtiExport::load_agent_library(AttachOperation*, outputStream*)

First attempt to add probe


 sudo perf probe -x /usr/java/jdk1.8.0_144/jre/lib/amd64/server/libjvm.so --add 'JvmtiExport::load_agent_library(AttachOperation*, outputStream*)'
Semantic error :There is non-digit char in line number.

...

Try mangled symbol instead

$ readelf -s --wide /usr/java/jdk1.8.0_144/jre/lib/amd64/server/libjvm.so | grep load_agen
 39207: 000000000079cd00  1389 FUNC    LOCAL  HIDDEN    13 _ZN11JvmtiExport18load_agent_libraryEP15AttachOperationP12outputStream

$ sudo perf probe -x /usr/java/jdk1.8.0_144/jre/lib/amd64/server/libjvm.so --add '_ZN11JvmtiExport18load_agent_libraryEP15AttachOperationP12outputStream'
Failed to find symbol _ZN11JvmtiExport18load_agent_libraryEP15AttachOperationP12outputStream in /usr/java/jdk1.8.0_144/jre/lib/amd64/server/libjvm.so
  Error: Failed to add events.

3rd attempt, add probe through function address. The address got from readelf or objdump

$ objdump -tT /usr/java/jdk1.8.0_144/jre/lib/amd64/server/libjvm.so | grep _ZN11JvmtiExport18load_agent_libraryEP15AttachOperationP12outputStream | awk '{print $1}'
000000000079cd00
$ sudo perf probe -x /usr/java/jdk1.8.0_144/jre/lib/amd64/server/libjvm.so --add '0x000000000079cd00'
Added new event:
  probe_libjvm:abs_79cd00 (on 0x000000000079cd00 in /usr/java/jdk1.8.0_144/jre/lib/amd64/server/libjvm.so)

You can now use it in all perf tools, such as:

        perf record -e probe_libjvm:abs_79cd00 -aR sleep 1

Now try this event

$ sudo perf record -e probe_libjvm:abs_79cd00 -a -g
Lowering default frequency rate to 750.
Please consider tweaking /proc/sys/kernel/perf_event_max_sample_rate.
 sudo perf report --stdio
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 2  of event 'probe_libjvm:abs_79cd00'
# Event count (approx.): 2
#
# Children      Self  Trace output
# ........  ........  ..............
#
   100.00%   100.00%  (7f304aad6d00)
            |
            ---start_thread
               java_start
               JavaThread::run
               JavaThread::thread_main_inner
               JvmtiExport::load_agent_library

system wide tracing which file is being read

sudo perf probe 'vfs_read file->f_path.dentry->d_name.name:string'