[
https://issues.apache.org/jira/browse/IGNITE-16675?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Mirza Aliev updated IGNITE-16675:
---------------------------------
Description:
After some investigation that was made under IGNITE-16559 (see the
[comment|https://issues.apache.org/jira/browse/IGNITE-16559?focusedCommentId=17495362&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-17495362]),
we came up the idea that we could investigate why initialisation of raft
groups could be time-consuming.
We see that init phase of starting raft group contains some time-consuming
operations like {{fsync}} or {{RocksDB.open}}
{noformat}
at sun.nio.ch.FileDispatcherImpl.force0(FileDispatcherImpl.java:-1)
at sun.nio.ch.FileDispatcherImpl.force(FileDispatcherImpl.java:82)
at sun.nio.ch.FileChannelImpl.force(FileChannelImpl.java:461)
at org.apache.ignite.raft.jraft.util.Utils.fsync(Utils.java:366)
at
org.apache.ignite.raft.jraft.storage.io.MessageFile.save(MessageFile.java:94)
at
org.apache.ignite.raft.jraft.storage.impl.LocalRaftMetaStorage.save(LocalRaftMetaStorage.java:114)
at
org.apache.ignite.raft.jraft.storage.impl.LocalRaftMetaStorage.setTermAndVotedFor(LocalRaftMetaStorage.java:186)
at
org.apache.ignite.raft.jraft.core.NodeImpl.electSelf(NodeImpl.java:1271)
at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:1054)
at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:126)
at
org.apache.ignite.raft.jraft.RaftGroupService.start(RaftGroupService.java:108)
- locked <0x1e42> (a org.apache.ignite.raft.jraft.RaftGroupService)
at
org.apache.ignite.internal.raft.server.impl.JraftServerImpl.startRaftGroup(JraftServerImpl.java:341)
- locked <0x1deb> (a
org.apache.ignite.internal.raft.server.impl.JraftServerImpl)
at
org.apache.ignite.internal.raft.Loza.prepareRaftGroupInternal(Loza.java:193)
at
org.apache.ignite.internal.raft.Loza.prepareRaftGroup(Loza.java:168)
{noformat}
{noformat}
at org.rocksdb.RocksDB.open(RocksDB.java:-1)
at org.rocksdb.RocksDB.open(RocksDB.java:306)
at
org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.openDB(RocksDBLogStorage.java:308)
at
org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.initAndLoad(RocksDBLogStorage.java:221)
at
org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.init(RocksDBLogStorage.java:198)
at
org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.init(RocksDBLogStorage.java:68)
at
org.apache.ignite.raft.jraft.storage.impl.LogManagerImpl.init(LogManagerImpl.java:183)
at
org.apache.ignite.raft.jraft.storage.impl.LogManagerImpl.init(LogManagerImpl.java:65)
at
org.apache.ignite.raft.jraft.core.NodeImpl.initLogStorage(NodeImpl.java:557)
at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:946)
at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:126)
at
org.apache.ignite.raft.jraft.RaftGroupService.start(RaftGroupService.java:108)
- locked <merged>(a org.apache.ignite.raft.jraft.RaftGroupService)
at
org.apache.ignite.internal.raft.server.impl.JraftServerImpl.startRaftGroup(JraftServerImpl.java:341)
- locked <merged>(a
org.apache.ignite.internal.raft.server.impl.JraftServerImpl)
at
org.apache.ignite.internal.raft.Loza.prepareRaftGroupInternal(Loza.java:193)
at
org.apache.ignite.internal.raft.Loza.prepareRaftGroup(Loza.java:168)
{noformat}
We made some pre-investigation, we started a raft group on one node 1000 times,
red line on the screenshot is a local run, other lines are from TC. Y axis
shows milliseconds. X axis represents test attmept. We measured
{{org.apache.ignite.raft.jraft.RaftGroupService#start}}. In general, we could
see that attempts are stable and they are not time-consuming (in some bad
cases, start could last about 1 second. We saw that behavour in TC), but there
are some statistical outliers, probably the are related to GC pauses.
!screenshot-1.png!
was:
After some investigation that was made under IGNITE-16559 (see the
[comment|https://issues.apache.org/jira/browse/IGNITE-16559?focusedCommentId=17495362&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-17495362]),
we came up the idea that we could investigate why initialisation of raft
groups could be time-consuming.
We see that init phase of starting raft group contains some time-consuming
operations like {{fsync}} or {{RocksDB.open}}
{noformat}
at sun.nio.ch.FileDispatcherImpl.force0(FileDispatcherImpl.java:-1)
at sun.nio.ch.FileDispatcherImpl.force(FileDispatcherImpl.java:82)
at sun.nio.ch.FileChannelImpl.force(FileChannelImpl.java:461)
at org.apache.ignite.raft.jraft.util.Utils.fsync(Utils.java:366)
at
org.apache.ignite.raft.jraft.storage.io.MessageFile.save(MessageFile.java:94)
at
org.apache.ignite.raft.jraft.storage.impl.LocalRaftMetaStorage.save(LocalRaftMetaStorage.java:114)
at
org.apache.ignite.raft.jraft.storage.impl.LocalRaftMetaStorage.setTermAndVotedFor(LocalRaftMetaStorage.java:186)
at
org.apache.ignite.raft.jraft.core.NodeImpl.electSelf(NodeImpl.java:1271)
at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:1054)
at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:126)
at
org.apache.ignite.raft.jraft.RaftGroupService.start(RaftGroupService.java:108)
- locked <0x1e42> (a org.apache.ignite.raft.jraft.RaftGroupService)
at
org.apache.ignite.internal.raft.server.impl.JraftServerImpl.startRaftGroup(JraftServerImpl.java:341)
- locked <0x1deb> (a
org.apache.ignite.internal.raft.server.impl.JraftServerImpl)
at
org.apache.ignite.internal.raft.Loza.prepareRaftGroupInternal(Loza.java:193)
at
org.apache.ignite.internal.raft.Loza.prepareRaftGroup(Loza.java:168)
{noformat}
{noformat}
at org.rocksdb.RocksDB.open(RocksDB.java:-1)
at org.rocksdb.RocksDB.open(RocksDB.java:306)
at
org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.openDB(RocksDBLogStorage.java:308)
at
org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.initAndLoad(RocksDBLogStorage.java:221)
at
org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.init(RocksDBLogStorage.java:198)
at
org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.init(RocksDBLogStorage.java:68)
at
org.apache.ignite.raft.jraft.storage.impl.LogManagerImpl.init(LogManagerImpl.java:183)
at
org.apache.ignite.raft.jraft.storage.impl.LogManagerImpl.init(LogManagerImpl.java:65)
at
org.apache.ignite.raft.jraft.core.NodeImpl.initLogStorage(NodeImpl.java:557)
at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:946)
at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:126)
at
org.apache.ignite.raft.jraft.RaftGroupService.start(RaftGroupService.java:108)
- locked <merged>(a org.apache.ignite.raft.jraft.RaftGroupService)
at
org.apache.ignite.internal.raft.server.impl.JraftServerImpl.startRaftGroup(JraftServerImpl.java:341)
- locked <merged>(a
org.apache.ignite.internal.raft.server.impl.JraftServerImpl)
at
org.apache.ignite.internal.raft.Loza.prepareRaftGroupInternal(Loza.java:193)
at
org.apache.ignite.internal.raft.Loza.prepareRaftGroup(Loza.java:168)
{noformat}
We made some pre-investigation, we started a raft group on one node 1000 times,
red line on the screenshot is a local run, other lines are from TC. Y axis
shows milliseconds. X axis represents test attmept. We measured
{{org.apache.ignite.raft.jraft.RaftGroupService#start}}. In general, we could
see that attempts are stable and they are not time-consuming (in some bad
cases, start could last about 1 second. We saw that behavour in TC), but there
are some statistical outliers, probably
!screenshot-1.png!
> Need to investigate why initialisation of raft groups could be
> time-consuming.
> -------------------------------------------------------------------------------
>
> Key: IGNITE-16675
> URL: https://issues.apache.org/jira/browse/IGNITE-16675
> Project: Ignite
> Issue Type: Task
> Reporter: Mirza Aliev
> Priority: Major
> Labels: ignite-3
> Attachments: screenshot-1.png
>
>
> After some investigation that was made under IGNITE-16559 (see the
> [comment|https://issues.apache.org/jira/browse/IGNITE-16559?focusedCommentId=17495362&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-17495362]),
> we came up the idea that we could investigate why initialisation of raft
> groups could be time-consuming.
> We see that init phase of starting raft group contains some time-consuming
> operations like {{fsync}} or {{RocksDB.open}}
> {noformat}
> at sun.nio.ch.FileDispatcherImpl.force0(FileDispatcherImpl.java:-1)
> at sun.nio.ch.FileDispatcherImpl.force(FileDispatcherImpl.java:82)
> at sun.nio.ch.FileChannelImpl.force(FileChannelImpl.java:461)
> at org.apache.ignite.raft.jraft.util.Utils.fsync(Utils.java:366)
> at
> org.apache.ignite.raft.jraft.storage.io.MessageFile.save(MessageFile.java:94)
> at
> org.apache.ignite.raft.jraft.storage.impl.LocalRaftMetaStorage.save(LocalRaftMetaStorage.java:114)
> at
> org.apache.ignite.raft.jraft.storage.impl.LocalRaftMetaStorage.setTermAndVotedFor(LocalRaftMetaStorage.java:186)
> at
> org.apache.ignite.raft.jraft.core.NodeImpl.electSelf(NodeImpl.java:1271)
> at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:1054)
> at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:126)
> at
> org.apache.ignite.raft.jraft.RaftGroupService.start(RaftGroupService.java:108)
> - locked <0x1e42> (a org.apache.ignite.raft.jraft.RaftGroupService)
> at
> org.apache.ignite.internal.raft.server.impl.JraftServerImpl.startRaftGroup(JraftServerImpl.java:341)
> - locked <0x1deb> (a
> org.apache.ignite.internal.raft.server.impl.JraftServerImpl)
> at
> org.apache.ignite.internal.raft.Loza.prepareRaftGroupInternal(Loza.java:193)
> at
> org.apache.ignite.internal.raft.Loza.prepareRaftGroup(Loza.java:168)
> {noformat}
> {noformat}
> at org.rocksdb.RocksDB.open(RocksDB.java:-1)
> at org.rocksdb.RocksDB.open(RocksDB.java:306)
> at
> org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.openDB(RocksDBLogStorage.java:308)
> at
> org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.initAndLoad(RocksDBLogStorage.java:221)
> at
> org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.init(RocksDBLogStorage.java:198)
> at
> org.apache.ignite.raft.jraft.storage.impl.RocksDBLogStorage.init(RocksDBLogStorage.java:68)
> at
> org.apache.ignite.raft.jraft.storage.impl.LogManagerImpl.init(LogManagerImpl.java:183)
> at
> org.apache.ignite.raft.jraft.storage.impl.LogManagerImpl.init(LogManagerImpl.java:65)
> at
> org.apache.ignite.raft.jraft.core.NodeImpl.initLogStorage(NodeImpl.java:557)
> at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:946)
> at org.apache.ignite.raft.jraft.core.NodeImpl.init(NodeImpl.java:126)
> at
> org.apache.ignite.raft.jraft.RaftGroupService.start(RaftGroupService.java:108)
> - locked <merged>(a org.apache.ignite.raft.jraft.RaftGroupService)
> at
> org.apache.ignite.internal.raft.server.impl.JraftServerImpl.startRaftGroup(JraftServerImpl.java:341)
> - locked <merged>(a
> org.apache.ignite.internal.raft.server.impl.JraftServerImpl)
> at
> org.apache.ignite.internal.raft.Loza.prepareRaftGroupInternal(Loza.java:193)
> at
> org.apache.ignite.internal.raft.Loza.prepareRaftGroup(Loza.java:168)
> {noformat}
> We made some pre-investigation, we started a raft group on one node 1000
> times, red line on the screenshot is a local run, other lines are from TC. Y
> axis shows milliseconds. X axis represents test attmept. We measured
> {{org.apache.ignite.raft.jraft.RaftGroupService#start}}. In general, we could
> see that attempts are stable and they are not time-consuming (in some bad
> cases, start could last about 1 second. We saw that behavour in TC), but
> there are some statistical outliers, probably the are related to GC pauses.
> !screenshot-1.png!
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
