Re: log session end - again

This patch brings up to date what I did last year (now unfortunately
bitrotted) to allow the logging of the end of a session, enabled by the
config setting "log_session_end - true". It produces lines like these:

for a local connection:
[21340] LOG: session end: duration: 0:00:23.41 user=andrew
database=template1 host=[local]

for a tcp connection:
[21351] LOG: session end: duration: 0:00:20.22 user=andrew
database=template1 host=127.0.0.1 port=33419

for a tcp connection when log_hostname = true:
[21373] LOG: session end: duration: 0:00:02.25 user=andrew
database=template1 host=alphonso port=33421

enjoy

andrew

Andrew Dunstan wrote:
> This patch brings up to date what I did last year (now unfortunately
> bitrotted) to allow the logging of the end of a session, enabled by
> the config setting "log_session_end - true". It produces lines like
> these:

If we log "session" end, shouldn't we also log "session" start, rather
than "connection" start? It seems there should be some symmetry here,
also for the configuration parameter names.

[redirecting to hackers]

If you like. I originally just made it happen if log_connections was
set, but Neil wanted a separate setting for it. What is the consensus
about a name?

cheers

andrew

Peter Eisentraut wrote:

>Andrew Dunstan wrote:
>
>
>>This patch brings up to date what I did last year (now unfortunately
>>bitrotted) to allow the logging of the end of a session, enabled by
>>the config setting "log_session_end - true". It produces lines like
>>these:
>>
>>
>
>If we log "session" end, shouldn't we also log "session" start, rather
>than "connection" start? It seems there should be some symmetry here,
>also for the configuration parameter names.
>
>
>

Andrew Dunstan wrote:
> [redirecting to hackers]
>
> If you like. I originally just made it happen if log_connections was
> set, but Neil wanted a separate setting for it. What is the consensus
> about a name?

log_disconnect?

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian wrote:

>Andrew Dunstan wrote:
>
>
>>[redirecting to hackers]
>>
>>If you like. I originally just made it happen if log_connections was
>>set, but Neil wanted a separate setting for it. What is the consensus
>>about a name?
>>
>>
>
>log_disconnect?
>
>

Not bad. Maybe for symmetry "log_disconnections" would be better.

Here's what the log lines look like:

for a local connection:
[21340] LOG: session end: duration: 0:00:23.41 user=andrew
database=template1 host=[local]

for a tcp connection:
[21351] LOG: session end: duration: 0:00:20.22 user=andrew
database=template1 host=127.0.0.1 port=33419

for a tcp connection when log_hostname = true:
[21373] LOG: session end: duration: 0:00:02.25 user=andrew
database=template1 host=alphonso port=33421

Do we want to change those too? Maybe "session end: duration:" should be
"disconnection: session time:" or some such.

cheers

andrew

Also, Andrew, on your other patch for log_session_info line, Magnus had
the idea of giving each session an id based on the first transaction of
the session. That seems like a useful addition to that variable, though
I am not sure what value to give a session before it executes its first
query.

---------------------------------------------------------------------------

Andrew Dunstan wrote:
>
>
> Bruce Momjian wrote:
>
> >Andrew Dunstan wrote:
> >
> >
> >>[redirecting to hackers]
> >>
> >>If you like. I originally just made it happen if log_connections was
> >>set, but Neil wanted a separate setting for it. What is the consensus
> >>about a name?
> >>
> >>
> >
> >log_disconnect?
> >
> >
>
> Not bad. Maybe for symmetry "log_disconnections" would be better.
>
> Here's what the log lines look like:
>
> for a local connection:
> [21340] LOG: session end: duration: 0:00:23.41 user=andrew
> database=template1 host=[local]
>
> for a tcp connection:
> [21351] LOG: session end: duration: 0:00:20.22 user=andrew
> database=template1 host=127.0.0.1 port=33419
>
> for a tcp connection when log_hostname = true:
> [21373] LOG: session end: duration: 0:00:02.25 user=andrew
> database=template1 host=alphonso port=33421
>
> Do we want to change those too? Maybe "session end: duration:" should be
> "disconnection: session time:" or some such.
>
> cheers
>
> andrew
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 3: if posting/reading through Usenet, please send an appropriate
> subscribe-nomail command to majordomo(at)postgresql(dot)org so that your
> message can get through to the mailing list cleanly
>

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian wrote:

>Also, Andrew, on your other patch for log_session_info line, Magnus had
>the idea of giving each session an id based on the first transaction of
>the session. That seems like a useful addition to that variable, though
>I am not sure what value to give a session before it executes its first
>query.
>
>
>

We can think about that. I am planning to tackle these separately (hence
today's patch).

I did think about using a cluster-wide sequence, if we can make such a
thing (might also be useful for system generated UIDs too).

cheers

andrew

Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
> Bruce Momjian wrote:
>> Also, Andrew, on your other patch for log_session_info line, Magnus had
>> the idea of giving each session an id based on the first transaction of
>> the session.

> I did think about using a cluster-wide sequence, if we can make such a
> thing (might also be useful for system generated UIDs too).

Not a good idea IMHO. If you do that, then there will be no such thing
as a purely read-only transaction, because *every* transaction will
include a nextval() call. That means even read-only transactions cannot
commit till the disk spins.

If we want a unique id for transient purposes like logging, then make
some kind of counter in shared memory. Don't use a sequence, it's much
too heavyweight.

regards, tom lane

Tom Lane wrote:

>Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
>
>
>>Bruce Momjian wrote:
>>
>>
>>>Also, Andrew, on your other patch for log_session_info line, Magnus had
>>>the idea of giving each session an id based on the first transaction of
>>>the session.
>>>
>>>
>
>
>
>>I did think about using a cluster-wide sequence, if we can make such a
>>thing (might also be useful for system generated UIDs too).
>>
>>
>
>Not a good idea IMHO. If you do that, then there will be no such thing
>as a purely read-only transaction, because *every* transaction will
>include a nextval() call. That means even read-only transactions cannot
>commit till the disk spins.
>
>If we want a unique id for transient purposes like logging, then make
>some kind of counter in shared memory. Don't use a sequence, it's much
>too heavyweight.
>
>
>

I'm not sure I understand. I didn't suggest that a sequence should be
used for txn ids. For the purpose I had in mind we would call nextval()
once per connection, and, for the other purpose where I suggested it
would be useful, once per "create user". That doesn't seem very heavyweight.

cheers

andrew

[note change of subject]

I wrote:

>
>
> Tom Lane wrote:
>
>> Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
>>
>>> I did think about using a cluster-wide sequence, if we can make such
>>> a thing (might also be useful for system generated UIDs too).
>>>
>>
>>
>> Not a good idea IMHO. If you do that, then there will be no such thing
>> as a purely read-only transaction, because *every* transaction will
>> include a nextval() call. That means even read-only transactions cannot
>> commit till the disk spins.
>>
>> If we want a unique id for transient purposes like logging, then make
>> some kind of counter in shared memory. Don't use a sequence, it's much
>> too heavyweight.
>>
>
> I'm not sure I understand. I didn't suggest that a sequence should be
> used for txn ids. For the purpose I had in mind we would call
> nextval() once per connection, and, for the other purpose where I
> suggested it would be useful, once per "create user". That doesn't
> seem very heavyweight.
>

If we really want a loggable session id then ISTM it should be not
transient at all, but in fact unique even across server restart. One
moderately simple scheme that occurred to me is to have to postmaster
keep a 64 bit counter, initialised by a call to gettimeofday(), and
bumped on every connection. The postmaster would just put the new
counter value into the port structure for the backend (and in the exec
case it would be written out and then read back by the backend, along
with the other port stuff set by postmaster). No need for a persistent
sequence or for shared memory, and it would be unique unless time went
backwards by exactly the right amount between server starts (you do run
ntp on your machines, don't you?).

I am less sure of the utility of such an ID, though. After all, if you
see a disconnect log message for a given PID you must know that any
reuse of that PID indicates a new session, or even if you just see a
connection message you know it must be a new session. OTOH, having a
unique SessionID might simplify the logic required of log analysis tools.

cheers

andrew

> >
> > Tom Lane wrote:
> >
> >> Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
> >>
> >>> I did think about using a cluster-wide sequence, if we can make such
> >>> a thing (might also be useful for system generated UIDs too).
> >>
> >> Not a good idea IMHO. If you do that, then there will be no such thing
> >> as a purely read-only transaction, because *every* transaction will
> >> include a nextval() call. That means even read-only transactions cannot
> >> commit till the disk spins.
> >>

A sequence could be used if it was created with a sufficiently large CACHE
value, so a read only transaction would only have to hit the disk if it
happened to be the one to hit an exhausted cache.

Kris Jurka

Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
> I'm not sure I understand. I didn't suggest that a sequence should be
> used for txn ids. For the purpose I had in mind we would call nextval()
> once per connection,

Oh, okay, I misunderstood. But why not just use the PID?

regards, tom lane

Andrew Dunstan wrote:
> I am less sure of the utility of such an ID, though. After all, if
> you see a disconnect log message for a given PID you must know that
> any reuse of that PID indicates a new session, or even if you just
> see a connection message you know it must be a new session. OTOH,
> having a unique SessionID might simplify the logic required of log
> analysis tools.

The PID *is* a unique session ID. Why is it not sufficient?

Peter Eisentraut wrote:

>Andrew Dunstan wrote:
>
>
>>I am less sure of the utility of such an ID, though. After all, if
>>you see a disconnect log message for a given PID you must know that
>>any reuse of that PID indicates a new session, or even if you just
>>see a connection message you know it must be a new session. OTOH,
>>having a unique SessionID might simplify the logic required of log
>>analysis tools.
>>
>>
>
>The PID *is* a unique session ID. Why is it not sufficient?
>

It's unique for the duration of the session, but it won't be for logs
covering a sufficient period of time, because PIDs are reused, in some
cases not even by cycling but being allocated randomly.

As I said elsewhere, I can live with that, but others wanted something
that was more unique (if such a term has meaning ;-)

cheers

andrew ("You are unique. Just like everybody else.")

Andrew Dunstan wrote:
> Tom Lane said:
> > Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
> >> I'm not sure I understand. I didn't suggest that a sequence should be
> >> used for txn ids. For the purpose I had in mind we would call
> >> nextval() once per connection,
> >
> > Oh, okay, I misunderstood. But why not just use the PID?
> >
>
> Bruce and others have suggested that PID is not sufficiently unique.
> Personally, I can live with it :-)

The nice things about using xid for session id is that is is unique for
a long time, rather than pid.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Tom Lane said:
> Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
>> I'm not sure I understand. I didn't suggest that a sequence should be
>> used for txn ids. For the purpose I had in mind we would call
>> nextval() once per connection,
>
> Oh, okay, I misunderstood. But why not just use the PID?
>

Bruce and others have suggested that PID is not sufficiently unique.
Personally, I can live with it :-)

cheers

andrew

--On Tuesday, February 03, 2004 11:12:03 -0500 Andrew Dunstan
<andrew(at)dunslane(dot)net> wrote:

>
>
> Peter Eisentraut wrote:
>
>> Andrew Dunstan wrote:
>>
>>
>>> I am less sure of the utility of such an ID, though. After all, if
>>> you see a disconnect log message for a given PID you must know that
>>> any reuse of that PID indicates a new session, or even if you just
>>> see a connection message you know it must be a new session. OTOH,
>>> having a unique SessionID might simplify the logic required of log
>>> analysis tools.
>>>
>>>
>>
>> The PID *is* a unique session ID. Why is it not sufficient?
>>
>
> It's unique for the duration of the session, but it won't be for logs
> covering a sufficient period of time, because PIDs are reused, in some
> cases not even by cycling but being allocated randomly.
>
> As I said elsewhere, I can live with that, but others wanted something
> that was more unique (if such a term has meaning ;-)
How about pid+unix time of start of backend?

LER

>
> cheers
>
> andrew ("You are unique. Just like everybody else.")
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 1: subscribe and unsubscribe commands go to majordomo(at)postgresql(dot)org
>

--
Larry Rosenman http://www.lerctr.org/~ler
Phone: +1 972-414-9812 E-Mail: ler(at)lerctr(dot)org
US Mail: 1905 Steamboat Springs Drive, Garland, TX 75044-6749

Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> Andrew Dunstan wrote:
>> Bruce and others have suggested that PID is not sufficiently unique.

> The nice things about using xid for session id is that is is unique for
> a long time, rather than pid.

Hmm. Now that I think about it, InitPostgres() always runs a
transaction during backend startup. If we simply saved aside the XID
assigned to that transaction, it would cost next to nothing to do and
would provide a reasonably unique ID. However, this happens much later
than the postmaster currently prints the log_connection message ...

regards, tom lane

Tom Lane wrote:

>Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
>
>
>>Andrew Dunstan wrote:
>>
>>
>>>Bruce and others have suggested that PID is not sufficiently unique.
>>>
>>>
>
>
>
>>The nice things about using xid for session id is that is is unique for
>>a long time, rather than pid.
>>
>>
>
>Hmm. Now that I think about it, InitPostgres() always runs a
>transaction during backend startup. If we simply saved aside the XID
>assigned to that transaction, it would cost next to nothing to do and
>would provide a reasonably unique ID. However, this happens much later
>than the postmaster currently prints the log_connection message ...
>
>
>

Right. And if we have sessionids we would want them logged there, I
think. And that would rule out anything based on xid or backend pid.
OTOH I am quite sure I can implement the time based counter idea I
suggested earlier with a very small amount of disturbance and very low
cost. Unless someone can see a flaw in the scheme.

cheers

andrew

Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
> Right. And if we have sessionids we would want them logged there, I
> think. And that would rule out anything based on xid or backend pid.

Uh, what's wrong with backend pid? Since we fork before we start doing
anything with a connection, it should surely be available soon enough
for the connection log message.

Larry's idea about combining PID and backend start time didn't sound too
unreasonable to me.

regards, tom lane

Tom Lane said:
> Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
>> Right. And if we have sessionids we would want them logged there, I
>> think. And that would rule out anything based on xid or backend pid.
>
> Uh, what's wrong with backend pid? Since we fork before we start doing
> anything with a connection, it should surely be available soon enough
> for the connection log message.
>
> Larry's idea about combining PID and backend start time didn't sound
> too unreasonable to me.
>

It did to me too. I was just looking at this code 2 days ago. Somehow when
I looked again I thought we logged connections in the postmaster. Larry's
idea should work just fine. For log compactness I think I'd hexencode it -
the SessionID doesn't need any semantics, it's just like a cookie.

cheers

andrew

Peter Eisentraut wrote:

>Andrew Dunstan wrote:
>
>
>>This patch brings up to date what I did last year (now unfortunately
>>bitrotted) to allow the logging of the end of a session, enabled by
>>the config setting "log_session_end - true". It produces lines like
>>these:
>>
>>
>
>If we log "session" end, shouldn't we also log "session" start, rather
>than "connection" start? It seems there should be some symmetry here,
>also for the configuration parameter names.
>
>
>

OK, this version of the patch uses the config parameter name
"log_disconnections" for the sake of symmetry, and changes the message
wording slightly accordingly.

cheers

andrew

Tom Lane wrote:
> Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
> > Right. And if we have sessionids we would want them logged there, I
> > think. And that would rule out anything based on xid or backend pid.
>
> Uh, what's wrong with backend pid? Since we fork before we start doing
> anything with a connection, it should surely be available soon enough
> for the connection log message.
>
> Larry's idea about combining PID and backend start time didn't sound too
> unreasonable to me.

Wow, like the idea too --- pid plus time_t start time of backend.
Actully, it would be good to have star time first so you can sort
everything in order of start time.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian wrote:

>Tom Lane wrote:
>
>
>>Larry's idea about combining PID and backend start time didn't sound too
>>unreasonable to me.
>>
>>
>
>Wow, like the idea too --- pid plus time_t start time of backend.
>Actully, it would be good to have star time first so you can sort
>everything in order of start time.
>
>

Yes. Of course, you would need either to sort additionally on log
timestamp or use an order-preserving sort.

Based on Larry's idea, I had in mind to provide a third escape in the
log_line_info string (in addition to the %U and %D that I had previously
done) of %S for sessionid, which would look something like this:
402251fc.713f

I will start redoing this feature when the log_disconnections patch is
dealt with.

cheers

andrew

On Thu, 5 Feb 2004, Bruce Momjian wrote:
> Wow, like the idea too --- pid plus time_t start time of backend.
> Actully, it would be good to have star time first so you can sort
> everything in order of start time.

Why not just add a printf like pattern so the user can output
whatever they like?
%p - backend pid
%t - connect time
%C - standard connection string "%t:%p"
%a - autoincrement number
...

People could add more in later if they want more options.

Chester Kustarz wrote:

>On Thu, 5 Feb 2004, Bruce Momjian wrote:
>
>
>>Wow, like the idea too --- pid plus time_t start time of backend.
>>Actully, it would be good to have star time first so you can sort
>>everything in order of start time.
>>
>>
>
>Why not just add a printf like pattern so the user can output
>whatever they like?
> %p - backend pid
> %t - connect time
> %C - standard connection string "%t:%p"
> %a - autoincrement number
>
>

log_line_info where this would be implemented is indeed done with a
printf like string, which is easily extensible The following is adapted
from the description of the original patch which it is my intention to
bring up to date soon and resubmit:

Prefixes each message in the server log file or syslog with extra
information as specified in the string. The default is an empty
string. The following sequences in the string are translated:
'%U' is replace with the username,
'%D' is replaced by the database name,
and '%%' is replaced by '%'.
All other characters are copied literally to the log. For example,
log_line_info = '<%U%%%D> '
will produce output like this:
<myuser%mydb> LOG: query: create table foo(blah text);

cheers

andrew

Andrew Dunstan wrote:
> Based on Larry's idea, I had in mind to provide a third escape in the
> log_line_info string (in addition to the %U and %D that I had previously
> done) of %S for sessionid, which would look something like this:
> 402251fc.713f
>
> I will start redoing this feature when the log_disconnections patch is
> dealt with.

Andrew, I can't find the log_disconnections patch. I know I saw it, but
I can't find it now. Would you resent it please?

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

You can find it here.

http://archives.postgresql.org/pgsql-patches/2004-02/msg00072.php

I know Neil was reviewing it and had a minor doc style quibble, as well
as the question he raised on -hackers about psql tab completion.

cheers

andrew

Bruce Momjian wrote:

>Andrew Dunstan wrote:
>
>
>>Based on Larry's idea, I had in mind to provide a third escape in the
>>log_line_info string (in addition to the %U and %D that I had previously
>>done) of %S for sessionid, which would look something like this:
>>402251fc.713f
>>
>>I will start redoing this feature when the log_disconnections patch is
>>dealt with.
>>
>>
>
>Andrew, I can't find the log_disconnections patch. I know I saw it, but
>I can't find it now. Would you resent it please?
>
>
>

Your patch has been added to the PostgreSQL unapplied patches list at:

http://momjian.postgresql.org/cgi-bin/pgpatches

I will try to apply it within the next 48 hours.

---------------------------------------------------------------------------

Andrew Dunstan wrote:
>
> You can find it here.
>
> http://archives.postgresql.org/pgsql-patches/2004-02/msg00072.php
>
> I know Neil was reviewing it and had a minor doc style quibble, as well
> as the question he raised on -hackers about psql tab completion.
>
> cheers
>
> andrew
>
> Bruce Momjian wrote:
>
> >Andrew Dunstan wrote:
> >
> >
> >>Based on Larry's idea, I had in mind to provide a third escape in the
> >>log_line_info string (in addition to the %U and %D that I had previously
> >>done) of %S for sessionid, which would look something like this:
> >>402251fc.713f
> >>
> >>I will start redoing this feature when the log_disconnections patch is
> >>dealt with.
> >>
> >>
> >
> >Andrew, I can't find the log_disconnections patch. I know I saw it, but
> >I can't find it now. Would you resent it please?
> >
> >
> >
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: Have you checked our extensive FAQ?
>
> http://www.postgresql.org/docs/faqs/FAQ.html
>

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Patch applied. Thanks.

I modified the doc wording a bit --- patch attached.

---------------------------------------------------------------------------

Andrew Dunstan wrote:
>
> You can find it here.
>
> http://archives.postgresql.org/pgsql-patches/2004-02/msg00072.php
>
> I know Neil was reviewing it and had a minor doc style quibble, as well
> as the question he raised on -hackers about psql tab completion.
>
> cheers
>
> andrew
>
> Bruce Momjian wrote:
>
> >Andrew Dunstan wrote:
> >
> >
> >>Based on Larry's idea, I had in mind to provide a third escape in the
> >>log_line_info string (in addition to the %U and %D that I had previously
> >>done) of %S for sessionid, which would look something like this:
> >>402251fc.713f
> >>
> >>I will start redoing this feature when the log_disconnections patch is
> >>dealt with.
> >>
> >>
> >
> >Andrew, I can't find the log_disconnections patch. I know I saw it, but
> >I can't find it now. Would you resent it please?
> >
> >
> >
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: Have you checked our extensive FAQ?
>
> http://www.postgresql.org/docs/faqs/FAQ.html
>

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073