Thread: Fix Error Message for allocate_recordbuf() Failure
Hello,
Attached is a patch for xlogreader.c for a more informative error message for allocate_recordbuf() failure.
The patch details are:
- Project name.: None
- Uniquely identifiable file name, so we can tell difference between your v1 and v24.: src/backend/access/transam/xlogreader.c
- What the patch does in a short paragraph.:
The patch enhances the error message when memory cannot be allocated to extend the readRecordBuf. The previous error message was implying an invalid (too long) record length and also did not specify how much memory we were trying to allocate when the memory allocation failure happened.
We have observed failed allocations in production systems where the reclength was only 344 bytes, but the extended allocation of 5 * Max(BLKSIZE, XLOG_BLCKSZ) failed due to out of memory.
- Whether the patch is for discussion or for application (see WIP notes below): for application.
- Which branch the patch is against (ordinarily this will be master). For more on branches in PostgreSQL, see Using Back Branches.: master
- Whether it compiles and tests successfully, so we know nothing obvious is broken.: Yes. We ran make check and all 166 tests passed.
- Whether it contains any platform-specific items and if so, has it been tested on other platforms.: Nothing platform specific.
- Confirm that the patch includes regression tests to check the new feature actually works as described.: None.
- Include documentation on how to use the new feature, including examples. See the documentation documentation for more information.: None needed.
- Describe the effect your patch has on performance, if any.: None.
- Try to include a few lines about why you chose to do things particular ways, rather than let your reviewer guess what was happening. This can be done as code comments, but it might also be an additional reviewers' guide, or additions to a README file in one of the code directories.:
Besides making the error message more informative, we had to modify allocate_recordbuf() to return the actual number of bytes that were being allocated.
- If your patch addresses a Todo item, please give the name of the Todo item in your email. This is so that the reviewers will know that the item needs to be marked as done if your patch is applied.: None.
Thank you.
Shoaib Lari
Attachment
On Sat, Jul 9, 2016 at 2:58 AM, Shoaib Lari <slari@pivotal.io> wrote: > Besides making the error message more informative, we had to modify > allocate_recordbuf() to return the actual number of bytes that were being > allocated. - report_invalid_record(state, "record length %u at %X/%X too long", - total_len, - (uint32) (RecPtr >> 32), (uint32) RecPtr); + report_invalid_record(state, + "cannot allocate %u bytes for record length %u at %X/%X", + newSizeOut, total_len, (uint32) (RecPtr >> 32), + (uint32) RecPtr); It does not look like a good idea to me to complicate the interface of allocate_recordbuf just to make more verbose one error message, meaning that it basically a complain related to the fact that palloc_extended(MCXT_ALLOC_NO_OOM) does not mention to the user the size that it has tried to allocate before returning NULL. Do you have a use case that would prove to be useful if this extra piece of information is provided? Because it seems to me that we don't really care if we know how much memory it has failed to allocate, we only want to know that it *has* failed and take actions only based on that. And even if we make this thing more verbose, a better approach would be surely to generate a WARNING message for backends in mcxt.c and have something printed to stderr for frontends in fe_memutils.c without calling exit(). -- Michael
On 11 July 2016 at 12:04, Michael Paquier <michael.paquier@gmail.com> wrote:
On Sat, Jul 9, 2016 at 2:58 AM, Shoaib Lari <slari@pivotal.io> wrote:
> Besides making the error message more informative, we had to modify
> allocate_recordbuf() to return the actual number of bytes that were being
> allocated.
- report_invalid_record(state, "record length %u at %X/%X too long",
- total_len,
- (uint32) (RecPtr >> 32), (uint32) RecPtr);
+ report_invalid_record(state,
+ "cannot allocate %u bytes for record
length %u at %X/%X",
+ newSizeOut, total_len, (uint32) (RecPtr >> 32),
+ (uint32) RecPtr);
It does not look like a good idea to me to complicate the interface of
allocate_recordbuf just to make more verbose one error message,
meaning that it basically a complain related to the fact that
palloc_extended(MCXT_ALLOC_NO_OOM) does not mention to the user the
size that it has tried to allocate before returning NULL. Do you have
a use case that would prove to be useful if this extra piece of
information is provided? Because it seems to me that we don't really
care if we know how much memory it has failed to allocate, we only
want to know that it *has* failed and take actions only based on that.
I actually find details of how much memory we tried to allocate to be really useful in other places that do emit it. Sometimes it's been an important clue when trying to figure out what's going on on a remote system with no or limited access. Even if it just tells me "we were probably incrementally allocating lots of small values since this failure is small" vs "this allocation is huge, look for something unusually large" or "this allocation is impossibly huge / some suspicious value look for memory corruption".
I tend to agree with your suggestion about a better approach but do think emitting details on allocation failures is useful. At least when people turn VM overcommit off ...
Thank you for the feedback.
We had encountered this error message when allocating a record buf of 344 bytes. The message "record length 344 at %X/%X too long" along with the comment /* We treat this as a "bogus data" condition */ masked the OOM condition, implying an error in log record size calculation logic.
The actual allocation that failed was for 5 * Max(BLCKSZ, XLOG_BLCKSZ), a much larger allocation.
Shoaib
On Sun, Jul 10, 2016 at 10:58 PM, Craig Ringer <craig@2ndquadrant.com> wrote:
On 11 July 2016 at 12:04, Michael Paquier <michael.paquier@gmail.com> wrote:On Sat, Jul 9, 2016 at 2:58 AM, Shoaib Lari <slari@pivotal.io> wrote:
> Besides making the error message more informative, we had to modify
> allocate_recordbuf() to return the actual number of bytes that were being
> allocated.
- report_invalid_record(state, "record length %u at %X/%X too long",
- total_len,
- (uint32) (RecPtr >> 32), (uint32) RecPtr);
+ report_invalid_record(state,
+ "cannot allocate %u bytes for record
length %u at %X/%X",
+ newSizeOut, total_len, (uint32) (RecPtr >> 32),
+ (uint32) RecPtr);
It does not look like a good idea to me to complicate the interface of
allocate_recordbuf just to make more verbose one error message,
meaning that it basically a complain related to the fact that
palloc_extended(MCXT_ALLOC_NO_OOM) does not mention to the user the
size that it has tried to allocate before returning NULL. Do you have
a use case that would prove to be useful if this extra piece of
information is provided? Because it seems to me that we don't really
care if we know how much memory it has failed to allocate, we only
want to know that it *has* failed and take actions only based on that.I actually find details of how much memory we tried to allocate to be really useful in other places that do emit it. Sometimes it's been an important clue when trying to figure out what's going on on a remote system with no or limited access. Even if it just tells me "we were probably incrementally allocating lots of small values since this failure is small" vs "this allocation is huge, look for something unusually large" or "this allocation is impossibly huge / some suspicious value look for memory corruption".I tend to agree with your suggestion about a better approach but do think emitting details on allocation failures is useful. At least when people turn VM overcommit off ...--
On Mon, Jul 11, 2016 at 12:04 AM, Michael Paquier <michael.paquier@gmail.com> wrote: > On Sat, Jul 9, 2016 at 2:58 AM, Shoaib Lari <slari@pivotal.io> wrote: >> Besides making the error message more informative, we had to modify >> allocate_recordbuf() to return the actual number of bytes that were being >> allocated. > > - report_invalid_record(state, "record length %u at %X/%X too long", > - total_len, > - (uint32) (RecPtr >> 32), (uint32) RecPtr); > + report_invalid_record(state, > + "cannot allocate %u bytes for record > length %u at %X/%X", > + newSizeOut, total_len, (uint32) (RecPtr >> 32), > + (uint32) RecPtr); > > It does not look like a good idea to me to complicate the interface of > allocate_recordbuf just to make more verbose one error message, ... For what it's worth, I think it's fine. Good error messages are a useful thing. More generally, I think the whole patch looks good and should be committed. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
On Wed, Sep 21, 2016 at 12:32 AM, Robert Haas <robertmhaas@gmail.com> wrote: > For what it's worth, I think it's fine. Good error messages are a useful thing. > > More generally, I think the whole patch looks good and should be committed. Hm. I'd think that it is still more portable to just issue a WARNING message in palloc_extended() when MCXT_ALLOC_NO_OOM then. Other code paths could benefit from that as well, and the patch proposed does nothing for the other places calling it. I am fine to write a patch for this purpose if you agree on that. -- Michael
On Wed, Sep 21, 2016 at 10:25 AM, Michael Paquier <michael.paquier@gmail.com> wrote: > On Wed, Sep 21, 2016 at 12:32 AM, Robert Haas <robertmhaas@gmail.com> wrote: >> For what it's worth, I think it's fine. Good error messages are a useful thing. >> >> More generally, I think the whole patch looks good and should be committed. > > Hm. I'd think that it is still more portable to just issue a WARNING > message in palloc_extended() when MCXT_ALLOC_NO_OOM then. Other code > paths could benefit from that as well, and the patch proposed does > nothing for the other places calling it. I am fine to write a patch > for this purpose if you agree on that. Or in short the attached. All the other callers of palloc_extended benefit from that. -- Michael
Attachment
On Tue, Sep 20, 2016 at 9:25 PM, Michael Paquier <michael.paquier@gmail.com> wrote: > On Wed, Sep 21, 2016 at 12:32 AM, Robert Haas <robertmhaas@gmail.com> wrote: >> For what it's worth, I think it's fine. Good error messages are a useful thing. >> >> More generally, I think the whole patch looks good and should be committed. > > Hm. I'd think that it is still more portable to just issue a WARNING > message in palloc_extended() when MCXT_ALLOC_NO_OOM then. Other code > paths could benefit from that as well, and the patch proposed does > nothing for the other places calling it. I am fine to write a patch > for this purpose if you agree on that. No, I strongly disagree with that. I think when you pass MCXT_ALLOC_NO_OOM, you're saying that you are prepared to deal with a NULL return value. It becomes your job to decide whether to emit any log message and which one to emit. If palloc_extended() insists on emitting a warning regardless, the caller can't now emit a more specific message without creating redundant log chatter. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company