Investigate occasional crashes in the socket_reader_test

[bieryAtFnal]

I've noticed that when I run the socket_reader_test several times, the emu-crt-bern-01 process will occasionally crash. The console output says "Segmentation fault (invalid memory reference)"

This seems to happen as the system is shutting down. (maybe the stop or scrap transition?)

I've seen the problem happen both on np04-srv-005 (EHN1 DAQ computer) and daq.fnal.gov (Fermilab teststand computer). And, I've seen it both with the fddaq-v5.4.0-rc1 build and a recent nightly build.

Below are instructions for reproducing the problem. (To help run the test several times, I created a "bundle" script [copied from daqsystemtest]. We may or may not want to keep this script around after this problem is debugged.)

These instructions make use of a recently nightly build. I'll mark this Issue as targeted to the v5.5.0 release, but if someone wants to advocate for trying to get a fix into 5.4.0, we can certainly talk about that. In any case, it would be great if someone would investigate the source of the crash and implement any code changes that seem to be needed.

DATE_PREFIX=`date '+%d%b'`
TIME_SUFFIX=`date '+%H%M'`

source /cvmfs/dunedaq.opensciencegrid.org/setup_dunedaq.sh
setup_dbt latest
dbt-create -n NFD_DEV_250820_A9 ${DATE_PREFIX}FDDevTest_${TIME_SUFFIX}
cd ${DATE_PREFIX}FDDevTest_${TIME_SUFFIX}/sourcecode

git clone https://github.com/DUNE-DAQ/daqsystemtest.git -b develop
git clone https://github.com/DUNE-DAQ/asiolibs.git -b kbiery/adding_bundle_script
cd ..

dbt-workarea-env
dbt-build -j 12
dbt-workarea-env

asiolibs_integtest_bundle.sh -N 10 --stop-on-fail

[denizergonul]

Hi, I've been running the script a several times now, I couldn't yet reproduce the bug. Is it possible that you have the logs from your previous run and maybe they can already help understanding what went wrong?
(I'm on np04-srv-015 and using the latest nightly.)

[bieryAtFnal]

Yes, there are logs from an example of this behavior on np04-srv-005 in /tmp/pytest-of-biery/pytest-6/run0.

[bieryAtFnal]

I should mention that I couldn't seem to get the problem to happen when I ran the tests yesterday on np04-srv-003. So, maybe there are only certain computers that have the "right" resources to cause the problem to occur...

[bieryAtFnal]

I have looked into the problem more, and I have a theory about what is happening...

For reference, I continue to see the problem when I run the socket_reader_test multiple times on Fermilab teststand computer daq.fnal.gov and on EHN1 data storage server np04-srv-005. I use the asiolibs_integtest_bundle.sh script that is available on the kbiery/adding_bundle_script and kbiery/integtest_crash_debugging branches in the asiolibs repo to run the test over and over again (e.g. asiolibs_integtest_bundle.sh -N 20 --stop-on-fail).

Typically, I see the crash happen if I run the test 5-10 times. So, `asiolibs_integtest_bundle.sh -N 10 --stop-on-fail' is very likely to demonstrate the problem on each of the two computers mentioned above.

The output that I see from the socket_reader_test regression test when the problem occurs is the following:

🚨 Problem(s) found in logfile /tmp/pytest-of-biery/pytest-77/run0/log_biery_local-socket-1x1-config_crt-data-source-01.txt:
2025-Oct-23 16:00:36,547 ERROR [static void ers::ErrorHandler::SignalHandler::action(int, siginfo_t*, void*) at /tmp/root/spack-stage/spack-stage-ers-NB_DEV_251021_A9-y6nv4piqugq5naidzqvbd2tvoyojtl5r/spack-src/src/ErrorHandler.cpp:90] Got signal 11 Segmentation fault (invalid memory reference)

	Parameters = 'name=Segmentation fault (invalid memory reference)' 'signum=11' 

	  #3  /nfs/home/biery/dunedaq/21OctFDDevAsiolibsTesting/install/asiolibs/lib64/libasiolibs_SocketWriterModule_duneDAQModule.so(void boost::asio::detail::reactive_socket_service<boost::asio::ip::udp>::async_send_to<boost::asio::const_buffers_1, boost::asio::detail::awaitable_handler<boost::asio::any_io_executor, boost::system::error_code, unsigned long>, boost::asio::any_io_executor>(boost::asio::detail::reactive_socket_service<boost::asio::ip::udp>::implementation_type&, boost::asio::const_buffers_1 const&, boost::asio::ip::basic_endpoint<boost::asio::ip::udp> const&, int, boost::asio::detail::awaitable_handler<boost::asio::any_io_executor, boost::system::error_code, unsigned long>&, boost::asio::any_io_executor const&)+0x3e4) [0x7ecf0d7ff104]

	  #4  /nfs/home/biery/dunedaq/21OctFDDevAsiolibsTesting/install/asiolibs/lib64/libasiolibs_SocketWriterModule_duneDAQModule.so(boost::asio::detail::awaitable_frame_base<boost::asio::any_io_executor>::await_transform<boost::asio::async_result<boost::asio::use_awaitable_t<boost::asio::any_io_executor>, void (boost::system::error_code, unsigned long)>::initiate<boost::asio::basic_datagram_socket<boost::asio::ip::udp, boost::asio::any_io_executor>::initiate_async_send_to, boost::asio::const_buffers_1, boost::asio::ip::basic_endpoint<boost::asio::ip::udp>, int>(boost::asio::basic_datagram_socket<boost::asio::ip::udp, boost::asio::any_io_executor>::initiate_async_send_to, boost::asio::use_awaitable_t<boost::asio::any_io_executor>, boost::asio::const_buffers_1, boost::asio::ip::basic_endpoint<boost::asio::ip::udp>, int)::{lambda(auto:1*)#1}>(boost::asio::async_result<boost::asio::use_awaitable_t<boost::asio::any_io_executor>, void (boost::system::error_code, unsigned long)>::initiate<boost::asio::basic_datagram_socket<boost::asio::ip::udp, boost::asio::any_io_executor>::initiate_async_send_to, boost::asio::const_buffers_1, boost::asio::ip::basic_endpoint<boost::asio::ip::udp>, int>(boost::asio::basic_datagram_socket<boost::asio::ip::udp, boost::asio::any_io_executor>::initiate_async_send_to, boost::asio::use_awaitable_t<boost::asio::any_io_executor>, boost::asio::const_buffers_1, boost::asio::ip::basic_endpoint<boost::asio::ip::udp>, int)::{lambda(auto:1*)#1}, std::enable_if<std::is_convertible<boost::asio::result_of<boost::asio::async_result<boost::asio::use_awaitable_t<boost::asio::any_io_executor>, void (boost::system::error_code, unsigned long)>::initiate<boost::asio::basic_datagram_socket<boost::asio::ip::udp, boost::asio::any_io_executor>::initiate_async_send_to, boost::asio::const_buffers_1, boost::asio::ip::basic_endpoint<boost::asio::ip::udp>, int>(boost::asio::basic_datagram_socket<boost::asio::ip::udp, boost::asio::any_io_executor>::initiate_async_send_to, boost::asio::use_awaitable_t<boost::asio::any_io_executor>, boost::asio::const_buffers_1, boost::asio::ip::basic_endpoint<boost::asio::ip::udp>, int)::{lambda(auto:1*)#1} (boost::asio::detail::awaitable_frame_base<boost::asio::any_io_executor>*)>::type, boost::asio::detail::awaitable_thread<boost::asio::any_io_executor>*>::value, void>::type*)::result::await_suspend(std::__n4861::coroutine_handle<void>)::{lambda(void*)#1}::_FUN(void*)+0x60) [0x7ecf0d7ff500]

	  #6  /cvmfs/dunedaq-development.opensciencegrid.org/nightly/NB_DEV_251021_A9/spack-0.22.0/opt/spack/linux-almalinux9-x86_64/gcc-13.2.0/iomanager-NB_DEV_251021_A9-bfbcuk6etgzqx2dnpoj3jqfowocal5eh/lib64/libiomanager.so(boost::asio::detail::executor_op<boost::asio::detail::executor_function, std::allocator<void>, boost::asio::detail::scheduler_operation>::do_complete(void*, boost::asio::detail::scheduler_operation*, boost::system::error_code const&, unsigned long)+0x9e) [0x7f02828bcf1e]

	  #7  /cvmfs/dunedaq-development.opensciencegrid.org/nightly/NB_DEV_251021_A9/spack-0.22.0/opt/spack/linux-almalinux9-x86_64/gcc-13.2.0/iomanager-NB_DEV_251021_A9-bfbcuk6etgzqx2dnpoj3jqfowocal5eh/lib64/libiomanager.so(boost::asio::detail::scheduler::do_run_one(boost::asio::detail::conditionally_enabled_mutex::scoped_lock&, boost::asio::detail::scheduler_thread_info&, boost::system::error_code const&)+0x325) [0x7f02828a6445]

The temporary changes that I have made on the asiolibs kbiery/integtest_crash_debugging branch to work around the problem are the following:

diff --git a/plugins/SocketWriterModule.cpp b/plugins/SocketWriterModule.cpp
index 2d63ebc..78899c5 100644
--- a/plugins/SocketWriterModule.cpp
+++ b/plugins/SocketWriterModule.cpp
@@ -33,6 +33,8 @@
 
 namespace dunedaq::asiolibs {
 
+std::atomic<int64_t> SocketWriterModule::m_num_sends_in_flight = 0;
+
 SocketWriterModule::SocketWriterModule(const std::string& name)
   : DAQModule(name)
   , m_work_guard(boost::asio::make_work_guard(m_io_context))
@@ -192,6 +194,7 @@ void
 SocketWriterModule::consume_payload(GenericReceiverConcept::TypeErasedPayload payload)
 {
   for (auto& writer : m_writers) {
+    ++m_num_sends_in_flight;
     std::visit([this, payload](auto& w) mutable { // lets payload to be moved
       boost::asio::co_spawn(m_io_context, w.start(std::move(payload)), boost::asio::detached);
     }, writer);
@@ -249,11 +252,20 @@ SocketWriterModule::do_stop(const CommandData_t&)
     }
   }
 
+  TLOG_DEBUG(0) << "KAB " << __LINE__ << " num_sends_in_flight=" << m_num_sends_in_flight;
+  for (int idx = 0; idx < 500; ++idx) {
+    std::this_thread::sleep_for(std::chrono::milliseconds(200));
+    TLOG_DEBUG(0) << "KAB" << idx << " " << __LINE__ << " num_sends_in_flight=" << m_num_sends_in_flight;
+    if (m_num_sends_in_flight < 10) {break;}
+  }
+
   for (auto& writer : m_writers) {
     std::visit([](auto& writer) { writer.stop(); }, writer);
   }
 
+  TLOG_DEBUG(0) << "KAB " << __LINE__ << " num_sends_in_flight=" << m_num_sends_in_flight;
   m_work_guard.reset();
+  TLOG_DEBUG(0) << "KAB " << __LINE__ << " num_sends_in_flight=" << m_num_sends_in_flight;
 }
 
 void
@@ -307,6 +319,7 @@ SocketWriterModule::TCPWriter::start(GenericReceiverConcept::TypeErasedPayload p
   ++m_socket_stats->sum_payloads;
   m_socket_stats->sum_bytes.fetch_add(bytes_sent);
   ++m_socket_stats->stats_packet_count;
+  --m_num_sends_in_flight;
 }
 
 void
@@ -341,7 +354,8 @@ SocketWriterModule::UDPWriter::start(GenericReceiverConcept::TypeErasedPayload p
   ++m_writer_config.socket_stats->num_payloads;
   ++m_writer_config.socket_stats->sum_payloads;
   m_writer_config.socket_stats->sum_bytes.fetch_add(bytes_sent);
-  ++m_writer_config.socket_stats->stats_packet_count;  
+  ++m_writer_config.socket_stats->stats_packet_count;
+  --m_num_sends_in_flight;
 }
 
 void
diff --git a/plugins/SocketWriterModule.hpp b/plugins/SocketWriterModule.hpp
index 7970c3c..2b4b9f1 100644
--- a/plugins/SocketWriterModule.hpp
+++ b/plugins/SocketWriterModule.hpp
@@ -280,6 +280,8 @@ private:
    */    
   std::atomic<bool> m_run_marker { false };
 
+  static std::atomic<int64_t> m_num_sends_in_flight;
+
   // Consume callback
   /**
    * @brief Raw data consume callback

My theory is that many many background tasks are spawned by the code in the following method:

void
SocketWriterModule::consume_payload(GenericReceiverConcept::TypeErasedPayload payload)
{
  for (auto& writer : m_writers) {
    ++m_num_sends_in_flight;
    std::visit([this, payload](auto& w) mutable { // lets payload to be moved
      boost::asio::co_spawn(m_io_context, w.start(std::move(payload)), boost::asio::detached);
    }, writer);
  }
}

and the code in the SocketWriterModule::do_stop() method needs to wait for them to finish after stopping the consumer thread and before stopping the writers.

Here are sample TRACE messages from a run that used my modified code (note that TRACE messages are shown in reverse time order):

(dbt) [biery@daq 23OctFDDevVariousTesting]$ echo ; tshowt | egrep 'PAUSE|RESUME|KAB' | head -50

  51 10-23 09:00:48.022908 3024613 3028808  90                  SocketWriterModule:268 DBG do_stop: KAB 268 num_sends_in_flight=0
  52 10-23 09:00:48.022879 3024613 3028808  90                  SocketWriterModule:266 DBG do_stop: KAB 266 num_sends_in_flight=0
  54 10-23 09:00:48.022773 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB41 258 num_sends_in_flight=0
  55 10-23 09:00:47.822699 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB40 258 num_sends_in_flight=77420
  56 10-23 09:00:47.622623 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB39 258 num_sends_in_flight=224924
  57 10-23 09:00:47.422547 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB38 258 num_sends_in_flight=422786
  58 10-23 09:00:47.222467 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB37 258 num_sends_in_flight=627032
  59 10-23 09:00:47.022345 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB36 258 num_sends_in_flight=679250
  60 10-23 09:00:46.822251 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB35 258 num_sends_in_flight=691713
  61 10-23 09:00:46.622156 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB34 258 num_sends_in_flight=705180
  62 10-23 09:00:46.422061 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB33 258 num_sends_in_flight=718212
  63 10-23 09:00:46.221963 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB32 258 num_sends_in_flight=731471
  64 10-23 09:00:46.021867 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB31 258 num_sends_in_flight=743513
  65 10-23 09:00:45.821771 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB30 258 num_sends_in_flight=756664
  66 10-23 09:00:45.621652 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB29 258 num_sends_in_flight=769963
  67 10-23 09:00:45.421558 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB28 258 num_sends_in_flight=784685
  68 10-23 09:00:45.221463 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB27 258 num_sends_in_flight=800593
  69 10-23 09:00:45.021370 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB26 258 num_sends_in_flight=817032
  70 10-23 09:00:44.821290 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB25 258 num_sends_in_flight=834642
  71 10-23 09:00:44.621210 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB24 258 num_sends_in_flight=849342
  72 10-23 09:00:44.421111 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB23 258 num_sends_in_flight=864924
  73 10-23 09:00:44.221017 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB22 258 num_sends_in_flight=878053
  74 10-23 09:00:44.020924 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB21 258 num_sends_in_flight=892420
  75 10-23 09:00:43.820844 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB20 258 num_sends_in_flight=906595
  76 10-23 09:00:43.620750 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB19 258 num_sends_in_flight=921370
  77 10-23 09:00:43.420657 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB18 258 num_sends_in_flight=935654
  78 10-23 09:00:43.218468 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB17 258 num_sends_in_flight=951245
  79 10-23 09:00:43.018370 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB16 258 num_sends_in_flight=965530
  80 10-23 09:00:42.818274 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB15 258 num_sends_in_flight=978400
  81 10-23 09:00:42.618180 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB14 258 num_sends_in_flight=989543
  82 10-23 09:00:42.418086 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB13 258 num_sends_in_flight=1002852
  83 10-23 09:00:42.218009 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB12 258 num_sends_in_flight=1018404
  84 10-23 09:00:42.017913 3024613 3028808  90                  SocketWriterModule:258 DBG do_stop: KAB11 258 num_sends_in_flight=1031074
  85 10-23 09:00:41.817799 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB10 258 num_sends_in_flight=1043872
  86 10-23 09:00:41.617701 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB9 258 num_sends_in_flight=1057449
  87 10-23 09:00:41.417606 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB8 258 num_sends_in_flight=1071064
  88 10-23 09:00:41.217511 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB7 258 num_sends_in_flight=1084237
  89 10-23 09:00:41.017438 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB6 258 num_sends_in_flight=1097217
  90 10-23 09:00:40.817345 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB5 258 num_sends_in_flight=1109720
  91 10-23 09:00:40.617261 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB4 258 num_sends_in_flight=1122056
  92 10-23 09:00:40.417142 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB3 258 num_sends_in_flight=1135519
  93 10-23 09:00:40.217049 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB2 258 num_sends_in_flight=1147599
  94 10-23 09:00:40.016967 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB1 258 num_sends_in_flight=1160446
  98 10-23 09:00:39.816864 3024613 3028808  89                  SocketWriterModule:258 DBG do_stop: KAB0 258 num_sends_in_flight=1173058
 107 10-23 09:00:39.616791 3024613 3028808  89                  SocketWriterModule:255 DBG do_stop: KAB 255 num_sends_in_flight=1186987
 173 10-23 09:00:35.277232 3025580 3028332  14                           MLTModule:291 LOG do_pause: ******* Triggers PAUSED! in run 101 *********
 188 10-23 09:00:14.658903 3025580 3027905  80                           MLTModule:307 LOG do_resume: ******* Triggers RESUMED! in run 101 *********

As we can see, there were over 1.1 million background tasks (sends) that were active when do_stop() was called.

[bieryAtFnal]

I have several questions about how to proceed:

1. should the number of background tasks that are spawned be throttled somehow so that there isn't such a large backlog when do_stop() is called?
2. is there a better way to check that there are no pending sends before the writers are stopped in the do_stop() method?

Independent of all of that, I suspect that there is another problem in the SocketWriterModule code. It looks to me that the code is unable to support multiple data-taking runs in the same DAQ session. The creation of threads and initialization of boost::asio objects and their destruction do not seem to be happening at complementary places in the life cycle of this class. For example, calling m_work_guard.reset(); in the do_stop() method seems like it will prevent any subsequent do_start from working reliably.

I believe that I have demonstrated this second problem by adding a second run to the drunc commands listed in the socket_reader_test. When I do that, I see the second run fail, which is what I was concerned about.

I suspect that this code needs to be looked at carefully by Readout working group experts, and we definitely should add a second run to the regression test.

[ShyamB97]

From a readout WG meeting, As @bieryAtFnal eludes to, this does require a review of how the socket reader/writer in asiolibs are configured.

Something to follow up on is if the IO context manager can be finely controlled, to better control the event loop during do_stop/do_conf.

An overall reminder/discussion of how best to configure the readers/writers is also needed to happen to understand how best to configure the socket.

[bieryAtFnal]

At last week's Readout WG meeting, a question was raised about whether the backlog of send tasks in the SocketWriter code builds up over time. Here is a set of TRACE messages that seems to indicate that it does. (the backlog reaches 1.2 M over the course of 26 seconds)

   51 11-03 14:00:17.072490  190308  195812 104                        SocketWriterModule:271 DBG do_stop: do_stop_TRACING 271 num_sends_in_flight=0
   52 11-03 14:00:17.072469  190308  195812 104                        SocketWriterModule:269 DBG do_stop: do_stop_TRACING 269 num_sends_in_flight=0
   54 11-03 14:00:17.072239  190308  195812 104                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING42 261 num_sends_in_flight=0
   55 11-03 14:00:16.872142  190308  195812 104                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING41 261 num_sends_in_flight=80859
   56 11-03 14:00:16.672065  190308  195812 104                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING40 261 num_sends_in_flight=283465
   57 11-03 14:00:16.472009  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING39 261 num_sends_in_flight=525812
   58 11-03 14:00:16.271919  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING38 261 num_sends_in_flight=699132
   59 11-03 14:00:16.071820  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING37 261 num_sends_in_flight=710567
   60 11-03 14:00:15.871728  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING36 261 num_sends_in_flight=723577
   61 11-03 14:00:15.671637  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING35 261 num_sends_in_flight=738735
   62 11-03 14:00:15.471549  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING34 261 num_sends_in_flight=754518
   63 11-03 14:00:15.271457  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING33 261 num_sends_in_flight=765745
   64 11-03 14:00:15.071353  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING32 261 num_sends_in_flight=778011
   65 11-03 14:00:14.871258  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING31 261 num_sends_in_flight=791700
   66 11-03 14:00:14.671161  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING30 261 num_sends_in_flight=805101
   67 11-03 14:00:14.471062  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING29 261 num_sends_in_flight=818146
   68 11-03 14:00:14.270973  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING28 261 num_sends_in_flight=830336
   69 11-03 14:00:14.070882  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING27 261 num_sends_in_flight=842658
   70 11-03 14:00:13.870768  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING26 261 num_sends_in_flight=855359
   71 11-03 14:00:13.670669  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING25 261 num_sends_in_flight=869849
   72 11-03 14:00:13.470550  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING24 261 num_sends_in_flight=884812
   73 11-03 14:00:13.270453  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING23 261 num_sends_in_flight=900634
   74 11-03 14:00:13.070363  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING22 261 num_sends_in_flight=913876
   75 11-03 14:00:12.870275  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING21 261 num_sends_in_flight=925771
   76 11-03 14:00:12.670199  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING20 261 num_sends_in_flight=942008
   77 11-03 14:00:12.470079  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING19 261 num_sends_in_flight=955489
   78 11-03 14:00:12.269984  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING18 261 num_sends_in_flight=971751
   79 11-03 14:00:12.069905  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING17 261 num_sends_in_flight=987944
   80 11-03 14:00:11.869811  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING16 261 num_sends_in_flight=1003805
   81 11-03 14:00:11.669719  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING15 261 num_sends_in_flight=1019865
   82 11-03 14:00:11.469624  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING14 261 num_sends_in_flight=1032741
   83 11-03 14:00:11.269517  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING13 261 num_sends_in_flight=1048893
   84 11-03 14:00:11.069453  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING12 261 num_sends_in_flight=1063230
   85 11-03 14:00:10.869363  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING11 261 num_sends_in_flight=1075725
   86 11-03 14:00:10.669273  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING10 261 num_sends_in_flight=1089801
   87 11-03 14:00:10.469181  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING9 261 num_sends_in_flight=1101587
   88 11-03 14:00:10.269102  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING8 261 num_sends_in_flight=1114276
   89 11-03 14:00:10.069012  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING7 261 num_sends_in_flight=1127546
   90 11-03 14:00:09.868877  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING6 261 num_sends_in_flight=1140138
   91 11-03 14:00:09.668796  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING5 261 num_sends_in_flight=1155838
   92 11-03 14:00:09.468719  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING4 261 num_sends_in_flight=1169879
   93 11-03 14:00:09.268643  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING3 261 num_sends_in_flight=1183076
   94 11-03 14:00:09.068560  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING2 261 num_sends_in_flight=1194883
   95 11-03 14:00:08.868441  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING1 261 num_sends_in_flight=1207003
   99 11-03 14:00:08.668345  190308  195812  43                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING0 261 num_sends_in_flight=1221970
  100 11-03 14:00:08.468257  190308  195812  43                        SocketWriterModule:258 DBG do_stop: do_stop_TRACING 258 num_sends_in_flight=1236224
  144 11-03 14:00:07.180294  190308  190880  25                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1200000
  145 11-03 14:00:07.180247  190308  190880  25                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1200000
  146 11-03 14:00:07.180218  190308  190880  25                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1200000
  162 11-03 14:00:04.843334  190308  190880  25                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1100000
  163 11-03 14:00:04.843261  190308  190880  25                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1100000
  164 11-03 14:00:04.843215  190308  190880  25                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1100000
  165 11-03 14:00:04.843154  190308  190880  25                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1100000
  181 11-03 14:00:04.554091  191347  195363 127                                 MLTModule:291 LOG do_pause: ******* Triggers PAUSED! in run 101 *********
  182 11-03 14:00:01.969970  190308  190880  80                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1000000
  183 11-03 13:59:59.390950  190308  190880   0                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=900000
  184 11-03 13:59:59.390931  190308  190880   0                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=899997
  185 11-03 13:59:56.664741  190308  190880 126                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=800000
  186 11-03 13:59:56.664729  190308  190880 126                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=800000
  187 11-03 13:59:56.664721  190308  190880 126                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=800000
  188 11-03 13:59:56.664670  190308  190880 126                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=800000
  189 11-03 13:59:56.664614  190308  190880 126                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=800000
  190 11-03 13:59:56.664590  190308  190880 126                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=800000
  191 11-03 13:59:54.388176  190308  190880  28                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=700000
  192 11-03 13:59:54.388142  190308  190880  28                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=700000
  193 11-03 13:59:54.388133  190308  190880  28                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=700000
  194 11-03 13:59:51.896646  190308  190880 115                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=600000
  195 11-03 13:59:51.896627  190308  190880 115                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=600000
  196 11-03 13:59:49.796227  190308  190880  27                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=500000
  197 11-03 13:59:49.796201  190308  190880  27                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=500000
  198 11-03 13:59:47.780450  190308  190880 105                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=400000
  199 11-03 13:59:47.780422  190308  190880 105                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=400000
  200 11-03 13:59:45.504483  190308  190880 122                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=300000
  201 11-03 13:59:45.504428  190308  190880 122                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=300000
  202 11-03 13:59:45.504404  190308  190880 122                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=300000
  216 11-03 13:59:44.414257  191347  194446  82                                 MLTModule:307 LOG do_resume: ******* Triggers RESUMED! in run 101 *********
  223 11-03 13:59:43.043821  190308  190880 118                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=200000
  224 11-03 13:59:43.043782  190308  190880 118                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=200000
  225 11-03 13:59:43.043713  190308  190880 118                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=200000
  226 11-03 13:59:43.043674  190308  190880 118                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=200000
  227 11-03 13:59:43.043672  190308  190880 118                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=199999
  228 11-03 13:59:41.036016  190308  190880  64                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=100000
  229 11-03 13:59:41.035950  190308  190880  64                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=100000

[bieryAtFnal]

Another way to answer the question about how the background tasks build up is to increase the duration of the run and see if the number of background tasks plateaus. Here is the output from a 40-second run (double the usual 20 seconds). The amount of backlog pretty much doubles.

   51 11-03 14:22:32.057385  349939  371623  37                        SocketWriterModule:271 DBG do_stop: do_stop_TRACING 271 num_sends_in_flight=1
   52 11-03 14:22:32.057383  349939  371623  37                        SocketWriterModule:269 DBG do_stop: do_stop_TRACING 269 num_sends_in_flight=1
   54 11-03 14:22:32.056987  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING68 261 num_sends_in_flight=1
   55 11-03 14:22:31.856907  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING67 261 num_sends_in_flight=73012
   56 11-03 14:22:31.656768  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING66 261 num_sends_in_flight=146343
   57 11-03 14:22:31.456695  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING65 261 num_sends_in_flight=351786
   58 11-03 14:22:31.256600  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING64 261 num_sends_in_flight=508021
   59 11-03 14:22:31.056525  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING63 261 num_sends_in_flight=695057
   60 11-03 14:22:30.856447  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING62 261 num_sends_in_flight=899737
   61 11-03 14:22:30.656372  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING61 261 num_sends_in_flight=1118754
   62 11-03 14:22:30.456293  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING60 261 num_sends_in_flight=1131164
   63 11-03 14:22:30.256233  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING59 261 num_sends_in_flight=1145970
   64 11-03 14:22:30.056165  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING58 261 num_sends_in_flight=1162676
   65 11-03 14:22:29.856086  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING57 261 num_sends_in_flight=1180528
   66 11-03 14:22:29.656026  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING56 261 num_sends_in_flight=1197514
   67 11-03 14:22:29.455960  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING55 261 num_sends_in_flight=1211289
   68 11-03 14:22:29.255898  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING54 261 num_sends_in_flight=1224346
   69 11-03 14:22:29.055819  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING53 261 num_sends_in_flight=1240737
   70 11-03 14:22:28.855741  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING52 261 num_sends_in_flight=1254291
   71 11-03 14:22:28.655639  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING51 261 num_sends_in_flight=1269460
   72 11-03 14:22:28.455558  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING50 261 num_sends_in_flight=1283175
   73 11-03 14:22:28.255473  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING49 261 num_sends_in_flight=1296109
   74 11-03 14:22:28.055398  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING48 261 num_sends_in_flight=1308737
   75 11-03 14:22:27.855321  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING47 261 num_sends_in_flight=1323227
   76 11-03 14:22:27.655239  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING46 261 num_sends_in_flight=1334290
   77 11-03 14:22:27.455122  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING45 261 num_sends_in_flight=1346269
   78 11-03 14:22:27.255034  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING44 261 num_sends_in_flight=1362449
   79 11-03 14:22:27.054961  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING43 261 num_sends_in_flight=1377679
   80 11-03 14:22:26.854902  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING42 261 num_sends_in_flight=1393785
   81 11-03 14:22:26.654841  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING41 261 num_sends_in_flight=1409689
   82 11-03 14:22:26.454784  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING40 261 num_sends_in_flight=1424700
   83 11-03 14:22:26.254712  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING39 261 num_sends_in_flight=1438701
   84 11-03 14:22:26.054651  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING38 261 num_sends_in_flight=1451744
   85 11-03 14:22:25.854591  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING37 261 num_sends_in_flight=1468745
   86 11-03 14:22:25.654533  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING36 261 num_sends_in_flight=1484874
   87 11-03 14:22:25.454471  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING35 261 num_sends_in_flight=1499173
   88 11-03 14:22:25.254410  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING34 261 num_sends_in_flight=1515263
   89 11-03 14:22:25.054349  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING33 261 num_sends_in_flight=1529935
   90 11-03 14:22:24.854273  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING32 261 num_sends_in_flight=1544636
   91 11-03 14:22:24.654224  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING31 261 num_sends_in_flight=1557668
   92 11-03 14:22:24.454163  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING30 261 num_sends_in_flight=1575086
   93 11-03 14:22:24.254083  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING29 261 num_sends_in_flight=1588622
   94 11-03 14:22:24.054025  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING28 261 num_sends_in_flight=1603383
   95 11-03 14:22:23.853962  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING27 261 num_sends_in_flight=1618292
   96 11-03 14:22:23.653867  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING26 261 num_sends_in_flight=1634503
   97 11-03 14:22:23.453808  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING25 261 num_sends_in_flight=1649740
   98 11-03 14:22:23.253747  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING24 261 num_sends_in_flight=1664598
   99 11-03 14:22:23.053687  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING23 261 num_sends_in_flight=1679052
  100 11-03 14:22:22.853626  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING22 261 num_sends_in_flight=1697158
  101 11-03 14:22:22.653562  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING21 261 num_sends_in_flight=1713544
  102 11-03 14:22:22.453497  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING20 261 num_sends_in_flight=1730769
  103 11-03 14:22:22.253384  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING19 261 num_sends_in_flight=1745576
  104 11-03 14:22:22.053324  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING18 261 num_sends_in_flight=1761111
  105 11-03 14:22:21.853264  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING17 261 num_sends_in_flight=1776888
  106 11-03 14:22:21.653205  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING16 261 num_sends_in_flight=1790382
  107 11-03 14:22:21.453146  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING15 261 num_sends_in_flight=1803124
  108 11-03 14:22:21.253086  349939  371623  38                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING14 261 num_sends_in_flight=1817929
  109 11-03 14:22:21.053022  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING13 261 num_sends_in_flight=1833420
  110 11-03 14:22:20.853001  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING12 261 num_sends_in_flight=1846877
  111 11-03 14:22:20.652937  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING11 261 num_sends_in_flight=1861393
  112 11-03 14:22:20.452868  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING10 261 num_sends_in_flight=1879410
  113 11-03 14:22:20.252773  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING9 261 num_sends_in_flight=1894312
  114 11-03 14:22:20.052680  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING8 261 num_sends_in_flight=1909623
  115 11-03 14:22:19.852564  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING7 261 num_sends_in_flight=1923224
  116 11-03 14:22:19.652459  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING6 261 num_sends_in_flight=1938067
  117 11-03 14:22:19.452371  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING5 261 num_sends_in_flight=1952398
  118 11-03 14:22:19.252301  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING4 261 num_sends_in_flight=1964949
  119 11-03 14:22:19.052190  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING3 261 num_sends_in_flight=1978441
  120 11-03 14:22:18.852094  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING2 261 num_sends_in_flight=1993061
  121 11-03 14:22:18.651966  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING1 261 num_sends_in_flight=2007563
  133 11-03 14:22:18.451864  349939  371623  37                        SocketWriterModule:261 DBG do_stop: do_stop_TRACING0 261 num_sends_in_flight=2024741
  134 11-03 14:22:18.251731  349939  371623  37                        SocketWriterModule:258 DBG do_stop: do_stop_TRACING 258 num_sends_in_flight=2037337
  170 11-03 14:22:16.566549  349939  350874  94                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=2000000
  171 11-03 14:22:16.566484  349939  350874  94                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1999998
  202 11-03 14:22:14.341525  350853  369974  81                                 MLTModule:291 LOG do_pause: ******* Triggers PAUSED! in run 101 *********
  203 11-03 14:22:13.648666  349939  350874  81                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1900000
  204 11-03 14:22:13.648608  349939  350874  81                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1899995
  205 11-03 14:22:10.519593  349939  350874  95                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1800000
  206 11-03 14:22:10.519533  349939  350874  95                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1800000
  207 11-03 14:22:10.519494  349939  350874  95                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1800000
  208 11-03 14:22:07.940144  349939  350874  74                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1700000
  209 11-03 14:22:07.940118  349939  350874  74                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1700000
  210 11-03 14:22:05.051791  349939  350874  44                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1600000
  211 11-03 14:22:05.051752  349939  350874  44                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1600000
  212 11-03 14:22:05.051744  349939  350874  44                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1600000
  213 11-03 14:22:02.632848  349939  350874  47                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1500000
  214 11-03 14:22:02.632804  349939  350874  47                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1500000
  215 11-03 14:22:00.364651  349939  350874 109                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1400000
  216 11-03 14:22:00.364623  349939  350874 109                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1400000
  217 11-03 14:21:58.072639  349939  350874  24                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1300000
  218 11-03 14:21:58.072585  349939  350874  24                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1300000
  219 11-03 14:21:58.072558  349939  350874  24                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1299996
  220 11-03 14:21:55.752298  349939  350874  16                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1200000
  221 11-03 14:21:55.752219  349939  350874  16                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1200000
  222 11-03 14:21:55.752182  349939  350874  16                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1200000
  223 11-03 14:21:53.523731  349939  350874  11                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1100000
  224 11-03 14:21:53.523696  349939  350874  11                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1099999
  225 11-03 14:21:51.284405  349939  350874  47                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=1000000
  226 11-03 14:21:49.175191  349939  350874   8                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=900000
  227 11-03 14:21:49.175182  349939  350874   8                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=899998
  228 11-03 14:21:47.081528  349939  350874  75                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=800000
  229 11-03 14:21:47.081505  349939  350874  75                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=800000
  230 11-03 14:21:44.875574  349939  350874  85                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=700000
  231 11-03 14:21:42.754672  349939  350874   3                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=600000
  232 11-03 14:21:42.754647  349939  350874   3                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=599999
  233 11-03 14:21:40.749653  349939  350874  39                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=500000
  234 11-03 14:21:40.749624  349939  350874  39                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=500000
  235 11-03 14:21:38.614076  349939  350874 117                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=400000
  236 11-03 14:21:38.614025  349939  350874 117                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=400000
  237 11-03 14:21:36.325333  349939  350874  28                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=300000
  255 11-03 14:21:34.172651  350853  361191  14                                 MLTModule:307 LOG do_resume: ******* Triggers RESUMED! in run 101 *********
  258 11-03 14:21:34.159657  349939  350874  53                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=200000
  259 11-03 14:21:34.159643  349939  350874  53                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=200000
  260 11-03 14:21:34.159630  349939  350874  53                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=200000
  261 11-03 14:21:32.028907  349939  350874  72                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=100000
  262 11-03 14:21:32.028860  349939  350874  72                        SocketWriterModule:199 DBG consume_payload: consume_payload_TRACING 199 num_sends_in_flight=99999