[
https://issues.apache.org/jira/browse/DERBY-7042?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16811686#comment-16811686
]
Rick Hillegas commented on DERBY-7042:
--------------------------------------
Thanks for those suggestions, Bryan. Attaching a new version of Derby7042.java.
This version adds another procedure which leaves more fingerprints in
derby.log. I also updated the script with the following changes:
* Moved the property-setting out of the script and onto the VM boot command,
just in case I'm misunderstanding when the properties take effect.
* Printed timestamps before and after the UPDATE statement.
* Increased the lock timeout to twice the length of the deadlock timeout.
* Performed two UPDATEs back-to-back.
I ran with the following trace properties:
{noformat}
-Dderby.storage.rowLocking=false \
-Dderby.locks.deadlockTimeout=5 \
-Dderby.locks.waitTimeout=10 \
-Dderby.locks.deadlockTrace=true \
-Dderby.locks.monitor=true \
-Dderby.language.logStatementText=true \
-Dderby.stream.error.logSeverityLevel=0 \
{noformat}
The revised experiment discloses the following behavior:
* The INSERT takes 10 seconds to run, the length of the lock timeout. Looking
inside derby.log, the 10 seconds elapse between the compilation and execution
of the insert trigger. The trigger compilation and execution occur AFTER the
execution of the INSERT statement.
* The first UPDATE takes 10 seconds to run, the length of the lock timeout. As
with the INSERT statement, the 10 seconds elapse between the compilation and
execution of the update trigger. The trigger compilation and execution occur
AFTER the execution of the UPDATE statement.
* The second UPDATE executes immediately. There is no pause between the
compilation and execution of the update trigger.
* There are no timeout or deadlock diagnostics in derby.log. However, there are
transaction ids on the statements. It appears that the triggers are being
compiled in the same transaction as their triggering statements.
Maybe, somehow, the table-level lock forced by derby.storage.rowLocking=false
is interfering with the compilation of the triggers. The second execution goes
fast because the triggers are already compiled and sitting in the statement
cache.
Here is the revised script:
{noformat}
connect 'jdbc:derby:memory:db1;create=true';
-- create schema
CREATE TABLE ZooAnimals
(
Name VARCHAR(255),
Amount INT,
Feed BOOLEAN,
Zoo VARCHAR(255)
)
;
CREATE PROCEDURE helloDML(dml varchar(100))
LANGUAGE JAVA
EXTERNAL NAME 'Derby7042.helloDML'
PARAMETER STYLE JAVA
NO SQL
;
CREATE TRIGGER ZooUpdateTrigger
AFTER UPDATE ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('UPDATE')
;
CREATE TRIGGER ZooInsertTrigger
AFTER INSERT ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('INSERT')
;
CREATE TRIGGER ZooDeleteTrigger
AFTER DELETE ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('DELETE')
;
-- populate table. this takes 10 seconds, the length of the lock timeout.
VALUES CURRENT_TIMESTAMP;
INSERT INTO ZooAnimals (Name, Amount, Feed, Zoo) VALUES ('Gorilla', 1, true,
'Cincinnati');
VALUES CURRENT_TIMESTAMP;
SELECT * FROM ZooAnimals;
-- reboot to flush the statement cache.
connect 'jdbc:derby:memory:db1;shutdown=true';
connect 'jdbc:derby:memory:db1';
-- update table. the UPDATE takes 10 seconds, the length of the lock timeout.
VALUES CURRENT_TIMESTAMP;
UPDATE ZooAnimals SET Name = 'Aardvark' WHERE Zoo = 'Cincinnati';
VALUES CURRENT_TIMESTAMP;
SELECT * FROM ZooAnimals;
-- try it again. the UPDATE runs immediately.
VALUES CURRENT_TIMESTAMP;
UPDATE ZooAnimals SET Name = 'Alligator' WHERE Zoo = 'Cincinnati';
VALUES CURRENT_TIMESTAMP;
SELECT * FROM ZooAnimals;
{noformat}
Here is its output:
{noformat}
ij version 10.16
ij> connect 'jdbc:derby:memory:db1;create=true';
ij> -- create schema
CREATE TABLE ZooAnimals
(
Name VARCHAR(255),
Amount INT,
Feed BOOLEAN,
Zoo VARCHAR(255)
)
;
0 rows inserted/updated/deleted
ij> CREATE PROCEDURE helloDML(dml varchar(100))
LANGUAGE JAVA
EXTERNAL NAME 'Derby7042.helloDML'
PARAMETER STYLE JAVA
NO SQL
;
0 rows inserted/updated/deleted
ij> CREATE TRIGGER ZooUpdateTrigger
AFTER UPDATE ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('UPDATE')
;
0 rows inserted/updated/deleted
ij> CREATE TRIGGER ZooInsertTrigger
AFTER INSERT ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('INSERT')
;
0 rows inserted/updated/deleted
ij> CREATE TRIGGER ZooDeleteTrigger
AFTER DELETE ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('DELETE')
;
0 rows inserted/updated/deleted
ij> -- populate table. this takes 10 seconds, the length of the lock timeout.
VALUES CURRENT_TIMESTAMP;
1
-----------------------------
2019-04-06 12:57:55.049
1 row selected
ij> INSERT INTO ZooAnimals (Name, Amount, Feed, Zoo) VALUES ('Gorilla', 1,
true, 'Cincinnati');
Hello INSERT
1 row inserted/updated/deleted
ij> VALUES CURRENT_TIMESTAMP;
1
-----------------------------
2019-04-06 12:58:05.173
1 row selected
ij> SELECT * FROM ZooAnimals;
NAME
|AMOUNT |FEED |ZOO
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Gorilla
|1 |true |Cincinnati
1 row selected
ij> -- reboot to flush the statement cache.
connect 'jdbc:derby:memory:db1;shutdown=true';
ERROR 08006: Database 'memory:db1' shutdown.
ij> connect 'jdbc:derby:memory:db1';
ij(CONNECTION1)> -- update table. the UPDATE takes 10 seconds, the length of
the lock timeout.
VALUES CURRENT_TIMESTAMP;
1
-----------------------------
2019-04-06 12:58:05.286
1 row selected
ij(CONNECTION1)> UPDATE ZooAnimals SET Name = 'Aardvark' WHERE Zoo =
'Cincinnati';
Hello UPDATE
1 row inserted/updated/deleted
ij(CONNECTION1)> VALUES CURRENT_TIMESTAMP;
1
-----------------------------
2019-04-06 12:58:15.379
1 row selected
ij(CONNECTION1)> SELECT * FROM ZooAnimals;
NAME
|AMOUNT |FEED |ZOO
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aardvark
|1 |true |Cincinnati
1 row selected
ij(CONNECTION1)> -- try it again. the UPDATE runs immediately.
VALUES CURRENT_TIMESTAMP;
1
-----------------------------
2019-04-06 12:58:15.389
1 row selected
ij(CONNECTION1)> UPDATE ZooAnimals SET Name = 'Alligator' WHERE Zoo =
'Cincinnati';
Hello UPDATE
1 row inserted/updated/deleted
ij(CONNECTION1)> VALUES CURRENT_TIMESTAMP;
1
-----------------------------
2019-04-06 12:58:15.4
1 row selected
ij(CONNECTION1)> SELECT * FROM ZooAnimals;
NAME
|AMOUNT |FEED |ZOO
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Alligator
|1 |true |Cincinnati
1 row selected
{noformat}
Here are the contents of derby.log:
{noformat}
----------------------------------------------------------------
Sat Apr 06 12:57:54 PDT 2019:
Booting Derby version The Apache Software Foundation - Apache Derby - 10.16.0.0
alpha - (1856150:1856701M): instance a816c00e-0169-f43a-9524-000007258cc8
on database directory memory:/Users/rhillegas/derby/mainline/db1 with class
loader jdk.internal.loader.ClassLoaders$AppClassLoader@484b61fc
Loaded from file:/Users/rhillegas/derby/mainline/trunk/jars/sane/derby.jar
java.vendor=Oracle Corporation
java.runtime.version=9+181
user.dir=/Users/rhillegas/derby/mainline
os.name=Mac OS X
os.arch=x86_64
os.version=10.14.2
derby.system.home=null
Database Class Loader started - derby.database.classpath=''
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 165), (SESSIONID = 0),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 165), (SESSIONID = 0),
(DATABASE = memory:db1), (DRDAID = null), Rolling back
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 166), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 167), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
-- create schema
CREATE TABLE ZooAnimals
(
Name VARCHAR(255),
Amount INT,
Feed BOOLEAN,
Zoo VARCHAR(255)
)
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 167), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement: --
create schema
CREATE TABLE ZooAnimals
(
Name VARCHAR(255),
Amount INT,
Feed BOOLEAN,
Zoo VARCHAR(255)
)
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 167), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: --
create schema
CREATE TABLE ZooAnimals
(
Name VARCHAR(255),
Amount INT,
Feed BOOLEAN,
Zoo VARCHAR(255)
)
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 167), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 170), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
CREATE PROCEDURE helloDML(dml varchar(100))
LANGUAGE JAVA
EXTERNAL NAME 'Derby7042.helloDML'
PARAMETER STYLE JAVA
NO SQL
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 170), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
CREATE PROCEDURE helloDML(dml varchar(100))
LANGUAGE JAVA
EXTERNAL NAME 'Derby7042.helloDML'
PARAMETER STYLE JAVA
NO SQL
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 170), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: CREATE
PROCEDURE helloDML(dml varchar(100))
LANGUAGE JAVA
EXTERNAL NAME 'Derby7042.helloDML'
PARAMETER STYLE JAVA
NO SQL
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 170), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 173), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
CREATE TRIGGER ZooUpdateTrigger
AFTER UPDATE ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('UPDATE')
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 173), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
CREATE TRIGGER ZooUpdateTrigger
AFTER UPDATE ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('UPDATE')
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 173), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: CREATE
TRIGGER ZooUpdateTrigger
AFTER UPDATE ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('UPDATE')
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 173), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
CALL "APP"."HELLODML"('UPDATE') :End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 173), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
CALL "APP"."HELLODML"('UPDATE') :End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 173), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 177), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
CREATE TRIGGER ZooInsertTrigger
AFTER INSERT ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('INSERT')
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 177), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
CREATE TRIGGER ZooInsertTrigger
AFTER INSERT ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('INSERT')
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 177), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: CREATE
TRIGGER ZooInsertTrigger
AFTER INSERT ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('INSERT')
:End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 177), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
CALL "APP"."HELLODML"('INSERT') :End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 177), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
CALL "APP"."HELLODML"('INSERT') :End prepared statement
Sat Apr 06 12:57:54 PDT 2019 Thread[main,5,main] (XID = 177), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 182), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
CREATE TRIGGER ZooDeleteTrigger
AFTER DELETE ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('DELETE')
:End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 182), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
CREATE TRIGGER ZooDeleteTrigger
AFTER DELETE ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('DELETE')
:End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 182), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: CREATE
TRIGGER ZooDeleteTrigger
AFTER DELETE ON ZOOANIMALS FOR EACH STATEMENT MODE DB2SQL
CALL helloDML('DELETE')
:End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 182), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
CALL "APP"."HELLODML"('DELETE') :End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 182), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
CALL "APP"."HELLODML"('DELETE') :End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 182), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
-- populate table. this takes 10 seconds, the length of the lock timeout.
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement: --
populate table. this takes 10 seconds, the length of the lock timeout.
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: --
populate table. this takes 10 seconds, the length of the lock timeout.
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
INSERT INTO ZooAnimals (Name, Amount, Feed, Zoo) VALUES ('Gorilla', 1, true,
'Cincinnati') :End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
INSERT INTO ZooAnimals (Name, Amount, Feed, Zoo) VALUES ('Gorilla', 1, true,
'Cincinnati') :End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: INSERT
INTO ZooAnimals (Name, Amount, Feed, Zoo) VALUES ('Gorilla', 1, true,
'Cincinnati') :End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
CALL "APP"."HELLODML"('INSERT') :End prepared statement
Sat Apr 06 12:57:55 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
CALL "APP"."HELLODML"('INSERT') :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: CALL
"APP"."HELLODML"('INSERT') :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 187), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 193), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 193), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 193), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: VALUES
CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 193), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 193), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 193), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
SELECT * FROM ZooAnimals :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 193), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
SELECT * FROM ZooAnimals :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 193), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: SELECT
* FROM ZooAnimals :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 193), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 193), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 196), (SESSIONID = 2),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 196), (SESSIONID = 2),
(DATABASE = memory:db1), (DRDAID = null), Rolling back
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 197), (SESSIONID = 3),
(DATABASE = memory:db1), (DRDAID = null), Committing
----------------------------------------------------------------
Sat Apr 06 12:58:05 PDT 2019:
Shutting down instance a816c00e-0169-f43a-9524-000007258cc8 on database
directory memory:/Users/rhillegas/derby/mainline/db1 with class loader
jdk.internal.loader.ClassLoaders$AppClassLoader@484b61fc
----------------------------------------------------------------
Sat Apr 06 12:58:05 PDT 2019:
Booting Derby version The Apache Software Foundation - Apache Derby - 10.16.0.0
alpha - (1856150:1856701M): instance 0a594127-0169-f43a-9524-000007258cc8
on database directory memory:/Users/rhillegas/derby/mainline/db1 with class
loader jdk.internal.loader.ClassLoaders$AppClassLoader@484b61fc
Loaded from file:/Users/rhillegas/derby/mainline/trunk/jars/sane/derby.jar
java.vendor=Oracle Corporation
java.runtime.version=9+181
user.dir=/Users/rhillegas/derby/mainline
os.name=Mac OS X
os.arch=x86_64
os.version=10.14.2
derby.system.home=null
Database Class Loader started - derby.database.classpath=''
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 203), (SESSIONID = 0),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 203), (SESSIONID = 0),
(DATABASE = memory:db1), (DRDAID = null), Rolling back
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 204), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
-- update table. the UPDATE takes 10 seconds, the length of the lock timeout.
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement: --
update table. the UPDATE takes 10 seconds, the length of the lock timeout.
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: --
update table. the UPDATE takes 10 seconds, the length of the lock timeout.
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
UPDATE ZooAnimals SET Name = 'Aardvark' WHERE Zoo = 'Cincinnati' :End prepared
statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
UPDATE ZooAnimals SET Name = 'Aardvark' WHERE Zoo = 'Cincinnati' :End prepared
statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: UPDATE
ZooAnimals SET Name = 'Aardvark' WHERE Zoo = 'Cincinnati' :End prepared
statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
CALL "APP"."HELLODML"('UPDATE') :End prepared statement
Sat Apr 06 12:58:05 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
CALL "APP"."HELLODML"('UPDATE') :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: CALL
"APP"."HELLODML"('UPDATE') :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 205), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 211), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 211), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 211), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: VALUES
CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 211), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 211), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 211), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
SELECT * FROM ZooAnimals :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 211), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
SELECT * FROM ZooAnimals :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 211), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: SELECT
* FROM ZooAnimals :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 211), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 211), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 214), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
-- try it again. the UPDATE runs immediately.
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 214), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement: --
try it again. the UPDATE runs immediately.
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 214), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: -- try
it again. the UPDATE runs immediately.
VALUES CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 214), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 214), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 214), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Begin compiling prepared statement:
UPDATE ZooAnimals SET Name = 'Alligator' WHERE Zoo = 'Cincinnati' :End prepared
statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 214), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), End compiling prepared statement:
UPDATE ZooAnimals SET Name = 'Alligator' WHERE Zoo = 'Cincinnati' :End prepared
statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 214), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: UPDATE
ZooAnimals SET Name = 'Alligator' WHERE Zoo = 'Cincinnati' :End prepared
statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 214), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: CALL
"APP"."HELLODML"('UPDATE') :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 214), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 218), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: VALUES
CURRENT_TIMESTAMP :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 218), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 218), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 218), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Executing prepared statement: SELECT
* FROM ZooAnimals :End prepared statement
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 218), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 218), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Committing
Sat Apr 06 12:58:15 PDT 2019 Thread[main,5,main] (XID = 218), (SESSIONID = 1),
(DATABASE = memory:db1), (DRDAID = null), Rolling back
----------------------------------------------------------------
Sat Apr 06 12:58:15 PDT 2019: Shutting down Derby engine
----------------------------------------------------------------
Sat Apr 06 12:58:15 PDT 2019:
Shutting down instance 0a594127-0169-f43a-9524-000007258cc8 on database
directory memory:/Users/rhillegas/derby/mainline/db1 with class loader
jdk.internal.loader.ClassLoaders$AppClassLoader@484b61fc
----------------------------------------------------------------
{noformat}
> Multiple triggers with rowLocking = false causes deadlock
> ---------------------------------------------------------
>
> Key: DERBY-7042
> URL: https://issues.apache.org/jira/browse/DERBY-7042
> Project: Derby
> Issue Type: Bug
> Components: Documentation, JDBC
> Affects Versions: 10.8.2.2, 10.8.3.0, 10.9.1.0, 10.10.1.1, 10.10.2.0,
> 10.11.1.1, 10.12.1.1, 10.13.1.1, 10.14.1.0, 10.14.2.0, 10.15.1.3
> Environment: ------------------ Java Information ------------------
> Java Version: 1.8.0_201
> Java Vendor: Oracle Corporation
> OS name: Linux
> OS architecture: i386
> OS version: 4.15.0-46-generic
> java.specification.name: Java Platform API Specification
> java.specification.version: 1.8
> java.runtime.version: 1.8.0_201-b09
> --------- Derby Information --------
> [.../TriggerRepro/derby/derby-10.14.1.0.jar] 10.14.1.0 - (1808820)
> Reporter: Michael Schuetze
> Priority: Minor
> Labels: documentation, performance
> Attachments: Derby7042.java, Derby7042.java
>
>
> Repro for the bug can be found here:
> [https://github.com/mjschuetze102/TriggerRepro]
> Includes a detailed README of steps that show effect of bug as well as two
> versions of the Derby database. 10.8.1.2, the last version where the bug was
> not present and version 10.14.1.0, for easy access.
> This may just be an issue of not having enough documentation on database
> Triggers (see Conclusions Based on Results)
> h2. Summary of Issue
> *Having multiple triggers with {{'derby.storage.rowLocking', 'false'}} causes
> issues with deadlocking*
> # Executing Update trigger causes deadlock when there is an Insert or Delete
> trigger
> # Executing Insert trigger causes deadlock when there is a Delete trigger
> # Executing Delete trigger does not cause deadlock
> *{{'derby.locks.deadlockTimeout'}} does not seem to work in above case*
> # While executing issue above, none of the triggers were terminated and
> waitTimeout time was hit
> h2. Conclusions Based on Results
> *Having multiple triggers with {{'derby.storage.rowLocking', 'false'}} causes
> issues with deadlocking*
> Triggers seem to get into deadlock scenarios with any trigger defined after
> itself. If this is the case, it should be documented somewhere that
> rowLocking needs to be enabled to use the trigger feature if multiple
> triggers would be used on the same database table.
> *{{'derby.locks.deadlockTimeout'}} does not seem to work in above case*
> Based on documentation, I could not find any concrete evidence of whether
> this is intended functionality.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
