|
This looks like a reproducible failure, as the same entry fails here:
https://s3-logs.opendaylight.org/logs/releng/vex-yul-odl-jenkins-1/bgpcep-csit-1node-bgp-ingest-all-sulfur/212/odl_1/odl1_karaf.log.gz
https://s3-logs.opendaylight.org/logs/releng/vex-yul-odl-jenkins-1/bgpcep-csit-1node-bgp-ingest-all-sulfur/213/odl_1/odl1_karaf.log.gz
|
|
Debugs are not turning up anything, really:
|
|
Trace logs are not much better:
It looks as though the appender just seizes up after being happy with 260K+ entries at a rate of 1000+ appends/s. I have added more trace points, added toString() to payload implementations and upgraded atomix. We'll retry this with 5.0.3.
|
|
Okay, it seems we are narrowing this down to Atomix:
This corresponds to a CommitTransactionPayload, nothing special. We have persisted a similar payload just before:
|
|
Alright, so some more evidence is here:
So the append took good 65 seconds to complete, but eventually it did complete. Unfortunately we do not store node performance data, so I do not have a smoking gun. What I suspect is happening that we are facing a segmented file rotation.
Looking at the numbers:
- we have a 128MiB journal (134 217 728 bytes)
- we have written 262217 entries worth with 132 119 382 bytes of data
- each entry contains additional 8 bytes of book keeping (length + crc32), for a total of 2 097 736 bytes
- hence we have 134 217 694 bytes stored
So indeed we are now flushing current segment and allocating a new one. We might be looking at flushing ~128MiB down to storage, which has unknown performance characteristics, but the driver node peaks at 9827 blocks written per second – which amounts to a rather underwhelming performance of 4.8MiB/s.
|
|
So we are already performing a flush() after each write, so I am at a loss as to what is taking 65 seconds: allocation of a new file? its mapping into memory?
|
|
So the next step here is to create a unit test for SegmentedFileJournal which performs something akin to the failure scenario.
Take SegmentedFileJournalTest as how-to for a new test. The test should:
- set up a new journal with default parameters (128MiB segments, 16MiB message size)
- write 1 million 1KiB messages into it, timing each write with a Stopwatch
- assert that each write takes less than 5 seconds
1M x 1KiB == 1GiB + overhead, which means we should hit segment changeover 8 times.
Once we have that, we can see if we can make it fail during local runs and if so, what exactly is the operation that takes so horribly long. If not, we will have something to throw at CSIT worker nodes to see how they react to it.
|
|
CONTROLLER-2056 lowers payload serialization overheads. CONTROLLER-2064 lowers baseline journal entry sizes. Both of these should improve the number of entries we can write out before having to rotate.
|
|
So we get a bit more:
https://s3-logs.opendaylight.org/logs/releng/vex-yul-odl-jenkins-1/bgpcep-csit-1node-bgp-ingest-all-argon/119/odl_1/odl1_karaf.log.gz
now fails at:
i.e. we get to entry 313062 instead of 262218 for the same journal (~19% improvement), and process 178203 routes instead of 165485 (~8% more), being very close to the target of 180000.
|
|
Good news is that now openflowplugin-csit-3node-clustering-bulkomatic-only does not fail, i.e. it just fits into the log before rotation.
|
|
I think there is another part which might be worthwhile to optimize: here we are writing two Strings, both of which seem to be good candidates for simpler representation.
What we really need to do first, though, is get hold of a segmented-file directory contents from CSIT.
So the next step is to run either BGP or OFP-bulkomatic tests locally.
|
|
Looking at a fresh log (from feature:install odl-netconf-mdsal), it seems the UUID part is there, we have "4ceb3db5-5148-414a-a2c7-cdeae7c8d56" repeating 33 times, which in turn matches the number of "org.opendaylight.controller.cluster.raft.persisted.*" objects persisted – i.e. the number of entries in that journal. So that's 33x35=1155 bytes we could perhaps squash to a definition + a WritableObject.writeLong() – potentially bringing that down to 35+2+32*2=103 bytes.
The other part is that we keep on repeating those cluster.raft.persisted object names – I suspect we could take control of those as well IFF we ditch Kryo and create a custom ObjectOutputStream – similar in some regards to io.netty.handler.codec.serialization.CompactObjectOutputStream.
Yet another part is that the payloads persisted repeat – "org.opendaylight.controller.cluster.datastore.persisted.CT" (i.e. CommitTransaction) repeats a number of times. This is coming from CDS itself, hence the custom OOS should be pluggable even without ditching Kryo.
|
|
I run locally these tests:
integration/test/csit/suites/bgpcep/bgpclustering/singlepeer_pc_shm_300kroutes.robot
integration/test/csit/suites/bgpcep/bgpingest/singlepeer_prefixcount.robot
integration/test/csit/suites/bgpcep/bgpingest/singlepeer_changecount.robot
with
feature:install odl-restconf odl-jolokia odl-bgpcep-data-change-counter odl-bgpcep-bgp odl-bgpcep-bgp-config-example
Will attach segmented-journal from karaf segmented-journal.tar.xz
|
Generated at Wed Feb 07 19:57:04 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.
data-1.log.xz
vim-data-1-log.png