Weirdness in the logfile

["Nick Elson [Sybase iAnywhere]" <@@@@com@>]

On the concern about rollbacks, make sure you include
the "-r" switch.

It is not certain what you are actually measuring here but
the following observastions may help:

It may be possible your login_procedure is issuing
a commit here. Also it is not uncommon for ODBC
applications and database frameworks to commit
every new connections; due to some implementing
logic to guarantee an autocommit behaviour, others
to clean-up history on connections possibly coming
from a connection pool. [not certain if commits with no
work pending get logged but a scenario]

The "-d" switch changes the way dbtran reports stuff.
More importantly it changes the order of actions and
may be reording things in the way that is confusing
you. I would try removing that. This effect alone
could be sufficient to explain your observation. This
'out of sequence' behaviour is highlighted in the
warning added to the head of the output

-- WARNING: Chronological ordered
output must not be applied to a database

similar caveats apply when reading. Also, when
operations in logs (console or transaction) occur at
the same clock resolution time, outputs can sometimes
reorder them as an artifact due to any sorting mechanisms.

Rollbacks at the ends of transactions and logs,
are not always displayed in the dbtran output unless
you add the "-r" switch. [some rollbacks are just
implied and understood]

You never see disconnects with dbtran. So it is
all too easy to associate operations from reused
connection ids when that is not the case. Since
you clearly are looking at a disconnect boundary
this is a factor to be aware of when assesing the
last two points.

It is possible the commit is a side effect of the
last operation (when the server is running in
'unchained' mode) and not comming from the
connection itself. As such it could be a housekeeping
entry required to clean up the reused connection
if only to keep it 'recoverable' during a startup or
application of backup log in a recovery scenario.

No. Checkpoints are not tied to commits.

If your application crashes or disconnects, uncommited
operations should be rolled back and the log should
be able to reflect that rollback (see -r comments above).
Some operations autocommit (DDL statements, DML
operations executed by the server with chained mode
off, ....) and so there must be some commit logged
in that case. It may be possible that trigger or RI
logic may present a delay to the commit.

It is possible you are looking at a reporting problem
with dbtran. V7 is pretty old (assuming you are using
the last 7.0.4EBF, 7.0 is much older than that) and
there may have been some problem in that version.

All in all it sound pretty benign. I can not determine
if the report represents any sort of fatal issue with
logging.

Do keep in mind the entries in the log were put in
there by the version of software running at the
of those connections time, and so the issue could
be due to older bugs than the reported version of dbtran.

And, well, you asked, but do not say why this is a concern
for you. If you do not have any recovery, replication or
indication of another area having troubles, it may be there
is nothing wrong here. Is there anything behind this concern?

We are using ASA 7 in Solaris and I have noticed something
kinda funny in the logfile pertaining to the sequence of
events.

When I do a dbtran -d on a logfile, I notice that the normal progression is
CONNECT
--> BEGIN TRANSACTION
----> UPDATE OR INSERT
---> COMMIT.

I looked at a log file that started a transaction, did 2 INSERTS and then
sat there for a long time (about 20 minutes). I then saw another
CONNECT coming from the same ID. After the CONNECT, all it
did was COMMIT and then it was done.

I have never seen this behavior before where a separate CONNECT
is issued to do the COMMIT on a prior transaction. Does this have
something to do with a checkpoint maybe? Is this what would happen
if you had an application that did not execute the COMMIT?

Some of our stuff turns off autocommit and I did see where
there was a path to exit the function prior to issuing a
COMMIT.

Does ASA do COMMITS on a checkpoint or after a
period of time?

[unknown]

Post by "Nick Elson [Sybase iAnywhere]" <@@@@com@>
And, well, you asked, but do not say why this is a concern
for you. If you do not have any recovery, replication or
indication of another area having troubles, it may be
there is nothing wrong here. Is there anything behind
this concern?

Wow Nick! Thanks for your detailed response. Your are
correct, I have an underlying concern here. Because we are
using Version 7 (most updated), we have the problem of
transactions not spanning logfile backups. We do a dbbackup
every half an hour on our highly transaction ASA DB. Every
once in a while, we have this problem where dbbackup runs
for a long long time. Usually the half hour backup takes 5
seconds or so. This particular time it took 20 minutes but
it finally finished. Now from what I understand, the
dbbackup must wait for all in progress transactions to
complete before it starts. This is why when it finally
finished, I snagged the logfile and did the dbtran on it.
The output from dbtran is probably not intended to debug
problems like this but rather to apply to a DB in case of
failure. I wrote a program to parse out the transactions
and print how long they were taking. I did it in
chronological order because I wanted to see the entries the
way they came in the front door to the DB. I parsed out
the milliseconds from the BEGIN TRANSACTION and COMMIT lines
and calculated the number of milliseconds each transaction
took. The one that took the longest (20 minutes) was the
one that did the individual CONNECT / COMMIT. That
statement seemed to free everything up and then it
completed. That statement was coming from an EJB running in
Jaguar (I recognize the SQL statements) so that got me
thinking that possibly a connection was not closed and
something (as you indicated) was just doing some periodic
housecleaning (i.e. taking a connection out of a pool,
etc.). We have been fighting this random problem of
dbbackup hanging for a long time. We usually just restart
Jaguar and it frees it up but it is an annoying problem that
is driving me crazy. If there was a way to see what
transaction was open and what SQL statement it was hung on
when at the time it is occuring - my life would be
complete! I appreciate your response.

["Nick Elson [Sybase iAnywhere]" <@@@@com@>]

That sounds like 'all systems are normal' then.
Jaguar. ASA 7.0.x. Blocked backups. . . . Those were the days.

I believe you have narrowed this down to the correct
transaction in question already. And it is just an
'out of order' output that is confusing you.

The bottom line is, you seem to truely require spanning
transaction support in the backups. And that requires V8+.
Upgrading to any newer product version should address this
issue for you, but I don't know if that is an option.

Unfortunately not much can be done with V7 without designing
some gear to identify open transactions and kill the associated
connections; iff the backup is running. Not trivial, and possibly
fraught with dangers.

You should be able to identify open transactions by the
"UncmtOps" column from the sa_conn_info( ) output.
You could get a footprint of activity from the sa_locks( ) output;
assuming knowing the table locks are being held on is sufficient.

It is also possible that your 20minute connection is "BlockedOn"
locks held by others (and thus that connection is not your
root cause), so you may want to check out the sa_conn_info( )
output to determine blockers/blockees at the time of your
next hang.

Once you know the connection(s) in question, it may be possible
to determine from the connection properties, things like the address
node and process id, (Host and Pid of AppInfo). I believe this
shows up in the console log if you add the -z switch to the server.


HTH

Post by unknown

Post by "Nick Elson [Sybase iAnywhere]" <@@@@com@>
And, well, you asked, but do not say why this is a concern
for you. If you do not have any recovery, replication or
indication of another area having troubles, it may be
there is nothing wrong here. Is there anything behind
this concern?

Wow Nick! Thanks for your detailed response. Your are
correct, I have an underlying concern here. Because we are
using Version 7 (most updated), we have the problem of
transactions not spanning logfile backups. We do a dbbackup
every half an hour on our highly transaction ASA DB. Every
once in a while, we have this problem where dbbackup runs
for a long long time. Usually the half hour backup takes 5
seconds or so. This particular time it took 20 minutes but
it finally finished. Now from what I understand, the
dbbackup must wait for all in progress transactions to
complete before it starts. This is why when it finally
finished, I snagged the logfile and did the dbtran on it.
The output from dbtran is probably not intended to debug
problems like this but rather to apply to a DB in case of
failure. I wrote a program to parse out the transactions
and print how long they were taking. I did it in
chronological order because I wanted to see the entries the
way they came in the front door to the DB. I parsed out
the milliseconds from the BEGIN TRANSACTION and COMMIT lines
and calculated the number of milliseconds each transaction
took. The one that took the longest (20 minutes) was the
one that did the individual CONNECT / COMMIT. That
statement seemed to free everything up and then it
completed. That statement was coming from an EJB running in
Jaguar (I recognize the SQL statements) so that got me
thinking that possibly a connection was not closed and
something (as you indicated) was just doing some periodic
housecleaning (i.e. taking a connection out of a pool,
etc.). We have been fighting this random problem of
dbbackup hanging for a long time. We usually just restart
Jaguar and it frees it up but it is an annoying problem that
is driving me crazy. If there was a way to see what
transaction was open and what SQL statement it was hung on
when at the time it is occuring - my life would be
complete! I appreciate your response.