Hello Sean,
>>> I am also very skeptical about the "need" that to add this functionality to
>> the Trace API, as it falls into the area of PSQL debugging/profiling which
>> is not
>> what the current functionality is about*.
>>
>> I don't propose to extend the Trace API in a way, which goes into debuging a
>> stored procedure with all that stuff like local variable values etc.
>>
>> IMHO this should be part of a separate Debug API, which AFAIK has been
>> discussed in the past to expose something more reliable to third-party
>> developer tools like Database Workbench, IBExpert ... than what they
>> currently try to "simulate".
>
> I am happy that you agree with the general functional boundaries.
>
>
>> For databases, which are very PSQL-centric, which have a lot of business
>> logic
>> implemented in PSQL, the Trace API is not of that much use today,
>> because:
>>
>> * No I/O statistics for procedure/trigger trace events. According to Vlad, it
>> should be available, he has a look on that
>
> I agree that this is a problem.
I have to apologize, possibly there was a good reason that my first test
didn't show any I/O statistics, but running another test, I now get some
I/O statistics at EXECUTE_PROCEDURE_FINISH level. This is the test case:
* Trace configuration
<database tourism.fdb>
enabled true
log_statement_start true
log_statement_finish true
log_procedure_start true
log_procedure_finish true
print_plan true
print_perf true
time_threshold 0
max_sql_length 2048
</database>
<services>
</services>
* Stored Procedure
SET TERM ^^ ;
CREATE PROCEDURE P_ENDLESSLOOP (
TO_VALUE Integer DEFAULT 1000000)
returns (
I Integer)
AS
declare variable dummy integer;
begin
i = 1;
while (i <= to_value) do
begin
execute procedure p_donothing;
select 1 from rdb$database into :dummy;
i = i + 1;
end
end ^^
SET TERM ; ^^
So, a mix of DML inside the SP and a call of another SP.
* SP gets executed via:
execute procedure P_ENDLESSLOOP(2);
In this example, we get the following trace output:
2012-07-09T21:30:48.7160 (2656:0000000000E6D9E8) EXECUTE_STATEMENT_START
tourism.fdb (ATT_3758, TOURISM:NONE, UNICODE_FSS, TCPv4:127.0.0.1)
C:\Program Files (x86)\Upscene Productions\Database Workbench 4
Pro\DBW4.exe:4748
(TRA_180412, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)
Statement 154:
-------------------------------------------------------------------------------
execute procedure P_ENDLESSLOOP(2)
2012-07-09T21:30:48.7160 (2656:0000000000E6D9E8) EXECUTE_PROCEDURE_START
tourism.fdb (ATT_3758, TOURISM:NONE, UNICODE_FSS, TCPv4:127.0.0.1)
C:\Program Files (x86)\Upscene Productions\Database Workbench 4
Pro\DBW4.exe:4748
(TRA_180412, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)
Procedure P_ENDLESSLOOP:
param0 = integer, "2"
2012-07-09T21:30:48.7160 (2656:0000000000E6D9E8) EXECUTE_PROCEDURE_START
tourism.fdb (ATT_3758, TOURISM:NONE, UNICODE_FSS, TCPv4:127.0.0.1)
C:\Program Files (x86)\Upscene Productions\Database Workbench 4
Pro\DBW4.exe:4748
(TRA_180412, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)
Procedure P_DONOTHING:
2012-07-09T21:30:48.7160 (2656:0000000000E6D9E8) EXECUTE_PROCEDURE_FINISH
tourism.fdb (ATT_3758, TOURISM:NONE, UNICODE_FSS, TCPv4:127.0.0.1)
C:\Program Files (x86)\Upscene Productions\Database Workbench 4
Pro\DBW4.exe:4748
(TRA_180412, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)
Procedure P_DONOTHING:
0 ms
2012-07-09T21:30:48.7160 (2656:0000000000E6D9E8) EXECUTE_PROCEDURE_START
tourism.fdb (ATT_3758, TOURISM:NONE, UNICODE_FSS, TCPv4:127.0.0.1)
C:\Program Files (x86)\Upscene Productions\Database Workbench 4
Pro\DBW4.exe:4748
(TRA_180412, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)
Procedure P_DONOTHING:
2012-07-09T21:30:48.7160 (2656:0000000000E6D9E8) EXECUTE_PROCEDURE_FINISH
tourism.fdb (ATT_3758, TOURISM:NONE, UNICODE_FSS, TCPv4:127.0.0.1)
C:\Program Files (x86)\Upscene Productions\Database Workbench 4
Pro\DBW4.exe:4748
(TRA_180412, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)
Procedure P_DONOTHING:
0 ms
2012-07-09T21:30:48.7160 (2656:0000000000E6D9E8) EXECUTE_PROCEDURE_FINISH
tourism.fdb (ATT_3758, TOURISM:NONE, UNICODE_FSS, TCPv4:127.0.0.1)
C:\Program Files (x86)\Upscene Productions\Database Workbench 4
Pro\DBW4.exe:4748
(TRA_180412, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)
Procedure P_ENDLESSLOOP:
param0 = integer, "2"
0 ms, 10 fetch(es)
Table Natural Index Update Insert
Delete Backout Purge Expunge
***************************************************************************************************************
RDB$DATABASE 2
2012-07-09T21:30:48.7160 (2656:0000000000E6D9E8) EXECUTE_STATEMENT_FINISH
tourism.fdb (ATT_3758, TOURISM:NONE, UNICODE_FSS, TCPv4:127.0.0.1)
C:\Program Files (x86)\Upscene Productions\Database Workbench 4
Pro\DBW4.exe:4748
(TRA_180412, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)
Statement 154:
-------------------------------------------------------------------------------
execute procedure P_ENDLESSLOOP(2)
0 records fetched
0 ms, 10 fetch(es)
Table Natural Index Update Insert
Delete Backout Purge Expunge
***************************************************************************************************************
RDB$DATABASE 2
We see the same I/O statistics for both the EXECUTE_PROCEDURE_FINISH and
EXECUTE_STATEMENT_FINISH trace event.
>> * Call of procedures inside a PSQL module are traced with their according
>> procedure trace events, but no I/O statistics as above
>
> Here I am not sure, I would tend to think that the analysis of "overhead"
> within a PSQL module should be a debugging task.
>
> I am inclined to say that all I/O should be aggregated/reported at the module
> (directly called SP or primary invoked Trigger) level and not the sub-module
> level.
Hmm, I tend to agree, although I'm not sure if this is just a weak
moment, because Roger Federer won Wimbledon yesterday. :-)
>> * Embedded SQL statements in PSQL aren't available in the trace output,
>> which seems to be a current/technical restriction
>
> I agree that this is a problem. But as with above, the I/O should be
> aggregated/reported at the module (EXECUTE BLOCK/EXECUTE STATEMENT) level.
Hmm, see above. :-) IMHO, it would add value already at Trace output
level to focus/pin-point a problem for forthcoming debugging tasks more
easily. Perhaps this statistic information is easily available at
sub-module level.
Anyway, I think it would be useful to offer something like a "caller id"
in the procedure trace output, which basically is the statement id of
the calling DML statement. This way, we don't lose the context of a SP
call and it's higher-level DSQL statement.
Regards,
Thomas
> Sean
>
> ------------------------------------------------------------------------------
> Live Security Virtual Conference
> Exclusive live event will cover all the ways today's security and
> threat landscape has changed and how IT managers can respond. Discussions
> will include endpoint security, mobile security and the latest in malware
> threats. http://www.accelacomm.com/jaw/sfrnl04242012/114/50122263/
> Firebird-Devel mailing list, web interface at
> https://lists.sourceforge.net/lists/listinfo/firebird-devel
>
------------------------------------------------------------------------------
Live Security Virtual Conference
Exclusive live event will cover all the ways today's security and
threat landscape has changed and how IT managers can respond. Discussions
will include endpoint security, mobile security and the latest in malware
threats. http://www.accelacomm.com/jaw/sfrnl04242012/114/50122263/
Firebird-Devel mailing list, web interface at
https://lists.sourceforge.net/lists/listinfo/firebird-devel
