feat(benchpress): report gc and render time spent in script (#50771)

pkozlowski-opensource · atscott · commit 2da3551a703e · 2023-10-05T10:52:26.000-07:00
GC and render events can happen _while_ running scripts as well as outside of the script blocks. The new metric entries capture both the gc and render time happening in the scrip blocks. PR Close #50771
diff --git a/packages/benchpress/src/metric/perflog_metric.ts b/packages/benchpress/src/metric/perflog_metric.ts
@@ -72,13 +72,15 @@ export class PerflogMetric extends Metric {
   override describe(): {[key: string]: string} {
     const res: {[key: string]: any} = {
       'scriptTime': 'script execution time in ms, including gc and render',
-      'pureScriptTime': 'script execution time in ms, without gc nor render'
+      'pureScriptTime': 'script execution time in ms, without gc nor render',
     };
     if (this._perfLogFeatures.render) {
       res['renderTime'] = 'render time in ms';
+      res['renderTimeInScript'] = 'render time in ms while executing script (usually means reflow)';
     }
     if (this._perfLogFeatures.gc) {
       res['gcTime'] = 'gc time in ms';
+      res['gcTimeInScript'] = 'gc time in ms while executing scripts';
       res['gcAmount'] = 'gc amount in kbytes';
       res['majorGcTime'] = 'time of major gcs in ms';
       if (this._forceGc) {
@@ -380,7 +382,11 @@ export class PerflogMetric extends Metric {
     if (frameTimes.length > 0) {
       this._addFrameMetrics(result, frameTimes);
     }
+
+    result['renderTimeInScript'] = renderTimeInScript;
+    result['gcTimeInScript'] = gcTimeInScript;
     result['pureScriptTime'] = result['scriptTime'] - gcTimeInScript - renderTimeInScript;
+
     return result;
   }
 
diff --git a/packages/benchpress/test/metric/perflog_metric_spec.ts b/packages/benchpress/test/metric/perflog_metric_spec.ts
@@ -80,18 +80,19 @@ describe('perflog metric', () => {
 
     expect(
         sortedKeys(createMetric([[]], new PerfLogFeatures({render: true, gc: false})).describe()))
-        .toEqual(['pureScriptTime', 'renderTime', 'scriptTime']);
+        .toEqual(['pureScriptTime', 'renderTime', 'renderTimeInScript', 'scriptTime']);
 
     expect(sortedKeys(createMetric([[]], null!).describe())).toEqual([
-      'gcAmount', 'gcTime', 'majorGcTime', 'pureScriptTime', 'renderTime', 'scriptTime'
+      'gcAmount', 'gcTime', 'gcTimeInScript', 'majorGcTime', 'pureScriptTime', 'renderTime',
+      'renderTimeInScript', 'scriptTime'
     ]);
 
     expect(sortedKeys(createMetric([[]], new PerfLogFeatures({render: true, gc: true}), {
                         forceGc: true
                       }).describe()))
         .toEqual([
-          'forcedGcAmount', 'forcedGcTime', 'gcAmount', 'gcTime', 'majorGcTime', 'pureScriptTime',
-          'renderTime', 'scriptTime'
+          'forcedGcAmount', 'forcedGcTime', 'gcAmount', 'gcTime', 'gcTimeInScript', 'majorGcTime',
+          'pureScriptTime', 'renderTime', 'renderTimeInScript', 'scriptTime'
         ]);
 
 
@@ -528,6 +529,21 @@ describe('perflog metric', () => {
       });
     });
 
+    it('should support renderTimeInScript metric', done => {
+      aggregate([
+        eventFactory.start('script', 0),
+        eventFactory.start('render', 1),
+        eventFactory.end('render', 3),
+        eventFactory.end('script', 5),
+      ]).then((data) => {
+        expect(data['renderTimeInScript']).toBe(2);
+        expect(data['renderTime']).toBe(2);
+        expect(data['pureScriptTime']).toBe(3);
+        expect(data['scriptTime']).toBe(5);
+        done();
+      });
+    });
+
     it('should support gcTime/gcAmount metric', done => {
       aggregate([
         eventFactory.start('gc', 0, {'usedHeapSize': 2500}),
@@ -551,6 +567,22 @@ describe('perflog metric', () => {
       });
     });
 
+    it('should support gcTimeInScript metric', done => {
+      aggregate([
+        eventFactory.start('script', 0),
+        eventFactory.start('gc', 1, {'usedHeapSize': 2500}),
+        eventFactory.end('gc', 3, {'usedHeapSize': 1000, 'majorGc': false}),
+        eventFactory.end('script', 5),
+
+      ]).then((data) => {
+        expect(data['gcTimeInScript']).toBe(2);
+        expect(data['gcTime']).toBe(2);
+        expect(data['pureScriptTime']).toBe(3);
+        expect(data['scriptTime']).toBe(5);
+        done();
+      });
+    });
+
     it('should support pureScriptTime = scriptTime-gcTime-renderTime', done => {
       aggregate([
         eventFactory.start('script', 0), eventFactory.start('gc', 1, {'usedHeapSize': 1000}),
