The unexpected delay of start application

[jo pillar]

Subject: Query Regarding Unusual Delay in Application Startup in ns-3

Hello everyone,

I hope this email finds you well. I am reaching out to seek assistance regarding an issue I've encountered in ns-3. I am currently using version ns3.36.1, and I've run into an unusual delay when starting applications.

I've created a BulkSendApplication and added send and recv callback functions to it. In my registered rx function, I create a new BulkSendApplication after receiving all data and set it to start at simulator::now.

However, I've noticed a discrepancy between the expected startup time of the application and its actual startup time. Below, I've attached simplified code snippets along with the output of the program.

```

void

InstallSendApp (const uint32_t srcId, const uint32_t destId)

{

  NS_LOG_UNCOND("node "<<srcId<<" application creat time at "<<Simulator::Now().GetSeconds());

  apps.Start (Simulator::Now ());

  apps.Stop (Seconds (SimTime));

  apps.Get (0)->TraceConnectWithoutContext ("Tx", MakeCallback (&SendComplete));

}

void

InstallSinkApp (const uint32_t destId)

{

  sinkApps.Get (0)->TraceConnectWithoutContext ("RxWithAddresses", MakeCallback (&RecvComplete));

  sinkApps.Start (Seconds (0));

  sinkApps.Stop (Seconds (SimTime));

}

void //rx callback

RecvComplete (Ptr<const Packet> pkt, const Address &src, const Address &dest)

{

  if (complete)

    {

      auto curId = tag.getSrcId ();

      Simulator::ScheduleNow(InstallSendApp,curId+1,curId+3);    

      NS_LOG_UNCOND ("has complete recv a flow from " << tag.getSrcId () << "at time "

                                                      << Simulator::Now ().GetSeconds ());

    }

}

// add some log on  StartApplication methods

void BulkSendApplication::StartApplication (void) // Called at time specified by Start

{

  NS_LOG_FUNCTION (this);

  Address from;

NS_LOG_UNCOND("node "<<GetNode()->GetId()<<" application enter start time at "<<Simulator::Now().GetSeconds());//My print

/*

......

*/

      if (ret == -1)

        {

          NS_FATAL_ERROR ("Failed to bind socket");

        }

      NS_LOG_UNCOND("node "<<GetNode()->GetId()<<" application start time at "<<Simulator::Now().GetSeconds());//My print

      m_socket->Connect (m_peer);

      NS_LOG_UNCOND("node "<<GetNode()->GetId()<<" application Connect time at "<<Simulator::Now().GetSeconds());//My print

/*

.......

*/

  if (m_connected)

    {

      m_socket->GetSockName (from);

      SendData (from, m_peer);

    }

}

```

Output:

```

has complete recv a flow from 1at time 0.901284
node 2 application creat time at 0.901284
node 2 application enter start time at 1.80357
node 2 application start time at 1.80357
node 2 application Connect time at 1.80357

```
Now there is a long delay between the  application create time and  application enter start time ! !!!
I would greatly appreciate any insights or suggestions you might have regarding this delay issue. I'm eager to identify the root cause and explore potential solutions.

Thank you very much for your assistance!

Best regards,
zhuodong wu

[Tommaso Pecorella]

Hi,

that's the delay needed by the nodes to find each other address - basically it's due to all the neighbour solicitations (ARPs if you're using IPV4). Depending on the topology this can be a short time, or a quite long time.

[jo pillar]

Hi 

Thank you for your prompt response and clarification regarding the delay issue.

From my understanding, ARP is used to obtain the MAC address of the destination host. When the destination host cannot be found in its own cache table, it sends out an ARP broadcast request and caches the result in its ARP cache table.

However, during my testing, I've noticed a significant delay between application creation and actual startup time. This delay does not seem to be shortened even when I've previously created applications with the same source and destination nodes.

Here are some sample timestamps illustrating the delay:

- Node 2 application creation time at 0.901284
- Node 2 application enters start time at 1.80357 (first creation)
- Node 2 application creation time at 76.0331
- Node 2 application enters start time at 152.067 (second creation)

I find this phenomenon quite peculiar and not in line with expected behavior. Do you have any suggestions on how to eliminate this delay? It's significantly impacting experimental results and deviates from theoretical expectations.

I appreciate any insights or recommendations you can provide regarding this matter.

Thank you for your assistance.

Best regards,

[Tommaso Pecorella]

Try using the NeighborCacheHelper, it has methods to pre-populate the ARP tables.

In my opinion if your theoretical expectations are heavily affected by ARP, then the theoretical model is... well, not really useful (it can not predict a realistic environment and/or it is too much affected by the "noise" of real protocols).

Nevertheless, just to check if it's ARP one can try to silence it.

Other possible explanations are:

- Tx buffers in the node (more than one app in the node sending data),

- Channel being congested and/or busy

- Errors in coding

As a side note, apps should not be "created" at run time, they can be started after the simulation start, but they should be created in advance.

[jo pillar]

Address this problem is very simple, just 

convert 

apps.Start (Simulator::Now ());

to

apps.Start (Seconds(0));

can solve the problem.

  

I hope this solution maybe help to you.

[Tommaso Pecorella]

It is, because it might be a symptom of something way more disturbing (a low level bug, or at least a low level unexpected behavior).

Please send a complete script, I want to check it.

For the records, "Simulator::Now()" returns the current time, so when the simulation is not yet started (i.e., before "Simulator::Run()"), it should return Seconds(0).

Now, the other quirk to consider is that "ApplicationContainer::Start" accepts an **absolute** time, i.e., start at time X, as opposite to the usual delta time (start X seconds after the current time). Hence, let's say that a careless dev would call "Start(Seconds(0))" when the simulation is running (let's say that the current time is Seconds 11)... that would be a huge error, because the application would't probably start correctly.

Anyway, please send a complete example.

[jo pillar]

#include "flow_stat.hpp"

#include "ns3/applications-module.h"

#include "ns3/coll-trace-tag.h"

#include "ns3/core-module.h"

#include "ns3/internet-module.h"

#include "ns3/ipv4-global-routing-helper.h"

#include "ns3/netanim-module.h"

#include "ns3/network-module.h"

#include "ns3/nstime.h"

#include "ns3/point-to-point-module.h"

#include "ns3/simulator.h"

#include <cassert>

#include <cstdlib>

#include <fstream>

#include <iostream>

#include <sstream>

#include <string>

#include <vector>

using namespace std;

using namespace ns3;

NodeContainer g_nodes; // Declare nodes objects

double SimTime = 10.00;

double SinkStartTime = 0.00001;

double AppStartTime = 0.0001;

constexpr uint32_t NEWFLOWID = UINT32_MAX;

// ---------- Prototypes ------------------------------------------------------

uint16_t g_port = 9;

// std::vector<std::vector<ApplicationContainer>> g_sendApplication;

void RecvComplete(Ptr<const Packet> pkt, const Address &src,

                  const Address &dest);

vector<vector<int>> readNxNMatrix(std::string adj_mat_file_name);

void printMatrix(const char *description, vector<vector<bool>> array);

uint32_t GetNextAction(uint32_t id);

void SendComplete(Ptr<const Packet> pkt);

void StartSendApp(int srcId, int destId);

NS_LOG_COMPONENT_DEFINE("COLL_SCHE");

void InstallSendApp(const uint32_t srcId, const uint32_t destId,

                    const uint32_t preFlowid) {

  static uint32_t curFlowId = 0;

  // auto i = srcId;

  if (srcId >= NodeList::GetNNodes() || destId >= NodeList::GetNNodes()) {

    cerr << "wrong" << endl;

    return;

  }

  // printf ("%s with %d %d\n", __FUNCTION__, srcId, destId);

  Ptr<Node> dstNode = NodeList::GetNode(destId);

  Ptr<Ipv4> ipv4 = dstNode->GetObject<Ipv4>();

  Ipv4InterfaceAddress ipv4_int_addr = ipv4->GetAddress(1, 0);

  Ipv4Address ip_addr = ipv4_int_addr.GetLocal();

  BulkSendHelper bulk("ns3::TcpSocketFactory",

                      InetSocketAddress(ip_addr, g_port));

  bulk.SetAttribute("MaxBytes", UintegerValue(1048576)); // 64MB

  // OnOffHelper onoff ("ns3::UdpSocketFactory", InetSocketAddress (ip_addr,

  // port)); // traffic flows from node[i] to node[j] onoff.SetConstantRate

  // (DataRate (AppPacketRate)); ApplicationContainer apps = onoff.Install

  // (nodes.Get (i));  // traffic sources are installed on all nodes

  auto apps = bulk.Install(NodeList::GetNode(srcId));

  // add tag

  auto bulkapp = DynamicCast<BulkSendApplication>(apps.Get(0));

  uint32_t flowId = 0;

  if (preFlowid == NEWFLOWID) {

    flowId = curFlowId++;

  } else {

    flowId = preFlowid;

  }

  assert(apps.GetN() == 1);

  // stat flow info

  std::ostringstream oss;

  oss << "start," << flowId << "," << srcId << "," << destId << ","

      << Simulator::Now().GetSeconds() << "\n";

  NS_LOG_UNCOND(oss.str());

  apps.Start(Simulator::Now());//!!! should start at 2s but real start at time 4s should change to apps.Start(Seconds(0));

  apps.Stop(Seconds(SimTime));

 

  apps.Get(0)->TraceConnectWithoutContext("Tx", MakeCallback(&SendComplete));

}

void InstallSinkApp(const uint32_t destId) {

  PacketSinkHelper sink("ns3::TcpSocketFactory",

                        InetSocketAddress(Ipv4Address::GetAny(), g_port));

  // 将PacketSink安装到节点1

  ApplicationContainer sinkApps = sink.Install(NodeList::GetNode(destId));

  sinkApps.Get(0)->TraceConnectWithoutContext("RxWithAddresses",

                                              MakeCallback(&RecvComplete));

  sinkApps.Start(Seconds(SinkStartTime));

  sinkApps.Stop(Seconds(SimTime));

}

void RecvComplete(Ptr<const Packet> pkt, const Address &src,

                  const Address &dest) {

  static int count = 0;

  static int srcId = 1;

  static int destId = 2;

  count++;

  if (count > 10000) {

    InstallSendApp((srcId++) % 6, (destId++) % 6, NEWFLOWID);

    // InstallSendApp (curId + 1, curId + 3);

    std::ostringstream oss;

    oss << "recv," << srcId << "," << destId << ","

        << Simulator::Now().GetSeconds() << "\n";

    NS_LOG_UNCOND(oss.str());

  }

  // if(!pkt->m_connected){

  //   printf("has completed a flow from node %d\n",pkt->NodeId);

  //   // cout<<" src "<<src<<"dest "<<dest<<"on time

  //   "<<Simulator::Now().GetSeconds()<< endl;

  // }

}

void SendComplete(Ptr<const Packet> pkt) {

;

}

int main(int argc, char *argv[]) {

  // ---------- Simulation Variables ------------------------------------------

  // Change the variables and file names only in this block!

  std::string LinkRateUnit("MBps");

  std::string LinkDelay("2ms");

  srand((unsigned)time(NULL)); // generate different seed each time

  // LogComponentEnable ("BulkSendApplication", LOG_LEVEL_INFO);

  // LogComponentEnable ("PacketSink", LOG_LEVEL_INFO);

  std::string tr_name("n-node-ppp.tr");

  std::string pcap_name("n-node-ppp");

  std::string flow_name("n-node-ppp.xml");

  std::string anim_name("n-node-ppp.anim.xml");

  std::string adj_mat_file_name(

      "contrib/opengym/examples/collective_schedule/dymmy_beel_6_adj.txt");

  CommandLine cmd(__FILE__);

  cmd.Parse(argc, argv);

  // ---------- End of Simulation Variables ----------------------------------

  // ---------- Read Adjacency Matrix ----------------------------------------

  auto Adj_Matrix = readNxNMatrix(adj_mat_file_name);

  // Optionally display 2-dimensional adjacency matrix (Adj_Matrix) array

  // printMatrix (adj_mat_file_name.c_str (),Adj_Matrix);

  // ---------- End of Read Adjacency Matrix ---------------------------------

  // ---------- Read Node Coordinates File -----------------------------------

  int n_nodes = Adj_Matrix.size();

  // g_sendApplication.resize (n_nodes);

  printf("node num %d\n", n_nodes);

  // ---------- End of Read Node Coordinates File ----------------------------

  // ---------- Network Setup ------------------------------------------------

  NS_LOG_INFO("Create Nodes.");

  g_nodes.Create(n_nodes);

  NS_LOG_INFO("Create P2P Link Attributes.");

  PointToPointHelper p2p;

  p2p.SetChannelAttribute("Delay", StringValue(LinkDelay));

  NS_LOG_INFO("Install Internet Stack to Nodes.");

  InternetStackHelper internet;

  internet.Install(NodeContainer::GetGlobal());

  NS_LOG_INFO("Assign Addresses to Nodes.");

  Ipv4AddressHelper ipv4_n;

  ipv4_n.SetBase("10.0.0.0", "255.255.255.252");

  NS_LOG_INFO("Create Links Between Nodes.");

  uint32_t linkCount = 0;

  for (size_t i = 0; i < Adj_Matrix.size(); i++) {

    for (size_t j = 0; j < Adj_Matrix[i].size(); j++) {

      if (auto band = Adj_Matrix[i][j]; band != 0) // C++17

      {

        NodeContainer n_links = NodeContainer(g_nodes.Get(i), g_nodes.Get(j));

        std::string LinkRate = to_string(band) + LinkRateUnit;

        p2p.SetDeviceAttribute("DataRate", StringValue(LinkRate));

        printf("node %ld to node %ld: %s\n", i, j, LinkRate.c_str());

        NetDeviceContainer n_devs = p2p.Install(n_links);

        ipv4_n.Assign(n_devs);

        ipv4_n.NewNetwork();

        linkCount++;

        NS_LOG_INFO("matrix element [" << i << "][" << j << "] is 1");

      } else {

        NS_LOG_INFO("matrix element [" << i << "][" << j << "] is 0");

      }

    }

  }

  NS_LOG_INFO("Number of links in the adjacency matrix is: " << linkCount);

  NS_LOG_INFO("Number of all nodes is: " << g_nodes.GetN());

  NS_LOG_INFO("Initialize Global Routing.");

  Ipv4GlobalRoutingHelper::PopulateRoutingTables();

  // ---------- End of Network Set-up ----------------------------------------

  // ---------- Create n*(n-1) CBR Flows -------------------------------------

  NS_LOG_INFO("Setup Packet Sinks.");

  NS_LOG_INFO("Setup CBR Traffic Sources.");

  // for (int i = 0; i < n_nodes; i++)

  //   {

  //     for (int j = 0; j < n_nodes; j++)

  //       {

  //         InstallSendApp (i, j);

  //       }

  //   }

  fprintf(stdout, "action,flowid,srcid,destid,time\n");

  Simulator::Schedule(Seconds(2),InstallSendApp,0, 1, NEWFLOWID);

  for (uint32_t i = 0; i < NodeList::GetNNodes(); i++) {

    InstallSinkApp(i);

  }

  // create a ns3 bulkApplication send 64kb data from 0 to 1

  // 为接收完成事件添加回调函数

  // sinkApps.Get (0)->TraceConnectWithoutContext ("RxWithAddresses",

  // MakeCallback (&ReceiveComplete));

  // ---------- End of Create n*(n-1) CBR Flows ------------------------------

  // ---------- Simulation Monitoring ----------------------------------------

  NS_LOG_INFO("Configure Tracing.");

  AsciiTraceHelper ascii;

  p2p.EnableAsciiAll(ascii.CreateFileStream(tr_name.c_str()));

  // p2p.EnablePcapAll (pcap_name.c_str());

  // Ptr<FlowMonitor> flowmon;

  // FlowMonitorHelper flowmonHelper;

  // flowmon = flowmonHelper.InstallAll ();

  // Configure animator with default settings

  NS_LOG_INFO("Run Simulation.");

  Simulator::Stop(Seconds(SimTime));

  Simulator::Run();

  // flowmon->SerializeToXmlFile (flow_name.c_str(), true, true);

  Simulator::Destroy();

  // ---------- End of Simulation Monitoring ---------------------------------

  cout << "end simulation" << endl;

  return 0;

}

// ---------- Function Definitions -------------------------------------------

vector<vector<int>> readNxNMatrix(std::string adj_mat_file_name) {

  ifstream adj_mat_file;

  adj_mat_file.open(adj_mat_file_name.c_str(), ios::in);

  if (adj_mat_file.fail()) {

    NS_FATAL_ERROR("File " << adj_mat_file_name.c_str() << " not found");

  }

  vector<vector<int>> array;

  int i = 0;

  int n_nodes = 0;

  while (!adj_mat_file.eof()) {

    string line;

    getline(adj_mat_file, line);

    if (line == "") {

      NS_LOG_WARN("WARNING: Ignoring blank row in the array: " << i);

      break;

    }

    istringstream iss(line);

    int element;

    vector<int> row;

    int j = 0;

    while (iss >> element) {

      row.push_back(element);

      j++;

    }

    if (i == 0) {

      n_nodes = j;

    }

    if (j != n_nodes) {

      NS_LOG_ERROR("ERROR: Number of elements in line "

                   << i << ": " << j

                   << " not equal to number of elements in line 0: "

                   << n_nodes);

      NS_FATAL_ERROR("ERROR: The number of rows is not equal to the number of "

                     "columns! in the "

                     "adjacency matrix");

    } else {

      array.push_back(row);

    }

    i++;

  }

  if (i != n_nodes) {

    NS_LOG_ERROR("There are " << i << " rows and " << n_nodes << " columns.");

    NS_FATAL_ERROR("ERROR: The number of rows is not equal to the number of "

                   "columns! in the "

                   "adjacency matrix");

  }

  adj_mat_file.close();

  return array;

}

vector<vector<double>>

readCordinatesFile(std::string node_coordinates_file_name) {

  ifstream node_coordinates_file;

  node_coordinates_file.open(node_coordinates_file_name.c_str(), ios::in);

  if (node_coordinates_file.fail()) {

    NS_FATAL_ERROR("File " << node_coordinates_file_name.c_str()

                           << " not found");

  }

  vector<vector<double>> coord_array;

  int m = 0;

  while (!node_coordinates_file.eof()) {

    string line;

    getline(node_coordinates_file, line);

    if (line == "") {

      NS_LOG_WARN("WARNING: Ignoring blank row: " << m);

      break;

    }

    istringstream iss(line);

    double coordinate;

    vector<double> row;

    int n = 0;

    while (iss >> coordinate) {

      row.push_back(coordinate);

      n++;

    }

    if (n != 2) {

      NS_LOG_ERROR("ERROR: Number of elements at line#"

                   << m << " is " << n

                   << " which is not equal to 2 for node coordinates file");

      exit(1);

    }

    else {

      coord_array.push_back(row);

    }

    m++;

  }

  node_coordinates_file.close();

  return coord_array;

}

void printMatrix(const char *description, vector<vector<bool>> array) {

  cout << "**** Start " << description << "********" << endl;

  for (size_t m = 0; m < array.size(); m++) {

    for (size_t n = 0; n < array[m].size(); n++) {

      cout << array[m][n] << ' ';

    }

    cout << endl;

  }

  cout << "**** End " << description << "********" << endl;

}

void printCoordinateArray(const char *description,

                          vector<vector<double>> coord_array) {

  cout << "**** Start " << description << "********" << endl;

  for (size_t m = 0; m < coord_array.size(); m++) {

    for (size_t n = 0; n < coord_array[m].size(); n++) {

      cout << coord_array[m][n] << ' ';

    }

    cout << endl;

  }

  cout << "**** End " << description << "********" << endl;

}

pay attention to line:74 and add print time  at function void BulkSendApplication::StartApplication (void)

[Tommaso Pecorella]

Thank you very much.

Unfortunately I'll not be able to run your script, because:

- I don't use gym,

- I don't have the files you're using as an input,

- There's a missing header.

- I don't have neither the time nor the willingness to fix your script.

Said so, the good news is that I don't even need to run your script, as you did exactly what I said to not do - or do only if you're a super-expert.

Creating (and starting) an application AFTER Simulator::Run is not a joke. It is possible, but you have to have a deep understanding of the simulator, its inner components, and how events are scheduled. Plus, of course, triple check the code.

This is exactly what your code does.

Said so, I have to correct myself:

> Now, the other quirk to consider is that "ApplicationContainer::Start" accepts an **absolute** time, i.e., start at time X, as opposite to the usual delta time (start X seconds after the current time). Hence, let's say that a careless dev would call "Start(Seconds(0))" when the simulation is running (let's say that the current time is Seconds 11)... that would be a huge error, because the application would't probably start correctly.

I was wrong - "ApplicationContainer::Start" accepts a **delta** time, like all the other Schedule functions - but usually it's used before Simulator::Start, so a delta is the same as an absolute time.

In your case, since you're starting the apps during the simulation, you have to use "0" to indicate "immediately".

Nevertheless, no matter what you do you'll get a (small) delay due to the TCP socket connection (3-way handshake).

[jo pillar]

So the documentation should be updated. According to the documentation，the application should be started at the given time.

[Tommaso Pecorella]

Yes, the documentation has to be clarified, but it's correct under the assumption that the user uses the helpers in the simulation setup phase and not in the running phase.