Subject: [dtn-users] 1 Hour Data Flow Test Results - DTN2.8.0 Changeset 3550 plus GlobalStorage patch

From: "Zoller, David A. (MSFC-EO60)[HOSC SERVICES CONTRACT]" <[email-masked]>
Date: Tue, 9 Oct 2012 12:51:33 -0500

Greetings yet again,
I expected the storage thread to be the final key but apparently not. I went to the start of this particular data flow (APIClient::handle_send() method) and added timing code to track down where the remaining bottlenecks were hiding. It didn't take long to discover that the first hit was in the line "b = new Bundle()".

This lead me down the same path that Angela and Brenton had uncovered in their testing. Creating a new bundle calls BundlePayload::init() which creates the payload file and then calls Bundle_Payload::sync_payload() which flushes the OS buffers to disk with the fsync() call. This fsync() call sometimes took 20 to 30 milliseconds to complete even though there is no actual data to be written at this point. As Brenton noted this is done even when configured for a memory database so maybe a configuration parameter should be checked at this point to determine the process flow. I am pretty sure that in the BundlePayload::init()method it is impossible for there to be any data to be flushed to disk but to be safe instead  of commenting out the call to sync_payload() I just added a check to only call it if the payload length is greater than zero.

Next, it turned out that the APIClient::handle_send() method later called sync_payload() after loading the payload which then took the hit. A search of the code found that this is the only place external to the BundlePayload class that calls sync_payload() (and init() makes the only internal  call). I decided to push this hit to the storage thread by commenting it out here and adding the call to sync_payload() right before the call to add the bundle to the database.

The next hit turned out to be in the "new Bundle()" call again and was the assignment of the Bundle ID. During the ingest-only phase of the test the hit was an occasional 20 to 55 milliseconds but after node 2 was online and the processing intensified the hit was much more often and sometimes 100+ milliseconds. This was tracked down to the GlobalStorage class when it updated the database after incrementing the Bundle ID which is most likely a flush to disk issue like above. I had left the GlobalStorage class updating the database immediately instead moving it to the storage thread so maybe there is some contention when multiple threads are updating the database at the same time. I added a lock to serialize the db updates but that did not solve the problem.

My work around here was of course another thread. I created a GlobalStorageDBUpdateThread which loops checking to see if a GlobalStorage  update is needed  with a usleep(1) call in between checks. I tried the yield and thread_yield calls instead of the usleep but those result in the thread using 100% of a CPU.  If an update is needed then a copy of the current global values is made to minimize the impact to the main processing threads and the copy is used in the database update. The clock does not provide 1 microsecond resolution so we are probably getting about 4000 or so checks per second (not verified) which seems adequate to keep the GlobalStorage table pretty close to a real time update other than during the [presumed] flush to disk hits.

At this point, processing was finally screaming along but became unstable. I first ran into the oasys::Time.elapsed_ms() issue that jward noted and had to beef up the pre-condition check. Then there was one of those fun Heisenberg segfaults that jumped to a different location whenever I added debug code to trap it. I finally narrowed it down to the TableBasedRouter::sort_routes() call to std::sort() to sort the two routes for a bundle. Two routes exist in this test the one initiated by Node2 to Node1 and the one initiated the other way. The comparator for the sort uses the priorty of the routes (both are zero) and then uses the number of bytes queued on their Links as a tie breaker to somewhat equalize the flow over the routes. I theorized that the bytes queued was changing during the sort causing problems. I removed the tie breaker and have not had any segfaults since. If that tie breaker is desired then the values could be determined before the sort for later use. Without the tie breaker the bundle count for the two Links in this run were: 375,201 transferred on the Node2->Node1 Link and 200,799 on the Node1->Node2 Link.

The BunRcvPost graph is basically a flat line at 160 Bundles/second which is what I was hoping to see. There is no reliance on the large socket buffer in the udp2dtn app to avoid losing network packets from the data source as in the previous iterations.

What's next? I ran a continuous data flow for a couple of days at 160 bundles/sec (23M bundles) without any issues but when I ran a test at 500 bundles/sec Node2 with a registration accepting delivery of the bundles started logging spin lock waits and was eventually killed by the OS with an out of memory error after ~2.3M bundles. Before submitting any patches, I plan to focus on the registration deliver aspect of the flow for a while and then look at a middle node. Hopefully I can crank out a set of patches in a month or two.

Best regards,
DZ

David Zoller
COLSA Corporation
Marshall Space Flight Center

DTN2 - One Hour Data Flow with the Receiver (Node2) Brought Online After 30 Minutes

Configuration

*        DTN2 changeset 3550 plus patches up to and including the GlobalStorage patch plus some statistics collection code.

*        OASYS changeset 2298 with all patches applied.

*        Computer (Node1)

o   HP xw4400 Workstation

o   Intel(R) Core(TM)2 CPU          6300  @ 1.86GHz   (dual core)

o   4GB memory

o   BerkeleyDB hosted on a Solid State Drive configured as an ext2 partition with the noatime and nodiratime options

*        Data flow is 160 non-custody bundles per second for 60 minutes

Bottom Line Results

*        576,000 UDP packets were transmitted (1316 byte payload)

*        576,000 packets were processed into bundles  (1316 byte payload)

*                     0 packets were lost due to UDP socket buffer overflow

o   40MB socket buffer holds ~30k packets or ~187 seconds of data

*        Finally achieved continuous ingest throughout the data flow

Timeline Highlights
Seconds after Node1 started

7

Data flow started at 160 packets/sec

7 - 1827

Successfully received 291,405 bundles at 160 bundles/sec

1827

Node2 makes contact (link-0 created) - reroute_all_bundles entered - ingest (BunRcvPost) continues at 160 bundles/sec but BunRcvProc halts

1841

reroute_all_bundles finished - elapsed 13.9 seconds

1841

Burst processing posted BundleReceived events, ingest at 160 bundles/sec and transmits 27 bundles

1841

Node1 establishes connection to Node2 - reroute_all_bundles entered - ingest (BunRcvPost) continues at 160 bundles/sec but BunRcvProc and Transmission halts

1857

reroute_all_bundles finished - elapsed 15.8 seconds

1857 - 1858

Burst processing posted BundleReceived events, ingest at 160 bundles/sec and transmit hits 385 bundles/sec

1859 - 2441

ingest avg=160 bundles/sec,  rcvd bundles routed avg=160 bundles/sec,   transmit avg=592 bundles/sec

2442

transmit spikes to 12438 bundles in 1 second

2443 - 2526

ingest avg=160 bundles/sec,  rcvd bundles routed avg=160 bundles/sec,   transmit avg=550 bundles/sec

2527 - 3606

all accumulated bundles transmitted, processing settles in at 160 bundles/sec

3606

Data flow terminates

3607

Processing complete in 1 hour