log session end - again

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:

[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@candle.pha.pa.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]
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
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
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@postgresql.org so that your
message can get through to the mailing list cleanly

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.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@dunslane.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@dunslane.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@dunslane.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@dunslane.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@dunslane.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@dunslane.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@candle.pha.pa.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@dunslane.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@dunslane.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@postgresql.org

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

Bruce Momjian <pgman@candle.pha.pa.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@candle.pha.pa.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@dunslane.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