Issue Details (XML | Word | Printable)

Key: CORE-2286
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Dmitry Yemanov
Reporter: Nunzio Modesto
Votes: 1
Watchers: 2
Operations

If you were logged in you would be able to see more operations.
Firebird Core

Selecting from MON$CALL_STACK within a Trigger or SP sometimes return 0 rows.

Created: 21/Jan/09 01:09 PM   Updated: 23/Apr/13 11:45 AM
Component/s: Engine
Affects Version/s: 2.1.2, 2.1.3, 3.0 Initial, 2.5.0, 2.1.4
Fix Version/s: 2.1.5, 2.5.2, 3.0 Alpha 1

Time Tracking:
Not Specified

Environment: PC Windows Vista Business 32 - 4GB Ram

Planning Status: Unspecified


 Description  « Hide
Selecting from MON$CALL_STACK within a Trigger or SP sometimes return 0 rows especially when the trigger is fired by a Foreign Key with cascade on update.

Metadata of the trigger :

Note:
If uncomment the first select in the trigger body it will return rows, but sometimes when the trigger is fired frequently in the same transaction it keeps returning the same set of rows instead the real call stack.)

CREATE OR ALTER TRIGGER ART_COLORI_AIUD0 FOR ART_COLORI
ACTIVE AFTER INSERT OR UPDATE OR DELETE POSITION 0
AS
DECLARE VARIABLE STK_COUNT INTEGER;
BEGIN
  --SELECT COUNT(*) FROM MON$CALL_STACK INTO :STK_COUNT;

  INSERT INTO CALL_STACK (MON$OBJECT_NAME) VALUES ('***************** begin ------');
  INSERT INTO CALL_STACK (MON$CALL_ID,
                          MON$STATEMENT_ID,
                          MON$CALLER_ID,
                          MON$OBJECT_NAME,
                          MON$OBJECT_TYPE,
                          MON$TIMESTAMP,
                          MON$SOURCE_LINE,
                          MON$SOURCE_COLUMN,
                          MON$STAT_ID)
  SELECT
    CS.* FROM MON$CALL_STACK CS
    LEFT JOIN MON$STATEMENTS ST ON (CS.MON$STATEMENT_ID = ST.MON$STATEMENT_ID)
  WHERE
    ST.MON$TRANSACTION_ID = CURRENT_TRANSACTION
  ORDER BY MON$CALL_ID ASC;
  INSERT INTO CALL_STACK (MON$OBJECT_NAME) VALUES ('************** end -----');
END

 All   Comments   Work Log   Change History   Version Control   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Dmitry Yemanov added a comment - 21/Jan/09 01:30 PM
The monitoring information snapshot is created upon the first reference to the MON$ tables and cached until the transaction completion. So any subsequent queries are expected to return the same set of rows.

Sean Leyne added a comment - 21/Jan/09 10:37 PM
Nunzio,

My sense of the example you provided is that you really are looking for database/SQL traceing which is a different function from what the MON$ tables are for. The SQL traceing functionality (SQL Trace) is scheduled to be introduced in the v2.5 release.

Nunzio Modesto added a comment - 22/Jan/09 05:09 AM
I just made the example that write the content of the mon$table in a persistent table on the database to figure out what was in the mon$call_stack table.

according to what Dimitry said the snapshot of the mon$ table is generated when I first reference the table itself, that's ok it make sense now why I always got the same set of records.

I'm using FB 2.1.2 so to solve that problem I wrote a UDF that allow me to check the mon$ table in a separate transaction/connection and it works ok (I'll drop that when the v2.5 will be released and I'll use the AUTONOMOUS TRANSACTION feature)

But the problem that sometimes the mon$call_stack returns 0 rows remains, and since the query is done inside a trigger there should be at least one row.

Dmitry Yemanov added a comment - 22/Jan/09 05:15 AM
Can you be sure that the failing query is always the first monitoring request in that transaction? Maybe zero rows is an already cached result?

Nunzio Modesto added a comment - 22/Jan/09 09:14 AM
Here's my test scenario

a UDF with a function name "udf_StackStatusOK" that does only the following in the given order:
- open a new connection to the database
- start a new transaction
- execute this query : SELECT MON$CALL_ID, MON$CALLER_ID, MON$OBJECT_NAME FROM MON$CALL_STACK
- dump the content to a log file
- close transaction
- close connection
- return a integer value always 1

Table TABLE1 with the following metadata:
- ID INTEGER (Primary Key)
- TEST VARCHAR(10)

Trigger TABLE1_AIUD0 on TABLE1 (after inser,update,delete):
- It only call the UDF Function (SELECT udf_StackStatusOK('TEST') FROM RDB$DATABASE INTO....)

Stored Procedure PERFORM_TEST which execute the following:
- UPDATE TABLE1 SET TEST = 'OK' WHERE ID = 1;
- UPDATE TABLE1 SET TEST = 'OK' WHERE ID = 2;
  
That's what I expected when I execute the procedure :
-- first update in SP with ID = 1 --
Trigger TABLE1_AIUD0
called by Stored Proc PERFORM_TEST
-- second update SP with ID = 1 --
Trigger TABLE1_AIUD0
called by Stored Proc PERFORM_TEST

That's what I get when I execute the procedure :
-- first update in SP with ID = 1 --
Trigger TABLE1_AIUD0
called by Stored Proc PERFORM_TEST
-- second update SP with ID = 1 --
< no records in mon$call_stack>

I also noted that the value of MON$CALLER_ID refers to a value not present
in table MON$CALL_STACK when a FOREIGN KEY with CASCADE on update attempt to
update the value of child tables.

Riccardo Fiorenza added a comment - 26/Jan/09 07:28 AM
Hi, I have the same problem with monitoring table MON$CALL_STACK and this configuration:
Firebird 2.1.1 on Windows XP SP3.

I have two simple tables ("TAB_H" and "TAB_R") with trigger ("TAB_H_AI0" and "TAB_R_AI0") after insert to capture the records from MON$CALL_STACK.

If I execute two INSERT queries inside the "SHOW_BUG" procedure on the tables "TAB_H" and "TAB_R", the first INSERT query on "TAB_H" returning a right call_stack while the second INSERT query on "TAB_R" show the same call_stack registered at the previous INSERT query on "TAB_H".
(show query C)

If I execute separatly the two INSERT queries then it's all ok without the bug.
(show queries A and B)

To reproduce this bug please create the following db structure (4 tables + 1 procedure),
and then exec these queries:
A) SELECT * FROM TEST_BUG('TAB_H');
B) SELECT * FROM TEST_BUG('TAB_R');
C) SELECT * FROM TEST_BUG(NULL);

The queries A) and B) are ok (NO BUG), while the query C) is wrong (BUG SHOWED).

Thank you,
Riccardo Fiorenza

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

CREATE TABLE CALL_STACK_H (
    MON$CALL_ID INTEGER,
    MON$STATEMENT_ID INTEGER,
    MON$CALLER_ID INTEGER,
    MON$OBJECT_NAME CHAR(31) CHARACTER SET UNICODE_FSS,
    MON$OBJECT_TYPE SMALLINT,
    MON$TIMESTAMP TIMESTAMP,
    MON$SOURCE_LINE INTEGER,
    MON$SOURCE_COLUMN INTEGER,
    MON$STAT_ID INTEGER
);

CREATE TABLE CALL_STACK_R (
    MON$CALL_ID INTEGER,
    MON$STATEMENT_ID INTEGER,
    MON$CALLER_ID INTEGER,
    MON$OBJECT_NAME CHAR(31) CHARACTER SET UNICODE_FSS,
    MON$OBJECT_TYPE SMALLINT,
    MON$TIMESTAMP TIMESTAMP,
    MON$SOURCE_LINE INTEGER,
    MON$SOURCE_COLUMN INTEGER,
    MON$STAT_ID INTEGER
);

CREATE TABLE TAB_H (
    TMS TIMESTAMP DEFAULT CURRENT_TIMESTAMP NOT NULL
);

CREATE TABLE TAB_R (
    TMS TIMESTAMP DEFAULT CURRENT_TIMESTAMP NOT NULL
);

SET TERM ^ ;

/* Trigger: TAB_H_AI0 */
CREATE TRIGGER TAB_H_AI0 FOR TAB_H
ACTIVE AFTER INSERT POSITION 0
AS
begin
  INSERT INTO CALL_STACK_H SELECT * FROM MON$CALL_STACK;
end
^

/* Trigger: TAB_R_AI0 */
CREATE TRIGGER TAB_R_AI0 FOR TAB_R
ACTIVE AFTER INSERT POSITION 0
AS
begin
  INSERT INTO CALL_STACK_R SELECT * FROM MON$CALL_STACK;
end
^

CREATE OR ALTER PROCEDURE TEST_BUG (
    TODO_INSERT_ONLY_ON CHAR(31) CHARACTER SET UNICODE_FSS)
RETURNS (
    CALL_STACK_TABLE CHAR(31) CHARACTER SET UNICODE_FSS,
    MON$CALL_ID INTEGER,
    MON$STATEMENT_ID INTEGER,
    MON$CALLER_ID INTEGER,
    MON$OBJECT_NAME CHAR(31) CHARACTER SET UNICODE_FSS,
    MON$OBJECT_TYPE SMALLINT,
    MON$TIMESTAMP TIMESTAMP,
    MON$SOURCE_LINE INTEGER,
    MON$SOURCE_COLUMN INTEGER,
    MON$STAT_ID INTEGER)
AS
begin
  -- Empty Cloned CALL_STACK Tables
  DELETE FROM CALL_STACK_H;
  DELETE FROM CALL_STACK_R;
  --
  if ((:TODO_INSERT_ONLY_ON IS NULL) OR (TODO_INSERT_ONLY_ON='TAB_H')) then
  begin
      INSERT INTO TAB_H(TMS) VALUES(CURRENT_TIMESTAMP);
  end
  if ((:TODO_INSERT_ONLY_ON IS NULL) OR (TODO_INSERT_ONLY_ON='TAB_R')) then
  begin
      INSERT INTO TAB_R(TMS) VALUES(CURRENT_TIMESTAMP);
  end
  -- Show Cloned CALL_STACK Records
  FOR
    SELECT 'CALL_STACK_H', MON$CALL_ID, MON$STATEMENT_ID, MON$CALLER_ID, MON$OBJECT_NAME, MON$OBJECT_TYPE, MON$TIMESTAMP, MON$SOURCE_LINE, MON$SOURCE_COLUMN, MON$STAT_ID FROM CALL_STACK_H
      UNION
    SELECT 'CALL_STACK_R', MON$CALL_ID, MON$STATEMENT_ID, MON$CALLER_ID, MON$OBJECT_NAME, MON$OBJECT_TYPE, MON$TIMESTAMP, MON$SOURCE_LINE, MON$SOURCE_COLUMN, MON$STAT_ID FROM CALL_STACK_R
    INTO :CALL_STACK_TABLE, :MON$CALL_ID, :MON$STATEMENT_ID, :MON$CALLER_ID, :MON$OBJECT_NAME, :MON$OBJECT_TYPE, :MON$TIMESTAMP, :MON$SOURCE_LINE, :MON$SOURCE_COLUMN, :MON$STAT_ID
  DO
    suspend;
end
^

SET TERM ; ^

COMMENT ON PARAMETER TEST_BUG.TODO_INSERT_ONLY_ON IS
'IF NULL => INSERT INTO TAB_H AND TAB_R TABLES';

/* Privileges of users */
GRANT ALL ON CALL_STACK_H TO PUBLIC;
GRANT ALL ON CALL_STACK_R TO PUBLIC;

/* Privileges of procedures */
GRANT SELECT, DELETE ON CALL_STACK_H TO PROCEDURE SHOW_BUG;
GRANT SELECT, DELETE ON CALL_STACK_R TO PROCEDURE SHOW_BUG;
GRANT INSERT ON TAB_H TO PROCEDURE SHOW_BUG;
GRANT INSERT ON TAB_R TO PROCEDURE SHOW_BUG;

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

Dmitry Yemanov added a comment - 26/Jan/09 09:14 AM
Riccardo, as it has been explained above, this is not a bug but the expected behavior.

Riccardo Fiorenza added a comment - 26/Jan/09 10:34 AM
Hm... ok... sorry, but for my scenario I believe that it's a real bug (or a real problem).

Have you tested my reported steps writed to repeat the bug ?

Can you explain me why it's not a bug ?

It's better that I will open a new report bug for my specific issue.

Dmitry Yemanov added a comment - 26/Jan/09 12:26 PM
Yes, I've tested your example and it works exactly the way I expect it to. Please read my other comments in this ticket for the explanation.

Riccardo Fiorenza added a comment - 26/Jan/09 12:44 PM
Ok, thanks... I understand the problem.

I will try to request this feature to allow re-generation of monitoring snapshot during the same transaction life.

P.S.
I need to know at runtime (inside a my trigger) if a specified query is the "low-level item" (level 0) of the call stack.
There is a different strategy to make this, without MON$CALL_STACK ?

Thank for all.

Dmitry Yemanov added a comment - 29/Aug/11 05:33 PM
Finally, I can confirm that sometimes the call stack could be empty if selected from inside a procedure or trigger, even if it was the first access to the MON$ tables in this transaction. So the issue actually exists, except the per transaction persistence specifics commented above.