Closed Bug 1618560 Opened 3 years ago Closed 6 months ago

Add support for profiling multiple java threads

Categories

(Core :: Gecko Profiler, enhancement, P2)

enhancement

Tracking

()

RESOLVED FIXED
100 Branch
Tracking Status
firefox100 --- fixed

People

(Reporter: canova, Assigned: mcomella)

References

(Blocks 3 open bugs)

Details

Attachments

(3 files)

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.

Priority: -- → P2

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.

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(); 
Assignee: nobody → michael.l.comella
See Also: → 1756251

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

Pushed by mcomella@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/416c97246140
support samples from multiple JVM threads in profiler. r=canaltinova

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
Flags: needinfo?(michael.l.comella)

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

Flags: needinfo?(michael.l.comella)

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

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

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

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:

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.

Blocks: 1760716

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

Pushed by mcomella@mozilla.com:
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
Status: NEW → RESOLVED
Closed: 6 months ago
Resolution: --- → FIXED
Target Milestone: --- → 100 Branch
You need to log in before you can comment on or make changes to this bug.