fix(profiler): improve performance (#280)

* chore(profiler): add timings average in logs

* fix(perf): improve performance of profiler

* chore(profiler): set c++ standard

* perf(profiler): improve read file performance

* chore(profiler): set thread names

* refactor(profiler): extract function

* refactor(profiler): extract function

* chore: generate binaries

* prune: remove duplicated confusing interface

* refactor(profiler): add supportFPS

* refactor(profiler): move function

* refactor: simplify ensureCppProfilerIsInstalled

* refactor: rename function

* refactor: move function

* refactor: move function

* refactor: move function

* refactor: remove platformProfiler from android

* chore: add profiler to measure flashlight performance

Author: Almouro

packages/commands/test/src/__tests__/measurePerformance.test.ts

@@ -6,18 +6,21 @@ import { Logger, LogLevel } from "@perf-profiler/logger";
 
 const mockPerformancePolling = new PerformancePollingMock();
 
-jest.mock("@perf-profiler/profiler", () => ({
-  ...jest.requireActual("@perf-profiler/profiler"),
-  profiler: {
-    ...jest.requireActual("@perf-profiler/profiler").profiler,
-    installProfilerOnDevice: jest.fn(),
-    getPidId: jest.fn(() => 123),
-    pollPerformanceMeasures: jest.fn((pid, { onMeasure, onStartMeasuring }) => {
-      mockPerformancePolling.setCallback(onMeasure);
-      onStartMeasuring();
-    }),
-  },
-}));
+jest.mock("@perf-profiler/profiler", () => {
+  const mockedProfiler = jest.requireActual("@perf-profiler/profiler").profiler;
+
+  mockedProfiler.installProfilerOnDevice = jest.fn();
+  mockedProfiler.getPidId = jest.fn(() => 123);
+  mockedProfiler.pollPerformanceMeasures = jest.fn((pid, { onMeasure, onStartMeasuring }) => {
+    mockPerformancePolling.setCallback(onMeasure);
+    onStartMeasuring();
+  });
+
+  return {
+    ...jest.requireActual("@perf-profiler/profiler"),
+    profiler: mockedProfiler,
+  };
+});
 
 Logger.setLogLevel(LogLevel.SILENT);
 

packages/platforms/android/cpp-profiler/CMakeLists.txt

@@ -1,3 +1,5 @@
 cmake_minimum_required(VERSION 3.16.0)
 project(android-cmake-flashlight)
 add_executable(BAMPerfProfiler src/main.cpp src/atrace.cpp src/utils.cpp)
+
+set(CMAKE_CXX_STANDARD 21)

packages/platforms/android/cpp-profiler/bin/BAMPerfProfiler-arm64-v8a

@@ -26,7 +26,7 @@ void printATraceLines()
   std::lock_guard<std::mutex> guard(aTraceLinesMutex);
   for (auto itr = aTraceLines.begin(), end_itr = aTraceLines.end(); itr != end_itr; ++itr)
   {
-    std::cout << *itr << std::endl;
+    std::cout << *itr << "\n";
   }
   aTraceLines.clear();
 }

packages/platforms/android/cpp-profiler/bin/BAMPerfProfiler-armeabi-v7a

@@ -3,36 +3,16 @@
 #include <iostream>
 #include <filesystem>
 #include "atrace.h"
-#include <fstream>
 #include <thread>
 #include <unistd.h>
 #include "utils.h"
 
 using std::cerr;
 using std::cout;
-using std::endl;
 using std::string;
 
 namespace fs = std::filesystem;
 
-void readFile(string filePath)
-{
-    std::ifstream file(filePath);
-    if (file.is_open())
-    {
-        string line;
-        while (std::getline(file, line))
-        {
-            log(line.c_str());
-        }
-        file.close();
-    }
-    else
-    {
-        cerr << "CPP_ERROR_CANNOT_OPEN_FILE " + filePath << endl;
-    }
-}
-
 class PidClosedError : public std::runtime_error
 {
 public:
@@ -68,6 +48,9 @@ void printMemoryStats(std::vector<string> pids)
     }
 }
 
+long long totalDurationSum = 0;
+long long measureCount = 0;
+
 long long printPerformanceMeasure(std::vector<string> pids)
 {
     auto start = std::chrono::system_clock::now();
@@ -97,13 +80,23 @@ long long printPerformanceMeasure(std::vector<string> pids)
     auto atraceDuration = std::chrono::duration_cast<std::chrono::milliseconds>(atraceEnd - memoryEnd);
     auto totalDuration = std::chrono::duration_cast<std::chrono::milliseconds>(end - start);
 
+    long long totalDurationMs = totalDuration.count();
+
     cout << "TOTAL EXEC TIME: " << totalDuration.count() << "|";
     cout << "CPU TIME: " << cpuDuration.count() << "|";
     cout << "MEMORY TIME: " << memoryDuration.count() << "|";
-    cout << "ATRACE TIME: " << atraceDuration.count() << endl;
+    cout << "ATRACE TIME: " << atraceDuration.count() << "\n";
+
+    measureCount++;
+    totalDurationSum += totalDurationMs;
+
+    log(separator);
+    cout << "AVERAGE TOTAL EXEC TIME: " << totalDurationSum / measureCount << "\n";
 
     log("=STOP MEASURE=");
 
+    cout << std::flush;
+
     return totalDuration.count();
 }
 
@@ -115,15 +108,19 @@ std::vector<string> pidOf(string bundleId)
 
 void pollPerformanceMeasures(std::string bundleId, int interval)
 {
+    pthread_setname_np(pthread_self(), "FL-Main");
+
     std::vector<string> pids;
 
     // We read atrace lines before the app is started
     // since it can take a bit of time to start and clear the traceOutputPath
     // but we'll clear them out periodically while the app isn't started
     // TODO handle ATrace not available on OS
     std::thread aTraceReadThread(readATraceThread);
+    pthread_setname_np(aTraceReadThread.native_handle(), "FL-Atrace");
 
-    cout << "Waiting for process to start..." << endl;
+    cout << "Waiting for process to start..."
+         << "\n";
 
     while (pids.empty())
     {
@@ -142,7 +139,7 @@ void pollPerformanceMeasures(std::string bundleId, int interval)
     }
     catch (const PidClosedError &e)
     {
-        cerr << "CPP_ERROR_MAIN_PID_CLOSED " << e.what() << endl;
+        cerr << "CPP_ERROR_MAIN_PID_CLOSED " << e.what() << "\n";
         pollPerformanceMeasures(bundleId, interval);
         return;
     }
@@ -152,12 +149,12 @@ void pollPerformanceMeasures(std::string bundleId, int interval)
 
 void printCpuClockTick()
 {
-    cout << sysconf(_SC_CLK_TCK) << endl;
+    cout << sysconf(_SC_CLK_TCK) << "\n";
 }
 
 void printRAMPageSize()
 {
-    cout << sysconf(_SC_PAGESIZE) << endl;
+    cout << sysconf(_SC_PAGESIZE) << "\n";
 }
 
 int main(int argc, char **argv)
@@ -187,7 +184,7 @@ int main(int argc, char **argv)
     }
     else
     {
-        cout << "Unknown method name: " << methodName << endl;
+        cout << "Unknown method name: " << methodName << "\n";
         return 1;
     }
 

packages/platforms/android/cpp-profiler/bin/BAMPerfProfiler-x86

@@ -3,13 +3,13 @@
 #include <array>
 #include <memory>
 #include <chrono>
+#include <fstream>
 
 using std::cout;
-using std::endl;
 
 void log(const std::string &msg)
 {
-  cout << msg << endl;
+  cout << msg << "\n";
 }
 
 void logTimestamp()
@@ -19,7 +19,7 @@ void logTimestamp()
                              now.time_since_epoch())
                              .count();
 
-  cout << "Timestamp: " << timestamp << endl;
+  cout << "Timestamp: " << timestamp << "\n";
 }
 
 std::string executeCommand(std::string command)
@@ -57,3 +57,28 @@ std::vector<std::string> split(const std::string &str, char delimiter)
 
   return result;
 }
+
+#define BUFFER_SIZE 2048
+
+void readFile(std::string_view path)
+{
+  constexpr auto read_size = std::size_t(BUFFER_SIZE);
+  auto stream = std::ifstream(path.data());
+  stream.exceptions(std::ios_base::badbit);
+
+  if (not stream)
+  {
+    std::cerr << "CPP_ERROR_CANNOT_OPEN_FILE " << path << "\n";
+    return;
+  }
+
+  auto out = std::string();
+  auto buf = std::string(read_size, '\0');
+  while (stream.read(&buf[0], read_size))
+  {
+    out.append(buf, 0, stream.gcount());
+  }
+  out.append(buf, 0, stream.gcount());
+
+  log(out);
+}

packages/platforms/android/cpp-profiler/bin/BAMPerfProfiler-x86_64

@@ -7,5 +7,6 @@ void log(const std::string &msg);
 void logTimestamp();
 std::string executeCommand(std::string command);
 std::vector<std::string> split(const std::string &str, char delimiter);
+void readFile(std::string_view path);
 
 #endif /* UTILS_H */

packages/platforms/android/cpp-profiler/src/atrace.cpp

@@ -2,21 +2,18 @@
 
 import { Logger } from "@perf-profiler/logger";
 import { Measure } from "@perf-profiler/types";
-import {
-  getCpuClockTick,
-  getRAMPageSize,
-  ensureCppProfilerIsInstalled,
-} from "./commands/cppProfiler";
 import { program } from "commander";
 import { detectCurrentAppBundleId } from "./commands/detectCurrentAppBundleId";
 import { getPidId } from "./commands/getPidId";
 import { getAbi } from "./commands/getAbi";
-import { pollPerformanceMeasures } from "./commands/pollPerformanceMeasures";
+import { AndroidProfiler } from "./commands/platforms/AndroidProfiler";
+
+const profiler = new AndroidProfiler();
 
 const debugCppConfig = () => {
-  ensureCppProfilerIsInstalled();
-  Logger.success(`CPU Clock tick: ${getCpuClockTick()}`);
-  Logger.success(`RAM Page size: ${getRAMPageSize()}`);
+  profiler.installProfilerOnDevice();
+  Logger.success(`CPU Clock tick: ${profiler.getCpuClockTick()}`);
+  Logger.success(`RAM Page size: ${profiler.getRAMPageSize()}`);
 };
 
 program.command("debugCppConfig").description("Debug CPP Config").action(debugCppConfig);
@@ -65,7 +62,7 @@ program
   .action((options) => {
     const bundleId = options.bundleId || detectCurrentAppBundleId().bundleId;
 
-    pollPerformanceMeasures(bundleId, {
+    profiler.pollPerformanceMeasures(bundleId, {
       onMeasure: (measure: Measure) => {
         const headers: string[] = [];
         const values: (number | undefined)[] = [];

packages/platforms/android/cpp-profiler/src/main.cpp

@@ -1,31 +1,6 @@
 import { Logger } from "@perf-profiler/logger";
-import { canIgnoreAwsTerminationError, executeLongRunningProcess } from "./shell";
-import { POLLING_INTERVAL } from "@perf-profiler/types";
-import { profiler } from "./platforms/platformProfiler";
 
-/**
- * Main setup function for the cpp profiler
- *
- * It will:
- * - install the C++ profiler for the correct architecture on the device
- * - Starts the atrace process (the c++ profiler will then starts another thread to read from it)
- * - Populate needed values like CPU clock tick and RAM page size
- *
- * This needs to be done before measures and can take a few seconds
- */
-export const ensureCppProfilerIsInstalled = () => {
-  profiler.ensureCppProfilerIsInstalled();
-};
-
-export const getCpuClockTick = () => {
-  return profiler.getCpuClockTick();
-};
-
-export const getRAMPageSize = () => {
-  return profiler.getRAMPageSize();
-};
-
-type CppPerformanceMeasure = {
+export type CppPerformanceMeasure = {
   pid: string;
   cpu: string;
   ram: string;
@@ -52,43 +27,3 @@ export const parseCppMeasure = (measure: string): CppPerformanceMeasure => {
 
   return { pid, cpu, ram, atrace, timestamp };
 };
-
-export const pollPerformanceMeasures = (
-  pid: string,
-  onData: (measure: CppPerformanceMeasure) => void,
-  onPidChanged?: (pid: string) => void
-) => {
-  ensureCppProfilerIsInstalled();
-
-  const DELIMITER = "=STOP MEASURE=";
-
-  const process = executeLongRunningProcess(
-    profiler.getDeviceCommand(
-      `${profiler.getDeviceProfilerPath()} pollPerformanceMeasures ${pid} ${POLLING_INTERVAL}`
-    ),
-    DELIMITER,
-    (data: string) => {
-      onData(parseCppMeasure(data));
-    }
-  );
-
-  process.stderr?.on("data", (data) => {
-    const log = data.toString();
-
-    // Ignore errors, it might be that the thread is dead and we can't read stats anymore
-    if (log.includes("CPP_ERROR_CANNOT_OPEN_FILE")) {
-      Logger.debug(log);
-    } else if (log.includes("CPP_ERROR_MAIN_PID_CLOSED")) {
-      onPidChanged?.(pid);
-    } else {
-      if (!canIgnoreAwsTerminationError(log)) Logger.error(log);
-    }
-  });
-
-  return {
-    stop: () => {
-      process.kill("SIGINT");
-      profiler.stop();
-    },
-  };
-};

packages/platforms/android/cpp-profiler/src/utils.cpp

@@ -1,19 +1,20 @@
 import { mapValues } from "lodash";
 import { CpuMeasure as Measure } from "@perf-profiler/types";
-import { getCpuClockTick } from "../cppProfiler";
 import { ProcessStat } from "./getCpuStatsByProcess";
 
 export class CpuMeasureAggregator {
   private previousTotalCpuTimePerProcessId: { [processId: string]: number } = {};
 
+  constructor(private cpuClockTick: number) {}
+
   private groupCpuUsage(
     stats: ProcessStat[],
     groupByIteratee: (stat: ProcessStat) => string,
     timeInterval: number
   ): {
     [by: string]: number;
   } {
-    const TICKS_FOR_TIME_INTERVAL = (getCpuClockTick() * timeInterval) / 1000;
+    const TICKS_FOR_TIME_INTERVAL = (this.cpuClockTick * timeInterval) / 1000;
 
     const toPercentage = (value: number) => Math.min((value * 100) / TICKS_FOR_TIME_INTERVAL, 100);