search

google / perfetto

Performance instrumentation and tracing for Android, Linux and Chrome (read-only mirror of https://android.googlesource.com/platform/external/perfetto/)
https://www.perfetto.dev
Apache License 2.0
2.86k stars 358 forks source link

"Java Heap Dumps" generates empty trace #531

Closed bolunli11 closed 1 month ago

bolunli11 commented 1 year ago

Hello,

I want to check a running Android application's Java heap usage. But Perfetto keeps generating empty trace files. Below is my workflow:

  1. Set up the proper testing environment in my phone: adb shell setenforce 0 adb shell setprop persist.traced.enable 1 (I'm using pixel7, so this step might not be necessary.)

  2. Generate the config file using Perfetto UI: buffers: { size_kb: 63488 fill_policy: DISCARD } buffers: { size_kb: 2048 fill_policy: DISCARD } data_sources: { config { name: "android.packages_list" target_buffer: 1 } } data_sources: { config { name: "android.java_hprof" target_buffer: 0 java_hprof_config { process_cmdline: "xxxApplication" continuous_dump_config { dump_phase_ms: 1000 dump_interval_ms: 1000 } } } } duration_ms: 15000

  3. Execution CLIs: adb push perfetto_config.pbtxt /data/local/tmp adb shell perfetto --txt -c /data/local/tmp/perfetto_config.pbtxt -o /data/local/tmp/trace.perfetto --wait 15s for the profiling adb pull /data/local/tmp/trace.perfetto

The file trace.perfetto only has 16kb, and it shows nothing when opened it with Perfetto UI.

Am I doing any wrong in the above steps? Thank you very much for your time reading this dumb question.

ddiproietto commented 1 year ago

Based on the fact that you're trying adb shell setenforce 0, I assume you're on a userdebug build. Otherwise, if you're on a regular user build, you can only capture a dump from profileable or debuggable apps (documentation for the native heap profiler, but the principle still applies here).

The config looks reasonable, but, since android 12 (which I assume you have, since you're on pixel 7), there's a more reliable way of recording that waits until all the data has been reported (i.e. using a large data_source_stop_timeout_ms). I suggest using the wrapper script tools/java_heap_dump in the perfetto repo that invokes adb perfetto for you with an approriate config to begin with.

Lastly, to understand what's happening, it's often invaluable to look at the logs. I would do adb logcat -c to clear the log buffer before recording, wait for the recording to finish and then look at the output of adb logcat. grepping for perfetto or hprof usually can tell you what's happening.

bolunli11 commented 1 year ago

I used the below CLI to dump the Java heap of a running Android application (debug build):

tools/java_heap_dump -n com.xxxApplication -c 1 --output /Users/xxx

After running for a while, I terminated it by ctrl+c. The generated trace was only 17KB and it showed nothing in Perfetto UI. Below is the logcat info filtering by perfetto:

2023-07-17 11:31:36.400 24512-24512 perfetto                pid-24512                            I     perfetto_cmd.cc:1001 Connected to the Perfetto traced service, starting tracing
2023-07-17 11:31:36.401   940-940   perfetto                traced                               I  ing_service_impl.cc:969 Configured tracing session 8, #sources:2, duration:0 ms, #buffers:1, total buffer size:100024 KB, total sessions:1, uid:2000 session name: ""
2023-07-17 11:31:36.443 24513-24513 perfetto                pid-24513                            I  approfd_producer.cc:245 Connected to the service, mode [central].
2023-07-17 11:31:36.443 24513-24513 perfetto                pid-24513                            I  a_hprof_producer.cc:174 Connected to the service.
2023-07-17 11:31:56.241 24512-24512 perfetto                perfetto                             I     perfetto_cmd.cc:1170 SIGINT/SIGTERM received: disabling tracing.
2023-07-17 11:31:56.246   938-938   perfetto                traced_probes                        I   probes_producer.cc:409 Producer stop (id=25)
2023-07-17 11:31:56.247 24512-24512 perfetto                perfetto                             I     perfetto_cmd.cc:1129 Wrote 16537 bytes into /data/misc/perfetto-traces/java-profile-7c3db2
2023-07-17 11:31:56.248   940-940   perfetto                traced                               I  ng_service_impl.cc:2442 Tracing session 8 ended, total sessions:0
2023-07-17 11:31:57.337 24785-24785 rm                      pid-24785                            I  type=1400 audit(0.0:58036): avc: denied { write } for name="java-profile-7c3db2" dev="dm-49" ino=81689 scontext=u:r:shell:s0 tcontext=u:object_r:perfetto_traces_data_file:s0 tclass=file permissive=1

Any help is appreciated!

ddiproietto commented 1 year ago 
2023-07-17 11:31:36.400 24512-24512 perfetto                pid-24512                            I     perfetto_cmd.cc:1001 Connected to the Perfetto traced service, starting tracing
2023-07-17 11:31:36.401   940-940   perfetto                traced                               I  ing_service_impl.cc:969 Configured tracing session 8, #sources:2, duration:0 ms, #buffers:1, total buffer size:100024 KB, total sessions:1, uid:2000 session name: ""
2023-07-17 11:31:36.443 24513-24513 perfetto                pid-24513                            I  approfd_producer.cc:245 Connected to the service, mode [central].
2023-07-17 11:31:36.443 24513-24513 perfetto                pid-24513                            I  a_hprof_producer.cc:174 Connected to the service.

At this point, the pid 24513 should send a signal to your app, which should emit a log message (here, if you're curious).

Is your app running before you start recording the trace? You can confirm by adb shell ps -A | grep com.xxxApplication

Alternatively, can you try targeting your app by pid instead of name (by using the -p flag instead of -n)?

Thanks!

bolunli11 commented 1 year ago

Thanks for your time checking my issue.

Using CLI adb shell ps -A | grep com.zhiliaoapp.musically: u0_a310 32158 776 39244548 1114616 0 0 S com.zhiliaoapp.musically This was consistent with adb shell top, the application is running and its pid is 32158.

Using CLI tools/java_heap_dump -p 32158 -c 1 --output /Users/bl/Desktop/test, the logcat info still didn't emit that expected log message:

2023-07-18 10:31:43.921  7412-7412  perfetto                pid-7412                             I     perfetto_cmd.cc:1001 Connected to the Perfetto traced service, starting tracing
2023-07-18 10:31:43.922   940-940   perfetto                traced                               I  ing_service_impl.cc:969 Configured tracing session 23, #sources:2, duration:0 ms, #buffers:1, total buffer size:100024 KB, total sessions:1, uid:2000 session name: ""
2023-07-18 10:31:43.960  7413-7413  perfetto                pid-7413                             I  approfd_producer.cc:245 Connected to the service, mode [central].
2023-07-18 10:31:43.960  7413-7413  perfetto                pid-7413                             I  a_hprof_producer.cc:174 Connected to the service.
2023-07-18 10:31:57.634  7413-7413  heapprofd               heapprofd                            I  type=1400 audit(0.0:115024): avc: denied { read } for name="cmdline" dev="proc" ino=12759320 scontext=u:r:heapprofd:s0 tcontext=u:r:perfetto:s0 tclass=file permissive=1
2023-07-18 10:32:02.929  7412-7412  perfetto                perfetto                             I     perfetto_cmd.cc:1170 SIGINT/SIGTERM received: disabling tracing.
2023-07-18 10:32:02.932   938-938   perfetto                traced_probes                        I   probes_producer.cc:409 Producer stop (id=62)
2023-07-18 10:32:02.934  7412-7412  perfetto                perfetto                             I     perfetto_cmd.cc:1129 Wrote 16516 bytes into /data/misc/perfetto-traces/java-profile-4ce097
2023-07-18 10:32:02.935   940-940   perfetto                traced                               I  ng_service_impl.cc:2442 Tracing session 23 ended, total sessions:0
2023-07-18 10:32:04.070  7670-7670  rm                      pid-7670                             I  type=1400 audit(0.0:119286): avc: denied { write } for name="java-profile-4ce097" dev="dm-49" ino=74374 scontext=u:r:shell:s0 tcontext=u:object_r:perfetto_traces_data_file:s0 tclass=file permissive=1

BTW, Perfetto worked very well when I checked my application's GC info (turned on the "Atrace userspace annotations") or CPU info (tried the CPU probes as well). Only both memory profiling ("Native heap profiling" and "Java heap dumps") didn't work.

ddiproietto commented 1 year ago

Can you share the result of adb shell getprop ro.system.build.fingerprint on your device?

What app are you trying to profile? Is this an app you built or an app you downloaded from Play store?

bolunli11 commented 1 year ago

adb shell getprop ro.system.build.fingerprint result: google/panther/panther:13/TQ3A.230605.012/10204971:user/release-keys

I'm running the TikTok app, it's a debug build version, not the release version in the Play store.

LalitMaganti commented 1 month ago

I think the problem here is that while it might be a debug build of the app, the app is still not profilable or debuggable. Please review documentation on that at https://perfetto.dev/docs/data-sources/native-heap-profiler#heapprofd-targets