1618560 - Add support for profiling multiple java threads

Status: RESOLVED FIXED

(Core :: Gecko Profiler, enhancement, P2)

Description

[Nazım Can Altınova [:canova][:canaltinova on phabricator]]

Currently we can only profile the Java Main Thread. It's useful for most of the cases but still developers may want to profile other Java threads as well. It would be good to connect this feature to profiler's threads filter so users can profile the threads they want.

Comment 1

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

This is a feature I'd like. Today I was comparing two profiles and I didn't see anything on the main thread that appeared to make a difference between them so I was curious to see the background threads. That being said, in my experience with the Android Studio profiler, the main thread has been the most useful.

As for which threads I wanted to look at, there are a number of thread pools that are created in Fenix so scanning the threads of those pools could potentially give me some insights.

Comment 2

[Greg Tatum [:gregtatum]]

I was chatting with :mleclair about this, and was thinking through how the C++ side of things could look. I thought I would paste it here just in case anyone else was looking into an implementation. These were just some initial thoughts.

Based off of the revision 2944e59a19f9

diff --git a/tools/profiler/core/platform.cpp b/tools/profiler/core/platform.cpp
--- a/tools/profiler/core/platform.cpp
+++ b/tools/profiler/core/platform.cpp
@@ -2718,38 +2718,40 @@ static JS::ProfilingCategoryPair InferJa
     return JS::ProfilingCategoryPair::JAVA_KOTLIN;
   }
   if (StartsWith(aName, "androidx.")) {
     return JS::ProfilingCategoryPair::JAVA_ANDROIDX;
   }
   return JS::ProfilingCategoryPair::OTHER;
 }
 
-static void CollectJavaThreadProfileData(ProfileBuffer& aProfileBuffer) {
+static void CollectJavaThreadProfileData(int threadId, ProfileBuffer& aProfileBuffer) {
+  if (!java::GeckoJavaSampler::IsThreadSampled(threadId)) {
+    return;
+  }
   // locked_profiler_start uses sample count is 1000 for Java thread.
   // This entry size is enough now, but we might have to estimate it
   // if we can customize it
 
   // Pass the samples
   // FIXME(bug 1618560): We are currently only profiling the Java main thread.
-  constexpr int threadId = 0;
   int sampleId = 0;
   while (true) {
     // Gets the data from the java main thread only.
-    double sampleTime = java::GeckoJavaSampler::GetSampleTime(sampleId);
+    double sampleTime = java::GeckoJavaSampler::GetSampleTime(threadId, sampleId);
     if (sampleTime == 0.0) {
       break;
     }
 
     aProfileBuffer.AddThreadIdEntry(threadId);
     aProfileBuffer.AddEntry(ProfileBufferEntry::Time(sampleTime));
     int frameId = 0;
     while (true) {
       jni::String::LocalRef frameName =
-          java::GeckoJavaSampler::GetFrameName(sampleId, frameId++);
+          java::GeckoJavaSampler::GetFrameName(threadId, sampleId, frameId++);
       if (!frameName) {
         break;
       }
       nsCString frameNameString = frameName->ToCString();
 
       auto categoryPair = InferJavaCategory(frameNameString);
       aProfileBuffer.CollectCodeLocation("", frameNameString.get(), 0, 0,
                                          Nothing(), Nothing(),
@@ -2757,17 +2759,17 @@ static void CollectJavaThreadProfileData
     }
     sampleId++;
   }
 
   // Pass the markers now
   while (true) {
     // Gets the data from the java main thread only.
     java::GeckoJavaSampler::Marker::LocalRef marker =
-        java::GeckoJavaSampler::PollNextMarker();
+        java::GeckoJavaSampler::PollNextMarker(threadId);
     if (!marker) {
       // All markers are transferred.
       break;
     }
 
     // Get all the marker information from the Java thread using JNI.
     nsCString markerName = marker->GetMarkerName()->ToCString();
     jni::String::LocalRef text = marker->GetMarkerText();
@@ -2879,39 +2881,42 @@ static void locked_profiler_stream_json_
       profiledThreadData->StreamJSON(
           buffer, cx, aWriter, CorePS::ProcessName(aLock),
           CorePS::ETLDplus1(aLock), CorePS::ProcessStartTime(), aSinceTime,
           ActivePS::FeatureJSTracer(aLock), aService);
     }
 
 #if defined(GP_OS_android)
     if (ActivePS::FeatureJava(aLock)) {
-      // We are allocating it chunk by chunk. So this will not allocate 64 MiB
-      // at once. This size should be more than enough for java threads.
-      // This buffer is being created for each process but Android has
-      // relatively less processes compared to desktop, so it's okay here.
-      mozilla::ProfileBufferChunkManagerWithLocalLimit chunkManager(
-          64 * 1024 * 1024, 1024 * 1024);
-      ProfileChunkedBuffer bufferManager(
-          ProfileChunkedBuffer::ThreadSafety::WithoutMutex, chunkManager);
-      ProfileBuffer javaBuffer(bufferManager);
-      CollectJavaThreadProfileData(javaBuffer);
-
-      // Thread id of java Main thread is 0, if we support profiling of other
-      // java thread, we have to get thread id and name via JNI.
-      RefPtr<ThreadInfo> threadInfo = new ThreadInfo(
-          "Java Main Thread", 0, false, CorePS::ProcessStartTime());
-      ProfiledThreadData profiledThreadData(threadInfo, nullptr);
-      profiledThreadData.StreamJSON(
-          javaBuffer, nullptr, aWriter, CorePS::ProcessName(aLock),
-          CorePS::ETLDplus1(aLock), CorePS::ProcessStartTime(), aSinceTime,
-          ActivePS::FeatureJSTracer(aLock), nullptr);
+      for (const auto& threadId : java::GeckoJavaSampler::GetRegisteredThreadIds()) {
+        // We are allocating it chunk by chunk. So this will not allocate 64 MiB
+        // at once. This size should be more than enough for java threads.
+        // This buffer is being created for each process but Android has
+        // relatively less processes compared to desktop, so it's okay here.
+        mozilla::ProfileBufferChunkManagerWithLocalLimit chunkManager(
+            64 * 1024 * 1024, 1024 * 1024);
+        ProfileChunkedBuffer bufferManager(
+            ProfileChunkedBuffer::ThreadSafety::WithoutMutex, chunkManager);
+        ProfileBuffer javaBuffer(bufferManager);
+        CollectJavaThreadProfileData(threadId, javaBuffer);
+
+        // Thread id of java Main thread is 0, if we support profiling of other
+        // java thread, we have to get thread id and name via JNI.
+        RefPtr<ThreadInfo> threadInfo = new ThreadInfo(
+            "Java Main Thread", threadIndex, false, CorePS::ProcessStartTime());
+        ProfiledThreadData profiledThreadData(threadInfo, nullptr);
+        profiledThreadData.StreamJSON(
+            javaBuffer, nullptr, aWriter, CorePS::ProcessName(aLock),
+            CorePS::ETLDplus1(aLock), CorePS::ProcessStartTime(), aSinceTime,
+            ActivePS::FeatureJSTracer(aLock), nullptr);
+      }
     }
 #endif
 
+
     UniquePtr<char[]> baseProfileThreads =
         ActivePS::MoveBaseProfileThreads(aLock);
     if (baseProfileThreads) {
       aWriter.Splice(baseProfileThreads.get());
     }
   }
   aWriter.EndArray(); 

Comment 3

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

Attachment: Bug 1618560 - support samples from multiple JVM threads in profiler. r=canaltinova

Comment 4

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

Attachment: Bug 1618560 - support markers from multiple JVM threads in profiler. r=canaltinova

Here is a sample profile taken with the combined patches:
https://share.firefox.dev/3pEcSi0

I added a "sample marker" in the dispatchToThreads method called from the
Gecko thread to demonstrate markers taken off the main thread.

Depends on D140434

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/416c97246140
support samples from multiple JVM threads in profiler. r=canaltinova

Comment 6

[Cristian Tuns]

Backed out for causing xpcshell failures in test_feature_java.js

• Backout link
• Push with failures
• Failure Log
• Failure line: TEST-UNEXPECTED-FAIL | tools/profiler/tests/xpcshell/test_feature_java.js | xpcshell return code: 0
• Failure line: TEST-UNEXPECTED-FAIL | tools/profiler/tests/xpcshell/test_feature_java.js | - "undefined" != null

Comment 7

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

I can't reproduce locally on my P2 or Moto G5 – I suspect it's a race condition caused by the slower emulators. I added debugging logging to the GeckoJavaSampler and pushed to try to get more info: https://treeherder.mozilla.org/jobs?repo=try&revision=3e2b321261e5ab53cf3d66b559a8bb7f831afc96

Comment 8

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

I don't think my test ran: I'm assuming it got bucketed into a separate test group so I reran with both test groups enabled. https://treeherder.mozilla.org/jobs?repo=try&revision=fdcbd919e9f331eca0f2e62d29ffaedc75e3f5a8

Comment 9

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

Our getThreadsToProfile method finds 0 threads to profile, which is unexpected given the main thread is always added. Added more logging: https://treeherder.mozilla.org/jobs?repo=try&revision=777cd52c056504cbe29a6d9919d032234dfa093f

Comment 10

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

The activeThreads we find doesn't include the main thread – weird. One theory is that the tests are running in a headless mode but since the test doesn't pass in headless mode before my changes, that seems unlikely. More logging: https://treeherder.mozilla.org/jobs?repo=try&revision=d255bba7a59d78c2c0d7f00f9770e6d3a93b2da0

Comment 11

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

More logging: https://treeherder.mozilla.org/jobs?repo=try&revision=e5d15d1ccc0fbee692f6e379485ff939056e6a89 And some results:

03-21 20:43:26.490  4206  4223 D GeckoJavaSampler: main thread: Thread[main,5,main] isAlive? true
03-21 20:43:26.490  4206  4223 I System.out: java.lang.ThreadGroup[name=main,maxpri=10]
03-21 20:43:26.490  4206  4223 I System.out:     Thread[Gecko,5,main]

The main thread is alive but inexplicably does not appear in the main thread group, either through currentThread().getThreadGroup().enumerate or mainThread.getThreadGroup().list(), even though it's a member of the main thread group. Some theories:

• API 7.0, used for automation, behaves differently from other builds (8.1 is the lowest I've tested). Given the implementation of list(), it seems like this might be a bug
• we don't have permission to view all of the threads in this ThreadGroup. This possibility is suggested by the javadoc for list which says an exception is thrown if the current thread cannot access the info of this thread group. However, enumerate succeeds so this seems unlikely

Comment 12

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

I investigated some more things – e.g. the ThreadGroup.threads internal variable and getting threads from the main thread – but I'm not getting anyway. I think we're hitting diminishing returns in investigating this issue so I'm going to do the naive thing and add the main thread from the Looper.getMainLooper().getThread() reference rather than fetching it from the enumerate list. We could be hiding a bug where we don't see all of the threads but hopefully 1) someone will file a bug if they see that and 2) at the very least this implementation will work just as well as the current implementation so we're not losing anything. I filed bug 1760716 to investigate this issue in the future.

I suspect the root cause has to do with how the test harness is configured but I was not able to reproduce the issue on my own x86_64 emulator.

Comment 13

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

Attachment: Bug 1618560 - add debug logging to GeckoJavaSampler. r=canaltinova

This is helpful when looking at logs from fenix in automation to answer
questions like, did the profiler start? Did it finish or did it crash before
then? Did it record any samples?

We had to add this logging temporarily to debug a test failure and it seemed
non-intrusive enough that we could keep it around long term.

Depends on D140435

Comment 14

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

Here is a try push running the test that was failing with the new code: https://treeherder.mozilla.org/jobs?repo=try&revision=c3bad444b194788d2aab6250782e7c633969b566

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7ce872d5073b
support samples from multiple JVM threads in profiler. r=canaltinova
https://hg.mozilla.org/integration/autoland/rev/ec30deb36e18
support markers from multiple JVM threads in profiler. r=canaltinova,geckoview-reviewers,agi
https://hg.mozilla.org/integration/autoland/rev/c040cda0f789
add debug logging to GeckoJavaSampler. r=canaltinova,agi

Comment 16

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/7ce872d5073b
https://hg.mozilla.org/mozilla-central/rev/ec30deb36e18
https://hg.mozilla.org/mozilla-central/rev/c040cda0f789