More than one CURRENT TIMESTAMP in a PROCEDURE

[Brian Tkatch]

I have a PROCEDURE that test other PROCEDUREs.

Timings_Call
------------------
Id
Group
Name
Text

Timings_Log
------------------
Id
Call
Start
Stop

Call gets populated and Log is to keep the times.

Data similar to:

INSERT INTO Timings_Call (Group, Name, Text) VALUES
('Report 1', 'Single', 'Report_001_SP(''values'', ...)'),
('Report 1', 'All', 'Report_001_SP(''values'', ...)'),
('Report 2', '', 'Report_002_SP(''values'', ...)'),
('Report 3', '', 'Report_003_SP(''values'', ...)')

A script runs the tests:

#!/bin/bash

db2 +o "CONNECT TO ..."
db2 +o "SET SCHEMA ..."
db2 +o "SET PATH ..., CURRENT PATH"
eval "$(db2 -x "SELECT 'db2 +o \"CALL Test_Timings_Call(' || CHAR(Id)
|| ')\"' FROM Timings_Call")"
db2 +o "CONNECT RESET"
db2 +o "TERMINATE"

which CALLs a PROCEDURE:

DROP SPECIFIC PROCEDURE Test_Timings_Call

CREATE PROCEDURE Test_Timings_Call(IN_Id INT)
SPECIFIC Test_Timings_Call
BEGIN

DECLARE Start_Time TIMESTAMP;
DECLARE Stop_Time TIMESTAMP;
DECLARE Query VARCHAR(256);

SELECT Text INTO Query FROM Timings_Call
WHERE Timings_Call.Id = IN_Id;

SET Start_Time = CURRENT TIMESTAMP;
EXECUTE IMMEDIATE Query;
SET Stop_Time = CURRENT TIMESTAMP;

INSERT INTO Timings_Log(Call, Start, Stop)
VALUES(IN_Id, Start_Time, Stop_Time);

END

The problem is the times in the TABLE are not accurate. As a test, from
a Windows client box, i cut and pasted a script:

C:\Program Files\SQLLIB\BIN>db2 -x VALUES CURRENT TIMESTAMP
2006-03-01-13.46.36.543961

C:\Program Files\SQLLIB\BIN>db2 +o "CALL Test_Timings_Call(13)"

C:\Program Files\SQLLIB\BIN>db2 -x VALUES CURRENT TIMESTAMP
2006-03-01-13.48.20.096003

C:\Program Files\SQLLIB\BIN>
C:\Program Files\SQLLIB\BIN>db2 "SELECT * FROM Timings_Log WHERE Call =
13"

ID CALL START STOP
----------- ----------- --------------------------
--------------------------
13 13 2006-02-22-11.26.45.724546
2006-02-22-11.26.45.806898
50 13 2006-02-24-10.50.24.530798
2006-02-24-10.50.24.605326
83 13 2006-02-28-16.24.48.837816
2006-02-28-16.24.48.845906
84 13 2006-03-01-13.46.36.690016
2006-03-01-13.46.36.744089

4 record(s) selected.

The command line CURRENT TIMESTAMPs show the query taking about 1.45
minutes. The log, however, shows it as less than a second.

What is happening here? And, how would i go about getting the actual
time?

B.

[Dj]

I'm not sure what you are realy trying to get, but have you tired using
DB2batch.
It will give you what I think you could be looking for.

"Brian Tkatch" <Ma***********@ThePentagon.com> wrote in message
news:11**********************@i40g2000cwc.googlegr oups.com...

I have a PROCEDURE that test other PROCEDUREs.

Timings_Call
------------------
Id
Group
Name
Text

Timings_Log
------------------
Id
Call
Start
Stop

Call gets populated and Log is to keep the times.

Data similar to:

INSERT INTO Timings_Call (Group, Name, Text) VALUES
('Report 1', 'Single', 'Report_001_SP(''values'', ...)'),
('Report 1', 'All', 'Report_001_SP(''values'', ...)'),
('Report 2', '', 'Report_002_SP(''values'', ...)'),
('Report 3', '', 'Report_003_SP(''values'', ...)')

A script runs the tests:

#!/bin/bash

db2 +o "CONNECT TO ..."
db2 +o "SET SCHEMA ..."
db2 +o "SET PATH ..., CURRENT PATH"
eval "$(db2 -x "SELECT 'db2 +o \"CALL Test_Timings_Call(' || CHAR(Id)
|| ')\"' FROM Timings_Call")"
db2 +o "CONNECT RESET"
db2 +o "TERMINATE"

which CALLs a PROCEDURE:

DROP SPECIFIC PROCEDURE Test_Timings_Call

CREATE PROCEDURE Test_Timings_Call(IN_Id INT)
SPECIFIC Test_Timings_Call
BEGIN

DECLARE Start_Time TIMESTAMP;
DECLARE Stop_Time TIMESTAMP;
DECLARE Query VARCHAR(256);

SELECT Text INTO Query FROM Timings_Call
WHERE Timings_Call.Id = IN_Id;

SET Start_Time = CURRENT TIMESTAMP;
EXECUTE IMMEDIATE Query;
SET Stop_Time = CURRENT TIMESTAMP;

INSERT INTO Timings_Log(Call, Start, Stop)
VALUES(IN_Id, Start_Time, Stop_Time);

END

The problem is the times in the TABLE are not accurate. As a test, from
a Windows client box, i cut and pasted a script:

C:\Program Files\SQLLIB\BIN>db2 -x VALUES CURRENT TIMESTAMP
2006-03-01-13.46.36.543961

C:\Program Files\SQLLIB\BIN>db2 +o "CALL Test_Timings_Call(13)"

C:\Program Files\SQLLIB\BIN>db2 -x VALUES CURRENT TIMESTAMP
2006-03-01-13.48.20.096003

C:\Program Files\SQLLIB\BIN>
C:\Program Files\SQLLIB\BIN>db2 "SELECT * FROM Timings_Log WHERE Call =
13"

ID CALL START STOP
----------- ----------- --------------------------
--------------------------
13 13 2006-02-22-11.26.45.724546
2006-02-22-11.26.45.806898
50 13 2006-02-24-10.50.24.530798
2006-02-24-10.50.24.605326
83 13 2006-02-28-16.24.48.837816
2006-02-28-16.24.48.845906
84 13 2006-03-01-13.46.36.690016
2006-03-01-13.46.36.744089

4 record(s) selected.

The command line CURRENT TIMESTAMPs show the query taking about 1.45
minutes. The log, however, shows it as less than a second.

What is happening here? And, how would i go about getting the actual
time?

B.

[Brian Tkatch]

>I'm not sure what you are realy trying to get

Mainly, the how long it takes to run a bunch of PROCEDUREs. With the
results stored in a TABLE.

What i posted above does all that, except the timing. Specifically:

SET Start_Time = CURRENT TIMESTAMP;
EXECUTE IMMEDIATE Query;
SET Stop_Time = CURRENT TIMESTAMP;

puts Stop_Time less than a second after Start_Time, even when the CALL
takes over a minute.

The questions are:

1) Why is the second SET statement executed before the EXECUTE
IMMEDIATE finishes?
2) How can i get the timing after it finishes?

but have you tired using DB2batch.

No, but per your suggestion i did.

bash-2.05$ echo "CALL schema.proc(parm1, ?, ?);" > a
bash-2.05$ db2batch -d dbname -f a -a user/pass -i complete -s on

ERROR!!! -> Auto-bind was not successful
Make sure bind file is in path
Type "db2batch -h" for more help

The CALL works in the CLP. I cut&pasted it without the trailing
semicolon.

Regardless, i don't see how this would retrieve the list of CALLs to
make from the DB and then put the timings back into the DB. Although,
its description looks nice otherwise.

B.

[Brian Tkatch]

The PROCEDUREs being CALLed all use DECLARE CURSOR WITH RETURN TO
CLIENT. My guess is, the EXECUTE IMMEDIATE doesn't actually execute the
CURSOR, rahter it just puts the CURSOR into a queue, and after the
CALLing PROCEDURE exists, the client runs it.

This means the (unix) script will have to SET the timing.

B.

[Knut Stolze]

Brian Tkatch wrote:

The PROCEDUREs being CALLed all use DECLARE CURSOR WITH RETURN TO
CLIENT. My guess is, the EXECUTE IMMEDIATE doesn't actually execute the
CURSOR, rahter it just puts the CURSOR into a queue, and after the
CALLing PROCEDURE exists, the client runs it.

A DECLARE CURSOR checks that the tables exist and the user has all the
necessary privileges. It also compiles the SQL statement and generates the
access plan. But it does _not_ execute the statement and, thus, no time is
spend during run time. For that you will have to OPEN the cursor and fetch
its results as DB2 will only do something when it really has to, i.e. when
you actually fetch the data from the result set.

So when you call the procedure at the CLP, DB2 will return the result set
and the DB2 CLP will take care of fetching all the rows for you.

And another point regarding db2batch: you can see how much time is spent
during the query compilation, the execution, and the fetch phases.

--
Knut Stolze
DB2 Information Integration Development
IBM Germany

[Brian Tkatch]

I appreciate the explanation.

As i reported, db2batch just gave me an error.

My current scheme is:

eval "$(db2 -x "SELECT 'db2 +o \"CALL Test_Timings_Call(' || CHAR(Id)
|| ')\" && db2 +o \"UPDATE Timings_Log SET Stop = CURRENT TIMESTAMP
WHERE Stop IS NULL\"' FROM Timings_Call")"

Though, i still have to test it.

B.

[Knut Stolze]

Brian Tkatch wrote:

I appreciate the explanation.

As i reported, db2batch just gave me an error.
Try db2batch on a simple "SELECT * FROM syscat.tables". If the bind error
does not disappear, just should have a look at the db2diag to see if
anything interesting appears there and resolve the issue.
My current scheme is:

eval "$(db2 -x "SELECT 'db2 +o \"CALL Test_Timings_Call(' || CHAR(Id)
|| ')\" && db2 +o \"UPDATE Timings_Log SET Stop = CURRENT TIMESTAMP
WHERE Stop IS NULL\"' FROM Timings_Call")"

What I might have missed is what you want to know: the execution time of the
procedure only or including the fetch time. Do you want to use this in a
production environment or for testing purposes?

--
Knut Stolze
DB2 Information Integration Development
IBM Germany

[Brian Tkatch]

>What I might have missed is what you want to know: the execution time of the

procedure only or including the fetch time.
The execution time, or perhaps even fetch time without the slowdown of
the network or printing on the screen.
Do you want to use this in a production environment or for testing purposes?

Are you asking where _i_ want it, or where i was told to put it? :)

It is to be used as a form of debugging if/when things slowdown. First
and foremost, fin if the problem is in the db, the network, or the
local client (VB program).

bash-2.05$ echo "SELECT * FROM syscat.tables" > a
bash-2.05$ db2batch -d dbname -f a -a user/pass -i complete -s on

ERROR!!! -> Could not connect to database, SQLCODE = -1013
Make sure database name is correct
Type "db2batch -h" for more help

So, i changed dbname to the actual dbname:

ERROR!!! -> Could not connect to database, SQLCODE = -30082
Make sure database name is correct
Type "db2batch -h" for more help

Progress....

changes user/pass to be actual user/pass:

ERROR!!! -> Auto-bind was not successful
Make sure bind file is in path
Type "db2batch -h" for more help

to check the file.....

bash-2.05$ db2 connect to
bash-2.05$ db2 -f a
[snip]
363 record(s) selected.

B.

[Knut Stolze]

Brian Tkatch wrote:

What I might have missed is what you want to know: the execution time of
the procedure only or including the fetch time.
The execution time, or perhaps even fetch time without the slowdown of
the network or printing on the screen.

I'll have to make up your mind about that. If you want to get the fetch
time, you will have to fetch all the results in the outer procedure. But
that discards your result set which the caller might actually be interested
in. If you just want to have the execution time, I'd say that you already
got it with the mechanism you've shown here initially.

Do you want to use this in a production environment or for testing
purposes?

Are you asking where _i_ want it, or where i was told to put it? :)

I don't really want to know the answer to the 2nd part of that. ;-)
changes user/pass to be actual user/pass:

ERROR!!! -> Auto-bind was not successful
Make sure bind file is in path
Type "db2batch -h" for more help

Which messages are in the db2diag for the duration when the failure of the
auto-bind occurs?

--
Knut Stolze
DB2 Information Integration Development
IBM Germany

[Brian Tkatch]

> But that discards your result set which the caller might actually be interested in.

I do want to discard it. This is only timing db execution. Hmm... does
it grab I/o fetching as well (even though it is not displayed)?

I don't really want to know the answer to the 2nd part of that. ;-)
OK, ok, i guess i could have chosen better verbiage. :P
Which messages are in the db2diag for the duration when the failure of the auto-bind occurs?

That's not my domain.

bash-2.05$ db2diag
bash: db2diag: command not found

I could ask the DBA for help here, but if i have what i need already, i
maynot care to bother.

B.

[Knut Stolze]

Brian Tkatch wrote:

But that discards your result set which the caller might actually be
interested in.

I do want to discard it. This is only timing db execution. Hmm... does
it grab I/o fetching as well (even though it is not displayed)?

When you fetch the results, you will get the complete timing from when the
fetch "reached" the DB2 engine up to the point when the engine returns the
control to the caller (the procedure in your case). So if there is any I/O
necessary to get the rows, this will be included.

The I/O may be asynchronous or reduced by prefetching or by whatever else
goes on under the covers. But I don't think that this is of interest to
you.

Which messages are in the db2diag for the duration when the failure of the
auto-bind occurs?

That's not my domain.

bash-2.05$ db2diag
bash: db2diag: command not found

I could ask the DBA for help here, but if i have what i need already, i
maynot care to bother.

Maybe you simply don't have the privileges for the binding, given that you
are not DBA.

--
Knut Stolze
DB2 Information Integration Development
IBM Germany

[lennart]

Brian Tkatch wrote:

[...]

That's not my domain.

bash-2.05$ db2diag
bash: db2diag: command not found

Try:

bash-2.05$ locate db2diag.log

when you have located the file, search for the period of time when the
error occurs and investigate from there

[...]

/Lennart

[Brian Tkatch]

Good idea. This is Solaris, so no locate here. (At least it isn't a
valid command.)

dbdir...find . -name db2diag.log got it, cd to directory, and tail -f
on the file. Open a second session and run the command.

2006-03-03-14.09.36.562346 Instance:[instance] Node:000
PID:955(db2batch) TID:1 Appid:*LOCAL.[instance].003BC3190936
aps binder service sqlajbnd_process Probe:2817

Error code
0xFFBFC834 : 0xFFFFFDD9 ....

PID:955 TID:1 Node:000 Title: sqlaj_error_struct
Dump File:[dbdir]/sqllib/db2dump/9551.000

B.

[Knut Stolze]

Brian Tkatch wrote:

Good idea. This is Solaris, so no locate here. (At least it isn't a
valid command.)

dbdir...find . -name db2diag.log got it, cd to directory, and tail -f
on the file. Open a second session and run the command.

2006-03-03-14.09.36.562346 Instance:[instance] Node:000
PID:955(db2batch) TID:1 Appid:*LOCAL.[instance].003BC3190936
aps binder service sqlajbnd_process Probe:2817

Error code
0xFFBFC834 : 0xFFFFFDD9 ....

Now that is getting us somewhere... ;-)

0xFFFFFDD9 = -551

SQL0551N "<authorization-ID>" does not have the privilege to
perform operation "<operation>" on object
"<name>".

So you _are_ missing some privileges for the binding and your DBA should
probably run the db2batch once to get the bind resolved.

--
Knut Stolze
DB2 Information Integration Development
IBM Germany

[Brian Tkatch]

Thanx Knut, i appreciate it. I'll pass the link to the dba.

B.

[Patrick]

Brian Tkatch wrote:

But that discards your result set which the caller might actually be interested in.

I do want to discard it. This is only timing db execution. Hmm... does
it grab I/o fetching as well (even though it is not displayed)?

I don't really want to know the answer to the 2nd part of that. ;-)

OK, ok, i guess i could have chosen better verbiage. :P

Which messages are in the db2diag for the duration when the failure of the auto-bind occurs?

That's not my domain.

bash-2.05$ db2diag
bash: db2diag: command not found

I could ask the DBA for help here, but if i have what i need already, i
maynot care to bother.

B.

[Patrick]

The error message from the db2diag.log file he received is:

2006-03-03-11.42.48.213650 Instance:srvr1780 Node:000
PID:7699(db2batch) TID:1 Appid:*LOCAL.srvr1780.01E143164248
aps binder service sqlajbnd_process Probe:2817

Error code
0xFFBFC834 : 0xFFFFFDD9 ....

PID:7699 TID:1 Node:000 Title: sqlaj_error_struct
Dump File:/clocal/udb/srvr1780/sqllib/db2dump/76991.000


Brian Tkatch wrote:

But that discards your result set which the caller might actually be interested in.

I do want to discard it. This is only timing db execution. Hmm... does
it grab I/o fetching as well (even though it is not displayed)?

I don't really want to know the answer to the 2nd part of that. ;-)

OK, ok, i guess i could have chosen better verbiage. :P

Which messages are in the db2diag for the duration when the failure of the auto-bind occurs?

That's not my domain.

bash-2.05$ db2diag
bash: db2diag: command not found

I could ask the DBA for help here, but if i have what i need already, i
maynot care to bother.

B.