[
https://issues.apache.org/jira/browse/DERBY-6011?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13531280#comment-13531280
]
Karl Wright commented on DERBY-6011:
------------------------------------
Adding derby.locks.deadlockTimeout=0 cuts the time from 10x worse than other
databases down to only 3x worse. However, even with that setting, there is
still quite a lot of long-running queries in the log:
{code}
WARN 2012-12-09 18:59:22,869 (Worker thread '10') - Found a long-running query
(52511 ms): [SELECT id,status,checktime FROM jobqueue WHERE dochash=? AND
jobid=? FOR UPDATE]
WARN 2012-12-09 18:59:22,869 (Worker thread '10') - Parameter 0:
'033689A1424C66E5C15F3A553ED632D7711F18C7'
WARN 2012-12-09 18:59:22,869 (Worker thread '10') - Parameter 1:
'1355097490879'
WARN 2012-12-09 18:59:22,949 (main) - Found a long-running query (52071 ms):
[SELECT jobid,CAST(COUNT(dochash) AS bigint) AS doccount FROM jobqueue t1 WHERE
EXISTS(SELECT 'x' FROM jobs t0 WHERE t0.id=t1.jobid AND id=?) GROUP BY jobid]
WARN 2012-12-09 18:59:22,949 (main) - Parameter 0: '1355097490879'
WARN 2012-12-09 18:59:22,949 (Worker thread '0') - Found a long-running query
(30291 ms): [SELECT id,status,checktime FROM jobqueue WHERE dochash=? AND
jobid=? FOR UPDATE]
WARN 2012-12-09 18:59:22,949 (Worker thread '0') - Parameter 0:
'42B481A0A216F2427C32510AF60BC454003C404E'
WARN 2012-12-09 18:59:22,949 (Worker thread '0') - Parameter 1:
'1355097490879'
WARN 2012-12-09 18:59:22,949 (Finisher thread) - Found a long-running query
(45233 ms): [SELECT id FROM jobqueue WHERE jobid=? AND status IN (?,?,?,?,?,?)
FETCH NEXT 1 ROWS ONLY]
WARN 2012-12-09 18:59:22,949 (Finisher thread) - Parameter 0: '1355097490879'
WARN 2012-12-09 18:59:22,949 (Finisher thread) - Parameter 1: 'A'
WARN 2012-12-09 18:59:22,949 (Finisher thread) - Parameter 2: 'a'
WARN 2012-12-09 18:59:22,949 (Finisher thread) - Parameter 3: 'P'
WARN 2012-12-09 18:59:22,949 (Finisher thread) - Parameter 4: 'F'
WARN 2012-12-09 18:59:22,949 (Finisher thread) - Parameter 5: 'f'
WARN 2012-12-09 18:59:22,949 (Finisher thread) - Parameter 6: 'G'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Found a long-running query
(51101 ms): [SELECT
t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
FROM jobqueue t0 WHERE t0.status IN (?,?) AND t0.checkaction=? AND
t0.checktime<=? AND EXISTS(SELECT 'x' FROM jobs t1 WHERE t1.status IN (?,?) AND
t1.id=t0.jobid AND t1.priority=?) AND NOT EXISTS(SELECT 'x' FROM jobqueue t2
WHERE t2.dochash=t0.dochash AND t2.status IN (?,?,?,?,?,?) AND
t2.jobid!=t0.jobid) AND NOT EXISTS(SELECT 'x' FROM prereqevents t3,events t4
WHERE t0.id=t3.owner AND t3.eventname=t4.name) ORDER BY t0.docpriority
ASC,t0.status ASC,t0.checkaction ASC,t0.checktime ASC FETCH NEXT 120 ROWS ONLY]
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 0: 'P'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 1: 'G'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 2: 'R'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 3: '1355097511858'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 4: 'A'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 5: 'a'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 6: '5'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 7: 'A'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 8: 'F'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 9: 'a'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 10: 'f'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 11: 'D'
WARN 2012-12-09 18:59:22,969 (Stuffer thread) - Parameter 12: 'd'
WARN 2012-12-09 19:00:03,021 (Worker thread '6') - Found a long-running query
(40052 ms): [SELECT id,status,checktime FROM jobqueue WHERE dochash=? AND
jobid=? FOR UPDATE]
WARN 2012-12-09 19:00:03,021 (Worker thread '6') - Parameter 0:
'089C4A318256A5BE24751A18C15B12534088AE53'
WARN 2012-12-09 19:00:03,021 (Worker thread '6') - Parameter 1:
'1355097490879'
WARN 2012-12-09 19:00:03,091 (main) - Found a long-running query (40142 ms):
[SELECT jobid,CAST(COUNT(dochash) AS bigint) AS doccount FROM jobqueue t1 WHERE
status IN (?,?,?,?,?,?) AND EXISTS(SELECT 'x' FROM jobs t0 WHERE t0.id=t1.jobid
AND id=?) GROUP BY jobid]
WARN 2012-12-09 19:00:03,091 (main) - Parameter 0: 'A'
WARN 2012-12-09 19:00:03,091 (main) - Parameter 1: 'a'
WARN 2012-12-09 19:00:03,091 (main) - Parameter 2: 'P'
WARN 2012-12-09 19:00:03,091 (main) - Parameter 3: 'F'
WARN 2012-12-09 19:00:03,091 (main) - Parameter 4: 'f'
WARN 2012-12-09 19:00:03,091 (main) - Parameter 5: 'G'
WARN 2012-12-09 19:00:03,091 (main) - Parameter 6: '1355097490879'
WARN 2012-12-09 19:00:03,091 (Finisher thread) - Found a long-running query
(30124 ms): [SELECT id FROM jobqueue WHERE jobid=? AND status IN (?,?,?,?,?,?)
FETCH NEXT 1 ROWS ONLY]
WARN 2012-12-09 19:00:03,091 (Finisher thread) - Parameter 0: '1355097490879'
WARN 2012-12-09 19:00:03,091 (Finisher thread) - Parameter 1: 'A'
WARN 2012-12-09 19:00:03,091 (Finisher thread) - Parameter 2: 'a'
WARN 2012-12-09 19:00:03,091 (Finisher thread) - Parameter 3: 'P'
WARN 2012-12-09 19:00:03,091 (Finisher thread) - Parameter 4: 'F'
WARN 2012-12-09 19:00:03,091 (Finisher thread) - Parameter 5: 'f'
WARN 2012-12-09 19:00:03,091 (Finisher thread) - Parameter 6: 'G'
WARN 2012-12-09 19:00:03,111 (Worker thread '8') - Found a long-running query
(39502 ms): [SELECT id,status,checktime FROM jobqueue WHERE dochash=? AND
jobid=? FOR UPDATE]
WARN 2012-12-09 19:00:03,111 (Worker thread '8') - Parameter 0:
'05A24080B87E69BADDA0A18B3FFD15C7585AFDEE'
WARN 2012-12-09 19:00:03,111 (Worker thread '8') - Parameter 1:
'1355097490879'
WARN 2012-12-09 19:00:03,111 (Stuffer thread) - Found a long-running query
(40112 ms): [SELECT docpriority,jobid,dochash,docid FROM jobqueue t0 WHERE
status IN (?,?) AND checkaction=? AND checktime<=? AND EXISTS(SELECT 'x' FROM
jobs t1 WHERE t1.status IN (?,?) AND t1.id=t0.jobid) ORDER BY docpriority
ASC,status ASC,checkaction ASC,checktime ASC FETCH NEXT 1 ROWS ONLY]
WARN 2012-12-09 19:00:03,111 (Stuffer thread) - Parameter 0: 'P'
WARN 2012-12-09 19:00:03,111 (Stuffer thread) - Parameter 1: 'G'
WARN 2012-12-09 19:00:03,111 (Stuffer thread) - Parameter 2: 'R'
WARN 2012-12-09 19:00:03,111 (Stuffer thread) - Parameter 3: '1355097511858'
WARN 2012-12-09 19:00:03,111 (Stuffer thread) - Parameter 4: 'A'
WARN 2012-12-09 19:00:03,111 (Stuffer thread) - Parameter 5: 'a'
WARN 2012-12-09 19:00:43,138 (Worker thread '8') - Found a long-running query
(40007 ms): [SELECT id,status,checktime FROM jobqueue WHERE dochash=? AND
jobid=? FOR UPDATE]
WARN 2012-12-09 19:00:43,138 (Worker thread '8') - Parameter 0:
'06115678F7341BDA326CEC24B8EBC61068045500'
WARN 2012-12-09 19:00:43,138 (Worker thread '8') - Parameter 1:
'1355097490879'
WARN 2012-12-09 19:00:43,218 (main) - Found a long-running query (40127 ms):
[SELECT jobid,CAST(COUNT(dochash) AS bigint) AS doccount FROM jobqueue t1 WHERE
status IN (?,?,?,?,?) AND EXISTS(SELECT 'x' FROM jobs t0 WHERE t0.id=t1.jobid
AND id=?) GROUP BY jobid]
WARN 2012-12-09 19:00:43,218 (main) - Parameter 0: 'C'
WARN 2012-12-09 19:00:43,218 (main) - Parameter 1: 'Z'
WARN 2012-12-09 19:00:43,218 (main) - Parameter 2: 'F'
WARN 2012-12-09 19:00:43,218 (main) - Parameter 3: 'f'
WARN 2012-12-09 19:00:43,218 (main) - Parameter 4: 'G'
WARN 2012-12-09 19:00:43,218 (main) - Parameter 5: '1355097490879'
WARN 2012-12-09 19:00:43,218 (Worker thread '1') - Found a long-running query
(39417 ms): [SELECT id,status,checktime FROM jobqueue WHERE dochash=? AND
jobid=? FOR UPDATE]
WARN 2012-12-09 19:00:43,218 (Worker thread '1') - Parameter 0:
'0593EFDEBC69F8EF57E3BBC6C028889F9EF149C5'
WARN 2012-12-09 19:00:43,218 (Worker thread '1') - Parameter 1:
'1355097490879'
WARN 2012-12-09 19:00:43,218 (Worker thread '12') - Found a long-running query
(48812 ms): [SELECT id,status,checktime FROM jobqueue WHERE dochash=? AND
jobid=? FOR UPDATE]
WARN 2012-12-09 19:00:43,218 (Worker thread '12') - Parameter 0:
'0F87592E9B7A46E5ED62CD24494494340CDF9017'
WARN 2012-12-09 19:00:43,218 (Worker thread '12') - Parameter 1:
'1355097490879'
WARN 2012-12-09 19:00:43,218 (Worker thread '9') - Found a long-running query
(32241 ms): [SELECT id,status,checktime FROM jobqueue WHERE dochash=? AND
jobid=? FOR UPDATE]
WARN 2012-12-09 19:00:43,218 (Worker thread '9') - Parameter 0:
'0CDC72CE178F4A53C54B31EEAA879ED10C8ABF50'
WARN 2012-12-09 19:00:43,218 (Worker thread '9') - Parameter 1:
'1355097490879'
WARN 2012-12-09 19:00:43,218 (Finisher thread) - Found a long-running query
(30112 ms): [SELECT id FROM jobqueue WHERE jobid=? AND status IN (?,?,?,?,?,?)
FETCH NEXT 1 ROWS ONLY]
WARN 2012-12-09 19:00:43,218 (Finisher thread) - Parameter 0: '1355097490879'
WARN 2012-12-09 19:00:43,218 (Finisher thread) - Parameter 1: 'A'
WARN 2012-12-09 19:00:43,218 (Finisher thread) - Parameter 2: 'a'
WARN 2012-12-09 19:00:43,218 (Finisher thread) - Parameter 3: 'P'
WARN 2012-12-09 19:00:43,218 (Finisher thread) - Parameter 4: 'F'
WARN 2012-12-09 19:00:43,218 (Finisher thread) - Parameter 5: 'f'
WARN 2012-12-09 19:00:43,218 (Finisher thread) - Parameter 6: 'G'
WARN 2012-12-09 19:01:03,308 (Worker thread '0') - Found a long-running query
(40889 ms): [SELECT id,status,checktime FROM jobqueue WHERE dochash=? AND
jobid=? FOR UPDATE]
WARN 2012-12-09 19:01:03,308 (Worker thread '0') - Parameter 0:
'42B481A0A216F2427C32510AF60BC454003C404E'
WARN 2012-12-09 19:01:03,308 (Worker thread '0') - Parameter 1:
'1355097490879'
WARN 2012-12-09 19:01:03,448 (Worker thread '2') - Found a long-running query
(32970 ms): [SELECT id,status,checktime FROM jobqueue WHERE dochash=? AND
jobid=? FOR UPDATE]
WARN 2012-12-09 19:01:03,448 (Worker thread '2') - Parameter 0:
'19EA2C455D02F87BD90F42697A383329C87528EB'
WARN 2012-12-09 19:01:03,448 (Worker thread '2') - Parameter 1:
'1355097490879'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Found a long-running query
(60227 ms): [SELECT
t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
FROM jobqueue t0 WHERE t0.status IN (?,?) AND t0.checkaction=? AND
t0.checktime<=? AND EXISTS(SELECT 'x' FROM jobs t1 WHERE t1.status IN (?,?) AND
t1.id=t0.jobid AND t1.priority=?) AND NOT EXISTS(SELECT 'x' FROM jobqueue t2
WHERE t2.dochash=t0.dochash AND t2.status IN (?,?,?,?,?,?) AND
t2.jobid!=t0.jobid) AND NOT EXISTS(SELECT 'x' FROM prereqevents t3,events t4
WHERE t0.id=t3.owner AND t3.eventname=t4.name) ORDER BY t0.docpriority
ASC,t0.status ASC,t0.checkaction ASC,t0.checktime ASC FETCH NEXT 120 ROWS ONLY]
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 0: 'P'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 1: 'G'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 2: 'R'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 3: '1355097603111'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 4: 'A'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 5: 'a'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 6: '5'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 7: 'A'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 8: 'F'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 9: 'a'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 10: 'f'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 11: 'D'
WARN 2012-12-09 19:01:03,458 (Stuffer thread) - Parameter 12: 'd'
{code}
Can you explain this?
> Derby performs very badly (seems to deadlock and timeout) in very simple
> multi-threaded tests
> ---------------------------------------------------------------------------------------------
>
> Key: DERBY-6011
> URL: https://issues.apache.org/jira/browse/DERBY-6011
> Project: Derby
> Issue Type: Bug
> Affects Versions: 10.7.1.1, 10.8.2.2, 10.9.1.0
> Environment: Lenovo laptop with SSD's, Windows 7, 64-bit, Sun JDK
> 1.6.xx
> Reporter: Karl Wright
> Attachments: derby.log, manifoldcf.log
>
>
> The Apache ManifoldCF project supports Derby as one of its underlying
> databases. Simple tests, however, demonstrate that Derby is apparently
> deadlocking and timing out repeatedly under multi-thread conditions. This
> problem is long-standing, and is not exhibited by any other database
> ManifoldCF supports, and makes a simple test take between 6x and 12x as long.
> There is a trivial test with demonstrates the problem vs. other databases.
> Please do the following (once you have java 1.6+, svn 1.7+, and ant 1.7+
> available):
> (1) Check out https://svn.apache.org/repos/asf/manifoldcf/trunk
> (2) Run the following ant target to download the dependencies: "ant
> make-core-deps"
> (3) Run the Derby test: "ant run-rss-tests-derby" . Note the time required -
> at least 180 seconds, can be up to 360 seconds.
> (4) Run the equivalent HSQLDB test: "ant run-rss-tests-HSQLDB". This test
> takes about 31 seconds to run.
> The output of the Derby test can be found in the directory
> "tests/rss/test-derby-output". Have a look at manifoldcf.log, where all
> long-running queries are reported. Derby.log is also included, which shows
> only that during the test's cleanup phase the database is deleted before it
> is shutdown, which is not pertinent to the performance issue.
> I am available to assist with ManifoldCF, if that seems to be required.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
