Thread: Valgrind Memcheck support
Valgrind's Memcheck tool[1] is handy for finding bugs, but our use of a custom
allocator limits its ability to detect problems in unmodified PostgreSQL.
During the 9.1 beta cycle, I found some bugs[2] with a rough patch adding
instrumentation to aset.c and mcxt.c such that Memcheck understood our
allocator. I've passed that patch around to a few people over time, and I've
now removed the roughness such that it's ready for upstream. In hopes of
making things clearer in the commit history, I've split out a preliminary
refactoring patch from the main patch and attached each separately.
Besides the aset.c/mcxt.c instrumentation, this patch adds explicit checks for
undefined memory to PageAddItem() and printtup(); this has caught C-language
functions that fabricate a Datum without initializing all bits. The inclusion
of all this is controlled by a pg_config_manual.h setting. The patch also
adds a "suppression file" that directs Valgrind to silences nominal errors we
don't plan to fix.
To smoke-test the instrumentation, I used "make installcheck" runs on x86_64
GNU/Linux and ppc64 GNU/Linux. This turned up various new and newly-detected
memory bugs, which I will discuss in a separate thread. With those fixed,
"make installcheck" has a clean report (in my one particular configuration).
I designed the suppression file to work across platforms; I specifically
anticipated eventual use on x86_64 Darwin and x86_64 FreeBSD. Valgrind 3.8.1
quickly crashed when running PostgreSQL on Darwin; I did not dig further.
Since aset.c and mcxt.c contain the hottest code paths in the backend, I
verified that a !USE_VALGRIND, non-assert build produces the same code before
and after the patch. Testing that revealed the need to move up the
AllocSizeIsValid() check in repalloc(), though I don't understand why GCC
reacted that way.
Peter Geoghegan and Korry Douglas provided valuable feedback on earlier
versions of this code.
Possible future directions:
- Test "make installcheck-world". When I last did this in past years, contrib did
trigger some errors.
- Test recovery, such as by running a streaming replica under Memcheck while
the primary runs "make installcheck-world".
- Test newer compilers and higher optimization levels. I used GCC 4.2 at -O1.
A brief look at -O2 results showed a new error that I have not studied. GCC
4.8 at -O3 might show still more due to increasingly-aggressive assumptions.
- A buildfarm member running its installcheck steps this way.
- Memcheck has support for detecting leaks. I have not explored that side at
all, always passing --leak-check=no. We could add support for freeing
"everything" at process exit, thereby making the leak detection meaningful.
Brief notes for folks reproducing my approach: I typically start the
Memcheck-hosted postgres like this:
valgrind --leak-check=no --gen-suppressions=all \
--suppressions=src/tools/valgrind.supp --time-stamp=yes \
--log-file=$HOME/pg-valgrind/%p.log postgres
If that detected an error on which I desired more detail, I would rerun a
smaller test case with "--track-origins=yes --read-var-info=yes". That slows
things noticeably but gives more-specific messaging. When even that left the
situation unclear, I would temporarily hack allocChunkLimit so every palloc()
turned into a malloc().
I strongly advise installing the latest-available Valgrind, particularly
because recent releases suffer far less of a performance drop processing the
instrumentation added by this patch. A "make installcheck" run takes 273
minutes under Vaglrind 3.6.0 but just 27 minutes under Valgrind 3.8.1.
Thanks,
nm
[1] http://valgrind.org/docs/manual/mc-manual.html
[2] http://www.postgresql.org/message-id/20110312133224.GA7833@tornado.gateway.2wire.net
--
Noah Misch
EnterpriseDB http://www.enterprisedb.com
Attachment
On 2013-06-09 17:25:59 -0400, Noah Misch wrote: > Valgrind's Memcheck tool[1] is handy for finding bugs, but our use of a custom > allocator limits its ability to detect problems in unmodified PostgreSQL. > During the 9.1 beta cycle, I found some bugs[2] with a rough patch adding > instrumentation to aset.c and mcxt.c such that Memcheck understood our > allocator. I've passed that patch around to a few people over time, and I've > now removed the roughness such that it's ready for upstream. In hopes of > making things clearer in the commit history, I've split out a preliminary > refactoring patch from the main patch and attached each separately. > Besides the aset.c/mcxt.c instrumentation, this patch adds explicit checks for > undefined memory to PageAddItem() and printtup(); this has caught C-language > functions that fabricate a Datum without initializing all bits. The inclusion > of all this is controlled by a pg_config_manual.h setting. The patch also > adds a "suppression file" that directs Valgrind to silences nominal errors we > don't plan to fix. Very nice work. I've started to do this quite some time back to smoke out some bugs in code of mine, but never got remotely to a point where it was submittable. But I already found some bugs with it. So I'd very happy if this could get committed. Will take a look. > I strongly advise installing the latest-available Valgrind, particularly > because recent releases suffer far less of a performance drop processing the > instrumentation added by this patch. A "make installcheck" run takes 273 > minutes under Vaglrind 3.6.0 but just 27 minutes under Valgrind 3.8.1. At least on linux amd64 I'd strongly suggest using something newer than (afair) 3.8.1, i.e. the svn version. Up to that version it corrupts the stack alignment inside signal handlers which doesn't get fixed up even after a fork(). This leads to mysterious segfaults, e.g. during elog()s due to the usage of sse registers which have stronger alignment requirements. Greetings, Andres Freund -- Andres Freund http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training & Services
Hi Noah,
On 2013-06-09 17:25:59 -0400, Noah Misch wrote:
> *** a/src/backend/tcop/postgres.c
> --- b/src/backend/tcop/postgres.c
> ***************
> *** 69,74 ****
> --- 69,75 ----
> #include "tcop/tcopprot.h"
> #include "tcop/utility.h"
> #include "utils/lsyscache.h"
> + #include "utils/memdebug.h"
> #include "utils/memutils.h"
> #include "utils/ps_status.h"
> #include "utils/snapmgr.h"
> ***************
> *** 846,851 **** exec_simple_query(const char *query_string)
> --- 847,856 ----
>
> TRACE_POSTGRESQL_QUERY_START(query_string);
>
> + #ifdef USE_VALGRIND
> + VALGRIND_PRINTF("statement: %s\n", query_string);
> + #endif
> +
Is there a special reason for adding more logging here? I find this
makes the instrumentation much less useful since reports easily get
burried in those traces. What's the advantage of doing this instead of
log_statement=...? Especially as that location afaics won't help for the
extended protocol?
Greetings,
Andres Freund
-- Andres Freund http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services
Sent from my iPad
On 27-Aug-2013, at 19:44, Andres Freund <andres@2ndquadrant.com> wrote:
> Hi Noah,
>
> On 2013-06-09 17:25:59 -0400, Noah Misch wrote:
>> *** a/src/backend/tcop/postgres.c
>> --- b/src/backend/tcop/postgres.c
>> ***************
>> *** 69,74 ****
>> --- 69,75 ----
>> #include "tcop/tcopprot.h"
>> #include "tcop/utility.h"
>> #include "utils/lsyscache.h"
>> + #include "utils/memdebug.h"
>> #include "utils/memutils.h"
>> #include "utils/ps_status.h"
>> #include "utils/snapmgr.h"
>> ***************
>> *** 846,851 **** exec_simple_query(const char *query_string)
>> --- 847,856 ----
>>
>> TRACE_POSTGRESQL_QUERY_START(query_string);
>>
>> + #ifdef USE_VALGRIND
>> + VALGRIND_PRINTF("statement: %s\n", query_string);
>> + #endif
>> +
>
> Is there a special reason for adding more logging here? I find this
> makes the instrumentation much less useful since reports easily get
> burried in those traces. What's the advantage of doing this instead of
> log_statement=...? Especially as that location afaics won't help for the
> extended protocol?
>
>
+1. I also feel that extra traces may tend to confuse up the actual hot spot. Extra debugging can be happily be done
withhigher log levels.
Regards,
Atri
On Tue, Aug 27, 2013 at 04:14:27PM +0200, Andres Freund wrote:
> On 2013-06-09 17:25:59 -0400, Noah Misch wrote:
> > ***************
> > *** 846,851 **** exec_simple_query(const char *query_string)
> > --- 847,856 ----
> >
> > TRACE_POSTGRESQL_QUERY_START(query_string);
> >
> > + #ifdef USE_VALGRIND
> > + VALGRIND_PRINTF("statement: %s\n", query_string);
> > + #endif
> > +
>
> Is there a special reason for adding more logging here? I find this
> makes the instrumentation much less useful since reports easily get
> burried in those traces. What's the advantage of doing this instead of
> log_statement=...? Especially as that location afaics won't help for the
> extended protocol?
I typically used "valgrind --log-file=...". To determine via log_statement
which SQL statement caused a particular Valgrind error, I would match by
timestamp; this was easier. In retrospect, log_statement would have sufficed
given both Valgrind and PostgreSQL logging to stderr. Emitting the message in
exec_simple_query() and not in exec_execute_message() is indeed indefensible.
That being said, could you tell me more about your workflow where the extra
messages cause a problem? Do you just typically diagnose each Valgrind error
without first isolating the pertinent SQL statement?
Thanks,
nm
--
Noah Misch
EnterpriseDB http://www.enterprisedb.com
On 2013-08-27 23:46:23 -0400, Noah Misch wrote:
> On Tue, Aug 27, 2013 at 04:14:27PM +0200, Andres Freund wrote:
> > On 2013-06-09 17:25:59 -0400, Noah Misch wrote:
> > > ***************
> > > *** 846,851 **** exec_simple_query(const char *query_string)
> > > --- 847,856 ----
> > >
> > > TRACE_POSTGRESQL_QUERY_START(query_string);
> > >
> > > + #ifdef USE_VALGRIND
> > > + VALGRIND_PRINTF("statement: %s\n", query_string);
> > > + #endif
> > > +
> >
> > Is there a special reason for adding more logging here? I find this
> > makes the instrumentation much less useful since reports easily get
> > burried in those traces. What's the advantage of doing this instead of
> > log_statement=...? Especially as that location afaics won't help for the
> > extended protocol?
>
> I typically used "valgrind --log-file=...". To determine via log_statement
> which SQL statement caused a particular Valgrind error, I would match by
> timestamp; this was easier. In retrospect, log_statement would have sufficed
> given both Valgrind and PostgreSQL logging to stderr. Emitting the message in
> exec_simple_query() and not in exec_execute_message() is indeed indefensible.
It's an understandable mistake, nothing indefensible. We don't really
test the extended protocol :(
> That being said, could you tell me more about your workflow where the extra
> messages cause a problem? Do you just typically diagnose each Valgrind error
> without first isolating the pertinent SQL statement?
There's basically two scenarios where I found it annoying:
a) I manually reproduce some issue, potentially involving several psql
shells. All those fire up autocompletion and such queries which bloat
the log while I actually only want to analyze something specific.
b) I don't actually look for anything triggered by an SQL statement
itself, but am looking for issues in a walsender, background worker,
whatever. I still need some foreground activity to trigger the behaviour
I want to see, but once more, valgrind's logs hide the error.
Also, I sometimes use valgrind's --db-command/--vgdb which gives you
enough context from the backtrace itself since you can just get the
statement from there.
I vote for just removing that VALGRIND_PRINTF - it doesn't give you
anything you cannot easily achieve otherwise...
Greetings,
Andres Freund
-- Andres Freund http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services
On Wed, Aug 28, 2013 at 03:16:14PM +0200, Andres Freund wrote:
> On 2013-08-27 23:46:23 -0400, Noah Misch wrote:
> > On Tue, Aug 27, 2013 at 04:14:27PM +0200, Andres Freund wrote:
> > > On 2013-06-09 17:25:59 -0400, Noah Misch wrote:
> > > > ***************
> > > > *** 846,851 **** exec_simple_query(const char *query_string)
> > > > --- 847,856 ----
> > > >
> > > > TRACE_POSTGRESQL_QUERY_START(query_string);
> > > >
> > > > + #ifdef USE_VALGRIND
> > > > + VALGRIND_PRINTF("statement: %s\n", query_string);
> > > > + #endif
> > > > +
> > >
> > > Is there a special reason for adding more logging here? I find this
> > > makes the instrumentation much less useful since reports easily get
> > > burried in those traces. What's the advantage of doing this instead of
> > > log_statement=...? Especially as that location afaics won't help for the
> > > extended protocol?
> > That being said, could you tell me more about your workflow where the extra
> > messages cause a problem? Do you just typically diagnose each Valgrind error
> > without first isolating the pertinent SQL statement?
>
> There's basically two scenarios where I found it annoying:
> a) I manually reproduce some issue, potentially involving several psql
> shells. All those fire up autocompletion and such queries which bloat
> the log while I actually only want to analyze something specific.
> b) I don't actually look for anything triggered by an SQL statement
> itself, but am looking for issues in a walsender, background worker,
> whatever. I still need some foreground activity to trigger the behaviour
> I want to see, but once more, valgrind's logs hide the error.
>
> Also, I sometimes use valgrind's --db-command/--vgdb which gives you
> enough context from the backtrace itself since you can just get the
> statement from there.
Gotcha. My largest use case was running "make installcheck" in search of
longstanding bugs. The runs were unattended, and associating each Valgrind
error with its proximate command was a basic need.
> I vote for just removing that VALGRIND_PRINTF - it doesn't give you
> anything you cannot easily achieve otherwise...
I'd like to see a buildfarm member running "make installcheck" under Valgrind,
so I'd like the code to fit the needs thereof without patching beyond
pg_config_manual.h. Perhaps having the buildfarm member do "valgrind postgres
--log-statement=all 2>combined-logfile" is good enough.
--
Noah Misch
EnterpriseDB http://www.enterprisedb.com
On Sun, Jun 9, 2013 at 10:25 PM, Noah Misch <noah@leadboat.com> wrote:
- Test recovery, such as by running a streaming replica under Memcheck while
the primary runs "make installcheck-world".
In general we need a lot more testing on the recovery code.
- Memcheck has support for detecting leaks. I have not explored that side at
all, always passing --leak-check=no. We could add support for freeing
"everything" at process exit, thereby making the leak detection meaningful.
I think this is missing the type of leaks we actually care about. The way palloc works we can be virtually certain that if we did that we wouldn't have any leaks. All it would detect are the random one-off mallocs we know very well are there.
The problems we've had with leaks in the past are invariably things allocated at the "wrong" memory context. Things that can grow for every row processed but are stored per-query or for every query processed but stored per-sesson. To detect that will requires more of a heuristic where when a child memory context is reset any parent context growth is logged.
--
greg
--
greg
On Wed, Aug 28, 2013 at 10:30:34PM -0400, Noah Misch wrote: > On Wed, Aug 28, 2013 at 03:16:14PM +0200, Andres Freund wrote: > > I vote for just removing that VALGRIND_PRINTF - it doesn't give you > > anything you cannot easily achieve otherwise... Done. > I'd like to see a buildfarm member running "make installcheck" under Valgrind, > so I'd like the code to fit the needs thereof without patching beyond > pg_config_manual.h. Perhaps having the buildfarm member do "valgrind postgres > --log-statement=all 2>combined-logfile" is good enough. -- Noah Misch EnterpriseDB http://www.enterprisedb.com
On Fri, Sep 06, 2013 at 09:55:09PM +0100, Greg Stark wrote: > On Sun, Jun 9, 2013 at 10:25 PM, Noah Misch <noah@leadboat.com> wrote: > > - Memcheck has support for detecting leaks. I have not explored that > > side at > > all, always passing --leak-check=no. We could add support for freeing > > "everything" at process exit, thereby making the leak detection > > meaningful. > > > > I think this is missing the type of leaks we actually care about. The way > palloc works we can be virtually certain that if we did that we wouldn't > have any leaks. All it would detect are the random one-off mallocs we know > very well are there. Probably so; it's not too promising. -- Noah Misch EnterpriseDB http://www.enterprisedb.com
On 2013-09-06 21:55:09 +0100, Greg Stark wrote: > On Sun, Jun 9, 2013 at 10:25 PM, Noah Misch <noah@leadboat.com> wrote: > > > - Test recovery, such as by running a streaming replica under Memcheck > > while > > the primary runs "make installcheck-world". > > > > In general we need a lot more testing on the recovery code. > > > > - Memcheck has support for detecting leaks. I have not explored that > > side at > > all, always passing --leak-check=no. We could add support for freeing > > "everything" at process exit, thereby making the leak detection > > meaningful. > > > > I think this is missing the type of leaks we actually care about. The way > palloc works we can be virtually certain that if we did that we wouldn't > have any leaks. All it would detect are the random one-off mallocs we know > very well are there. Well, we do have a good number of things that allocate stuff in TopMemoryContext. So it might already catch leaks into that. IIRC we don't reset that, but even if, that can easily be removed. Valgrind's detection for "unreachable memory" is nice for that. Greetings, Andres Freund -- Andres Freund http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training & Services