Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Fri, Nov 8, 2024 at 4:23 PM Jacob Champion
 wrote:
> While I work on breaking pgstat_bestart() apart, here is a v6 which
> pushes down the "coarse" wait events. No changes to 0001 yet.

v7 rewrites 0001 by splitting pgstat_bestart() into three phases.
(0002-3 are unchanged.)

1. pgstat_bestart_initial() reports STATE_STARTING, fills in the early
fields and clears out the rest.
2. pgstat_bestart_security() reports the SSL/GSS status of the
connection. This is only for backends with a valid MyProcPort; they
call it twice.
3. pgstat_bestart_final() fills in the user and database IDs, takes
the entry out of STATE_STARTING, and reports the application_name.

I was wondering if maybe I should fill in application_name before
taking the entry out of STATE_STARTING, in order to establish the rule
that "starting" pgstat entries are always partially filled, and that
DBAs can rely on their full contents once they've proceeded past it.
Thoughts?

I've added machinery to 001_ssltests.pl to make sure we see early
transport security stats prior to user authentication. This overlaps
quite a bit with the new 007_pre_auth.pl, so if we'd rather not have
the latter (as briefly discussed upthread) I can move the rest of it
over.

Thanks,
--Jacob


v7-0001-pgstat-report-in-earlier-with-STATE_STARTING.patch
Description: Binary data


v7-0002-Report-external-auth-calls-as-wait-events.patch
Description: Binary data


v7-0003-squash-Report-external-auth-calls-as-wait-events.patch
Description: Binary data

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Thu, Nov 7, 2024 at 4:38 PM Jacob Champion
 wrote:
> Oh... I think that alone is enough to change my mind; I neglected the
> effects of that little pgstat_report_appname() stinger...

(Note that application_name is not yet set at the site of the first
call, so I think the set-unset-set can't happen after all -- but I
didn't realize that before a lot of digging, which is further evidence
that I need to simplify...)

> I will plumb these down as far as I can.

While I work on breaking pgstat_bestart() apart, here is a v6 which
pushes down the "coarse" wait events. No changes to 0001 yet.

I violated the "one event name per call site" rule with
TranslateName(). The call pattern there is "call once to figure out
the buffer length, then call again to fill it in", and IMO that didn't
deserve differentiation. But if anyone objects, I'm happy to change it
(and I'd appreciate some name suggestions in that case).

While I was breaking apart the LDAP events, I noticed that
ldap_unbind() does a lot more than just dropping the connection, so
I've refactored things a bit more in order to wrap all those calls.
That is done separately in 0003, which I will fold into 0002 once I
have confirmation that it's not controversial to anyone.

Thanks!
--Jacob
1:  e755fdccf1 = 1:  e755fdccf1 pgstat: report in earlier with STATE_STARTING
2:  858e95f996 ! 2:  3f14df0308 Report external auth calls as wait events
@@ src/backend/libpq/auth.c: pg_SSPI_recvauth(Port *port)
  
free(tokenuser);
  
-   if (!port->hba->compat_realm)
-   {
--  int status = pg_SSPI_make_upn(accountname, 
sizeof(accountname),
--  
  domainname, sizeof(domainname),
--  
  port->hba->upn_username);
-+  int status;
+@@ src/backend/libpq/auth.c: pg_SSPI_make_upn(char *accountname,
+*/
+ 
+   samname = psprintf("%s\\%s", domainname, accountname);
 +
-+  pgstat_report_wait_start(WAIT_EVENT_SSPI_MAKE_UPN);
-+  status = pg_SSPI_make_upn(accountname, sizeof(accountname),
-+domainname, 
sizeof(domainname),
-+
port->hba->upn_username);
-+  pgstat_report_wait_end();
++  pgstat_report_wait_start(WAIT_EVENT_SSPI_TRANSLATE_NAME);
+   res = TranslateName(samname, NameSamCompatible, NameUserPrincipal,
+   NULL, &upnamesize);
++  pgstat_report_wait_end();
+ 
+   if ((!res && GetLastError() != ERROR_INSUFFICIENT_BUFFER)
+   || upnamesize == 0)
+@@ src/backend/libpq/auth.c: pg_SSPI_make_upn(char *accountname,
+   /* upnamesize includes the terminating NUL. */
+   upname = palloc(upnamesize);
+ 
++  pgstat_report_wait_start(WAIT_EVENT_SSPI_TRANSLATE_NAME);
+   res = TranslateName(samname, NameSamCompatible, NameUserPrincipal,
+   upname, &upnamesize);
++  pgstat_report_wait_end();
  
-   if (status != STATUS_OK)
-   /* Error already reported from pg_SSPI_make_upn */
+   pfree(samname);
+   if (res)
 @@ src/backend/libpq/auth.c: CheckPAMAuth(Port *port, const char *user, 
const char *password)
return STATUS_ERROR;
}
@@ src/backend/libpq/auth.c: CheckPAMAuth(Port *port, const char *user, 
const char
  
if (retval != PAM_SUCCESS)
{
-@@ src/backend/libpq/auth.c: CheckLDAPAuth(Port *port)
-   if (passwd == NULL)
-   return STATUS_EOF;  /* client wouldn't send 
password */
+@@ src/backend/libpq/auth.c: InitializeLDAPConnection(Port *port, LDAP 
**ldap)
+   }
  
--  if (InitializeLDAPConnection(port, &ldap) == STATUS_ERROR)
-+  pgstat_report_wait_start(WAIT_EVENT_LDAP_INITIALIZE);
-+  r = InitializeLDAPConnection(port, &ldap);
-+  pgstat_report_wait_end();
+   /* Look up a list of LDAP server hosts and port numbers 
*/
+-  if (ldap_domain2hostlist(domain, &hostlist))
++  pgstat_report_wait_start(WAIT_EVENT_LDAP_HOST_LOOKUP);
++  r = ldap_domain2hostlist(domain, &hostlist);
++  pgstat_report_wait_end();
 +
-+  if (r == STATUS_ERROR)
++  if (r)
+   {
+   ereport(LOG,
+   (errmsg("LDAP authentication 
could not find DNS SRV records for \"%s\"",
+@@ src/backend/libpq/auth.c: InitializeLDAPConnection(Port *port, LDAP 
**ldap)
+ 
+   if (port->hba->ldaptls)
{
-   /* Error message already sent

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Thu, Nov 7, 2024 at 2:56 PM Andres Freund  wrote:
> It does actually make things harder - what if somebody added a
> pgstat_report_activity() somewhere between the call? It would suddenly get
> lost after the second "initialization".  Actually, the proposed patch already
> has weird, externally visible, consequences - the application name is set,
> then suddenly becomes unset, then is set again.

Oh... I think that alone is enough to change my mind; I neglected the
effects of that little pgstat_report_appname() stinger...

> Additionally PGSTAT_BEGIN_WRITE_ACTIVITY() would already happen twice if you
> initialize twice...

Sure. I was just trying not to introduce that to _all_ backend code
paths, but it sounds like that's not a concern. (Plus, it turns out to
be four calls, due again to the application_name reporting...)

> That doesn't seem like a reason to just initialize twice to me. If you have
> one initialization step that properly initializes everything to a minimal
> default state, you then can have granular functions that set up the user,
> database, SSL, GSS information separately.

I will start work on that then (unless Michael has already beaten me to it?).

> But more importantly, because of not having nesting, adding one "coarse" "wait
> event" means that anyone adding a wait event at a finer grade suddenly needs
> to be aware of all the paths that could lead to the execution of the new
> code and change all of them to not use the wait event anymore. It imposes a
> tax on measuring actual "out of postgres" wait events.
>
> One very useful wait event would be for memory allocations that hit the
> kernel. Those can take a fairly long time, because they might need to write
> dirty buffers to disk before there is enough free memory. Now imagine that we
> redefine the system memory allocator (or just postgres') so that all memory
> allocations from the kernel use a wait event.  Now suddenly all that code that
> uses "coarse" wait events suddenly has a *rare* path - because most of the 
> time
> we can carve memory out of a larger OS level memory allocation - where wait
> events would be nested.

Okay, that makes a lot of sense. I will plumb these down as far as I can.

Thanks very much!

--Jacob

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Andres Freund]

Hi,

On 2024-11-07 14:29:18 -0800, Jacob Champion wrote:
> On Thu, Nov 7, 2024 at 1:37 PM Andres Freund  wrote:
> > > - the pre-auth step must always initialize the entire pgstat struct
> >
> > Correct. And that has to happen exactly once, not twice.
> 
> What goes wrong if it happens twice?

Primarily it's architecturally wrong. For no reason that I can see.

It does actually make things harder - what if somebody added a
pgstat_report_activity() somewhere between the call? It would suddenly get
lost after the second "initialization".  Actually, the proposed patch already
has weird, externally visible, consequences - the application name is set,
then suddenly becomes unset, then is set again.


> > > - two-step initialization requires two PGSTAT_BEGIN_WRITE_ACTIVITY()
> > > calls for _every_ backend
> >
> > That's fine - PGSTAT_BEGIN_WRITE_ACTIVITY() is *extremely* cheap on the 
> > write
> > side. That's the whole point of of the sequence-lock like mechanism.
> 
> Okay, cool. I'll retract that concern.

Additionally PGSTAT_BEGIN_WRITE_ACTIVITY() would already happen twice if you
initialize twice...


> > > - two-step initialization requires us to couple against the order that
> > > authentication information is being filled in (pre-auth, post-auth, or
> > > both)
> >
> > Not sure what you mean with this?
> 
> In other words: if we split it, people who make changes to the order
> that authentication information is determined during startup must know
> to keep an eye on this code as well. Whereas with the current
> patchset, the layers are decoupled and the order doesn't matter.
> Quoting from above:
> 
>   Finally, if we're okay with all of that, future maintainers need to be
>   careful about which fields get copied in the first (preauth) step, the
>   second step, or both. GSS, for example, can be set up during transport
>   negotiation (first step) or authentication (second step), so we have
>   to duplicate the logic there. SSL is currently first-step-only, I
>   think -- but are we sure we want to hardcode the assumption that cert
>   auth can't change any of those parameters after the transport has been
>   established? (I've been brainstorming ways we might use TLS 1.3's
>   post-handshake CertificateRequest, for example.)

That doesn't seem like a reason to just initialize twice to me. If you have
one initialization step that properly initializes everything to a minimal
default state, you then can have granular functions that set up the user,
database, SSL, GSS information separately.



> > If you increase the iteration count for whatever secret
> > "hashing" method to be very high, it's not a wait, it's just CPU
> > use.
> 
> I don't yet understand why this is a useful distinction to make. I
> understand that they are different, but what are the bad consequences
> if pg_stat_activity records a CPU busy wait in the same way it records
> an I/O wait -- as long as they're not nested?

Well, first, because you suddenly can't use wait events anymore to find waits.

But more importantly, because of not having nesting, adding one "coarse" "wait
event" means that anyone adding a wait event at a finer grade suddenly needs
to be aware of all the paths that could lead to the execution of the new
code and change all of them to not use the wait event anymore. It imposes a
tax on measuring actual "out of postgres" wait events.


> > My point is that you're redefining wait events to be "in some region of 
> > code"
> > and that once you start doing that, there's a lot of other places you could
> > suddenly use wait events.
> >
> > But wait events aren't actually suitable for that - they're a *single-depth*
> > mechanism, which means that if you start waiting, the prior wait event is
> > lost, and
> > a) the nested region isn't attributed to the parent while active
> > b) once the nested wait event is over, the parent isn't reset
> 
> I understand that they shouldn't be nested. But as long as they're
> not, isn't that fine? And if the concern is that they'll accidentally
> get nested, whether in this patch or in the future, can't we just
> programmatically assert that we haven't?

One very useful wait event would be for memory allocations that hit the
kernel. Those can take a fairly long time, because they might need to write
dirty buffers to disk before there is enough free memory. Now imagine that we
redefine the system memory allocator (or just postgres') so that all memory
allocations from the kernel use a wait event.  Now suddenly all that code that
uses "coarse" wait events suddenly has a *rare* path - because most of the time
we can carve memory out of a larger OS level memory allocation - where wait
events would be nested.

Greetings,

Andres Freund

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Thu, Nov 7, 2024 at 1:37 PM Andres Freund  wrote:
> > - the pre-auth step must always initialize the entire pgstat struct
>
> Correct. And that has to happen exactly once, not twice.

What goes wrong if it happens twice?

> > - two-step initialization requires two PGSTAT_BEGIN_WRITE_ACTIVITY()
> > calls for _every_ backend
>
> That's fine - PGSTAT_BEGIN_WRITE_ACTIVITY() is *extremely* cheap on the write
> side. That's the whole point of of the sequence-lock like mechanism.

Okay, cool. I'll retract that concern.

> > - two-step initialization requires us to couple against the order that
> > authentication information is being filled in (pre-auth, post-auth, or
> > both)
>
> Not sure what you mean with this?

In other words: if we split it, people who make changes to the order
that authentication information is determined during startup must know
to keep an eye on this code as well. Whereas with the current
patchset, the layers are decoupled and the order doesn't matter.
Quoting from above:

  Finally, if we're okay with all of that, future maintainers need to be
  careful about which fields get copied in the first (preauth) step, the
  second step, or both. GSS, for example, can be set up during transport
  negotiation (first step) or authentication (second step), so we have
  to duplicate the logic there. SSL is currently first-step-only, I
  think -- but are we sure we want to hardcode the assumption that cert
  auth can't change any of those parameters after the transport has been
  established? (I've been brainstorming ways we might use TLS 1.3's
  post-handshake CertificateRequest, for example.)

> If you increase the iteration count for whatever secret
> "hashing" method to be very high, it's not a wait, it's just CPU
> use.

I don't yet understand why this is a useful distinction to make. I
understand that they are different, but what are the bad consequences
if pg_stat_activity records a CPU busy wait in the same way it records
an I/O wait -- as long as they're not nested?

> My point is that you're redefining wait events to be "in some region of code"
> and that once you start doing that, there's a lot of other places you could
> suddenly use wait events.
>
> But wait events aren't actually suitable for that - they're a *single-depth*
> mechanism, which means that if you start waiting, the prior wait event is
> lost, and
> a) the nested region isn't attributed to the parent while active
> b) once the nested wait event is over, the parent isn't reset

I understand that they shouldn't be nested. But as long as they're
not, isn't that fine? And if the concern is that they'll accidentally
get nested, whether in this patch or in the future, can't we just
programmatically assert that we haven't?

Thanks,
--Jacob

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Andres Freund]

Hi,

On 2024-11-07 12:11:46 -0800, Jacob Champion wrote:
> On Thu, Nov 7, 2024 at 11:41 AM Andres Freund  wrote:
> > I think the patch should not be merged as-is. It's just too ugly and 
> > fragile.
> 
> Understood; I'm trying to find a way forward, and I'm pointing out
> that the alternatives I've tried seem to me to be _more_ fragile.
> 
> Are there any items in this list that you disagree with/are less
> concerned about?
> 
> - the pre-auth step must always initialize the entire pgstat struct

Correct. And that has to happen exactly once, not twice.


> - two-step initialization requires two PGSTAT_BEGIN_WRITE_ACTIVITY()
> calls for _every_ backend

That's fine - PGSTAT_BEGIN_WRITE_ACTIVITY() is *extremely* cheap on the write
side. That's the whole point of of the sequence-lock like mechanism.


> - two-step initialization requires us to couple against the order that
> authentication information is being filled in (pre-auth, post-auth, or
> both)

Not sure what you mean with this?


> > I think it might make more sense to use pgstat_report_activity() or such 
> > here,
> > rather than using wait events to describe something that's not a wait.
> 
> I'm not sure why you're saying these aren't waits. If pam_authenticate
> is capable of hanging for hours and bringing down a production system,
> is that not a "wait"?

It may or may not be. If you increase the iteration count for whatever secret
"hashing" method to be very high, it's not a wait, it's just CPU
use. Similarly, if you have a cpu expensive WHERE clause, that's not a
wait. But if you wait for network IO due to pam using ldap underneath or you
need to read toast values from disk, those are waits.


> > > I agree that would be amazing! I'm not about to tackle reliable
> > > interrupts for all of the current blocking auth code for v18, though.
> > > I'm just trying to make it observable when we do something that
> > > blocks.
> >
> > Well, with that justification we could end up adding wait events for large
> > swaths of code that might not actually ever wait.
> 
> If it were hypothetically useful to do so, would that be a problem?
> I'm trying not to propose things that aren't actually useful.

My point is that you're redefining wait events to be "in some region of code"
and that once you start doing that, there's a lot of other places you could
suddenly use wait events.

But wait events aren't actually suitable for that - they're a *single-depth*
mechanism, which means that if you start waiting, the prior wait event is
lost, and
a) the nested region isn't attributed to the parent while active
b) once the nested wait event is over, the parent isn't reset

Greetings,

Andres Freund

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Thu, Nov 7, 2024 at 11:41 AM Andres Freund  wrote:
> I think the patch should not be merged as-is. It's just too ugly and fragile.

Understood; I'm trying to find a way forward, and I'm pointing out
that the alternatives I've tried seem to me to be _more_ fragile.

Are there any items in this list that you disagree with/are less
concerned about?

- the pre-auth step must always initialize the entire pgstat struct
- two-step initialization requires two PGSTAT_BEGIN_WRITE_ACTIVITY()
calls for _every_ backend
- two-step initialization requires us to couple against the order that
authentication information is being filled in (pre-auth, post-auth, or
both)

> I think it might make more sense to use pgstat_report_activity() or such here,
> rather than using wait events to describe something that's not a wait.

I'm not sure why you're saying these aren't waits. If pam_authenticate
is capable of hanging for hours and bringing down a production system,
is that not a "wait"?

> > I agree that would be amazing! I'm not about to tackle reliable
> > interrupts for all of the current blocking auth code for v18, though.
> > I'm just trying to make it observable when we do something that
> > blocks.
>
> Well, with that justification we could end up adding wait events for large
> swaths of code that might not actually ever wait.

If it were hypothetically useful to do so, would that be a problem?
I'm trying not to propose things that aren't actually useful.

--Jacob

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Andres Freund]

Hi,

On 2024-11-07 10:44:25 -0800, Jacob Champion wrote:
> On Thu, Nov 7, 2024 at 10:12 AM Andres Freund  wrote:
> > I don't understand why the pgstat_bestart()/pgstat_bestart_pre_auth() split
> > makes sense. The latter is going to redo most of the work that the former
> > did. What's the point of that?
> >
> > Why not have a new function that initializes just the missing additional
> > information? Or for that matter, why not move most of what pgstat_bestart()
> > does into pgstat_beinit()?
> 
> I talk about that up above [1]. I agree that this is all complicated
> and fragile, but at the moment, I think splitting things apart is not
> going to reduce the complexity in any way. I'm all ears for a
> different approach, though (and it sounds like Michael is taking a
> stab at it too).

I think the patch should not be merged as-is. It's just too ugly and fragile.


> > This doesn't really seem like it's actually using wait events to describe
> > waits. The new wait events cover stuff like memory allocations etc, see
> > e.g. pg_SSPI_make_upn().
> 
> I've also asked about the "scope" of the waits in the OP [2]. I can
> move them downwards in the stack, if you'd prefer.

Well, right now they're just not actually wait events, so yes, they'd need to
be moved down.

I think it might make more sense to use pgstat_report_activity() or such here,
rather than using wait events to describe something that's not a wait.


> > This isn't just pedantry - all the relevant code really needs to be 
> > rewritten
> > to allow the blocking to happen in an interruptible way, otherwise
> > authentication timeout etc can't realiably work. Once that's done you can
> > actually define useful wait events too.
> 
> I agree that would be amazing! I'm not about to tackle reliable
> interrupts for all of the current blocking auth code for v18, though.
> I'm just trying to make it observable when we do something that
> blocks.

Well, with that justification we could end up adding wait events for large
swaths of code that might not actually ever wait.

Greetings,

Andres Freund

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Thu, Nov 7, 2024 at 10:12 AM Andres Freund  wrote:
> I don't understand why the pgstat_bestart()/pgstat_bestart_pre_auth() split
> makes sense. The latter is going to redo most of the work that the former
> did. What's the point of that?
>
> Why not have a new function that initializes just the missing additional
> information? Or for that matter, why not move most of what pgstat_bestart()
> does into pgstat_beinit()?

I talk about that up above [1]. I agree that this is all complicated
and fragile, but at the moment, I think splitting things apart is not
going to reduce the complexity in any way. I'm all ears for a
different approach, though (and it sounds like Michael is taking a
stab at it too).

> This doesn't really seem like it's actually using wait events to describe
> waits. The new wait events cover stuff like memory allocations etc, see
> e.g. pg_SSPI_make_upn().

I've also asked about the "scope" of the waits in the OP [2]. I can
move them downwards in the stack, if you'd prefer.

All of these are intended to cover parts of the code that can actually
hang, but for things like SSPI I'm just working off of inspection and
Win32 documentation. So if it's not actually true that some of these
call points can hang, let me know and I can remove them. (For the
particular example you called out, I'm just trying to cover both calls
to TranslateName() in a maintainable place. The documentation says
"TranslateName fails if it cannot bind to Active Directory on a domain
controller." which seemed pretty wait-worthy to me.)

> This isn't just pedantry - all the relevant code really needs to be rewritten
> to allow the blocking to happen in an interruptible way, otherwise
> authentication timeout etc can't realiably work. Once that's done you can
> actually define useful wait events too.

I agree that would be amazing! I'm not about to tackle reliable
interrupts for all of the current blocking auth code for v18, though.
I'm just trying to make it observable when we do something that
blocks.

--Jacob

[1] 
https://www.postgresql.org/message-id/CAOYmi%2BkLzSWrDHZbJg8bWZ94oP_K98mkoEvetgupOBVoy5H_ag%40mail.gmail.com
[2] 
https://www.postgresql.org/message-id/CAOYmi%2B%3D60deN20WDyCoHCiecgivJxr%3D98s7s7-C8SkXwrCfHXg%40mail.gmail.com

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Andres Freund]

Hi,

On 2024-11-07 09:20:24 -0800, Jacob Champion wrote:
> From e755fdccf16cb4fcd3036e1209291750ffecd261 Mon Sep 17 00:00:00 2001
> From: Jacob Champion 
> Date: Fri, 3 May 2024 15:54:58 -0700
> Subject: [PATCH v5 1/2] pgstat: report in earlier with STATE_STARTING
> 
> Add pgstat_bestart_pre_auth(), which reports a 'starting' state while
> waiting for backend initialization and client authentication to
> complete. Since we hold a transaction open for a good amount of that,
> and some authentication methods call out to external systems, having a
> pg_stat_activity entry helps DBAs debug when things go badly wrong.

I don't understand why the pgstat_bestart()/pgstat_bestart_pre_auth() split
makes sense. The latter is going to redo most of the work that the former
did. What's the point of that?

Why not have a new function that initializes just the missing additional
information? Or for that matter, why not move most of what pgstat_bestart()
does into pgstat_beinit()?

As-is I'm -1 on this patch, it makes something complicated and fragile even
more so.


> From 858e95f996589461e2840047fa35675b6f96e46d Mon Sep 17 00:00:00 2001
> From: Jacob Champion 
> Date: Fri, 3 May 2024 15:58:23 -0700
> Subject: [PATCH v5 2/2] Report external auth calls as wait events
> 
> Introduce a new "Auth" wait class for various external authentication
> systems, to make it obvious what's going wrong if one of those systems
> hangs. Each new wait event is unique in order to more easily pinpoint
> problematic locations in the code.

This doesn't really seem like it's actually using wait events to describe
waits. The new wait events cover stuff like memory allocations etc, see
e.g. pg_SSPI_make_upn().

I have some sympathy for that, it'd be nice if we had some generic way to
describe what code is doing - but it doesn't really seem good to use wait
events for that. Right now a backend reporting a wait allows to conclude that
a backend isn't running postgres code and busy or blocked outside of postgres
- but that's not true anymore if you have wait event cover generic things like
memory allocations (or even various library functions).

This isn't just pedantry - all the relevant code really needs to be rewritten
to allow the blocking to happen in an interruptible way, otherwise
authentication timeout etc can't realiably work. Once that's done you can
actually define useful wait events too.

Greetings,

Andres Freund

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Tue, Nov 5, 2024 at 9:48 PM Michael Paquier  wrote:
> +PAM_ACCT_MGMT  "Waiting for the local PAM service to validate the user 
> account."
> +PAM_AUTHENTICATE   "Waiting for the local PAM service to authenticate 
> the user."
>
> Is "local" required for both?  Perhaps just use "the PAM service".

Done in v5.

> +SSPI_LOOKUP_ACCOUNT_SID"Waiting for Windows to find the user's 
> account SID."
>
> We don't document SID in doc/.  So perhaps this should add be "SID
> (system identifier)".

I switched to "user's security identifier", which seems to be
search-engine-friendly.

On Wed, Nov 6, 2024 at 7:15 PM Michael Paquier  wrote:
> 0002 has been done as ba08edb06545 after adding a bit more
> documentation that was missing.  0001 as well with 70291a3c66ec.

Thanks!

> Note that 0003 is lacking an EXTRA_INSTALL in the Makefile of
> src/test/authentication/, or the test would fail if doing for example
> a `make check` in this path.
>
> The following nit is also required in the script for installcheck, to
> skip the test if the module is not installed:
> if (!$node->check_extension('injection_points'))
> {
> plan skip_all => 'Extension injection_points not installed';
> }

Fixed.

> 007_injection_points.pl is a name too generic as it could apply in a
> lot more places, without being linked to injection points.  How about
> something like 007_pre_auth.pl?

Renamed.

Thanks!
--Jacob
1:  64289b97e5 < -:  -- BackgroundPsql: handle empty query results
2:  18a9531a25 < -:  -- Test::Cluster: let background_psql() work 
asynchronously
3:  c8071f91d8 ! 1:  e755fdccf1 pgstat: report in earlier with STATE_STARTING
@@ src/test/authentication/Makefile: subdir = src/test/authentication
  top_builddir = ../../..
  include $(top_builddir)/src/Makefile.global
  
++EXTRA_INSTALL = src/test/modules/injection_points
++
 +export enable_injection_points
 +
  check:
@@ src/test/authentication/meson.build: tests += {
't/004_file_inclusion.pl',
't/005_sspi.pl',
't/006_login_trigger.pl',
-+  't/007_injection_points.pl',
++  't/007_pre_auth.pl',
  ],
},
  }
 
- ## src/test/authentication/t/007_injection_points.pl (new) ##
+ ## src/test/authentication/t/007_pre_auth.pl (new) ##
 @@
 +
 +# Copyright (c) 2021-2024, PostgreSQL Global Development Group
 +
-+# Tests requiring injection_points functionality, to check on behavior 
that
-+# would otherwise race against authentication.
++# Tests for connection behavior prior to authentication.
 +
 +use strict;
 +use warnings FATAL => 'all';
@@ src/test/authentication/t/007_injection_points.pl (new)
 +]);
 +
 +$node->start;
++
++# Check if the extension injection_points is available, as it may be
++# possible that this script is run with installcheck, where the module
++# would not be installed by default.
++if (!$node->check_extension('injection_points'))
++{
++  plan skip_all => 'Extension injection_points not installed';
++}
++
 +$node->safe_psql('postgres', 'CREATE EXTENSION injection_points');
 +
 +# Connect to the server and inject a waitpoint.
4:  d14b97cb77 ! 2:  858e95f996 Report external auth calls as wait events
@@ src/backend/utils/activity/wait_event_names.txt: XACT_GROUP_UPDATE   
"Waiting for
 +LDAP_BIND_FOR_SEARCH  "Waiting for an LDAP bind operation to search 
the directory."
 +LDAP_INITIALIZE   "Waiting to initialize an LDAP connection."
 +LDAP_SEARCH   "Waiting for an LDAP search operation to complete."
-+PAM_ACCT_MGMT "Waiting for the local PAM service to validate the user 
account."
-+PAM_AUTHENTICATE  "Waiting for the local PAM service to authenticate the 
user."
++PAM_ACCT_MGMT "Waiting for the PAM service to validate the user 
account."
++PAM_AUTHENTICATE  "Waiting for the PAM service to authenticate the user."
 +RADIUS_TRANSACTION"Waiting for a RADIUS transaction to complete."
 +SSPI_ACCEPT_SECURITY_CONTEXT  "Waiting for a Windows security 
provider to accept the client's SSPI token."
 +SSPI_ACQUIRE_CREDENTIALS_HANDLE   "Waiting for a Windows security 
provider to acquire server credentials for SSPI."
-+SSPI_LOOKUP_ACCOUNT_SID   "Waiting for Windows to find the user's account 
SID."
++SSPI_LOOKUP_ACCOUNT_SID   "Waiting for Windows to find the user's 
security identifier."
 +SSPI_MAKE_UPN "Waiting for Windows to translate a Kerberos UPN."
 +
 +ABI_compatibility:


v5-0001-pgstat-report-in-earlier-with-STATE_STARTING.patch
Description: Binary data


v5-0002-Report-external-auth-calls-as-wait-events.patch
Description: Binary data

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Michael Paquier]

On Wed, Nov 06, 2024 at 02:48:31PM +0900, Michael Paquier wrote:
> I'm OK with 0002 to add the wait parameter to BackgroundPsql and be
> able to take some actions until a manual wait_connect().  I'll go do
> this one.  Also perhaps 0001 while on it but I am a bit puzzled by the
> removal of the three ok() calls in 037_invalid_database.pl.

0002 has been done as ba08edb06545 after adding a bit more
documentation that was missing.  0001 as well with 70291a3c66ec.  The
original expectation of 037_invalid_database.pl with the banner data
expected in the output was interesting..

Note that 0003 is lacking an EXTRA_INSTALL in the Makefile of
src/test/authentication/, or the test would fail if doing for example
a `make check` in this path.

The following nit is also required in the script for installcheck, to
skip the test if the module is not installed:
if (!$node->check_extension('injection_points'))
{
plan skip_all => 'Extension injection_points not installed';
}

See src/test/modules/test_misc/t/005_timeouts.pl as one example.  (I
know, these are tricky to know about..)

007_injection_points.pl is a name too generic as it could apply in a
lot more places, without being linked to injection points.  How about
something like 007_pre_auth.pl?
--
Michael


signature.asc
Description: PGP signature

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Michael Paquier]

On Fri, Nov 01, 2024 at 02:47:38PM -0700, Jacob Champion wrote:
> On Sun, Sep 1, 2024 at 5:10 PM Michael Paquier  wrote:
>> Could it be more transparent to use a "startup" or
>> "starting"" state instead that gets also used by pgstat_bestart() in
>> the case of the patch where !pre_auth?
> 
> Done. (I've used "starting".)

0003 looks much cleaner this way.

> Added a new "Auth" class (to cover both authn and authz during
> startup), plus documentation.

+PAM_ACCT_MGMT  "Waiting for the local PAM service to validate the user 
account."
+PAM_AUTHENTICATE   "Waiting for the local PAM service to authenticate the 
user."

Is "local" required for both?  Perhaps just use "the PAM service".

+SSPI_LOOKUP_ACCOUNT_SID"Waiting for Windows to find the user's account 
SID."

We don't document SID in doc/.  So perhaps this should add be "SID
(system identifier)".

+SSPI_MAKE_UPN  "Waiting for Windows to translate a Kerberos UPN."

UPN is mentioned once in doc/ already.  Perhaps this one is OK left
alone..

Except for these tweaks 0004 looks OK.

> The more I look at this, the more uneasy I feel about the goal. Best I
> can tell, the pre-auth step can't ignore irrelevant fields, because
> they may contain junk from the previous owner of the shared memory. So
> if we want to optimize, we can only change the second step to skip
> fields that were already filled in by the pre-auth step.
> 
> That has its own problems: not every backend type uses the pre-auth
> step in the current patch. Which means a bunch of backends that don't
> benefit from the two-step initialization nevertheless have to either
> do two PGSTAT_BEGIN_WRITE_ACTIVITY() dances in a row, or else we
> duplicate a bunch of the logic to make sure they maintain the same
> efficient code path as before.
> 
> Finally, if we're okay with all of that, future maintainers need to be
> careful about which fields get copied in the first (preauth) step, the
> second step, or both. GSS, for example, can be set up during transport
> negotiation (first step) or authentication (second step), so we have
> to duplicate the logic there. SSL is currently first-step-only, I
> think -- but are we sure we want to hardcode the assumption that cert
> auth can't change any of those parameters after the transport has been
> established? (I've been brainstorming ways we might use TLS 1.3's
> post-handshake CertificateRequest, for example.)

The future field maintenance and what one would need to think more
about in the future is a good point.  I still feel slightly uneasy
about the way 0003 is shaped with its new pgstat_bestart_pre_auth(),
but I think that I'm just going to put my hands down on 0003 and see
if I can finish with something I'm a bit more comfortable with.  Let's
see..

> So before I commit to this path, I just want to double-check that all
> of the above sounds good and non-controversial. :)

The goal of the thread is sound.

I'm OK with 0002 to add the wait parameter to BackgroundPsql and be
able to take some actions until a manual wait_connect().  I'll go do
this one.  Also perhaps 0001 while on it but I am a bit puzzled by the
removal of the three ok() calls in 037_invalid_database.pl.
--
Michael


signature.asc
Description: PGP signature

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

Hi all,

Here's a v4, with a separate wait event for each location. (I could
use some eyes on the specific phrasing I've chosen for each one.)

On Sun, Sep 1, 2024 at 5:10 PM Michael Paquier  wrote:
> Could it be more transparent to use a "startup" or
> "starting"" state instead that gets also used by pgstat_bestart() in
> the case of the patch where !pre_auth?

Done. (I've used "starting".)

On Mon, Sep 9, 2024 at 10:30 PM Michael Paquier  wrote:
> A new category would be more adapted.  IPC is not adapted because are
> not waiting for another server process.  Perhaps just use a new
> "Authentication" class, as in "The server is waiting for an
> authentication operation to complete"?

Added a new "Auth" class (to cover both authn and authz during
startup), plus documentation.

On Wed, Sep 11, 2024 at 4:42 PM Michael Paquier  wrote:
> Setting up twice the structure as the patch proposes is kind of
> a weird concept, but it feels to me that we should split that and set
> the fields in the pre-auth step and ignore the irrelevant ones, then
> complete the rest in a second step.

The more I look at this, the more uneasy I feel about the goal. Best I
can tell, the pre-auth step can't ignore irrelevant fields, because
they may contain junk from the previous owner of the shared memory. So
if we want to optimize, we can only change the second step to skip
fields that were already filled in by the pre-auth step.

That has its own problems: not every backend type uses the pre-auth
step in the current patch. Which means a bunch of backends that don't
benefit from the two-step initialization nevertheless have to either
do two PGSTAT_BEGIN_WRITE_ACTIVITY() dances in a row, or else we
duplicate a bunch of the logic to make sure they maintain the same
efficient code path as before.

Finally, if we're okay with all of that, future maintainers need to be
careful about which fields get copied in the first (preauth) step, the
second step, or both. GSS, for example, can be set up during transport
negotiation (first step) or authentication (second step), so we have
to duplicate the logic there. SSL is currently first-step-only, I
think -- but are we sure we want to hardcode the assumption that cert
auth can't change any of those parameters after the transport has been
established? (I've been brainstorming ways we might use TLS 1.3's
post-handshake CertificateRequest, for example.)

So before I commit to this path, I just want to double-check that all
of the above sounds good and non-controversial. :)

--

In the meantime, is anyone willing and able to commit 0001 and/or 0002?

Thanks!
--Jacob
1:  8f9315949e = 1:  64289b97e5 BackgroundPsql: handle empty query results
2:  7f404f5ee8 ! 2:  18a9531a25 Test::Cluster: let background_psql() work 
asynchronously
@@ src/test/perl/PostgreSQL/Test/Cluster.pm: connection.
  
  =cut
 @@ src/test/perl/PostgreSQL/Test/Cluster.pm: sub background_psql
-   '-');
+   '-XAtq', '-d', $psql_connstr, '-f', '-');
  
$params{on_error_stop} = 1 unless defined $params{on_error_stop};
 +  $params{wait} = 1 unless defined $params{wait};
3:  a7a7551d09 ! 3:  c8071f91d8 pgstat: report in earlier with 
STATE_AUTHENTICATING
@@ Metadata
 Author: Jacob Champion 
 
  ## Commit message ##
-pgstat: report in earlier with STATE_AUTHENTICATING
+pgstat: report in earlier with STATE_STARTING
 
-Add pgstat_bestart_pre_auth(), which reports an 'authenticating' state
-while waiting for backend initialization and client authentication to
+Add pgstat_bestart_pre_auth(), which reports a 'starting' state while
+waiting for backend initialization and client authentication to
 complete. Since we hold a transaction open for a good amount of that,
 and some authentication methods call out to external systems, having a
 pg_stat_activity entry helps DBAs debug when things go badly wrong.
 
+ ## doc/src/sgml/monitoring.sgml ##
+@@ doc/src/sgml/monitoring.sgml: postgres   27093  0.0  0.0  30096  2752 ? 
   Ss   11:34   0:00 postgres: ser
+Current overall state of this backend.
+Possible values are:
+
++
++ 
++  starting: The backend is in initial startup. 
Client
++  authentication is performed during this phase.
++ 
++
+ 
+ 
+   active: The backend is executing a query.
+
  ## src/backend/utils/activity/backend_status.c ##
 @@ src/backend/utils/activity/backend_status.c: static int 
localNumBackends = 0;
  static MemoryContext backendStatusSnapContext;
@@ src/backend/utils/activity/backend_status.c: pgstat_bestart(void)
  #endif
  
 -  lbeentry.st_state = STATE_UNDEFINED;
-+  lbeentry.st_state = pre_auth ? STATE_AUTHENTICATING : STATE_UNDEFINED;
++  lbeentry.st_state = pre_auth ? STATE_START

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Noah Misch]

On Wed, Sep 11, 2024 at 09:00:33AM -0400, Robert Haas wrote:
> On Tue, Sep 10, 2024 at 4:58 PM Noah Misch  wrote:
> > ... a rule of "each wait event appears in one
> > pgstat_report_wait_start()" would be a rule I don't want.
> 
> As the original committer of the wait event stuff, I intended for the
> rule that you do not want to be the actual rule. However, I see that I
> didn't spell that out anywhere in the commit message, or the commit
> itself.
> 
> > I see this level of fine-grained naming
> > as making the event name a sort of stable proxy for FILE:LINE.  I'd value
> > exposing such a proxy, all else being equal, but I don't think wait event
> > names like AuthLdapBindLdapbinddn/AuthLdapBindUser are the right way.  Wait
> > event names should be more independent of today's code-level details.
> 
> I don't agree with that. One of the most difficult parts of supporting
> PostgreSQL, in my experience, is that it's often very difficult to
> find out what has gone wrong when a system starts behaving badly. It
> is often necessary to ask customers to install a debugger and do stuff
> with it, or give them an instrumented build, in order to determine the
> root cause of a problem that in some cases is not even particularly
> complicated. While needing to refer to specific source code details
> may not be a common experience for the typical end user, it is
> extremely common for me. This problem commonly arises with error
> messages

That is a problem.  Half the time, error verbosity doesn't disambiguate enough
for me, and I need backtrace_functions.  I now find it hard to believe how
long we coped without backtrace_functions.

I withdraw the objection to "each wait event appears in one
pgstat_report_wait_start()".

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Michael Paquier]

On Wed, Sep 11, 2024 at 02:29:49PM -0700, Jacob Champion wrote:
> On Mon, Sep 9, 2024 at 10:30 PM Michael Paquier  wrote:
>> No.  My question was about splitting pgstat_bestart() and
>> pgstat_bestart_pre_auth() in a cleaner way, because authenticated
>> connections finish by calling both, meaning that we do twice the same
>> setup for backend entries depending on the authentication path taken.
>> That seems like a waste.
> 
> I can try to separate them out. I'm a little wary of messing with the
> CRITICAL_SECTION guarantees, though. I thought the idea was that you
> filled in the entire struct to prevent tearing. (If I've misunderstood
> that, please let me know :D)

Hm, yeah.  We surely should be careful about the consequences of that.
Setting up twice the structure as the patch proposes is kind of
a weird concept, but it feels to me that we should split that and set
the fields in the pre-auth step and ignore the irrelevant ones, then
complete the rest in a second step.  We are going to do that anyway if
we want to be able to have backend entries earlier in the
authentication phase.

>> Couldn't it be better to have a one-one mapping
>> instead, adding twelve entries in wait_event_names.txt?
> 
> (I have no strong opinions on this myself, but while the debate is
> ongoing, I'll work on a version of the patch with more detailed wait
> events. It's easy to collapse them again if that gets the most votes.)

Thanks.  Robert is arguing upthread about more granularity, which is
also what I understand is the original intention of the wait events.
Noah has a different view.  Let's see where it goes but I've given my
opinion.

> I can test for specific contents of the entry, if you'd like. My
> primary goal was to test that an entry shows up if that part of the
> code hangs. I think a regression would otherwise go completely
> unnoticed.

Perhaps that would be useful, not sure.  Based on my first
impressions, I'd tend to say no to these extra test cycles, but I'm
okay to be proved wrong, as well.
--
Michael


signature.asc
Description: PGP signature

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Mon, Sep 9, 2024 at 10:30 PM Michael Paquier  wrote:
> No.  My question was about splitting pgstat_bestart() and
> pgstat_bestart_pre_auth() in a cleaner way, because authenticated
> connections finish by calling both, meaning that we do twice the same
> setup for backend entries depending on the authentication path taken.
> That seems like a waste.

I can try to separate them out. I'm a little wary of messing with the
CRITICAL_SECTION guarantees, though. I thought the idea was that you
filled in the entire struct to prevent tearing. (If I've misunderstood
that, please let me know :D)

> Perhaps just use a new
> "Authentication" class, as in "The server is waiting for an
> authentication operation to complete"?

Sounds good.

> Couldn't it be better to have a one-one mapping
> instead, adding twelve entries in wait_event_names.txt?

(I have no strong opinions on this myself, but while the debate is
ongoing, I'll work on a version of the patch with more detailed wait
events. It's easy to collapse them again if that gets the most votes.)

> I am not really on board with the test based on injection points
> proposed, though.  It checks that the "authenticating" flag is set in
> pg_stat_activity, but it does nothing else.  That seems limited.  Or
> are you planning for more?

I can test for specific contents of the entry, if you'd like. My
primary goal was to test that an entry shows up if that part of the
code hangs. I think a regression would otherwise go completely
unnoticed.

Thanks!
--Jacob

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Robert Haas]

On Tue, Sep 10, 2024 at 4:58 PM Noah Misch  wrote:
> ... a rule of "each wait event appears in one
> pgstat_report_wait_start()" would be a rule I don't want.

As the original committer of the wait event stuff, I intended for the
rule that you do not want to be the actual rule. However, I see that I
didn't spell that out anywhere in the commit message, or the commit
itself.

> I see this level of fine-grained naming
> as making the event name a sort of stable proxy for FILE:LINE.  I'd value
> exposing such a proxy, all else being equal, but I don't think wait event
> names like AuthLdapBindLdapbinddn/AuthLdapBindUser are the right way.  Wait
> event names should be more independent of today's code-level details.

I don't agree with that. One of the most difficult parts of supporting
PostgreSQL, in my experience, is that it's often very difficult to
find out what has gone wrong when a system starts behaving badly. It
is often necessary to ask customers to install a debugger and do stuff
with it, or give them an instrumented build, in order to determine the
root cause of a problem that in some cases is not even particularly
complicated. While needing to refer to specific source code details
may not be a common experience for the typical end user, it is
extremely common for me. This problem commonly arises with error
messages, because we have lots of error messages that are exactly the
same, although thankfully it has become less common due to "could not
find tuple for THINGY %u" no longer being a message that no longer
typically reaches users. But even when someone has a complaint about
an error message and there are multiple instances of that error
message, I know that:

(1) I can ask them to set the error verbosity to verbose. I don't have
that option for wait events.

(2) The primary function of the error message is to be understandable
to the user, which means that it needs to be written in plain English.
The primary function of a wait event is to make it possible to
understand the behavior of the system and troubleshoot problems, and
it becomes much less effective as soon as it starts saying that thing
A and thing B are so similar that nobody will ever care about the
distinction. It is very hard to be certain of that. When somebody
reports that they've got a whole bunch of wait events on some wait
event that nobody has ever complained about before, I want to go look
at the code in that specific place and try to figure out what's
happening. If I have to start imagining possible scenarios based on 2
or more call sites, or if I have to start by getting them to install a
modified build with those properly split apart and trying to reproduce
the problem, it's a lot harder.

In my experience, the number of distinct wait events that a particular
installation experiences is rarely very large. It is probably measured
in dozens. A user who wishes to disregard the distinction between
similarly-named wait events won't find it prohibitively difficult to
look over the list of all the wait events they ever see and decide
which ones they'd like to merge for reporting purposes. But a user who
really needs things separated out and finds that they aren't is simply
out of luck.

-- 
Robert Haas
EDB: http://www.enterprisedb.com

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Michael Paquier]

On Tue, Sep 10, 2024 at 01:58:50PM -0700, Noah Misch wrote:
> On Tue, Sep 10, 2024 at 02:51:23PM -0400, Robert Haas wrote:
>> I think unique names are a good idea. If a user doesn't care about the
>> difference between sdgjsA and sdjgsB, they can easily ignore the
>> trailing suffix, and IME, people typically do that without really
>> stopping to think about it. If on the other hand the two are lumped
>> together as sdjgs and a user needs to distinguish them, they can't. So
>> I see unique names as having much more upside than downside.
> 
> I agree a person can ignore the distinction, but that requires the person to
> be consuming the raw event list.  It's reasonable to tell your monitoring tool
> to give you the top N wait events.  Individual AuthnLdap* events may all miss
> the cut even though their aggregate would have made the cut.  Before you know
> to teach that monitoring tool to group AuthnLdap* together, it won't show you
> any of those names.

That's a fair point.  I use a bunch of aggregates with group bys for
any monitoring queries looking for event point patterns.  In my
experience, when dealing with enough connections, patterns show up
anyway even if there is noise because some of the events that I was
looking for are rather short-term, like a sync events interleaving
with locks  storing an average of the events into a secondary table
with some INSERT SELECT.

> I felt commit c789f0f also chose sub-optimally in this respect, particularly
> with the DblinkGetConnect/DblinkConnect pair.  I didn't feel strongly enough
> to complain at the time, but a rule of "each wait event appears in one
> pgstat_report_wait_start()" would be a rule I don't want.  One needs
> familiarity with the dblink implementation internals to grasp the
> DblinkGetConnect/DblinkConnect distinction, and a plausible refactor of dblink
> would make those names cease to fit.  I see this level of fine-grained naming
> as making the event name a sort of stable proxy for FILE:LINE.  I'd value
> exposing such a proxy, all else being equal, but I don't think wait event
> names like AuthLdapBindLdapbinddn/AuthLdapBindUser are the right way.  Wait
> event names should be more independent of today's code-level details.

Depends.  I'd rather choose more granularity to know exactly which
part of the code I am dealing with, especially in the case of this
thread where these are embedded around external function calls.  If,
for example, one notices that a stack of pg_stat_activity scans are
complaining about a specific step in the authentication process, it is
going to offer a much better hint than having to guess which part of
the authentication step is slow, like in LDAP.

Wait event additions are also kind of cheap in terms of maintenance in
core, creating a new translation cost.  So I also think there are more
upsides to be wilder here with more points and more granularity.
--
Michael


signature.asc
Description: PGP signature

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Noah Misch]

On Tue, Sep 10, 2024 at 02:51:23PM -0400, Robert Haas wrote:
> On Tue, Sep 10, 2024 at 1:27 PM Noah Misch  wrote:
> > On Tue, Sep 10, 2024 at 02:29:57PM +0900, Michael Paquier wrote:
> > > You are adding twelve event points with only 5
> > > new wait names.  Couldn't it be better to have a one-one mapping
> > > instead, adding twelve entries in wait_event_names.txt?
> >
> > No, I think the patch's level of detail is better.  One shouldn't expect the
> > two ldap_simple_bind_s() calls to have different-enough performance
> > characteristics to justify exposing that level of detail to the DBA.
> > ldap_search_s() and InitializeLDAPConnection() differ more, but the DBA 
> > mostly
> > just needs to know the scale of their LDAP responsiveness problem.
> >
> > (Someday, it might be good to expose the file:line and/or backtrace 
> > associated
> > with a wait, like we do for ereport().  As a way to satisfy rare needs for
> > more detail, I'd prefer that over giving every pgstat_report_wait_start() a
> > different name.)
> 
> I think unique names are a good idea. If a user doesn't care about the
> difference between sdgjsA and sdjgsB, they can easily ignore the
> trailing suffix, and IME, people typically do that without really
> stopping to think about it. If on the other hand the two are lumped
> together as sdjgs and a user needs to distinguish them, they can't. So
> I see unique names as having much more upside than downside.

I agree a person can ignore the distinction, but that requires the person to
be consuming the raw event list.  It's reasonable to tell your monitoring tool
to give you the top N wait events.  Individual AuthnLdap* events may all miss
the cut even though their aggregate would have made the cut.  Before you know
to teach that monitoring tool to group AuthnLdap* together, it won't show you
any of those names.

I felt commit c789f0f also chose sub-optimally in this respect, particularly
with the DblinkGetConnect/DblinkConnect pair.  I didn't feel strongly enough
to complain at the time, but a rule of "each wait event appears in one
pgstat_report_wait_start()" would be a rule I don't want.  One needs
familiarity with the dblink implementation internals to grasp the
DblinkGetConnect/DblinkConnect distinction, and a plausible refactor of dblink
would make those names cease to fit.  I see this level of fine-grained naming
as making the event name a sort of stable proxy for FILE:LINE.  I'd value
exposing such a proxy, all else being equal, but I don't think wait event
names like AuthLdapBindLdapbinddn/AuthLdapBindUser are the right way.  Wait
event names should be more independent of today's code-level details.

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Robert Haas]

On Tue, Sep 10, 2024 at 1:27 PM Noah Misch  wrote:
> On Tue, Sep 10, 2024 at 02:29:57PM +0900, Michael Paquier wrote:
> > You are adding twelve event points with only 5
> > new wait names.  Couldn't it be better to have a one-one mapping
> > instead, adding twelve entries in wait_event_names.txt?
>
> No, I think the patch's level of detail is better.  One shouldn't expect the
> two ldap_simple_bind_s() calls to have different-enough performance
> characteristics to justify exposing that level of detail to the DBA.
> ldap_search_s() and InitializeLDAPConnection() differ more, but the DBA mostly
> just needs to know the scale of their LDAP responsiveness problem.
>
> (Someday, it might be good to expose the file:line and/or backtrace associated
> with a wait, like we do for ereport().  As a way to satisfy rare needs for
> more detail, I'd prefer that over giving every pgstat_report_wait_start() a
> different name.)

I think unique names are a good idea. If a user doesn't care about the
difference between sdgjsA and sdjgsB, they can easily ignore the
trailing suffix, and IME, people typically do that without really
stopping to think about it. If on the other hand the two are lumped
together as sdjgs and a user needs to distinguish them, they can't. So
I see unique names as having much more upside than downside.

-- 
Robert Haas
EDB: http://www.enterprisedb.com

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Noah Misch]

On Tue, Sep 10, 2024 at 02:29:57PM +0900, Michael Paquier wrote:
> You are adding twelve event points with only 5
> new wait names.  Couldn't it be better to have a one-one mapping
> instead, adding twelve entries in wait_event_names.txt?

No, I think the patch's level of detail is better.  One shouldn't expect the
two ldap_simple_bind_s() calls to have different-enough performance
characteristics to justify exposing that level of detail to the DBA.
ldap_search_s() and InitializeLDAPConnection() differ more, but the DBA mostly
just needs to know the scale of their LDAP responsiveness problem.

(Someday, it might be good to expose the file:line and/or backtrace associated
with a wait, like we do for ereport().  As a way to satisfy rare needs for
more detail, I'd prefer that over giving every pgstat_report_wait_start() a
different name.)

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Michael Paquier]

On Tue, Sep 03, 2024 at 02:47:57PM -0700, Jacob Champion wrote:
> On Sun, Sep 1, 2024 at 5:10 PM Michael Paquier  wrote:
>> that gets also used by pgstat_bestart() in
>> the case of the patch where !pre_auth?
> 
> To clarify, do you want me to just add the new boolean directly to
> pgstat_bestart()'s parameter list?

No.  My question was about splitting pgstat_bestart() and
pgstat_bestart_pre_auth() in a cleaner way, because authenticated
connections finish by calling both, meaning that we do twice the same
setup for backend entries depending on the authentication path taken.
That seems like a waste.

>> The addition of the new wait event states in 0004 is a good idea,
>> indeed,
> 
> Thanks! Any thoughts on the two open questions for it?:
> 1) Should we add a new wait event class rather than reusing IPC?

A new category would be more adapted.  IPC is not adapted because are
not waiting for another server process.  Perhaps just use a new
"Authentication" class, as in "The server is waiting for an
authentication operation to complete"?

> 2) Is the level at which I've inserted calls to
> pgstat_report_wait_start()/_end() sane and maintainable?

These don't worry me.  You are adding twelve event points with only 5
new wait names.  Couldn't it be better to have a one-one mapping
instead, adding twelve entries in wait_event_names.txt?

I am not really on board with the test based on injection points
proposed, though.  It checks that the "authenticating" flag is set in
pg_stat_activity, but it does nothing else.  That seems limited.  Or
are you planning for more?
--
Michael


signature.asc
Description: PGP signature

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Sun, Sep 1, 2024 at 5:10 PM Michael Paquier  wrote:
> On Fri, Aug 30, 2024 at 04:10:32PM -0400, Andrew Dunstan wrote:
> > Patch 0001 looks sane to me.
> So does 0002 to me.

Thanks both!

> I'm not much a fan of the addition of
> pgstat_bestart_pre_auth(), which is just a shortcut to set a different
> state in the backend entry to tell that it is authenticating.  Is
> authenticating the term for this state of the process startups,
> actually?  Could it be more transparent to use a "startup" or
> "starting"" state instead

Yeah, I think I should rename that. Especially if we adopt new wait
states to make it obvious where we're stuck.

"startup", "starting", "initializing", "connecting"...?

> that gets also used by pgstat_bestart() in
> the case of the patch where !pre_auth?

To clarify, do you want me to just add the new boolean directly to
pgstat_bestart()'s parameter list?

> The addition of the new wait event states in 0004 is a good idea,
> indeed,

Thanks! Any thoughts on the two open questions for it?:
1) Should we add a new wait event class rather than reusing IPC?
2) Is the level at which I've inserted calls to
pgstat_report_wait_start()/_end() sane and maintainable?

> and these can be seen in pg_stat_activity once we get out of
> PGSTAT_END_WRITE_ACTIVITY() (err.. Right?).

It doesn't look like pgstat_report_wait_start() uses that machinery.

--Jacob

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Michael Paquier]

On Fri, Aug 30, 2024 at 04:10:32PM -0400, Andrew Dunstan wrote:
> 
> On 2024-08-29 Th 4:44 PM, Jacob Champion wrote:
> > As for the other patches, I'll ping Andrew about 0001,
> 
> 
> Patch 0001 looks sane to me.

So does 0002 to me.  I'm not much a fan of the addition of
pgstat_bestart_pre_auth(), which is just a shortcut to set a different
state in the backend entry to tell that it is authenticating.  Is
authenticating the term for this state of the process startups,
actually?  Could it be more transparent to use a "startup" or
"starting"" state instead that gets also used by pgstat_bestart() in
the case of the patch where !pre_auth?

The addition of the new wait event states in 0004 is a good idea,
indeed, and these can be seen in pg_stat_activity once we get out of
PGSTAT_END_WRITE_ACTIVITY() (err.. Right?).
--
Michael


signature.asc
Description: PGP signature

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Andrew Dunstan]

On 2024-08-29 Th 4:44 PM, Jacob Champion wrote:

As for the other patches, I'll ping Andrew about 0001,



Patch 0001 looks sane to me.


cheers


andrew

--
Andrew Dunstan
EDB:https://www.enterprisedb.com

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Sun, Jun 30, 2024 at 10:48 AM Noah Misch  wrote:v
> > Would anyone like me to be more aggressive, and create a pgstat entry
> > as soon as we have the opening transaction? Or... as soon as a
> > connection is made?
>
> All else being equal, I'd like backends to have one before taking any lmgr
> lock or snapshot.

v3-0003 pushes the pgstat creation as far back as I felt comfortable,
right after the PGPROC registration by InitProcessPhase2(). That
function does lock the ProcArray, but if it gets held forever due to
some bug, you won't be able to use pg_stat_activity to debug it
anyway. And with this ordering, pg_stat_get_activity() will be able to
retrieve the proc entry by PID without a race.

This approach ends up registering an early entry for more cases than
the original patchset. For example, autovacuum and other background
workers will now briefly get their own "authenticating" state, which
seems like it could potentially confuse people. Should I rename the
state, or am I overthinking it?

> You could release the xmin before calling PAM or LDAP.  If you've copied all
> relevant catalog content to local memory, that's fine to do.

I played with the xmin problem a little bit, but I've shelved it for
now. There's probably a way to do that safely; I just don't understand
enough about the invariants to do it. For example, there's a comment
later on that says

 * We established a catalog snapshot while reading pg_authid and/or
 * pg_database;

and I'm a little nervous about invalidating the snapshot halfway
through that process. Even if PAM and LDAP don't rely on pg_authid or
other shared catalogs today, shouldn't they be allowed to in the
future, without being coupled to InitPostgres implementation order?
And I don't think we can move the pg_database checks before
authentication.

As for the other patches, I'll ping Andrew about 0001, and 0004
remains in its original WIP state. Anyone excited about that wait
event idea?

Thanks!
--Jacob


v3-0002-Test-Cluster-let-background_psql-work-asynchronou.patch
Description: Binary data


v3-0001-BackgroundPsql-handle-empty-query-results.patch
Description: Binary data


v3-0003-pgstat-report-in-earlier-with-STATE_AUTHENTICATIN.patch
Description: Binary data


v3-0004-WIP-report-external-auth-calls-as-wait-events.patch
Description: Binary data

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Noah Misch]

On Mon, Jul 08, 2024 at 02:09:21PM -0700, Jacob Champion wrote:
> On Sun, Jun 30, 2024 at 10:48 AM Noah Misch  wrote:
> > That said, it
> > may be more fruitful to arrange for authentication timeout to cut through 
> > PAM
> > etc.
> 
> That seems mostly out of our hands -- the misbehaving modules are free
> to ignore our signals (and do). Is there another way to force the
> issue?

Two ways at least (neither of them cheap):
- Invoke PAM in a subprocess, and SIGKILL that process if needed.
- Modify the module to be interruptible.

> > Hanging connection slots hurt even if they lack an xmin.
> 
> Oh, would releasing the xmin not really move the needle, then?

It still moves the needle.

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Jacob Champion]

On Sun, Jun 30, 2024 at 10:48 AM Noah Misch  wrote:
> That looks like a reasonable user experience.  Is any field newly-nullable?

Technically I think the answer is no, since backends such as walwriter
already have null database and user fields. It's new for a client
backend to have nulls there, though.

> That said, it
> may be more fruitful to arrange for authentication timeout to cut through PAM
> etc.

That seems mostly out of our hands -- the misbehaving modules are free
to ignore our signals (and do). Is there another way to force the
issue?

> Hanging connection slots hurt even if they lack an xmin.

Oh, would releasing the xmin not really move the needle, then?

> I assume it
> takes an immediate shutdown to fix them?

That's my understanding, yeah.

> > Would anyone like me to be more aggressive, and create a pgstat entry
> > as soon as we have the opening transaction? Or... as soon as a
> > connection is made?
>
> All else being equal, I'd like backends to have one before taking any lmgr
> lock or snapshot.

I can look at this for the next patchset version.

> > I haven't decided how to test these patches. Seems like a potential
> > use case for injection points, but I think I'd need to preload an
> > injection library rather than using the existing extension. Does that
> > seem like an okay way to go?
>
> Yes.

I misunderstood how injection points worked. No preload module needed,
so v2 adds a waitpoint and a test along with a couple of needed tweaks
to BackgroundPsql. I think 0001 should probably be applied
independently.

Thanks,
--Jacob


v2-0001-BackgroundPsql-handle-empty-query-results.patch
Description: Binary data


v2-0002-Test-Cluster-let-background_psql-work-asynchronou.patch
Description: Binary data


v2-0004-WIP-report-external-auth-calls-as-wait-events.patch
Description: Binary data


v2-0003-pgstat-report-in-earlier-with-STATE_AUTHENTICATIN.patch
Description: Binary data

Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

[Noah Misch]

On Mon, May 06, 2024 at 02:23:38PM -0700, Jacob Champion wrote:
> =# select * from pg_stat_activity where state = 'authenticating';
> -[ RECORD 1 ]+--
> datid|
> datname  |
> pid  | 745662
> leader_pid   |
> usesysid |
> usename  |
> application_name |
> client_addr  | 127.0.0.1
> client_hostname  |
> client_port  | 38304
> backend_start| 2024-05-06 11:25:23.905923-07
> xact_start   |
> query_start  |
> state_change |
> wait_event_type  | Client
> wait_event   | ClientRead
> state| authenticating
> backend_xid  |
> backend_xmin | 784
> query_id |
> query|
> backend_type | client backend

That looks like a reasonable user experience.  Is any field newly-nullable?

> = Open Issues, Idle Thoughts =
> 
> Maybe it's wishful thinking, but it'd be cool if a misbehaving
> authentication exchange did not impact replicas in any way. Is there a
> way to make that opening transaction lighterweight?

You could release the xmin before calling PAM or LDAP.  If you've copied all
relevant catalog content to local memory, that's fine to do.  That said, it
may be more fruitful to arrange for authentication timeout to cut through PAM
etc.  Hanging connection slots hurt even if they lack an xmin.  I assume it
takes an immediate shutdown to fix them?

> Would anyone like me to be more aggressive, and create a pgstat entry
> as soon as we have the opening transaction? Or... as soon as a
> connection is made?

All else being equal, I'd like backends to have one before taking any lmgr
lock or snapshot.

> I haven't decided how to test these patches. Seems like a potential
> use case for injection points, but I think I'd need to preload an
> injection library rather than using the existing extension. Does that
> seem like an okay way to go?

Yes.

Thanks,
nm