fix(profiler): improve accuracy of CPU measures (#140)

* fix(profiler): ensure process names with space get taken into account The regex also gets rid of the parenthesis automatically * refactor: use thread names constant * fix(profiler): handle multiple processes with same name This is similar to what Android Studio displays Say you have an app loading several images, chances are the app will create a different process to load each images but with the same name For instance, let's say this launches 5 different processes each accounting for 20% CPU usage in the same 500ms window Before this fix, the stats would be additionned, meaning we would see one single thread with that name with 100% CPU usage. It would thus hit the high CPU usage threshold, even though, nothing is actually saturating After this fix you would see process 20% process (2) 20% ... process (5) 20% Worth noting that a more ideal fix would have been to store processes by ids, but that actually makes the list of processes less readable and more difficult to compare Say every 500ms you load 5 requests, your 5 request processes would get recreated with same name but different ids, so every 500ms, 5 new processes would get added to the list. By still grouping by name, but allowing for multiple occurrences in a 500ms window, we keep only a smaller amount of processes, like Android Studio does for instance. It's also easier to compare and track with multiple iterations Side note: I kept the sanitizeName function just for previous reports which included parenthesis, just made sure it didn't remove the parenthesis that we added
bamlab · Jul 28, 2023 · 5038cb7 · 5038cb7
1 parent ccb4c92
commit 5038cb7
Show file tree

Hide file tree

Showing 16 changed files with 1,178 additions and 197 deletions.
diff --git a/examples/cli/index.ts b/examples/cli/index.ts
@@ -5,6 +5,7 @@ import {
   pollPerformanceMeasures,
 } from "@perf-profiler/profiler";
 import { getAverageCpuUsage } from "@perf-profiler/reporter";
+import { ThreadNames } from "@perf-profiler/types";
 
 const bundleId = detectCurrentAppBundleId().bundleId || "";
 const pid = getPidId(bundleId) || "";
@@ -14,7 +15,7 @@ const measures: Measure[] = [];
 const polling = pollPerformanceMeasures(pid, {
   onMeasure: (measure: Measure) => {
     measures.push(measure);
-    console.log(`JS Thread CPU Usage: ${measure.cpu.perName["(mqt_js)"]}%`);
+    console.log(`JS Thread CPU Usage: ${measure.cpu.perName[ThreadNames.JS_THREAD]}%`);
     console.log(`RAM Usage: ${measure.ram}MB`);
   },
 });

diff --git a/examples/cli/package.json b/examples/cli/package.json
@@ -5,6 +5,7 @@
   "main": "dist/index.js",
   "dependencies": {
     "@perf-profiler/reporter": "*",
-    "@perf-profiler/profiler": "*"
+    "@perf-profiler/profiler": "*",
+    "@perf-profiler/types": "*"
   }
 }
diff --git a/packages/android-performance-profiler/src/commands/cpu/CpuMeasureAggregator.ts b/packages/android-performance-profiler/src/commands/cpu/CpuMeasureAggregator.ts
@@ -51,8 +51,6 @@ export class CpuMeasureAggregator {
       (stat: ProcessStat) => stat.cpuNumber,
       interval
     );
-    // Not exactly sure what cpu number-1 is, deleting for now
-    delete cpuUsagePerCore["-1"];
 
     const cpuUsagePerProcessName = this.groupCpuUsage(
       stats,

diff --git a/...ages/android-performance-profiler/src/commands/cpu/__tests__/getCpuStatsByProcess.test.ts b/...ages/android-performance-profiler/src/commands/cpu/__tests__/getCpuStatsByProcess.test.ts
@@ -0,0 +1,39 @@
+import { processOutput } from "../getCpuStatsByProcess";
+
+const SAMPLE_STATS = `27986 (OkHttp TaskRunn) S 480 480 0 0 -1 1077952576 6 0 0 0 50 20 40 0 20 0 53 0 233304293 1726836736 45377 18446744073709551615 1 1 0 0 0 0 4612 1 1073775864 0 0 0 -1 5 0 0 0 0 0 0 0 0 0 0 0 0 0
+27987 (FrescoDecodeExe) S 480 480 0 0 -1 1077952576 3966 0 0 0 23 3 7 0 30 10 53 0 233304298 1726836736 45377 18446744073709551615 1 1 0 0 0 0 4612 1 1073775864 0 0 0 -1 2 0 0 0 0 0 0 0 0 0 0 0 0 0
+27988 (content.com/...) S 480 480 0 0 -1 1077952576 396 0 0 0 28 5 5 0 20 0 53 0 233304298 1726836736 45377 18446744073709551615 1 1 0 0 0 0 4612 1 1073775864 0 0 0 -1 5 0 0 0 0 0 0 0 0 0 0 0 0 0
+1234 (com.example) S 480 480 0 0 -1 1077952576 396 0 0 0 28 5 5 0 20 0 53 0 233304298 1726836736 45377 18446744073709551615 1 1 0 0 0 0 4612 1 1073775864 0 0 0 -1 5 0 0 0 0 0 0 0 0 0 0 0 0 0`;
+
+describe("getCpuStatsByProcess", () => {
+  it("extract CPU thread stats from profiler output", () => {
+    expect(processOutput(SAMPLE_STATS, "1234")).toMatchInlineSnapshot(`
+      [
+        {
+          "cpuNumber": "5",
+          "processId": "27986",
+          "processName": "OkHttp TaskRunn",
+          "totalCpuTime": 70,
+        },
+        {
+          "cpuNumber": "2",
+          "processId": "27987",
+          "processName": "FrescoDecodeExe",
+          "totalCpuTime": 26,
+        },
+        {
+          "cpuNumber": "5",
+          "processId": "27988",
+          "processName": "content.com/...",
+          "totalCpuTime": 33,
+        },
+        {
+          "cpuNumber": "5",
+          "processId": "1234",
+          "processName": "UI Thread",
+          "totalCpuTime": 33,
+        },
+      ]
+    `);
+  });
+});
diff --git a/packages/android-performance-profiler/src/commands/cpu/getCpuStatsByProcess.ts b/packages/android-performance-profiler/src/commands/cpu/getCpuStatsByProcess.ts
@@ -1,24 +1,55 @@
+import { ThreadNames } from "@perf-profiler/types";
+
 export interface ProcessStat {
   processId: string;
   processName: string;
   totalCpuTime: number;
   cpuNumber: string;
 }
 
-export const processOutput = (output: string, pid: string): ProcessStat[] =>
-  output
+export const processOutput = (output: string, pid: string): ProcessStat[] => {
+  /**
+   * We can have multiple processes with the same name but a different pid
+   *
+   * Say your app dispatches multiple "OkHttp Dispatch" processes to make several requests at the same time
+   *
+   * We'll display:
+   *  - OkHttp Dispatch: xx%
+   *  - OkHttp Dispatch (2): xx%
+   *  - OkHttp Dispatch (3): xx%
+   *  ...
+   */
+  const processNameCount: { [name: string]: number } = {};
+
+  return output
     .split(/\r\n|\n|\r/)
     .filter(Boolean)
-    .map((stats) => stats.split(" "))
+    .map((stats) => {
+      const match = stats.match(/^(\d+) \(([^)]+)\) (.*)/);
+      if (!match) {
+        throw new Error(`Invalid line: ${stats}`);
+      }
+
+      const [, processId, processName, remaining] = match;
+      const parts = remaining.split(" ");
+
+      return [processId, processName, ...parts];
+    })
     .filter(Boolean)
     .map((subProcessStats) => {
       const processId = subProcessStats[0];
-      let processName = processId === pid ? "UI Thread" : subProcessStats[1];
+      let processName = processId === pid ? ThreadNames.UI_THREAD : subProcessStats[1];
 
       if (processName.includes(`Binder:${pid}_`)) {
         processName = processName.replace(`Binder:${pid}_`, "Binder #");
       }
 
+      processNameCount[processName] = (processNameCount[processName] || 0) + 1;
+
+      if (processNameCount[processName] > 1) {
+        processName = `${processName} (${processNameCount[processName]})`;
+      }
+
       const utime = parseInt(subProcessStats[13], 10);
       const stime = parseInt(subProcessStats[14], 10);
 
@@ -28,3 +59,4 @@ export const processOutput = (output: string, pid: string): ProcessStat[] =>
 
       return { processId, processName, totalCpuTime, cpuNumber };
     });
+};
diff --git a/packages/android-performance-profiler/src/commands/pollPerformanceMeasures.ts b/packages/android-performance-profiler/src/commands/pollPerformanceMeasures.ts
@@ -1,4 +1,4 @@
-import { Measure } from "@perf-profiler/types";
+import { Measure, ThreadNames } from "@perf-profiler/types";
 import { CpuMeasureAggregator } from "./cpu/CpuMeasureAggregator";
 import { processOutput } from "./cpu/getCpuStatsByProcess";
 import { processOutput as processRamOutput } from "./ram/pollRamUsage";
@@ -55,7 +55,7 @@ export const pollPerformanceMeasures = (
           frameTimes,
           atraceInterval,
           Math.max(
-            cpuMeasures.perName["UI Thread"] || 0,
+            cpuMeasures.perName[ThreadNames.UI_THREAD] || 0,
             // Hack for Flutter apps - if this thread is heavy app will be laggy
             cpuMeasures.perName["(1.ui)"] || 0
           )

diff --git a/packages/e2e-performance/src/__tests__/__snapshots__/PerformanceMeasurer.test.ts.snap b/packages/e2e-performance/src/__tests__/__snapshots__/PerformanceMeasurer.test.ts.snap
@@ -5,50 +5,58 @@ exports[`PerformanceMeasurer handles c++ errors correctly 1`] = `
   {
     "cpu": {
       "perCore": {
-        "0": 8,
-        "1": 0,
+        "0": 12,
+        "1": 2,
         "2": 0,
-        "3": 48,
+        "3": 50,
         "4": 0,
         "6": 100,
         "7": 2,
       },
       "perName": {
-        "(ADB-JDWP": 0,
-        "(AsyncTask": 0,
-        "(BMScavenger)": 0,
-        "(Binder #1)": 0,
-        "(Binder #2)": 0,
-        "(Binder #3)": 0,
-        "(Binder #4)": 0,
-        "(Binder #5)": 0,
-        "(CookieMonsterBa)": 0,
-        "(CookieMonsterCl)": 0,
-        "(FinalizerDaemon)": 0,
-        "(FinalizerWatchd)": 0,
-        "(FlipperConnecti)": 0,
-        "(FlipperEventBas)": 0,
-        "(FutureTimekeepr)": 0,
-        "(HeapTaskDaemon)": 0,
-        "(HybridData": 0,
-        "(JITWorker)": 0,
-        "(Jit": 0,
-        "(OkHttp": 2,
-        "(Profile": 0,
-        "(ReferenceQueueD)": 0,
-        "(RenderThread)": 6,
-        "(Signal": 0,
-        "(alhost:8097/...)": 0,
-        "(com.example)": 48,
-        "(hwuiTask0)": 0,
-        "(hwuiTask1)": 0,
-        "(mali-cmar-backe)": 2,
-        "(mali-mem-purge)": 0,
-        "(mali-utility-wo)": 0,
-        "(mqt_js)": 100,
-        "(mqt_native_modu)": 2,
-        "(perfetto_hprof_)": 0,
-        "(queued-work-loo)": 0,
+        "ADB-JDWP Connec": 0,
+        "AsyncTask #1": 0,
+        "BMScavenger": 0,
+        "Binder #1": 0,
+        "Binder #2": 0,
+        "Binder #2 (2)": 0,
+        "Binder #3": 0,
+        "Binder #4": 0,
+        "Binder #5": 0,
+        "CookieMonsterBa": 0,
+        "CookieMonsterCl": 0,
+        "FinalizerDaemon": 0,
+        "FinalizerWatchd": 0,
+        "FlipperConnecti": 0,
+        "FlipperEventBas": 0,
+        "FutureTimekeepr": 0,
+        "HeapTaskDaemon": 0,
+        "HybridData Dest": 0,
+        "JITWorker": 0,
+        "Jit thread pool": 2,
+        "OkHttp Dispatch": 2,
+        "OkHttp Dispatch (2)": 4,
+        "OkHttp TaskRunn": 0,
+        "Profile Saver": 0,
+        "ReferenceQueueD": 0,
+        "RenderThread": 6,
+        "Signal Catcher": 0,
+        "alhost:8097/...": 0,
+        "com.example": 48,
+        "hwuiTask0": 0,
+        "hwuiTask1": 0,
+        "mali-cmar-backe": 2,
+        "mali-mem-purge": 0,
+        "mali-utility-wo": 0,
+        "mali-utility-wo (2)": 0,
+        "mali-utility-wo (3)": 0,
+        "mali-utility-wo (4)": 0,
+        "mqt_js": 100,
+        "mqt_native_modu": 2,
+        "perfetto_hprof_": 0,
+        "queued-work-loo": 0,
+        "queued-work-loo (2)": 0,
+        "queued-work-loo (3)": 0,
       },
     },
     "fps": 60,
@@ -67,41 +75,49 @@ exports[`PerformanceMeasurer handles c++ errors correctly 1`] = `
         "7": 0,
       },
       "perName": {
-        "(ADB-JDWP": 0,
-        "(AsyncTask": 0,
-        "(BMScavenger)": 0,
-        "(Binder #1)": 0,
-        "(Binder #2)": 0,
-        "(Binder #3)": 0,
-        "(Binder #4)": 0,
-        "(Binder #5)": 0,
-        "(CookieMonsterBa)": 0,
-        "(CookieMonsterCl)": 0,
-        "(FinalizerDaemon)": 0,
-        "(FinalizerWatchd)": 0,
-        "(FlipperConnecti)": 0,
-        "(FlipperEventBas)": 0,
-        "(FutureTimekeepr)": 0,
-        "(HeapTaskDaemon)": 0,
-        "(HybridData": 0,
-        "(JITWorker)": 0,
-        "(Jit": 0,
-        "(OkHttp": 0,
-        "(Profile": 0,
-        "(ReferenceQueueD)": 0,
-        "(RenderThread)": 0,
-        "(Signal": 0,
-        "(alhost:8097/...)": 0,
-        "(com.example)": 0,
-        "(hwuiTask0)": 0,
-        "(hwuiTask1)": 0,
-        "(mali-cmar-backe)": 0,
-        "(mali-mem-purge)": 0,
-        "(mali-utility-wo)": 0,
-        "(mqt_js)": 0,
-        "(mqt_native_modu)": 0,
-        "(perfetto_hprof_)": 0,
-        "(queued-work-loo)": 0,
+        "ADB-JDWP Connec": 0,
+        "AsyncTask #1": 0,
+        "BMScavenger": 0,
+        "Binder #1": 0,
+        "Binder #2": 0,
+        "Binder #2 (2)": 0,
+        "Binder #3": 0,
+        "Binder #4": 0,
+        "Binder #5": 0,
+        "CookieMonsterBa": 0,
+        "CookieMonsterCl": 0,
+        "FinalizerDaemon": 0,
+        "FinalizerWatchd": 0,
+        "FlipperConnecti": 0,
+        "FlipperEventBas": 0,
+        "FutureTimekeepr": 0,
+        "HeapTaskDaemon": 0,
+        "HybridData Dest": 0,
+        "JITWorker": 0,
+        "Jit thread pool": 0,
+        "OkHttp Dispatch": 0,
+        "OkHttp Dispatch (2)": 0,
+        "OkHttp TaskRunn": 0,
+        "Profile Saver": 0,
+        "ReferenceQueueD": 0,
+        "RenderThread": 0,
+        "Signal Catcher": 0,
+        "alhost:8097/...": 0,
+        "com.example": 0,
+        "hwuiTask0": 0,
+        "hwuiTask1": 0,
+        "mali-cmar-backe": 0,
+        "mali-mem-purge": 0,
+        "mali-utility-wo": 0,
+        "mali-utility-wo (2)": 0,
+        "mali-utility-wo (3)": 0,
+        "mali-utility-wo (4)": 0,
+        "mqt_js": 0,
+        "mqt_native_modu": 0,
+        "perfetto_hprof_": 0,
+        "queued-work-loo": 0,
+        "queued-work-loo (2)": 0,
+        "queued-work-loo (3)": 0,
       },
     },
     "fps": 60,