[
https://issues.apache.org/jira/browse/HDDS-17345?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Siyao Meng updated HDDS-17345:
------------------------------
Description:
{code}
Tests run: 6, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 44.89 s <<<
FAILURE! -- in
org.apache.hadoop.ozone.dn.scanner.TestBackgroundContainerMetadataScannerIntegration
org.apache.hadoop.ozone.dn.scanner.TestBackgroundContainerMetadataScannerIntegration.testCorruptionDetected(ContainerTestCorruptions)[2]
-- Time elapsed: 5.119 s <<< ERROR!
java.util.concurrent.TimeoutException:
Timed out waiting for condition. Thread diagnostics:
...
at
org.apache.ozone.test.GenericTestUtils.waitFor(GenericTestUtils.java:137)
at
org.apache.hadoop.ozone.dn.scanner.ContainerScannerIntegrationTests.closeContainerAndWait(ContainerScannerIntegrationTests.java:169)
at
org.apache.hadoop.ozone.dn.scanner.ContainerScannerIntegrationTests.writeDataThenCloseContainer(ContainerScannerIntegrationTests.java:162)
at
org.apache.hadoop.ozone.dn.scanner.ContainerScannerIntegrationTests.writeDataThenCloseContainer(ContainerScannerIntegrationTests.java:151)
at
org.apache.hadoop.ozone.dn.scanner.TestBackgroundContainerMetadataScannerIntegration.testCorruptionDetected(TestBackgroundContainerMetadataScannerIntegration.java:96)
{code}
h3. Root cause
{{ContainerScannerIntegrationTests#closeContainerAndWait}} gives the datanode
only 5 seconds to report the container as CLOSED after asking SCM to close it.
That window covers SCM sending the close command (ReplicationManager runs every
second) plus the datanode applying the close through Ratis, which includes
{{KeyValueContainer#flushAndSyncDB}} (RocksDB {{flushWal}} with sync). In the
failed run the close event for container #3 was triggered at 11:32:56.5, the
thread dump at the timeout shows the ContainerOp thread still inside
{{RocksDB.flushWal}}, and the container became CLOSED at 11:33:03.0, about 6.5
seconds later. The close itself succeeded; the wait was just too short for a
slow fsync on the CI runner.
Close latency per container in the failed run, measured from the SCM close
event:
||Container||Close command sent||Datanode synced||
|#1|+1.06s|+2.84s|
|*#3 (failed)*|*+0.83s*|*+6.52s*|
|#4|+0.29s|+1.98s|
|#6|+0.17s|+1.74s|
|#8|+0.98s|+1.51s|
|#10|+0.38s|+1.99s|
Config tuning does not help here. The only configurable part is SCM dispatching
the close command (at most about 1 second, and the test already sets the
ReplicationManager interval to 1 second). The slow step is the
{{flushLog(true)}} call in {{KeyValueContainer#flushAndSyncDB}}, which always
syncs and has no config switch. Normal closes in the same run took 1.5 to 2.8
seconds; the failed one spent about 5.7 seconds in that sync.
h3. Fix
Raise the close wait timeout in {{closeContainerAndWait}} from 5 to 15 seconds,
the same as other waits for a container to close
({{OzoneTestHelper.waitForContainerClose}},
{{TestDuplicateContainerDirScannerIntegration}}). That is more than twice the
slowest close seen on the CI runner (6.5 seconds). The helper is shared by all
scanner integration tests.
- https://github.com/apache/ozone/actions/runs/39763337594/job/119785408645
was:
{code}
Tests run: 6, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 44.89 s <<<
FAILURE! -- in
org.apache.hadoop.ozone.dn.scanner.TestBackgroundContainerMetadataScannerIntegration
org.apache.hadoop.ozone.dn.scanner.TestBackgroundContainerMetadataScannerIntegration.testCorruptionDetected(ContainerTestCorruptions)[2]
-- Time elapsed: 5.119 s <<< ERROR!
java.util.concurrent.TimeoutException:
Timed out waiting for condition. Thread diagnostics:
...
at
org.apache.ozone.test.GenericTestUtils.waitFor(GenericTestUtils.java:137)
at
org.apache.hadoop.ozone.dn.scanner.ContainerScannerIntegrationTests.closeContainerAndWait(ContainerScannerIntegrationTests.java:169)
at
org.apache.hadoop.ozone.dn.scanner.ContainerScannerIntegrationTests.writeDataThenCloseContainer(ContainerScannerIntegrationTests.java:162)
at
org.apache.hadoop.ozone.dn.scanner.ContainerScannerIntegrationTests.writeDataThenCloseContainer(ContainerScannerIntegrationTests.java:151)
at
org.apache.hadoop.ozone.dn.scanner.TestBackgroundContainerMetadataScannerIntegration.testCorruptionDetected(TestBackgroundContainerMetadataScannerIntegration.java:96)
{code}
h3. Root cause
{{ContainerScannerIntegrationTests#closeContainerAndWait}} gives the datanode
only 5 seconds to report the container as CLOSED after asking SCM to close it.
That window covers SCM sending the close command (ReplicationManager runs every
second) plus the datanode applying the close through Ratis, which includes
{{KeyValueContainer#flushAndSyncDB}} (RocksDB {{flushWal}} with sync). In the
failed run the close event for container #3 was triggered at 11:32:56.5, the
thread dump at the timeout shows the ContainerOp thread still inside
{{RocksDB.flushWal}}, and the container became CLOSED at 11:33:03.0, about 6.5
seconds later. The close itself succeeded; the wait was just too short for a
slow fsync on the CI runner.
Close latency per container in the failed run, measured from the SCM close
event:
||Container||Close command sent||Datanode synced||
|#1|+1.06s|+2.84s|
|*#3 (failed)*|*+0.83s*|*+6.52s*|
|#4|+0.29s|+1.98s|
|#6|+0.17s|+1.74s|
|#8|+0.98s|+1.51s|
|#10|+0.38s|+1.99s|
Config tuning does not help here. The only configurable part is SCM dispatching
the close command (at most about 1 second, and the test already sets the
ReplicationManager interval to 1 second). The slow step is the
{{flushLog(true)}} call in {{KeyValueContainer#flushAndSyncDB}}, which always
syncs and has no config switch. Normal closes in the same run took 1.5 to 2.8
seconds; the failed one spent about 5.7 seconds in that sync.
h3. Fix
Raise the close wait timeout in {{closeContainerAndWait}} from 5 to 15 seconds,
the same as other waits for a container to close
({{OzoneTestHelper.waitForContainerClose}},
{{TestDuplicateContainerDirScannerIntegration}}). The helper is shared by all
scanner integration tests.
- https://github.com/apache/ozone/actions/runs/39763337594/job/119785408645
> Intermittent failure in
> TestBackgroundContainerMetadataScannerIntegration#testCorruptionDetected
> ------------------------------------------------------------------------------------------------
>
> Key: HDDS-17345
> URL: https://issues.apache.org/jira/browse/HDDS-17345
> Project: Apache Ozone
> Issue Type: Sub-task
> Components: Ozone Datanode, test
> Reporter: Siyao Meng
> Assignee: Siyao Meng
> Priority: Major
> Labels: pull-request-available
>
> {code}
> Tests run: 6, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 44.89 s <<<
> FAILURE! -- in
> org.apache.hadoop.ozone.dn.scanner.TestBackgroundContainerMetadataScannerIntegration
> org.apache.hadoop.ozone.dn.scanner.TestBackgroundContainerMetadataScannerIntegration.testCorruptionDetected(ContainerTestCorruptions)[2]
> -- Time elapsed: 5.119 s <<< ERROR!
> java.util.concurrent.TimeoutException:
> Timed out waiting for condition. Thread diagnostics:
> ...
> at
> org.apache.ozone.test.GenericTestUtils.waitFor(GenericTestUtils.java:137)
> at
> org.apache.hadoop.ozone.dn.scanner.ContainerScannerIntegrationTests.closeContainerAndWait(ContainerScannerIntegrationTests.java:169)
> at
> org.apache.hadoop.ozone.dn.scanner.ContainerScannerIntegrationTests.writeDataThenCloseContainer(ContainerScannerIntegrationTests.java:162)
> at
> org.apache.hadoop.ozone.dn.scanner.ContainerScannerIntegrationTests.writeDataThenCloseContainer(ContainerScannerIntegrationTests.java:151)
> at
> org.apache.hadoop.ozone.dn.scanner.TestBackgroundContainerMetadataScannerIntegration.testCorruptionDetected(TestBackgroundContainerMetadataScannerIntegration.java:96)
> {code}
> h3. Root cause
> {{ContainerScannerIntegrationTests#closeContainerAndWait}} gives the datanode
> only 5 seconds to report the container as CLOSED after asking SCM to close
> it. That window covers SCM sending the close command (ReplicationManager runs
> every second) plus the datanode applying the close through Ratis, which
> includes {{KeyValueContainer#flushAndSyncDB}} (RocksDB {{flushWal}} with
> sync). In the failed run the close event for container #3 was triggered at
> 11:32:56.5, the thread dump at the timeout shows the ContainerOp thread still
> inside {{RocksDB.flushWal}}, and the container became CLOSED at 11:33:03.0,
> about 6.5 seconds later. The close itself succeeded; the wait was just too
> short for a slow fsync on the CI runner.
> Close latency per container in the failed run, measured from the SCM close
> event:
> ||Container||Close command sent||Datanode synced||
> |#1|+1.06s|+2.84s|
> |*#3 (failed)*|*+0.83s*|*+6.52s*|
> |#4|+0.29s|+1.98s|
> |#6|+0.17s|+1.74s|
> |#8|+0.98s|+1.51s|
> |#10|+0.38s|+1.99s|
> Config tuning does not help here. The only configurable part is SCM
> dispatching the close command (at most about 1 second, and the test already
> sets the ReplicationManager interval to 1 second). The slow step is the
> {{flushLog(true)}} call in {{KeyValueContainer#flushAndSyncDB}}, which always
> syncs and has no config switch. Normal closes in the same run took 1.5 to 2.8
> seconds; the failed one spent about 5.7 seconds in that sync.
> h3. Fix
> Raise the close wait timeout in {{closeContainerAndWait}} from 5 to 15
> seconds, the same as other waits for a container to close
> ({{OzoneTestHelper.waitForContainerClose}},
> {{TestDuplicateContainerDirScannerIntegration}}). That is more than twice the
> slowest close seen on the CI runner (6.5 seconds). The helper is shared by
> all scanner integration tests.
> - https://github.com/apache/ozone/actions/runs/39763337594/job/119785408645
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
