db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Karl Wright (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (DERBY-6011) Derby performs very badly (seems to deadlock and timeout) in very simple multi-threaded tests
Date Thu, 13 Dec 2012 18:26:13 GMT

    [ 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

Mime
View raw message