activity.setStatus causes a massive performance hit during build (1s slower per 1.000 queries)

[georgiee]

Summary

activity.setStatus which is used by gatsby during the build to report the page query and html page building progress introduces a performance hit in the dimension of 1s for every 1000 queries. It's like the status call costs exactly 1ms per call. This heavily builds up in environments with 10k's of queries.

Demonstration:
https://github.com/georgiee/gatsby/tree/performance-test-activity/benchmarks/query

(run on my machine, 2,7 GHz Intel Core i7 13 macbook 2018)

Description

I observed a rather dramatic performance difference while using gatsby's activity tool in our internal source plugin where we process 10-20k pages at the moment. First we thought it's caused by the code block but soon we identified the status update as the cause.

exports.sourceNodes = ({ reporter }) => {
  const activity = reporter.activityTimer(`foo`);
  activity.start();

  const count = 10000;
  for(let i = 0; i < count; i++) {
    activity.setStatus('bar' + i);
  }

  activity.end();
}

This will take 8.5s on my machine during the build and is doing nothing. From this point I checked on the page query and static html output as those two things also rely on the status update.

Here the results for 10.000 pages/queries. The pages are almost empty, there are actually no page queries to run but still being processed. .cache is always cleared.

1. With activity updates

Queries	Static HTML
12.476 s	4.170 s
13.538 s	3.981 s
13.190 s	4.802 s
12.780 s	4.976 s

here how it looks like (excerpt). You can see the status being updated. Each update costs around 1ms.

2. Without activity updates
(disabled in gatsby core, behind a new flag)

Queries	Static HTML
4.181 s	4.236 s
4.289 s	4.518 s
4.262 s	4.327 s
4.158 s	4.051 s

Here how it looks like (excerpt). No more status updates.

You can see how much faster the queries are running now. The page process is also a little bit faster but their update frequency is larger so the impact is smaller (0.5-1s faster, comapred to 8-9s faster queries).

This scales almost linear. 20.000 queries causes almost an overhead of 20 seconds.

Example/Reproduction

Here is the modified Gatsby Project. I used the benchmark project and synced it with gatsby-dev-cli.

https://github.com/georgiee/gatsby/tree/performance-test-activity/benchmarks/query

Solution/Workarounds

1. Let me silence the gatsby build output entirely (I couldn't find any option https://www.gatsbyjs.org/docs/gatsby-cli/#options-1)
2. Let me choose to display progress updates or not
3. Like with the pages update in larger batches not per query.

Edit/Appendix

This has also an impact on gatsby develop (startup, refresh if enabled) of course as the output is the same for the page queries runner.

[sidharthachatterjee]

Thanks for the detailed issue! This is known issue and is being tracked upstream in vadimdemedes/ink#212

Also in #15505

[georgiee]

Hello thanks for those useful references and the upstream issue. My initial idea to turn off status reports entirely with an option would get rid of the Ink dependency and clean up the logs.

Is this even an option as I don't find any signs of different log output levels in the sources nor do people request that feature. I found the issue with the number 3 from Kyle #3 which was open for quite some time but never implemented.

Should we leave this issue open or close it as a duplicate of #15505 ? Thanks for taking your time, very much appreciated!

[wardpeet]

thanks @georgiee i'll close this as a duplicate of #15505, let's move the discussion to that thread. This issue will still be linked so we don't lose any information.

Thanks a ton you for the awesome write-down. This is really great.