feat: Add "long tasks" internal message (#1506)

metal-messiah · web-flow · commit c1d0a564e645 · 2025-07-01T09:40:51.000-06:00
diff --git a/src/common/wrap/wrap-function.js b/src/common/wrap/wrap-function.js
@@ -76,6 +76,7 @@ export function createWrapperWithEmitter (emitter, always) {
       var originalThis
       var ctx
       var result
+      let thrownError
 
       try {
         originalThis = this
@@ -93,17 +94,31 @@ export function createWrapperWithEmitter (emitter, always) {
       // Warning: start events may mutate args!
       safeEmit(prefix + 'start', [args, originalThis, methodName], ctx, bubble)
 
+      const fnStartTime = performance.now()
+      let fnEndTime = fnStartTime
       try {
         result = fn.apply(originalThis, args)
+        fnEndTime = performance.now()
         return result
       } catch (err) {
+        fnEndTime = performance.now()
         safeEmit(prefix + 'err', [args, originalThis, err], ctx, bubble)
-
         // rethrow error so we don't effect execution by observing.
-        throw err
+        thrownError = err
+        throw thrownError
       } finally {
-        // happens no matter what.
-        safeEmit(prefix + 'end', [args, originalThis, result], ctx, bubble)
+        const duration = fnEndTime - fnStartTime
+        const task = {
+          duration,
+          isLongTask: duration >= 50,
+          methodName,
+          thrownError
+          // could add more properties here later if needed by downstream features
+        }
+        // standalone long task message
+        if (task.isLongTask) safeEmit('long-task', [task], ctx, bubble)
+        // -end message also includes the task execution info
+        safeEmit(prefix + 'end', [args, originalThis, result, task], ctx, bubble)
       }
     }
   }
diff --git a/tests/assets/long-tasks.html b/tests/assets/long-tasks.html
@@ -0,0 +1,137 @@
+<!DOCTYPE html>
+<!--
+  Copyright 2020 New Relic Corporation.
+  PDX-License-Identifier: Apache-2.0
+-->
+<html>
+  <head>
+    <title>RUM Unit Test</title>
+    {init}{config}
+    <script>
+      NREUM.init.harvest.interval = 30;
+      NREUM.init.logging.enabled = false;
+    </script>
+    {loader}
+  </head>
+  <body>
+    <div>This page executes lots of different FNs that take a short or long amount of syncronous time to execute</div>
+    <pre>
+  The operations behave like this:
+
+    click (anywhere)!
+
+    document.addEventListener (click)
+    ---- SHORT TASK
+    ---- LONG TASK (with setTimeout -- should resolve after short tasks but still be detected!)
+    ---- SHORT TASK (x3)
+    ---- XHR send
+    ---- XHR load callback (Should have an error tied to the long task)
+    ------- SHORT TASK
+    ------- LONG TASK
+    ------- SHORT TASK
+    ------- Promise constructor
+    ----------- LONG TASK
+    ----------- SHORT TASK
+    ------- Promise then callback (async)
+    ----------- SHORT TASK
+    ----------- LONG TASK
+
+    Due to the way syncronous tasks block each other in JS, you may see no activity and then
+     multiple long tasks resolving at the "same time", since they cascade like dominoes when syncronous
+    </pre>
+    <hr />
+    <div id="content"></div>
+    <script type="text/javascript">
+      document.addEventListener(
+        "click",
+        function test () {
+          const contents = document.querySelector("#content");
+          updateDOM("Document Clicked!", true);
+          simulatedShortTask("document addEventListener");
+
+          var xhr = new XMLHttpRequest();
+          xhr.open("POST", "/echo");
+          xhr.send("123");
+
+          simulatedLongTask("document addEventListener", true); // LONG TASK AFFECTING DOC AEL CB
+
+          simulatedShortTask("document addEventListener");
+          simulatedShortTask("document addEventListener");
+          simulatedShortTask("document addEventListener");
+
+          xhr.addEventListener(
+            "load",
+            function () {
+              simulatedShortTask("xhr addEventListener");
+              simulatedLongTask("xhr addEventListener"); // LONG TASK AFFECTING XHR LOAD CB
+              simulatedShortTask("xhr addEventListener");
+
+              a = new Promise((resolve, reject) => {
+                simulatedLongTask("promise constructor"); // LONG TASK AFFECTING PROMISE CONSTRUCTOR
+                simulatedShortTask("promise constructor");
+                resolve();
+              });
+
+              a.then(() => {
+                simulatedShortTask("promise.then");
+                simulatedLongTask("promise.then"); // LONG TASK AFFECTING PROMISE THEN CB
+              });
+
+              throw new Error("I threw an error in the XHR load callback! Fix ME!");
+            },
+            true
+          );
+
+          function simulatedShortTask(name) {
+            const start = performance.now();
+            updateDOM(name + " task started");
+            let i = 0;
+            const loops = getRandomInt(10000, 1000000);
+            while (i < loops) {
+              i++;
+            }
+            const end  = performance.now()
+            updateDOM(name + " duration: " + (end-start).toFixed(4), "green");
+          }
+
+          function simulatedLongTask(name, useSetTimeout) {
+            const start = performance.now();
+            updateDOM(name + " task started");
+            // so as to not let the slow task block rendering for demo purposes
+
+            const executor = useSetTimeout
+              ? (fn) => setTimeout(fn, 0)
+              : function slowHandler(fn) {
+                  fn();
+                };
+
+            executor(reallySlowFn);
+
+            function reallySlowFn() {
+              let i = 0;
+              const loops = getRandomInt(100000000, 5000000000);
+              while (i < loops) {
+                i++;
+              }
+              const end = performance.now()
+              updateDOM("Long task (" + name + ") duration: " + (end-start).toFixed(4), "red");
+            }
+          }
+
+          window.location.hash = Math.random();
+
+          function updateDOM(text, color) {
+            const elem = document.createElement("div");
+            elem.innerHTML = text;
+            elem.style.color = color || "black";
+            contents.appendChild(elem);
+          }
+          function getRandomInt(min, max) {
+            return Math.ceil(Math.floor(Math.random() * (max - min + 1)) + min);
+          }
+        },
+        false
+      );
+    </script>
+  </body>
+</html>
diff --git a/tests/components/api.test.js b/tests/components/api.test.js
@@ -804,7 +804,12 @@ describe('API tests', () => {
           expectHandled(SUPPORTABILITY_METRIC_CHANNEL, ['API/wrapLogger/called'])
 
           expectEmitted('wrap-logger-start', [expect.any(Array), expect.any(Object), 'myObservedLogger'])
-          expectEmitted('wrap-logger-end', [['test1'], expect.any(Object), undefined])
+          expectEmitted('wrap-logger-end', [['test1'], expect.any(Object), undefined, expect.objectContaining({
+            duration: expect.any(Number),
+            isLongTask: false,
+            methodName: 'myObservedLogger',
+            thrownError: undefined
+          })])
 
           expectHandled(SUPPORTABILITY_METRIC_CHANNEL, ['API/logging/info/called'])
           expectHandled('log', [expect.any(Number), 'test1', {}, 'INFO', undefined])
@@ -832,7 +837,12 @@ describe('API tests', () => {
           expectHandled(SUPPORTABILITY_METRIC_CHANNEL, ['API/wrapLogger/called'])
 
           expectEmitted('wrap-logger-start', [expect.any(Array), expect.any(Object), randomMethodName])
-          expectEmitted('wrap-logger-end', [['test1'], expect.any(Object), undefined])
+          expectEmitted('wrap-logger-end', [['test1'], expect.any(Object), undefined, expect.objectContaining({
+            duration: expect.any(Number),
+            isLongTask: false,
+            methodName: randomMethodName,
+            thrownError: undefined
+          })])
 
           expectHandled(SUPPORTABILITY_METRIC_CHANNEL, ['API/logging/warn/called'])
           expectHandled('log', [expect.any(Number), 'test1', {}, 'warn', undefined])
@@ -853,7 +863,12 @@ describe('API tests', () => {
           expectHandled(SUPPORTABILITY_METRIC_CHANNEL, ['API/wrapLogger/called'])
 
           expectEmitted('wrap-logger-start', [expect.any(Array), expect.any(Object), randomMethodName])
-          expectEmitted('wrap-logger-end', [['test1', { test2: 2 }, ['test3'], true, 1], expect.any(Object), undefined])
+          expectEmitted('wrap-logger-end', [['test1', { test2: 2 }, ['test3'], true, 1], expect.any(Object), undefined, expect.objectContaining({
+            duration: expect.any(Number),
+            isLongTask: false,
+            methodName: randomMethodName,
+            thrownError: undefined
+          })])
         })
 
         test('wrapped function should still behave as intended', () => {
diff --git a/tests/components/wrappings/wrap-function.test.js b/tests/components/wrappings/wrap-function.test.js
@@ -174,4 +174,163 @@ describe('Wrap function', () => {
     })
     outer()
   })
+
+  describe('long tasks', () => {
+    let onLongTask, onShortTask
+    afterEach(async () => {
+      if (onLongTask) {
+        baseEE.removeEventListener('long-task', onLongTask)
+        onLongTask = null
+      }
+      if (onShortTask) {
+        baseEE.removeEventListener('short-task', onShortTask)
+        onShortTask = null
+      }
+    })
+
+    test('does not emit long task event if fn takes less than 50ms', (done) => {
+      onLongTask = function () {
+        seenLongTask = true // set flag to check if long task event was emitted
+      }
+      onShortTask = function (_, __, ____, task) {
+        expectShortTask(task)
+        expect(seenLongTask).toEqual(false) // no long task event emitted
+        done()
+      }
+      let seenLongTask = false
+      baseEE.on('long-task', onLongTask)
+
+      baseEE.on('short-end', onShortTask)
+
+      const shortTask = wrapFn(() => {}, 'short-')
+      shortTask(thisCtx)
+    })
+
+    test('emits long task message if fn takes more than 50ms', (done) => {
+      onLongTask = function (task) {
+        expectLongTask(task)
+        done()
+      }
+
+      const reallySlowFn = function reallySlowFn () {
+        slowFn(100000000, 1000000000) // this should take more than 50ms
+      }
+
+      const longTask = wrapFn(reallySlowFn, 'long-', thisCtx, 'reallySlowFn', true)
+      baseEE.on('long-task', onLongTask)
+
+      longTask(thisCtx)
+    })
+
+    test('emits long task message if fn errors out', (done) => {
+      const err = new Error('TEST')
+      onLongTask = function (task) {
+        expectLongTask(task, err)
+        done()
+      }
+
+      const reallySlowFn = function reallySlowFn () {
+        slowFn(100000000, 1000000000) // this should take more than 50ms
+        throw err // this should throw an error
+      }
+
+      const longTask = wrapFn(reallySlowFn, 'long-', thisCtx, 'reallySlowFn', true)
+      baseEE.on('long-task', onLongTask)
+
+      try {
+        expect(longTask(thisCtx)).throws('TEST') // should throw an error
+      } catch (e) {
+        // We expect the error to be thrown, so we catch it here to avoid failing the test.
+        // The long task event should still be emitted and handled by onLongTask.
+      }
+    })
+
+    test('finished fn message also has task info', (done) => {
+      onShortTask = function (_, __, ___, task) {
+        expectShortTask(task)
+        seenTasks.short = true
+        isDone()
+      }
+      onLongTask = function (_, __, ___, task) {
+        expectLongTask(task)
+        seenTasks.long = true
+        isDone()
+      }
+
+      const reallySlowFn = function reallySlowFn () {
+        slowFn(100000000, 1000000000) // this should take more than 50ms
+      }
+
+      const seenTasks = { short: false, long: false }
+
+      const shortTask = wrapFn(() => {}, 'short-')
+      const longTask = wrapFn(reallySlowFn, 'long-', thisCtx, 'reallySlowFn', true)
+
+      baseEE.on('short-end', onShortTask)
+
+      baseEE.on('long-end', onLongTask)
+
+      function isDone () {
+        if (seenTasks.short && seenTasks.long) {
+          done() // both tasks emitted
+        }
+      }
+
+      shortTask(thisCtx) // this should not emit long task
+      longTask(thisCtx)
+    })
+
+    test('nested long tasks emit twice', (done) => {
+      const seenLongTasks = { fn1: false, fn2: false, calls: 0 }
+      onLongTask = function (task) {
+        expectLongTask(task)
+        seenLongTasks[task.methodName] = true
+        seenLongTasks.calls++
+        if (seenLongTasks.calls === 2 && seenLongTasks.fn1 && seenLongTasks.fn2) {
+          done() // both long tasks emitted
+        }
+      }
+
+      baseEE.on('long-task', onLongTask)
+
+      const fn2 = function fn2 (ctx) {
+        return slowFn()
+      }
+      const wrappedFn2 = wrapFn(fn2, 'fn2-', thisCtx, 'fn2', true)
+
+      const fn1 = function fn1 (ctx) {
+        slowFn()
+        return wrappedFn2(ctx)
+      }
+      const longTask = wrapFn(fn1, 'fn1-', thisCtx, 'fn1', true)
+      longTask(thisCtx)
+    })
+  })
+
+  function expectLongTask (task, error) {
+    expect(task).toBeDefined() // task info is passed
+    expect(task.duration).toBeGreaterThanOrEqual(50) // can tell that task took less than 50ms
+    expect(task.isLongTask).toEqual(true) // task is marked as short task
+    if (error) expect(task.thrownError).toEqual(error) // task has thrown error
+    else expect(task.thrownError).toBeUndefined() // task has not thrown error
+  }
+  function expectShortTask (task, error) {
+    expect(task).toBeDefined() // task info is passed
+    expect(task.duration).toBeLessThan(50) // can tell that task took less than 50ms
+    expect(task.isLongTask).toEqual(false) // task is marked as short task
+    if (error) expect(task.thrownError).toEqual(error) // task has thrown error
+    else expect(task.thrownError).toBeUndefined() // task has not thrown error
+  }
+
+  function slowFn (from = 100000000, to = 1000000000) {
+    let i = 0
+    const loops = getRandomInt(from, to)
+    while (i < loops) {
+      i++
+    }
+    function getRandomInt (min, max) {
+      return Math.ceil(Math.floor(Math.random() * (max - min + 1)) + min)
+    }
+    return i
+  }
 })
