Skip to content

Draft:Enrich NS_LOG with log start/end time

Mattia Lecci requested to merge mattia-lecci/ns-3-dev:feature/log-time-interval into master

This is a WIP/discussion to add this feature.

Motivation

Sometimes error arise after several seconds of simulation in classes that output a lot of logging (e.g., channel/spectrum classes when many users are present). File sizes can easily grow to the order GBs.

Solution

Only activate logs in specified time intervals, e.g., from 1.2s to 1.5s.

One possibility is to schedule specified logs in the main script of your simulation, e.g.,

Simulator::Schedule (Seconds (1.2), &LogComponentEnable, "PointToPointChannel".c_str(), LOG_ALL);
Simulator::Schedule (Seconds (1.5), &LogComponentDisable, "PointToPointChannel".c_str(), LOG_ALL);

We would like to propose a way to support such feature from the NS_LOG environment variable. The proposed code is an extremely early stage WIP to support this feature. For the moment, the code can accept this type of input string:

NS_LOG="1.2s:1.5s:PointToPointChannel=**" ./waf --run fifth

For the moment, the API for adding start/end log time is still to be decided. This is how it works now:

  • The character : separates log components and times
  • For each token
    • If there is a = character, process the log component
    • Otherwise, check if it's a valid Time string (see code changes below)
      • If it is, the first will be a log start time, the second a log end time
      • Otherwise, if it's a log component assume LOG_ALL, otherwise report error Check below for other possible APIs.

Code changes

NOTE: for the moment, the proposed code is clearly not well-refined and must be improved. It only serves as a working example on how this feature could be added.

  • Added to LogComponent several static variables
static Time m_tLogStart;  //!< Start time of logs
static Time m_tLogEnd;    //!< End time of logs
static std::list<std::pair<LogComponent, LogLevel>> m_envLogs; //!< Log components and levels parsed from NS_LOG environment variable
static bool m_envLogsCollected; //!< Flag: true if NS_LOG was parsed into m_envLogs
static bool m_envLogsActivated; //!< Flag: true if m_engLogs have been scheduled
  • Added utility function LogLevel GetLogLevel (const std::string levelStr)
  • CheckEnvironmentVariables now parses NS_LOG and collects log components into m_envLogs
  • Since no clear API was defined so far, Time::Time (const std::string& s) was changed to throw std::runtime_error ("Unable to parse Time string: \"" + s + "\"") instead of NS_ABORT_MSG ("Can't Parse Time " << s). In this way, one can catch the exception and act upon it instead on interrupting the simulation. Maybe a bool IsTime(std::string) should be added. See solution section above.

There are some unclear points and comments from my side:

  • What is the difference between EnvVarCheck and CheckEnvironmentVariables?
  • The code in log.cc looks rather unstable, with multiple repeated blocks of code (e.g., see previous bullet point) and it's unclear when some function are called and what should they assume (is Simulator already up and running? when are logs enabled? how can they be enabled or disabled? why is the NS_LOG variable parsed multiple times?)

Possible APIs

  1. The one currently suggested: just include valid Time strings :-separated like the rest of the log components, the first will be assumed to be the log start time, the second will be the log end time
  2. The same, but force log start/end times to be at the beginning or the end of NS_LOG
  3. Custom syntax: <start>/<end>, e.g., 1.2s/1.5s. This could also allow more general cases such as 1.2s/ (start from 1.2s) and /1.5s (end at 1.5s). Note that specifying only an end time is not supported in the previous APIs.
  4. Make it more explicit by adding keywords such as LogStartTime=1.2s:LogEndTime=1.5s. Note: this would obscure valid log components that a user might want to create for some reason, although it would be unlikely, but it would keep a style consistent to that of other log components.
  5. For the moment, the code enables/disables all log components specified in NS_LOG at those specified times. Further flexibility could allow a user to specify custom start/end logging times for each log component separately. This could became very cumbersome, e.g., NS_LOG="PointToPointChannel=**-1.2s/1.5s:PacketSink=level_info|prefix_all-1s/5s" ./waf --run fifth. Being a very specific corner case it might not be worth the extra effort and a more complex API. Note: LogLevel are |-separated, thus I would propose a different separator for start/end time, e.g., - as in the example.

Notes

This work is related to GSOC2021SEM, mentored by @DvdMgr and I.

Merge request reports