Problems with bytea performance

[mramato]

I originally opened this as part of a knex issue: knex/knex#2052 but was directed here instead.

I have a simple query:

SELECT glb FROM models where assets_id = 16 LIMIT 1;

glb is a bytea column and the value I'm retrieving is 28630077 bytes (~27MB) (models contains a single row in this example). The query takes 13305 ms to run and the Node process (not the DB process) maxes out the CPU while the query is running). If I query for the assets_id column instead of the glb column, it only takes 2 ms.

Running the same query with the same data from the psql command line completes almost immediately:

time psql -A -c "SELECT glb FROM models where assets_id = 16 LIMIT 1;" master postgres > out.glb

real    0m0.679s
user    0m0.000s
sys     0m0.031s

I also tested the same query in pg-native and it completed in ~450ms, but using pg-native isn't an option for me at this time (though I might have to re-evaluate that depending on where this issue goes).

Here's the table definition for completeness.

CREATE TABLE public.models
(
  assets_id integer NOT NULL,
  glb bytea NOT NULL,
  CONSTRAINT models_pkey PRIMARY KEY (assets_id),
  CONSTRAINT models_assets_id_foreign FOREIGN KEY (assets_id)
      REFERENCES public.assets (id) MATCH SIMPLE
      ON UPDATE NO ACTION ON DELETE CASCADE
)
WITH (
  OIDS=FALSE
);
ALTER TABLE public.models
  OWNER TO postgres;

Finally, I thought maybe it was a performance issue in the type parser, but all of the time is taken up by the query and then the typeParser completes almost instantly at the end.

Am I doing something wrong? Or is there a performance issue with bytea issues? I'd be happy to debug this further myself if someone can point me in the correct direction. Thanks in advance.

[vitaly-t]

I'd be happy to debug this further myself if someone can point me in the correct direction

Please do, many people would want to know 😉 Your own test is the best direction so far, add logs within the connection and the pg-types, see where the main delay happens ;)

UPDATE

On second thought though, since use of the pg-native made such a huge difference, means it is not a pg-types issue, more like inside the Connection object. There may be something wrong with the read operation.

[vitaly-t]

This caught my interest, so I did some quick local testing, and I can confirm the following results...

Reading a single bytes field that contains a 16MB file:

• With JavaScript bindings: 4s
• With Native bindings: 200ms

That's a 20x difference - huge!!!!

[mramato]

On second thought though, since use of the pg-native made such a huge difference, means it is not a pg-types issue, more like inside the Connection object.

Thanks, I'll start there and see what I can find.

[mramato]

Reading is faster for you in JavaScript? Or is that a typo?

Just saw your edit. Glad you can reproduce. I'll keep digging but let me know if you find something on your end.

[mramato]

I did some profiling and a huge amount of time (~10 seconds of the 13 for my test case) is spent in Reader.addChunk from packet-reader: https://github.com/brianc/node-packet-reader/blob/master/index.js#L18

More specifically, it looks like lastChunk is set to a buffer instead of false most of the time causing tons of Buffer.concat calls, (874 in my case) which kills performance and probably applies a ton of memory pressure as well. I'm not exactly sure why this is happening, but I'm guessing refactoring the code to avoid all of the extra allocations would go a long way to fixing this. In my own memory streams, I usually keep an array of buffers and only concast once at the end; but I haven't learned enough about the code here yet to know if that's a possible solution.

Thoughts?

[vitaly-t]

I'm not sure yet. All I can see is that all the time is being spent inside the on data handler:

https://github.com/brianc/node-postgres/blob/master/lib/connection.js#L128

Which line in there results in the longest delay - harder to tell.

[vitaly-t]

Yeah, most of the time is being spent on this line: https://github.com/brianc/node-postgres/blob/master/lib/connection.js#L129

From my total 4s it eats about 3.2s of time, that's definitely bad!!!

[mramato]

Yep, that's exactly what I'm seeing. I think I know what the problem is and I'm trying to rewrite addChunk to be more performant.

[vitaly-t]

@brianc It seems that this line kills the performance when dealing with large bytea columns: https://github.com/brianc/node-packet-reader/blob/master/index.js#L22

It slows down the library 20 times (from my tests), compared to the Native Bindings.

And it may be worthwhile revisiting the entire on-data handler: https://github.com/brianc/node-postgres/blob/master/lib/connection.js#L128

Unfortunately, I cannot be more specific at present, those things require a bit of a closer look.

[mramato]

@vitaly-t, I have a fix for the packet-reader problem that I mentioned in #1286 (comment).

I've gone from ~13 seconds to ~450ms, matching the native time!

[vitaly-t]

@mramato Wow, magical! I want to see that! Will you do a PR? ;)

I was, in the meantime, trying to ask a question here: http://stackoverflow.com/questions/43900530/slow-buffer-concat

@mramato If you are doing a PR, keep an eye on this question on StackOverflow, it might offer even a better idea, as there is already one answer there ;)