karlseguin / pg.zig

Native PostgreSQL driver / client for Zig
MIT License
158 stars 9 forks source link

Issues with the dynamic buffer #24

Closed zigster64 closed 3 weeks ago

zigster64 commented 3 weeks ago

Im seeing issues with the contents of the dynamic buffer, under very specific circumstances. I haven't been able to definitively put a finger on them yet, and I expect that might take a bit of time.

These all refer to the buffer used in reader.zig, in the situation where im inside a StartFlow, and Im using an opt.allocator (being the http.result.arena allocator)

In my DB connection, im using 4k page sizes

This is using self.allocator.realloc()

This has 2 possible paths in std.mem : 1 - It tries to resize buf. If this works, then the buffer is resized, retains the same ptr, and everything works 2 - If a resize fails, it then allocates a new buffer of the correct size, copies the old buffer contents to the new, then memsets the old buffer with undefined (0xAA ?), then frees the old buffer, then returns the new slice

In cases where the reallocation is small (ie - fits within 4k page size), then everything seems to work fine and reliable.

In cases where the reallocation is large, and resize fails (more than 4k ... and Im checking this by inserting debugs into my stdlib to see that its failing to resize) ... then what Im seeing in my app is that when the next message is read in result.zig, then this code here is returning unreasonably large values

                        message_length = std.mem.readInt(u32, buf[start + 1 .. start + 5][0..4], .big) + 1;

ie - Message size = 820Mb, or 2.3GB or whatever :(
The values of start / pos / etc in the reader look correct - its the contents of but that are incorrect.

Which in turn fail. Sometimes they fail with a runtime panic, sometimes they fail with a hanging read on the DB socket looking for 800Mb of data.

ouch. That's hard to reason about.

I have made this small change in my copy of reader.zig, and ... for now ... it seems to fix the problem at my end, and my application works reliably over very large queries.

                            } else {
                                // currently using a dynamically alllocated buffer, we'll
                                // grow or allocate a larger one (which is what realloc does)
                                std.debug.print("realloc the new buff  ml {} current_len {} start {} pos {}\n", .{ message_length, current_length, start, pos });
                                // comment out the old realloc
                                // new_buf = try self.allocator.realloc(buf, message_length);

                               // do it manually
                                if (allocator.resize(buf, message_length)) {
                                    std.debug.print("Resized buffer to {}, buf len is now {}\n", .{ message_length, buf.len });
                                    new_buf = buf;
                                } else {
                                    new_buf = try allocator.alloc(u8, message_length);
                                    std.debug.print("Resize failed, realloc buffer to {}\n", .{message_length});
                                    self.buf_allocator = allocator;
                                    @memcpy(new_buf[0..current_length], buf[start..pos]);
                                    allocator.free(buf);
                                }
                                std.debug.print("realloc success - buf.len is now {}\n", .{new_buf.len});
                                lib.metrics.allocReader(message_length - current_length);
                            }

Very odd - the logic above is similar to what std.mem.Allocator.realloc() is doing ?

If I stick with using realloc, then my application reliably crashes at the same spots.

Suggests that either - My app has some serious memory corruption issues, or Zig stdlib realloc is broken. One of the 2 must be true.

I notice the test cases in reader.zig don't pick this up at the moment, because there are all small enough re-allocs to fit within the page size, and they all appear to resize correctly (rather than create a new buf to fit the new message)

Another option at my end - if I use 64k page sizes for the DB connection, im not hitting any queries that require a realloc, so I don't see any other problem. This suggests to me that my app might not be the source of memory corruption issues after all. Hard to say.

I guess the next step is for me to try to build a zig test case that exactly triggers what Im seeing here, then we can debug it from there.

On that note - If I run zig test, it's expecting a DB setup on localhost / user Postgres, with a few tables setup. I can get it running if I guess what those test schemas should be and manually add them to my local Postgres server. You probably have these on your local setup already, but might need to add CREATE TABLE statements in the test runner so its all setup.

karlseguin commented 3 weeks ago

It was manually doing the realloc before last week's issue: https://github.com/karlseguin/pg.zig/blob/3814e9dec3c2296104f1e653f58be2ce804d32de/src/reader.zig#L184

If you have docker, you can create a testing image via:

docker build tests/ -f tests/Dockerfile -t "pgzig:pg"

And then start it up for testing via:

make d
karlseguin commented 3 weeks ago

What version of httpz? res.arena as of ~ 3 weeks is different. It's a thread-local buffer with fallback to a proper arena. If you have a recent version, maybe try ee92e0a6feca8b831fea9657dcf69a79af35a07c where res.arena is a typical Arena just to see if the problem goes away. This would quickly point to or eliminate the custom FallBackAllocator as a possible source of the issue.

zigster64 commented 3 weeks ago

Yep about the manual realloc - my app was working fine on that release, and regressed after the last update that removed the manual realloc to the stdlib version. I did notice the subtle change in the PR

Experiment.

Updated zig from 0.13 -> 0.14.today = same problem in same spot (just in case stdlib changed radically)

http -> ee92e. + pg -> master = same problem in same spot with realloc

http -> ee92e + pg -> my hacked realloc = works fine

zigster64 commented 3 weeks ago

Is statement creating an arena based off the allocator passed along as the query opt ?

Creating an arena inside an arena ?

karlseguin commented 3 weeks ago

Yes. Arena within Arena should be fine (and even normal, due to the opaque and composable nature of zig allocators).

With res.arena, it's really: arena -> custom fallback allocator -> []byte || arena

zigster64 commented 3 weeks ago

The only difference I can see between stdlib realloc, and what you had originally is - stdlib stamps 0xAA values all over the original buffer in the case where it can't be resized. This is for double-free detection.

Thinking maybe - something to do with arenas skipping the "Free" operation, combined with trashing the old contents.

Will have to do some experiments outside of pg to find out what std.mem.Allocator.realloc() is really doing I think

karlseguin commented 3 weeks ago

I think the issue is that this has to still happen during realloc:

https://github.com/karlseguin/pg.zig/blob/3814e9dec3c2296104f1e653f58be2ce804d32de/src/reader.zig#L198

When the buffer is resized, there can still be an old message at the front of it. The "next" message needs to be moved back to the start of the buffer. realloc doesn't know anything about the meaning of the data, it just grows the buffer and, failing that, allocates new space and copies the whole thing over.

Trying to write a test that will reproduce it, because it needs the right (or wrong, depending on your point of view), sequence of reads.

karlseguin commented 3 weeks ago

Pretty sure that fixes it. With the new test data in the "Reader: start/endFlow large overread" test, if that new if (start > 0) { .... } is removed, the data is corrupt.

zigster64 commented 3 weeks ago

ah yes - because it then resets self.start = 0 immediately after setting up buf (either alloc new or grow the existing one), so the data was out of synch in just that one case.

Very subtle ! Its been a bit tricky to visualise whats in the buffer, and what start/pos mean. Is making sense now (slowly)

So happy to see this one fixed - pretty sure that was also the root cause of that bus error I was seeing before, so its been lurking around for a bit, just hard to reproduce.

Tested now with a number of large queries that generate a lot of iterator traffic

Works fine. I haven't spent any time looking at memory usage / leaks yet - doesnt appear to have any leaks that I can see (which is expected given that its all arenas off the http request)

This stack is starting to look really good. Thx again