[
https://issues.apache.org/jira/browse/OAK-3743?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15056017#comment-15056017
]
Julian Reschke edited comment on OAK-3743 at 12/14/15 2:12 PM:
---------------------------------------------------------------
Looking at the unit test log for a slow test:
{noformat}
13:09:19.441 INFO [pool-172-thread-1] DocumentNodeStore.java:543 Initialized
DocumentNodeStore with clusterNodeId: 1 (id: 1, startTime: 1450098559352,
machineId: mac:56847afe9799, instanceId:
/home/jenkins/jenkins-slave/workspace/Apache Jackrabbit Oak
matrix/jdk/jdk-1.6u45/label/Ubuntu/nsfixtures/DOCUMENT_RDB/profile/unittesting/oak-jcr,
pid: 9051, uuid: f9119c1a-1a53-4005-82ca-bcd81254382c, readWriteMode: null,
state: NONE, revLock: NONE, oakVersion: 1.4-SNAPSHOT)
13:09:25.459 INFO [pool-172-thread-1] IndexUpdate.java:182 Found a new index
node [reference]. Reindexing is requested
13:09:25.459 INFO [pool-172-thread-1] IndexUpdate.java:147 Reindexing will be
performed for following indexes: [/oak:index/reference, /oak:index/nodetype,
/oak:index/uuid]
13:09:30.602 INFO [pool-172-thread-1] IndexUpdate.java:257 Indexing report
- /oak:index/nodetype*(1232)
13:09:30.718 INFO [pool-172-thread-1] IndexUpdate.java:147 Reindexing will be
performed for following indexes: [/oak:index/principalName,
/oak:index/acPrincipalName, /oak:index/authorizableId]
13:09:30.768 INFO [pool-172-thread-1] IndexUpdate.java:257 Indexing report
- /oak:index/principalName*(2)
- /oak:index/authorizableId*(2)
13:09:31.971 INFO [pool-172-thread-1] DocumentNodeStore.java:555 Starting
disposal of DocumentNodeStore with clusterNodeId: 1 (id: 1, startTime:
1450098559352, machineId: mac:56847afe9799, instanceId:
/home/jenkins/jenkins-slave/workspace/Apache Jackrabbit Oak
matrix/jdk/jdk-1.6u45/label/Ubuntu/nsfixtures/DOCUMENT_RDB/profile/unittesting/oak-jcr,
pid: 9051, uuid: f9119c1a-1a53-4005-82ca-bcd81254382c, readWriteMode: null,
state: NONE, revLock: NONE, oakVersion: 1.4-SNAPSHOT)
13:09:32.672 INFO [pool-172-thread-1] RDBDocumentStore.java:450
RDBDocumentStore (1.4-SNAPSHOT) disposed (Cluster Node updates: [1=8]) (tables
dropped: T1a8f3c8d4b2e430dbc90796f9165c307_SETTINGS
T1a8f3c8d4b2e430dbc90796f9165c307_NODES
T1a8f3c8d4b2e430dbc90796f9165c307_CLUSTERNODES
T1a8f3c8d4b2e430dbc90796f9165c307_JOURNAL)
13:09:32.939 INFO [pool-172-thread-1] DocumentNodeStore.java:612 Disposed
DocumentNodeStore with clusterNodeId: 1
{noformat}
So we're spending ~6s until the first message from {{IndexUpdate}}, and at
least another ~5s inside {{IndexUpdate}}
was (Author: reschke):
Looking at the unit test log for a slow test:
{noformat}
13:09:19.441 INFO [pool-172-thread-1] DocumentNodeStore.java:543 Initialized
DocumentNodeStore with clusterNodeId: 1 (id: 1, startTime: 1450098559352,
machineId: mac:56847afe9799, instanceId:
/home/jenkins/jenkins-slave/workspace/Apache Jackrabbit Oak
matrix/jdk/jdk-1.6u45/label/Ubuntu/nsfixtures/DOCUMENT_RDB/profile/unittesting/oak-jcr,
pid: 9051, uuid: f9119c1a-1a53-4005-82ca-bcd81254382c, readWriteMode: null,
state: NONE, revLock: NONE, oakVersion: 1.4-SNAPSHOT)
13:09:25.459 INFO [pool-172-thread-1] IndexUpdate.java:182 Found a new index
node [reference]. Reindexing is requested
13:09:25.459 INFO [pool-172-thread-1] IndexUpdate.java:147 Reindexing will be
performed for following indexes: [/oak:index/reference, /oak:index/nodetype,
/oak:index/uuid]
13:09:30.602 INFO [pool-172-thread-1] IndexUpdate.java:257 Indexing report
- /oak:index/nodetype*(1232)
13:09:30.718 INFO [pool-172-thread-1] IndexUpdate.java:147 Reindexing will be
performed for following indexes: [/oak:index/principalName,
/oak:index/acPrincipalName, /oak:index/authorizableId]
13:09:30.768 INFO [pool-172-thread-1] IndexUpdate.java:257 Indexing report
- /oak:index/principalName*(2)
- /oak:index/authorizableId*(2)
13:09:31.971 INFO [pool-172-thread-1] DocumentNodeStore.java:555 Starting
disposal of DocumentNodeStore with clusterNodeId: 1 (id: 1, startTime:
1450098559352, machineId: mac:56847afe9799, instanceId:
/home/jenkins/jenkins-slave/workspace/Apache Jackrabbit Oak
matrix/jdk/jdk-1.6u45/label/Ubuntu/nsfixtures/DOCUMENT_RDB/profile/unittesting/oak-jcr,
pid: 9051, uuid: f9119c1a-1a53-4005-82ca-bcd81254382c, readWriteMode: null,
state: NONE, revLock: NONE, oakVersion: 1.4-SNAPSHOT)
13:09:32.672 INFO [pool-172-thread-1] RDBDocumentStore.java:450
RDBDocumentStore (1.4-SNAPSHOT) disposed (Cluster Node updates: [1=8]) (tables
dropped: T1a8f3c8d4b2e430dbc90796f9165c307_SETTINGS
T1a8f3c8d4b2e430dbc90796f9165c307_NODES
T1a8f3c8d4b2e430dbc90796f9165c307_CLUSTERNODES
T1a8f3c8d4b2e430dbc90796f9165c307_JOURNAL)
13:09:32.939 INFO [pool-172-thread-1] DocumentNodeStore.java:612 Disposed
DocumentNodeStore with clusterNodeId: 1
{noformat}
So we're spending ~6s until the first message from {IndexUpdate}, and at least
another ~5s inside {IndexUpdate}
> Build time out after 90 mins on Jenkins
> ---------------------------------------
>
> Key: OAK-3743
> URL: https://issues.apache.org/jira/browse/OAK-3743
> Project: Jackrabbit Oak
> Issue Type: Bug
> Components: rdbmk
> Environment: Jenkins, Ubuntu:
> https://builds.apache.org/job/Apache%20Jackrabbit%20Oak%20matrix/
> Reporter: Michael Dürig
> Assignee: Thomas Mueller
> Labels: CI, Jenkins
> Fix For: 1.4
>
> Attachments: OAK-3743-parallelized.patch
>
>
> Every 2nd build or so is aborted after a time out (90 mins):
> {noformat}
> Build timed out (after 90 minutes). Marking the build as aborted.
> Build was aborted
> [FINDBUGS] Skipping publisher since build result is ABORTED
> Recording test results
> Finished: ABORTED
> {noformat}
> See e.g.
> https://builds.apache.org/job/Apache%20Jackrabbit%20Oak%20matrix/585/jdk=jdk1.8.0_11,label=Ubuntu,nsfixtures=DOCUMENT_RDB,profile=unittesting/console
> Interestingly when successful, the build takes about 30mins, so way below the
> 90 min. timeout.
> Also seen at builds 587, 590, 591, 593, 595, 597, 598, 604, 608, 609, 610
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
