Thread: Logging conflicted queries on deadlocks
Here is a patch to log conflicted queries on deadlocks. Queries are dumped at CONTEXT in the same sorting order as DETAIL messages. Those queries are picked from pg_stat_get_backend_activity, as same as pg_stat_activity, so that users cannot see other user's queries. (It might be better to log all queries in the server log and mask them in the client response, but I'm not sure how to do it...) | ERROR: deadlock detected | DETAIL: Process 3088 waits for ShareLock on transaction 608; blocked by process 2928. | Process 2928 waits for ShareLock on transaction 609; blocked by process 2824. | Process 2824 waits for ShareLock on transaction 610; blocked by process 3088. | CONTEXT: Process 3088: UPDATE test SET i = i WHERE i = 1; | Process 2928: <insufficient privilege> | Process 2824: UPDATE test SET i = i WHERE i = 3; | STATEMENT: UPDATE test SET i = i WHERE i = 1; Alvaro Herrera <alvherre@commandprompt.com> wrote: > Perhaps it could be shown in CONTEXT, like so: > > I think it's useful to show the PID of each statement, for the case > where there are more than two processes deadlocked. Thanks for response. I bought your suggestion :-) Regards, --- ITAGAKI Takahiro NTT Open Source Software Center
Attachment
Your patch has been added to the PostgreSQL unapplied patches list at:
http://momjian.postgresql.org/cgi-bin/pgpatches
It will be applied as soon as one of the PostgreSQL committers reviews
and approves it.
---------------------------------------------------------------------------
ITAGAKI Takahiro wrote:
>
> Here is a patch to log conflicted queries on deadlocks. Queries are dumped
> at CONTEXT in the same sorting order as DETAIL messages. Those queries are
> picked from pg_stat_get_backend_activity, as same as pg_stat_activity,
> so that users cannot see other user's queries. (It might be better to log
> all queries in the server log and mask them in the client response, but
> I'm not sure how to do it...)
>
> | ERROR: deadlock detected
> | DETAIL: Process 3088 waits for ShareLock on transaction 608; blocked by process 2928.
> | Process 2928 waits for ShareLock on transaction 609; blocked by process 2824.
> | Process 2824 waits for ShareLock on transaction 610; blocked by process 3088.
> | CONTEXT: Process 3088: UPDATE test SET i = i WHERE i = 1;
> | Process 2928: <insufficient privilege>
> | Process 2824: UPDATE test SET i = i WHERE i = 3;
> | STATEMENT: UPDATE test SET i = i WHERE i = 1;
>
>
> Alvaro Herrera <alvherre@commandprompt.com> wrote:
>
> > Perhaps it could be shown in CONTEXT, like so:
> >
> > I think it's useful to show the PID of each statement, for the case
> > where there are more than two processes deadlocked.
>
> Thanks for response. I bought your suggestion :-)
>
> Regards,
> ---
> ITAGAKI Takahiro
> NTT Open Source Software Center
>
[ Attachment, skipping... ]
>
> ---------------------------(end of broadcast)---------------------------
> TIP 6: explain analyze is your friend
--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://postgres.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
ITAGAKI Takahiro <itagaki.takahiro@oss.ntt.co.jp> writes:
> Here is a patch to log conflicted queries on deadlocks. Queries are dumped
> at CONTEXT in the same sorting order as DETAIL messages. Those queries are
> picked from pg_stat_get_backend_activity, as same as pg_stat_activity,
> so that users cannot see other user's queries.
Applied with revisions. It's a cute idea --- I first thought it
couldn't work reliably because of race conditions, but actually we
haven't aborted our own transaction at this point, so everyone else
involved in the deadlock is still waiting and it should be safe to
grab their activity strings.
However there was still a big implementation problem, which is that
looking at pg_stat_activity could deliver very stale results, not only
about other backends' queries but even our own. The data for that
comes from a snapshot that might have been taken much earlier in our
transaction. I replaced the code you were using with a new pgstat.c
entry point that delivers up-to-date info directly from the shared
memory array.
> (It might be better to log all queries in the server log and mask them
> in the client response, but I'm not sure how to do it...)
Yeah, that would be cute, but we don't have any way to deliver a
different CONTEXT string to the client than we do to the log. We could
generate duplicate messages that go only to the log but that seemed
pretty ugly. In practice this definition is probably good enough.
One thing that I worried about for a little bit is that you can imagine
privilege-escalation scenarios. Suppose that the user is allowed to
call some SECURITY DEFINER function that runs as superuser, and a
deadlock occurs inside that. As the patch stands, every query involved
in the deadlock will be reported, which might be undesirable. We could
make the test use the outermost session user's ID instead of current
ID, but that might only move the security risks someplace else.
Thoughts?
regards, tom lane
"Tom Lane" <tgl@sss.pgh.pa.us> writes: > ITAGAKI Takahiro <itagaki.takahiro@oss.ntt.co.jp> writes: >> Here is a patch to log conflicted queries on deadlocks. Queries are dumped >> at CONTEXT in the same sorting order as DETAIL messages. Those queries are >> picked from pg_stat_get_backend_activity, as same as pg_stat_activity, >> so that users cannot see other user's queries. > > Applied with revisions. It's a cute idea --- I first thought it > couldn't work reliably because of race conditions, but actually we > haven't aborted our own transaction at this point, so everyone else > involved in the deadlock is still waiting and it should be safe to > grab their activity strings. There's no way the other transaction's timeout could fire while we're doing this is there? Are we still holding the lw locks at this point which would prevent that? > One thing that I worried about for a little bit is that you can imagine > privilege-escalation scenarios. Suppose that the user is allowed to > call some SECURITY DEFINER function that runs as superuser, and a > deadlock occurs inside that. As the patch stands, every query involved > in the deadlock will be reported, which might be undesirable. We could > make the test use the outermost session user's ID instead of current > ID, but that might only move the security risks someplace else. > Thoughts? Perhaps we should only do this if the current user's ID is the same as the outermost session user's ID? -- Gregory Stark EnterpriseDB http://www.enterprisedb.com Ask me about EnterpriseDB's 24x7 Postgres support!
"Gregory Stark" <stark@enterprisedb.com> writes: > There's no way the other transaction's timeout could fire while we're doing > this is there? Are we still holding the lw locks at this point which would > prevent that? Ah, reading the patch I see comments indicating that yes that's possible and no, we don't really care. So, ok. If the backend disappears entirely could the string be empty? Perhaps it would be safer to copy out st_activity inside the loop checking st_changecount? It is a really nice feature though. Note that there was an unrelated demand for just this info on one of the other lists just today. Thanks very much Itagaki-san! -- Gregory Stark EnterpriseDB http://www.enterprisedb.com Ask me about EnterpriseDB's On-Demand Production Tuning
Gregory Stark <stark@enterprisedb.com> writes:
> Ah, reading the patch I see comments indicating that yes that's possible and
> no, we don't really care. So, ok. If the backend disappears entirely could the
> string be empty?
Right, we'd be pointing at a BackendStatusArray entry that was now
unused, or even perhaps recycled by a new session. That memory doesn't
move, so we don't need to worry about picking up something that's not
a status string at all, but worst case it could be not the string we
want. I think the odds are pretty low though.
Perhaps it would be safer to copy out st_activity inside the
> loop checking st_changecount?
Don't think it would really help any --- the other backend could've
aborted and changed its status string before we ever get to this code at
all.
> It is a really nice feature though. Note that there was an unrelated demand
> for just this info on one of the other lists just today. Thanks very much
> Itagaki-san!
That was my feeling --- the usefulness is high enough that a small
probability of a wrong display is a small price to pay.
regards, tom lane
Gregory Stark <stark@enterprisedb.com> writes:
> "Tom Lane" <tgl@sss.pgh.pa.us> writes:
>> One thing that I worried about for a little bit is that you can imagine
>> privilege-escalation scenarios.
> Perhaps we should only do this if the current user's ID is the same as the
> outermost session user's ID?
A conservative approach would be to report the query texts *only* in the
server log and never to the client --- this would need a bit of klugery
but seems doable.
regards, tom lane
I wrote:
>>>> One thing that I worried about for a little bit is that you can imagine
>>>> privilege-escalation scenarios.
> A conservative approach would be to report the query texts *only* in the
> server log and never to the client --- this would need a bit of klugery
> but seems doable.
Anybody have any opinions about changing this or sticking with the
behavior as-submitted? It doesn't seem like an open-and-shut issue
to me.
If we report the query texts only to the server log, we could remove all
restrictions on which users' queries would be reported. That would
clearly be helpful in some cases. On the other hand, it would clearly
be less convenient to use than the existing approach that sends
information to the client. I'm not real excited about adding still
another wart to ereport() to make this possible, either.
Comments welcome.
regards, tom lane
Tom Lane wrote: > If we report the query texts only to the server log, we could remove all > restrictions on which users' queries would be reported. That would > clearly be helpful in some cases. On the other hand, it would clearly > be less convenient to use than the existing approach that sends > information to the client. I'm not real excited about adding still > another wart to ereport() to make this possible, either. I think we should report to the client where it is not a security breach, and to the server log otherwise. I'm not sure about warts. A separate server-only context field perhaps? Or a separate flag in ErrorData elements saying whether each particular one should go to server only. If we add that, perhaps we could clean up the stuff in checkSharedDependency with it, too. -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
Alvaro Herrera <alvherre@commandprompt.com> writes:
> I think we should report to the client where it is not a security
> breach, and to the server log otherwise.
Well, the point of my original comment is that it's not always so
obvious what might be a security breach or not.
> I'm not sure about warts. A separate server-only context field perhaps?
> Or a separate flag in ErrorData elements saying whether each particular
> one should go to server only.
Yeah, one or the other. I was actually thinking about a server-only
addition to the detail field, because using CONTEXT for this doesn't
really seem like quite the right thing --- if the deadlock occurs inside
a function or some other place where lines will get appended to CONTEXT,
it could be confusing. If we're going to add features to elog.c to
support this specific case, what I'd rather have is
DETAIL: Process A waits for ...
Process B waits for ...
Process A: <query text>
Process B: <query text>
where the second group of lines only appears in the server log.
> If we add that, perhaps we could clean up the stuff in
> checkSharedDependency with it, too.
Hmm, hadn't realized there were other use-cases already. That makes me
a little more willing to spend effort here. Not sure that the above
design quite works for pg_shdepend though. Do we need two independent
strings for client and log details?
regards, tom lane
On Sun, Mar 23, 2008 at 3:21 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > I wrote: > > A conservative approach would be to report the query texts *only* in the > > server log and never to the client --- this would need a bit of klugery > > but seems doable. > > Anybody have any opinions about changing this or sticking with the > behavior as-submitted? It doesn't seem like an open-and-shut issue > to me. From my experience, client apps usually don't report the information about deadlock in a useful way (and they often don't report anything at all except a standard error message). We usually dig into the server log to find the information (and it's often useless because we (currently) don't have information about the queries involved so we log all queries for a while to have more debugging information). So my point is that having all the information we can collect in the server log is essential. I don't think the client app can do anything useful with the query texts: they usually hide this sort of technical details. -- Guillaume
Tom Lane schrieb: > ITAGAKI Takahiro <itagaki.takahiro@oss.ntt.co.jp> writes: > >> Here is a patch to log conflicted queries on deadlocks. Queries are dumped >> at CONTEXT in the same sorting order as DETAIL messages. Those queries are >> picked from pg_stat_get_backend_activity, as same as pg_stat_activity, >> so that users cannot see other user's queries. >> > > Applied with revisions. It's a cute idea --- I first thought it > couldn't work reliably because of race conditions, but actually we > haven't aborted our own transaction at this point, so everyone else > involved in the deadlock is still waiting and it should be safe to > grab their activity strings. > > However there was still a big implementation problem, which is that > looking at pg_stat_activity could deliver very stale results, not only > about other backends' queries but even our own. The data for that > comes from a snapshot that might have been taken much earlier in our > transaction. I replaced the code you were using with a new pgstat.c > entry point that delivers up-to-date info directly from the shared > memory array. > Is there a chance that I might get this patch running in 8.1 and 8.2 releases? I modified the original patch to compile with 8.2.7, but it did not work: ERROR: deadlock detected DETAIL: Process 26289 waits for ShareLock on transaction 57039190; blocked by process 26277. Process 26277 waits for ShareLock on transaction 57039191; blocked by process 26289. CONTEXT: Process 26289: <backend information not available> Process 26277: <backend information not available>