Add more powerful benchmarks

[kibertoad]

No description provided.

[kibertoad]

@Uzlopak There is definitely something wrong with how our benchmarks are written, I don't think we were actually awaiting anything to finish processing originally and were counting who knows what. Now it seems to be fixed, but for some reason nothing gets returned as a result of the operation. Could you take a look? Wonder if we are using wrong header.

You can see it in action by running benchmarks/package.json -> benchmark-busboy

[Uzlopak]

@kibertoad

Does this help?

[Uzlopak]

allowUnsafe does not really generate data :/

[kibertoad]

@Uzlopak Version that is currently pushed returns immediately, promise is not resolved properly for some reason. I'm trying to produce much simpler example based on our usage of Busboy in types-multipart.spec.js, but it isn't returning any content either. This makes me wonder if our results are even correct 😂

[Uzlopak]

pushed now.

If i make some low rounds, like 10 warmup and 10 benchmark cycles it will get results.

[Uzlopak]

@kibertoad

dto@1.0.0 benchmark-all /home/aras/Workspace/fastify/direct/busboy/benchmarks
npm run benchmark-busboy && npm run benchmark-fastify -p high

dto@1.0.0 benchmark-busboy /home/aras/Workspace/fastify/direct/busboy/benchmarks
node busboy/executioner.js -c 0

second
Mean time for busboy is 1945927.3472222222 nanoseconds
all done

dto@1.0.0 benchmark-fastify /home/aras/Workspace/fastify/direct/busboy/benchmarks
node busboy/executioner.js -c 1 "high"

second
Mean time for @fastify/busboy is 1765178.5027777778 nanoseconds
Something went wrong: ENOENT: no such file or directory, open '/home/aras/Workspace/fastify/direct/busboy/benchmarks/_results/Busboy_comparison-@fastify/busboy-Node_12.json'

[Uzlopak]

Also it seems that the preset command line parameter is not passed to executioner.js

[kibertoad]

@Uzlopak Much better now, thank you! Still trying to figure out what can we listen to to ensure that we actually read the expected parts of the payload in expected way; knowing that we fired the finish event is not enough, we may as well read nothing before doing so.

I am very concerned that if I add this:

        busboy.on('part', function (p) {
            callbacks.partBegin++;
            p.on('header', function (header) {
                for (var h in header)
                console.log('Part header: k: ' + inspect(h) + ', v: ' + inspect(header[h]));
            });
            p.on('data', function (data) {
                //callbacks.partData++;
                console.log('Part data: ' + inspect(data.toString()));
            });
            p.on('end', function () {
                console.log('End of part\n');
                //callbacks.partEnd++;
            });
        });

then none of the part listeners log anything. It feels like we are not doing anything.

[kibertoad]

Also it seems that the preset command line parameter is not passed to executioner.js

commonBuilder.js is supposed to read it on its own, is that not working?

[Uzlopak]

I think the actual mistake was that i took the dicer benchmarks. part is not a busboy event but a dicer event.
First of all: sorry about that.

What we can do is to listen to the file event, as we have only one file, and accumulate the size of the provided chunk(s) (=> bytesRead). in finish we could then return the bytesRead.

The thing is we dont pipe anything through the file system or so. So it makes actually sense to just listen to the file event and pipe the data into the nirvana.

So we should actually also handle the file stream:
busboy.on('file', (fieldname, file, filename, encoding, mimetype) => {
console.log(File [${fieldname}]: filename: ${filename}, encoding: ${encoding}, mimetype: ${mimetype});
file.on('data', data => {
console.log(File [${fieldname}] got ${data.length} bytes);
});
file.on('end', () => {
console.log(File [${fieldname}] Finished);
});
});

[kibertoad]

Ah, that part actually comes from Dicer, which explains why it wouldn't work for Busboy which I don't think is passing through all the events it gets from Dicer. But events that Busboy emits are not documented, ant the one used by fastify-multipart (file) is not hit either.

[kibertoad]

The thing is we dont pipe anything through the file system or so. So it makes actually sense to just listen to the file event and pipe the data into the nirvana.

Great point!

[kibertoad]

@Uzlopak Pushed the change, it's still not firing any file events. Do we still miss something?

[Uzlopak]

It is really strange. Even legacy busboy behaves the same :/ So it is not even something were I could blame that we maybe broke something...

[Uzlopak]

It ignores the parts in this line.
So this means, the payload is wrong?

busboy/deps/dicer/lib/Dicer.js

Line 157 in 82a9a50

if (this._isPreamble && this._events.preamble) { this.emit('preamble', this._part) } else if (this._isPreamble !== true && this._events.part) { this.emit('part', this._part) } else { this._ignore() }

[kibertoad]

Yes, looks like it.

[Uzlopak]

The payload seems valid. I really dont get it... What is the issue?

[Uzlopak]

At this point it is easier to setup a fastify instance and run the autocannon against it than writing a benchmark... WTF

[Uzlopak]

Ok.. the most stupidest thing

[Uzlopak]

I go to sleep now, knowing I solved this ridiculously issue...

npm run benchmark-all

> dto@1.0.0 benchmark-all /home/aras/Workspace/fastify/direct/busboy/benchmarks
> npm run benchmark-busboy && npm run benchmark-fastify -p high


> dto@1.0.0 benchmark-busboy /home/aras/Workspace/fastify/direct/busboy/benchmarks
> node busboy/executioner.js -c 0

second
Mean time for busboy is 305643.6620498615 nanoseconds
all done

> dto@1.0.0 benchmark-fastify /home/aras/Workspace/fastify/direct/busboy/benchmarks
> node busboy/executioner.js -c 1 "high"

second
Mean time for @fastify/busboy is 165044.7206085754 nanoseconds

Something went wrong: ENOENT: no such file or directory, open '/home/aras/Workspace/fastify/direct/busboy/benchmarks/_results/Busboy_comparison-@fastify/busboy-Node_12.json'

[kibertoad]

@Uzlopak Woooohooo! Awesome, great job!

[kibertoad]

I'll wrap up remaining loose ends and prepare it for review.

[kibertoad]

@Uzlopak I've added real validators to ensure our results are consistent, and they are sometimes passing, and sometimes failing. Do you have any ideas what could make them randomly fail sometimes? Could be that we actually have a bug in there that makes both implementations sometimes swallow some data or generate some in excess.
Reproduction: just run either "benchmark-fastify" or "benchmark-busboy" several times in the row. It will fail more times than it will pass.
Considering that we do buffer.toString() both when processing and when asserting, should be identical?..

[Uzlopak]

Actually... I think this is because of generating Buffer data. I assume that it fails, e.g. when \r\n is created randomly. What happens if you give a specific string like consecutive 'AAAAAA...'? Does it still fail?

[kibertoad]

@Uzlopak You were right, replacing data with deterministic set resolved the issue. This is now ready for review :)

[Uzlopak]

first review, will test now

[Uzlopak]

Suggested change

	"benchmark-all-medium": "npm run benchmark-busboy && npm run benchmark-fastify -p medium",
	"benchmark-all-medium": "npm run benchmark-busboy -- -p medium && npm run benchmark-fastify -- -p medium",

[Uzlopak]

good job.