fix: Schedule the execution of the finish to let all the spans being closed first

[kamilogorek]

Fixes #3001

[github-actions]

size-limit report

Path	Size
@sentry/browser - CDN Bundle (gzipped)	19.65 KB (0%)
@sentry/browser - Webpack	20.51 KB (0%)
@sentry/react - Webpack	20.51 KB (0%)
@sentry/browser + @sentry/tracing - CDN Bundle (gzipped)	26.64 KB (0%)

[lobsterkatie]

setImmediate seems to have pretty poor support: https://developer.mozilla.org/en-US/docs/Web/API/Window/setImmediate

Is there another option?

[xr0master]

@lobsterkatie the code is for the node.js, it has setImmediate support from the very beginning.
Although I'm still curious why not use the close event.

[kamilogorek]

@xr0master I was thinking about this solution as well. finish is called after the data has been moved to the network layer, where close has a time overhead of draining and closing a socket. In this scenario, we want to be as precise time-wise as possible though.
Second thing is that if we ever decide to move both, span and transaction to close event, this solution would still work, where if we use two distinct events now, it'd have to be fixed again.

[xr0master]

@kamilogorek it makes sense. I wonder what the gap is between the finish event and the closing event. Perhaps it could have been ignored. However, the decision to use setImmediate to move the event callback to the end of the stack is more correct.

[kamilogorek]

@xr0master I performed some tests for GET and POST requests. For GET the difference is ~3ms, for POST it's ~1ms.

[get] end: 321.83476996421814
[get] setImmediate: 325.74649310112
[get] close: 328.78951811790466
[get] setImmediate delta: 3.9117231369018555
[get] close delta: 6.954748153686523

[post] end: 328.02444314956665
[post] setImmediate: 328.17708802223206
[post] close: 329.0955080986023
[post] setImmediate delta: 0.15264487266540527
[post] close delta: 1.0710649490356445

quick hacky test implementation

const http = require("http");
const { performance } = require("perf_hooks");

http
  .get("http://en6m65p7lz2gi.x.pipedream.net", (resp) => {
    resp.on("data", (d) => {});

    let end;
    resp.on("end", () => {
      const now = performance.now();
      end = now;
      console.log(`[get] end: ${now}`);
      setImmediate(() => {
        const now = performance.now();
        console.log(`[get] setImmediate: ${now}`);
        console.log(`[get] setImmediate delta: ${now - end}`);
      });
    });

    resp.on("close", () => {
      const now = performance.now();
      console.log(`[get] close: ${now}`);
      console.log(`[get] close delta: ${now - end}`);
    });
  })
  .on("error", (err) => {
    console.log("Error: " + err.message);
  });

const req = http
  .request(
    {
      host: "en6m65p7lz2gi.x.pipedream.net",
      method: "POST",
    },
    (resp) => {
      resp.on("data", (d) => {});

      let end;
      resp.on("end", () => {
        const now = performance.now();
        end = now;
        console.log(`[post] end: ${now}`);
        setImmediate(() => {
          const now = performance.now();
          console.log(`[post] setImmediate: ${now}`);
          console.log(`[post] setImmediate delta: ${now - end}`);
        });
      });

      resp.on("close", () => {
        const now = performance.now();
        console.log(`[post] close: ${now}`);
        console.log(`[post] close delta: ${now - end}`);
      });
    }
  )
  .on("error", (error) => {
    console.error(error);
  });

req.write(
  JSON.stringify({
    todo: "Buy the milk",
  })
);
req.end();

[xr0master]

@kamilogorek Thanks for the testing and results. This is very useful.