Document how to investigate rollup performance issues in order to locate+report a bug

[kg]

Documentation is

• Missing
• Needed
• Confusing
• Not sure?

Please Explain in Detail...

I'm trying to investigate a regression with rollup in my build pipeline where some changes to my JS have caused rollup build times to increase from ~5 seconds to ~78 (!) seconds. I eventually found --perf and once I got it working was able to use that to verify some of my measurements. Unfortunately, the timing data seems unreliable and also quite coarse-grained - for one file the BUILD timing lists 75320ms but none of the sub-items last more than a few hundred msec, so the rest of that time is just... not recorded. For the other file the time is reported but all under one plugin (dts - transform whatever that is - I didn't configure rollup, I'm just troubleshooting).

At present based on the information I have it's not clear to me where this issue should be reported, and the data I'm getting isn't precise/accurate enough for me to try and narrow down the cause or reduce it to a small reproduction case.

Your Proposal for Changes

Please expand on your issue template to describe what developers like me should do when looking to report a performance issue, and if possible provide a bit more info in the docs on how to use --perf to do so. It took a good amount of searching and experimenting to even figure out how to get timings - I only knew it was possible because I saw timings in an old report about a similar performance issue.

[kzc]

You can create a custom plugin to provide module level timing granularity of events (or whatever information you want) and insert it into the plugin list to indirectly debug other plugins:

$ cat spy.js
module.exports = (options = {}) => {
    const tag = options.tag || "spy";
    function log(prefix, ...args) {
        console.error(`*** ${Date.now()/1000} ${tag} ${prefix}`, ...args);
    }
    return {
        name: "spy",
        options(options) {
            //log("options", JSON.stringify(options));
            log("options");
        },
        outputOptions(options) {
            //log("outputOptions", JSON.stringify(options));
            log("outputOptions");
        },
        buildStart(options) {
            //log("buildStart", JSON.stringify(options));
            log("buildStart");
        },
        resolveId(id, importer) {
            log("resolveId", JSON.stringify(id), JSON.stringify(importer));
        },
        load(id, importer) {
            log("load", JSON.stringify(id));
        },
        moduleParsed(stuff) {
            log("moduleParsed", JSON.stringify(stuff.id));
        },
        transform(code, id) {
            //log("transform", JSON.stringify(id));
            log("transform", JSON.stringify(id), JSON.stringify(code));
        },
        generateBundle(options, bundle, isWrite) {
            //for (var k in bundle) log("generateBundle module", k, JSON.stringify(bundle[k]));
            log("generateBundle");
        },
    }
};

Here's an example plugin to debug with no knowledge of the spy plugin above:

$ cat slow-plugin.js 
var path = require("path");
module.exports = (options = {}) => {
    async function sleep(ms) {
        return new Promise(resolve => {
            setTimeout(resolve, ms);
        });
    }
    return {
        name: "slow-plugin",
        async resolveId(id, importer) {
            await sleep(3000);
            return "./" + path.relative(process.cwd(), id);
        },
        async load(id, importer) {
            await sleep(5000);
        },
        async transform(code, id) {
            await sleep(7000);
            return `// ${JSON.stringify(id)}\n${code}`;
        },
    }
};

Just place the spy plugin before and after the suspected problematic plugin using different tags to differentiate them. I happen to be using the CLI, but you could integrate it into a rollup config file just as easily:

$ rollup dingo.mjs -p ./spy='{tag:"spy1"}' -p ./slow-plugin.js -p ./spy='{tag:"spy2"}' --silent
*** 1639166443.255 spy1 options
*** 1639166443.26 spy2 options
*** 1639166443.262 spy1 buildStart
*** 1639166443.262 spy2 buildStart
*** 1639166443.263 spy1 resolveId "dingo.mjs" undefined
*** 1639166446.267 spy1 load "./dingo.mjs"
*** 1639166451.268 spy2 load "./dingo.mjs"
*** 1639166451.271 spy1 transform "./dingo.mjs" "import \"./bingo.mjs\";\nconsole.log(\"DINGO\");\n"
*** 1639166458.273 spy2 transform "./dingo.mjs" "// \"./dingo.mjs\"\nimport \"./bingo.mjs\";\nconsole.log(\"DINGO\");\n"
*** 1639166458.284 spy1 resolveId "./bingo.mjs" "./dingo.mjs"
*** 1639166461.286 spy1 moduleParsed "./dingo.mjs"
*** 1639166461.286 spy2 moduleParsed "./dingo.mjs"
*** 1639166461.286 spy1 load "./bingo.mjs"
*** 1639166466.288 spy2 load "./bingo.mjs"
*** 1639166466.289 spy1 transform "./bingo.mjs" "console.log(\"BINGO\");\n"
*** 1639166473.291 spy2 transform "./bingo.mjs" "// \"./bingo.mjs\"\nconsole.log(\"BINGO\");\n"
*** 1639166473.293 spy1 moduleParsed "./bingo.mjs"
*** 1639166473.293 spy2 moduleParsed "./bingo.mjs"
*** 1639166473.298 spy1 outputOptions
*** 1639166473.298 spy2 outputOptions
*** 1639166473.308 spy1 generateBundle
*** 1639166473.308 spy2 generateBundle
// "./bingo.mjs"
console.log("BINGO");

// "./dingo.mjs"
console.log("DINGO");

From the timings in the log you can infer that slow-plugin.js spends 3 seconds on every resolveId, 5 seconds on every load and 7 seconds on every transform. Note that the spy plugin does not modify the modules - it is a passive monitor. The code change from spy1 transform to spy2 transform as seen in the log above would have taken place in the transform of slow-plugin.js.

[kg]

Great, I will file appropriate bugs once I figure out what's going on - one of them is definitely dts so that's not rollup's fault, but removing dts didn't make the other issue go away.

Do you want a PR that expands the information for --perf, or would you prefer to leave that out of the docs?

[kg]

I just wanted to post an update: The time is all being spent in typescript, which explains why for one file it was in dts (since that is generating .d.ts files from my typescript) but in the other it wasn't in a third-party plugin. Oddly it is not being reported as under the rollup typescript plugin, so I'll file a report about that reporting issue. I was able to get a CPU profile out of tsc and reproduce it there, then view the profile in chromium - it might be cool to document how to get a cpu profile out of rollup if possible, because it is very easy to open one of those in chrome devtools and look at the callstacks to figure out where time is going.

[FoxDaxian]

Did you use 'ts.CompilerHost'?
what is your tsoptions if you used?
I has same one, but now it is not so slow after changed tsoptons

[kg]

Did you use 'ts.CompilerHost'? what your tsoptions if you used? I has same one, but now it is not so slow after changed tsoptons

Pretty much default typescript settings, just plugins: [typescript()]. In the end this was a typescript 'bug', where typescript type checking performance fell off a cliff and as a result made everything touching one .ts file (including rollup) take forever to finish. Fixing it didn't require any changes to our rollup config so in practice it wasn't a rollup bug - expanding the docs may help someone in the future find their answer quicker.