[Bug 954] Time::SetResolution

[Bug 954] Support Time::SetResolution in user code, v2

Revised patch addressing issues from Dec 2012.

This is roughly what was proposed at the ns-3 Developer meeting
in March 2013.

Notable changes from that discussion:

- Can't initialize a class static data member in the header, without C++11.
  Instead, I added a StaticInit () function, and force every compilation
  unit to invoke it.

- This means we can dispense with the static bool m_markingTime, and just
  use the non-nullness of the set pointer, which I renamed g_markingTimes.

- In my testing, it appears that the CriticalSection is unnecessary (no
  where else in src/core uses it either)

- The real problem appears to be static initialization order between
  Time and Simulator, triggered by the call in Time to Simulator::Schedule.
  I adopted Mathieu's suggestion of adding an explicit call in
  Simulator::Run to Time::ClearMarkedTimes.

There are still some lingering style issues (whitespace), but I didn't
want to clutter the code review with more noise.


[Bug 954] Support Time::SetResolution in user code.

This patch logs the address of every Time, until SetResolution
is called.  On SetResolution, every existing Time is converted to the
new resolution, and the log is deleted.  This allows users to SetResolution
exactly once.

I also considered lazy conversion, adding a unit to Time, and checking
each Time as it was accessed, but this requires constant checks on
each access.  Assuming that Times are accessed many times (per instance),
confining the additional work to construction/destruction seems like
a better approach.

Note that once Time::SetResolution is called, the data structure that
tracks live Time objects (a std::set) is deleted, so we only support
setting the resolution once.  This reduces subsequent overhead to a
function call and test (and only on construction/destruction), which
should be very small.

[Peter Barnes, 2012-11-11 07:30:28]

Hello Folks,

Here is a solution to Bug 954:
https://www.nsnam.org/bugzilla/show_bug.cgi?id=954

Code review: http://codereview.appspot.com/6821106/

Peter

[Vedran Miletić, 2012-11-14 15:03:50]

On 2012/11/11 07:30:28, Peter Barnes wrote:
> Hello Folks,
> 
> Here is a solution to Bug 954:
> https://www.nsnam.org/bugzilla/show_bug.cgi?id=954
> 
> Code review: http://codereview.appspot.com/6821106/
> 
> Peter

Patch doesn't apply here, fails in nstime.h. Can you regenerate it against
current ns-3-dev?

[Tommaso Pecorella, 2012-11-14 16:56:40]

I have to confess I didn't check the code very deeply, but I trust 100% Peter. 

I checked the overall structure, tho, and seems all very logical. The overhead
needed is confined in pre-simulation and just for "Time" instances created in
that brief time, as is the ones needed to launch basic evens, so not an
incredible number. Hence, it shouldn't affect actual simulations too much.

I just have one request. Since changing the time resolution is now allowed
exactly once, is it possible to enforce this by raising an assert if the user
tries to do it twice ? I'm fairly sure people doesn't read the read me.

T.

[Peter Barnes, 2012-11-14 23:30:23]

I had the same thought.  The assert is at time.cc:233.

On 2012/11/14 16:56:40, Tommaso Pecorella wrote:
> I just have one request. Since changing the time resolution is now allowed
> exactly once, is it possible to enforce this by raising an assert if the user
> tries to do it twice ? I'm fairly sure people doesn't read the read me.

[Peter Barnes, 2012-11-15 06:04:32]

Operator error.  The correct patch is now on code review.appsppot.com

On 2012/11/14 15:03:50, Vedran Miletić wrote:
> Patch doesn't apply here, fails in nstime.h. Can you regenerate it against
> current ns-3-dev?

[Tommaso Pecorella, 2012-11-15 21:31:16]

On 2012/11/15 06:04:32, Peter Barnes wrote:
> Operator error.  The correct patch is now on code http://review.appsppot.com

Seems you're not lucky with the links... :P

T.

[Peter Barnes, 2012-11-16 19:39:28]

Working at weapons lab, we have ingrained in us a Russia proverb:  Trust, but
verify...

On 2012/11/14 16:56:40, Tommaso Pecorella wrote:
> I have to confess I didn't check the code very deeply, but I trust 100% Peter.

[Peter Barnes, 2012-11-16 19:39:53]

Which is why I need code review...

On 2012/11/15 21:31:16, Tommaso Pecorella wrote:
> Seems you're not lucky with the links... :P

[Vedran Miletić, 2012-11-17 19:13:27]

+1 on what Tommaso said. This is a great feature.

Aside from coding style and variable naming issues, I have no objections to
merging this. Documentation and tests are good.

[Peter Barnes, 2012-11-19 17:36:33]

I'm happy to make changes.  What issues do you see?

On 2012/11/17 19:13:27, Vedran Miletić wrote:
> Aside from coding style and variable naming issues,

[Vedran Miletić, 2012-11-19 23:23:11]

Hi Peter,

this is it. Some additional suggestions on assert and documetation are included.

Regards,
Vedran

https://codereview.appspot.com/6821106/diff/8001/src/core/model/nstime.h
File src/core/model/nstime.h (right):

https://codereview.appspot.com/6821106/diff/8001/src/core/model/nstime.h#newc...
src/core/model/nstime.h:78: * in a 64 bit integer, whose interpretation will
depend on the global
I usually tell my students that ns-3 uses 128-bit integer type for storing time.
It would be great if you elaborated here that ns-3 uses 64 bits are used for
integer part of the time and 64 bits for fractional part.

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc
File src/core/model/time.cc (left):

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc#oldco...
src/core/model/time.cc:63: if (trailer == std::string ("ns"))
I believe our convention is that else and if go on the same line.

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc
File src/core/model/time.cc (right):

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc#newco...
src/core/model/time.cc:125: NS_LOG_FUNCTION_NOARGS();
Why this change of NS_LOG_FUNCTION?

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc#newco...
src/core/model/time.cc:126: if (convert)
I suggest introducing private variable m_timeResolutionChanged and adding prior
to this something like
NS_ASSERT_MSG (m_timeResolutionChanged == false, "Changing time resolution more
than once is not allowed.")

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc#newco...
src/core/model/time.cc:166: Time::Times_set *
should be something like TimesSet

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc#newco...
src/core/model/time.cc:167: Time::GetTimes_set ( const bool deleteMe /* = false
*/ )
GetTimesSet

[Peter Barnes, 2012-11-29 04:02:21]

https://codereview.appspot.com/6821106/diff/8001/src/core/model/nstime.h
File src/core/model/nstime.h (right):

https://codereview.appspot.com/6821106/diff/8001/src/core/model/nstime.h#newc...
src/core/model/nstime.h:78: * in a 64 bit integer, whose interpretation will
depend on the global
On 2012/11/19 23:23:11, Vedran Miletić wrote:
> I usually tell my students that ns-3 uses 128-bit integer type for storing
time.
Except that Time has only int64_t m_data; uint64x64_t was changed to in64_t in
rev 7036 [f94c610203be].

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc
File src/core/model/time.cc (left):

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc#oldco...
src/core/model/time.cc:63: if (trailer == std::string ("ns"))
On 2012/11/19 23:23:11, Vedran Miletić wrote:
> I believe our convention is that else and if go on the same line.
Fixed

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc
File src/core/model/time.cc (right):

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc#newco...
src/core/model/time.cc:125: NS_LOG_FUNCTION_NOARGS();
On 2012/11/19 23:23:11, Vedran Miletić wrote:
> Why this change of NS_LOG_FUNCTION?
Reverted.

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc#newco...
src/core/model/time.cc:126: if (convert)
On 2012/11/19 23:23:11, Vedran Miletić wrote:
> I suggest introducing private variable m_timeResolutionChanged and adding
prior
> to this something like
> NS_ASSERT_MSG (m_timeResolutionChanged == false, "Changing time resolution
more
> than once is not allowed.")

This is farther down at time.cc:233

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc#newco...
src/core/model/time.cc:166: Time::Times_set *
On 2012/11/19 23:23:11, Vedran Miletić wrote:
> should be something like TimesSet
Right

https://codereview.appspot.com/6821106/diff/8001/src/core/model/time.cc#newco...
src/core/model/time.cc:167: Time::GetTimes_set ( const bool deleteMe /* = false
*/ )
On 2012/11/19 23:23:11, Vedran Miletić wrote:
> GetTimesSet
Right

[Mathieu Lacage, 2013-06-11 07:03:57]

What is really missing, is a performance analysis of the impact of this code.
i.e., I would like to see numbers that show:

1) the impact of this change on micro benchmarks that use Time 

2) a rough idea of whether or not we can measure an impact on macro benchmarks
such as the example programs we have in the tree. Basically, add tracking code
to the header functions you changed in nstime.h to count the number of times
these functions are called, see which example programs call these functions the
most often relative to their wall-clock-time-to-completion, take the top-5, and
measure the time to completion before and after the patch for these top-5
programs we have in the tree.

https://codereview.appspot.com/6821106/diff/20001/src/core/model/nstime.h
File src/core/model/nstime.h (right):

https://codereview.appspot.com/6821106/diff/20001/src/core/model/nstime.h#new...
src/core/model/nstime.h:110: inline Time &operator = (const int64_t &value)
Maybe you were looking for the Timestep function ? If so, it would be safer to
remove that operator

[Peter Barnes, 2013-06-14 00:50:04]

On 2013/06/11 07:03:57, Mathieu Lacage wrote:
> What is really missing, is a performance analysis of the impact of
> this code. i.e., I would like to see numbers that show:
> 
> 1) the impact of this change on micro benchmarks that use Time
> 
> 2) a rough idea of whether or not we can measure an impact on macro
> benchmarks
> 
> > >
> > >> >
> > >> >> >
1.  Microbenchmark

I wrote a micro benchmark with this main loop:

  std::vector<Time> times; times.reserve (iterations);

  int start = clock (); for (int64_t i = 0; i < iterations; ++i) {
  times[i] = Time::FromInteger (i, Time::NS);
    }
  times.clear (); int stop = clock ();

The patch affects only Time ctor/dtor in this code.  With 1E6 iterations
I measure a difference of

  0.582 ± 0.009 ns / iteration (patch is slower than ns-3-dev)

after Time::SetResolution has been called, as would be the case during
Simulator::Run.  (Before SetResolution, the patch takes 123 ns, vs. 1.2
ns for ns-3-dev.)


2.  Macrobenchmark

I modified utils/bench-simulator to schedule from an
ExponentialRandomVariable, with mean 100 ns.  The code initializes by
scheduling a population of events.  When the simulator runs, each event
schedules a new event, until the desired total number of events have
been processed.

With an initial population of 10^8, and processing 10^9 events, I
measure a difference of

  -0.35 ± 0.80 ns/event (consistent with zero)

This is after Time::SetResolution, since the main loop is
Simulator::Run. (The initialization phase, scheduling the initial event
population, has a difference of -5.5 ± 20.5 ns/event, also consistent
with zero).


3.  Details

Benchmarks were run on a 2.7 GHz Intel Core i7 (quad core) with 16 GB
1600 MHz DDR3 memory, running Mac 10.8.4.  The machine was in use for
other work during runs (though I avoided compiling).

The microbenchmark results are the average of 30 runs for ns-3-dev, and
20 runs for the patch.  (The first ten runs for the patch were before
Time::SetResolution was called.).  Each run had 1E6 iterations, and took
~1.2 ms. The executing process was primed by one run before the data
runs.  The priming run ran slower, 4.2 ns / iteration.  The following
run, the first data run, was consistent with the remaining data runs.

The macrobenchmark runs used the default MapScheduler.  Results are the
average of five runs for each code base.  Each run used a population of
1E8 events, executed 1E9 events, and took ~155 s (~101 s in
initialization, and ~54 s in Simulator::Run). The executing process was
primed by one run before the data runs.  The priming run ran
significantly slower, 2270 s.  I have no explanation for this behavior.
The following run, the first data run, was consistent with the remaining
data runs.  The priming run had to be the same as the data runs (not
shorter), or the first data run would take significantly longer than
subsequent runs.

[Mathieu Lacage, 2013-07-04 07:09:36]

+1 for merging if you can either remove the extra operator = I spotted earlier
or explain why it is needed.

[Vedran Miletić, 2013-07-04 07:52:41]

Peter, can we get rid of this?

./ns3/nstime.h: At global scope:
./ns3/nstime.h:619:13: error: ‘ns3::g_TimeStaticInit’ defined but not used
[-Werror=unused-variable]
cc1plus: all warnings being treated as errors

[Peter Barnes, 2013-07-04 14:32:14]

On 2013/07/04 07:52:41, Vedran Miletić wrote:
> Peter, can we get rid of this?
> 
> ./ns3/nstime.h: At global scope:
> ./ns3/nstime.h:619:13: error: ‘ns3::g_TimeStaticInit’ defined but not used
> [-Werror=unused-variable]
> cc1plus: all warnings being treated as errors

With difficulty. It's at file global scope, so NS_UNUSED doesn't work b/c that
generates executable code. I have an NS_UNUSED_STATIC macro, but it only works
for gcc, via __attribute__ ((unused)). I haven't found equivalents for other
compilers, such as clang, xlc, icc, VS.

So at this point we can

* (hokey) leave it as is, which generates this extra and erroneous warning when
there is already some other error or ns time.h was included erroneously,or 
* (perhaps less hokey) silence the warning, but only in gcc.

[Peter Barnes, 2013-07-04 14:33:56]

https://codereview.appspot.com/6821106/diff/20001/src/core/model/nstime.h
File src/core/model/nstime.h (right):

https://codereview.appspot.com/6821106/diff/20001/src/core/model/nstime.h#new...
src/core/model/nstime.h:110: inline Time &operator = (const int64_t &value)
On 2013/06/11 07:03:57, Mathieu Lacage wrote:
> Maybe you were looking for the Timestep function ? If so, it would be safer to
> remove that operator

This is needed for the conversion at time.cc:269 where we have to assign to an
existing Time. Time step creates a new Time.   What's your safety concern?

[Mathieu Lacage, 2013-07-10 13:25:19]

On 2013/07/04 14:33:56, Peter Barnes wrote:
> https://codereview.appspot.com/6821106/diff/20001/src/core/model/nstime.h
> File src/core/model/nstime.h (right):
> 
>
https://codereview.appspot.com/6821106/diff/20001/src/core/model/nstime.h#new...
> src/core/model/nstime.h:110: inline Time &operator = (const int64_t &value)
> On 2013/06/11 07:03:57, Mathieu Lacage wrote:
> > Maybe you were looking for the Timestep function ? If so, it would be safer
to
> > remove that operator
> 
> This is needed for the conversion at time.cc:269 where we have to assign to an
> existing Time. Time step creates a new Time.   What's your safety concern?

It would be nice if you could go through the extra call to Timestep. 

My main concern is that if users could invoke this operator, they could write
this:

Time t;
t = 10;

Which makes zero sense, really. Forcing them to use the Timestep function at
least avoids the most common mistakes that come from someone who wants to assign
10s to a Time object.

[Peter Barnes, 2013-07-16 01:15:05]

On 2013/07/16 01:05:01, Peter Barnes wrote:

Well, that didn't go smoothly.  This is the v2 patch (Patch Set 3), on top of
the latest ns-3-dev, with two changes:

- addition of NS_UNUSED_GLOBAL() macro, which can be used at file global scope
to suppress "unused variable" warnings from gcc

- removal of operator= (int64_t)

[Peter Barnes, 2013-07-18 23:57:58]

I think all review comments have been addressed.  Okay to commit?  

I'd like to get this in and widely tested before the next release cycle.
Peter

[Vedran Miletić, 2013-07-22 09:51:14]

On 2013/07/18 23:57:58, Peter Barnes wrote:
> I think all review comments have been addressed.  Okay to commit?  
> 
> I'd like to get this in and widely tested before the next release cycle.
> Peter

Looks good to me. I suggest cleaning up trailing whitespace before committing.

[Vedran Miletić, 2013-07-23 09:31:05]

On 2013/07/22 09:51:14, Vedran Miletić wrote:
> On 2013/07/18 23:57:58, Peter Barnes wrote:
> > I think all review comments have been addressed.  Okay to commit?  
> > 
> > I'd like to get this in and widely tested before the next release cycle.
> > Peter
> 
> Looks good to me. I suggest cleaning up trailing whitespace before committing.

WAIT! Something nasty is happening with Time in ObjectFactories. Namely, if you
change:

Time::SetResolution (Time::NS)

to, say

Time::SetResolution (Time::US)

in first.cc, you get

msg="Invalid value for attribute set (Delay) on ns3::PointToPointChannel",
file=../src/core/model/object-factory.cc, line=75
terminate called without an active exception
Command
['/home/vedranm/workspace/ns-3-allinone/ns-3-dev/build/examples/tutorial/ns3-dev-first-debug']
terminated with signal SIGIOT. Run it under a debugger to get more information
(./waf --run <program> --command-template="gdb --args %s <args>").

I will try to look at it as I would love to have it fixed ideally right now, but
I can't promise anything.

Regards,
Vedran

[Tommaso Pecorella, 2013-07-23 10:50:12]

On 2013/07/23 09:31:05, Vedran Miletić wrote:
> WAIT! Something nasty is happening with Time in ObjectFactories. Namely, if
you
> change:
> 
> Time::SetResolution (Time::NS)
> 
> to, say
> 
> Time::SetResolution (Time::US)


Seems a nasty bug, possibly related with the new TimeCheckers.

The bug is localized here:
Ptr<const AttributeChecker>
MakeTimeChecker (const Time min, const Time max)
{
  NS_LOG_FUNCTION (min << max);

  struct Checker : public AttributeChecker
  {
    Checker (const Time minValue, const Time maxValue)
      : m_minValue (minValue),
        m_maxValue (maxValue) {}
    virtual bool Check (const AttributeValue &value) const {
      NS_LOG_FUNCTION (&value);
      const TimeValue *v = dynamic_cast<const TimeValue *> (&value);
      if (v == 0)
        {
          return false;
        }
      return v->Get () >= m_minValue && v->Get () <= m_maxValue;
    }
[...]

When the const TimeValue *v = dynamic_cast<const TimeValue *> (&value) is
called, the return is "0".

Time::NS is the default ns-3 time resolution, so changing triggers the bug.

No idea on how to fix this.

T.

[Vedran Miletić, 2013-07-23 11:04:02]

On 2013/07/23 10:50:12, Tommaso Pecorella wrote:
> On 2013/07/23 09:31:05, Vedran Miletić wrote:
> > WAIT! Something nasty is happening with Time in ObjectFactories. Namely, if
> you
> > change:
> > 
> > Time::SetResolution (Time::NS)
> > 
> > to, say
> > 
> > Time::SetResolution (Time::US)
> 
> 
> Seems a nasty bug, possibly related with the new TimeCheckers.
> 
> The bug is localized here:
> Ptr<const AttributeChecker>
> MakeTimeChecker (const Time min, const Time max)
> {
>   NS_LOG_FUNCTION (min << max);
> 
>   struct Checker : public AttributeChecker
>   {
>     Checker (const Time minValue, const Time maxValue)
>       : m_minValue (minValue),
>         m_maxValue (maxValue) {}
>     virtual bool Check (const AttributeValue &value) const {
>       NS_LOG_FUNCTION (&value);
>       const TimeValue *v = dynamic_cast<const TimeValue *> (&value);
>       if (v == 0)
>         {
>           return false;
>         }
>       return v->Get () >= m_minValue && v->Get () <= m_maxValue;
>     }
> [...]
> 
> When the const TimeValue *v = dynamic_cast<const TimeValue *> (&value) is
> called, the return is "0".
> 
> Time::NS is the default ns-3 time resolution, so changing triggers the bug.
> 
> No idea on how to fix this.
> 
> T.

I actually independently came to the same conclusion. :-)

Minimal example that fails is:

int main (int argc, char *argv[])
{
  Ptr<const AttributeChecker> ac = MakeTimeChecker ();
  Time::SetResolution (Time::MS);
  
  NS_LOG_UNCOND (ac->Check (TimeValue (Seconds (1))));

  return 0;
}

However:

int main (int argc, char *argv[])
{
  Time::SetResolution (Time::MS);
  Ptr<const AttributeChecker> ac = MakeTimeChecker ();
  
  NS_LOG_UNCOND (ac->Check (TimeValue (Seconds (1))));

  return 0;
}

works.

First one yields +9223372036854.0ms for minimal value in the checker, and
+9223372036854.0ms for max. Second one yields -9223372036854775808.0ms and
+9223372036854775807.0ms.

Regards,
Vedran

[Peter Barnes, 2013-07-24 21:15:57]

Tommaso and Vedran:  thanks for finding this, and the excellent examples.

The issue occurs when SetResolution converts Times which hold the Time::Min or
Time::Max value, as occurs with Time attribute checkers created by
MakeTimeChecker (...).

The proposed fix is to trap Min/Max values in the conversion, and not alter
their values.  In effect, treat Min/Max values as +/- Inf.  As a result, a Time
equal to Min or Max before SetResolution, will still equal Min/Max after
SetResolution.

Patch attached, and on codereview.

[Peter Barnes, 2013-07-24 21:16:03]

Tommaso and Vedran:  thanks for finding this, and the excellent examples.

The issue occurs when SetResolution converts Times which hold the Time::Min or
Time::Max value, as occurs with Time attribute checkers created by
MakeTimeChecker (...).

The proposed fix is to trap Min/Max values in the conversion, and not alter
their values.  In effect, treat Min/Max values as +/- Inf.  As a result, a Time
equal to Min or Max before SetResolution, will still equal Min/Max after
SetResolution.

Patch attached, and on codereview.

Peter


On Jul 23, 2013, at 4:04 AM, rivanvx@gmail.com wrote:
> On 2013/07/23 10:50:12, Tommaso Pecorella wrote:
>> On 2013/07/23 09:31:05, Vedran Miletić wrote:
>> > WAIT! Something nasty is happening with Time in ObjectFactories.
> 
> I actually independently came to the same conclusion. :-)
> 
> Minimal example that fails is:
> 
> int main (int argc, char *argv[])
> {
>  Ptr<const AttributeChecker> ac = MakeTimeChecker ();
>  Time::SetResolution (Time::MS);
> 
>  // PDB edited to print limits
>  NS_LOG_UNCOND (ac->GetUnderlyingTypeInformation ());
> 
>  return 0;
> }
> https://codereview.appspot.com/6821106/

____________
Peter Barnes
pdbj@mac.com

[Vedran Miletić, 2013-07-25 11:01:10]

Peter, Tommaso et. al., there is more.

Time t0 = Seconds (-1);
NS_LOG_UNCOND (t0.GetSeconds ());
Time::SetResolution (Time::MS);
NS_LOG_UNCOND (t0.GetSeconds ());

yields:

-1
1.84467e+10

I think I know where the bug is; I got to run now, but I will test my idea in an
hour or two.

Regards,
Vedran

[barnes26_llnl.gov, 2013-07-25 19:17:36]

Wow, that's been lurking for a while, since Time::Information::factor was
introduced as uint64_t in 92a84235d8f2, Jul 2010.

You can demonstrate in ns-3-dev:

  Time tneg = Seconds (-1);
  NS_LOG_UNCOND ( tneg << ", in s: " << tneg.ToInteger (Time::S));

produces

  -1000000000.0ns, in s: 18446744072

This arises because the conversion is done by

  in64_t v = m_data;
  v *= info->factor;

Because factor is unsigned, v is promoted to unsigned for the multiplication,
then interpreted as signed.  Changing factor to int64_t fixes the problem.

Commit 7805771a836a

Thanks,
Peter

On Jul 25, 2013, at 4:01 AM, <rivanvx@gmail.com>
 wrote:
> Peter, Tommaso et. al., there is more.
> 
> Time t0 = Seconds (-1);
> NS_LOG_UNCOND (t0.GetSeconds ());
> Time::SetResolution (Time::MS);
> NS_LOG_UNCOND (t0.GetSeconds ());
> 
> yields:
> 
> -1
> 1.84467e+10
> https://codereview.appspot.com/6821106/

_______________________________________________________________________
Dr. Peter D. Barnes, Jr.                Physics Division
Lawrence Livermore National Laboratory  Physical and Life Sciences
7000 East Avenue, L-50                  email:  pdbarnes@llnl.gov
P. O. Box 808                           Voice:  (925) 422-3384
Livermore, California 94550             Fax:    (925) 423-3371

[Vedran Miletić, 2013-07-26 12:08:15]

On 2013/07/25 19:17:36, barnes26_llnl.gov wrote:
> Wow, that's been lurking for a while, since Time::Information::factor was
> introduced as uint64_t in 92a84235d8f2, Jul 2010.
> 
> You can demonstrate in ns-3-dev:
> 
>   Time tneg = Seconds (-1);
>   NS_LOG_UNCOND ( tneg << ", in s: " << tneg.ToInteger (Time::S));
> 
> produces
> 
>   -1000000000.0ns, in s: 18446744072
> 
> This arises because the conversion is done by
> 
>   in64_t v = m_data;
>   v *= info->factor;
> 
> Because factor is unsigned, v is promoted to unsigned for the multiplication,
> then interpreted as signed.  Changing factor to int64_t fixes the problem.
> 
> Commit 7805771a836a
> 
> Thanks,
> Peter

Wow, that was quick. What do you think about adding a test case that would check
if this gets broken again?

Regards,
Vedran

[Vedran Miletić, 2013-07-27 14:33:34]

Peter, I can't apply this, sorry. Could you post the entire patch merged
together and rebased on top of the current ns-3-dev?

[Peter Barnes, 2013-07-31 18:59:41]

Patch Set 6 : Rebased on r10104 8705e2943d7d 

Peter

On Jul 27, 2013, at 7:33 AM, rivanvx@gmail.com wrote:
> Peter, I can't apply this, sorry. Could you post the entire patch merged
> together and rebased on top of the current ns-3-dev?
> 
> https://codereview.appspot.com/6821106/

____________
Peter Barnes
pdbj@mac.com

[Vedran Miletić, 2013-07-31 20:40:06]

On 2013/07/31 18:59:41, Peter Barnes wrote:
> Patch Set 6 : Rebased on r10104 8705e2943d7d 
> 
> Peter
> 
> On Jul 27, 2013, at 7:33 AM, mailto:rivanvx@gmail.com wrote:
> > Peter, I can't apply this, sorry. Could you post the entire patch merged
> > together and rebased on top of the current ns-3-dev?
> > 
> > https://codereview.appspot.com/6821106/
> 
> ____________
> Peter Barnes
> mailto:pdbj@mac.com
> 

Thanks Peter.

Regards,
Vedran

[Vedran Miletić, 2013-08-01 10:32:18]

On 2013/07/31 20:40:06, Vedran Miletić wrote:
> On 2013/07/31 18:59:41, Peter Barnes wrote:
> > Patch Set 6 : Rebased on r10104 8705e2943d7d 
> > 
> > Peter
> > 
> > On Jul 27, 2013, at 7:33 AM, mailto:rivanvx@gmail.com wrote:
> > > Peter, I can't apply this, sorry. Could you post the entire patch merged
> > > together and rebased on top of the current ns-3-dev?
> > > 
> > > https://codereview.appspot.com/6821106/
> > 
> > ____________
> > Peter Barnes
> > mailto:pdbj@mac.com
> > 
> 
> Thanks Peter.
> 
> Regards,
> Vedran

FAIL: TestSuite attributes

Regards,
Vedran

[Vedran Miletić, 2013-08-04 08:44:37]

On 2013/08/02 00:46:10, Peter Barnes wrote:

Peter,

I'm sorry to report that I get crashes with some Python examples;
src/core/examples/sample-simulator.py and src/bridge/examples/csma-bridge.py
will crash once or twice in ten runs.

I hope it's not the same issue as last time, since I would really like to have
this in 3.18.

Regards,
Vedran

[Vedran Miletić, 2013-08-05 16:20:30]

On 2013/08/04 08:44:37, Vedran Miletić wrote:
> On 2013/08/02 00:46:10, Peter Barnes wrote:
> 
> Peter,
> 
> I'm sorry to report that I get crashes with some Python examples;
> src/core/examples/sample-simulator.py and src/bridge/examples/csma-bridge.py
> will crash once or twice in ten runs.
> 
> I hope it's not the same issue as last time, since I would really like to have
> this in 3.18.
> 
> Regards,
> Vedran

Also, test suite average FAILs in optimized build (on Debian jessie/sid, g++
4.8.1).

Regards,
Vedran

[Vedran Miletić, 2013-08-12 22:05:14]

On 2013/08/05 16:20:30, Vedran Miletić wrote:
> On 2013/08/04 08:44:37, Vedran Miletić wrote:
> > On 2013/08/02 00:46:10, Peter Barnes wrote:
> > 
> > Peter,
> > 
> > I'm sorry to report that I get crashes with some Python examples;
> > src/core/examples/sample-simulator.py and src/bridge/examples/csma-bridge.py
> > will crash once or twice in ten runs.
> > 
> > I hope it's not the same issue as last time, since I would really like to
have
> > this in 3.18.
> > 
> > Regards,
> > Vedran
> 
> Also, test suite average FAILs in optimized build (on Debian jessie/sid, g++
> 4.8.1).
> 
> Regards,
> Vedran

I'm glad to report that this works on Debian wheezy. And I can't reproduce
Python crashes either.

Maybe we shouldn't worry too much about it; jessie is testing distribution
anyway, and it will be a while until it gets released as stable.

Regards,
Vedran

[Vedran Miletić, 2013-08-12 22:26:05]

On 2013/08/12 22:05:14, Vedran Miletić wrote:
> On 2013/08/05 16:20:30, Vedran Miletić wrote:
> > On 2013/08/04 08:44:37, Vedran Miletić wrote:
> > > On 2013/08/02 00:46:10, Peter Barnes wrote:
> > > 
> > > Peter,
> > > 
> > > I'm sorry to report that I get crashes with some Python examples;
> > > src/core/examples/sample-simulator.py and
src/bridge/examples/csma-bridge.py
> > > will crash once or twice in ten runs.
> > > 
> > > I hope it's not the same issue as last time, since I would really like to
> have
> > > this in 3.18.
> > > 
> > > Regards,
> > > Vedran
> > 
> > Also, test suite average FAILs in optimized build (on Debian jessie/sid, g++
> > 4.8.1).
> > 
> > Regards,
> > Vedran
> 
> I'm glad to report that this works on Debian wheezy. And I can't reproduce
> Python crashes either.
> 
> Maybe we shouldn't worry too much about it; jessie is testing distribution
> anyway, and it will be a while until it gets released as stable.
> 
> Regards,
> Vedran

Sorry, I spoke too soon. Python examples do crash, but rarely compared to
jessie. However it does happen frequently with optimized build on
src/flow-monitor/examples/wifi-olsr-flowmon.py (but still not every time).

Regards,
Vedran

[Peter Barnes, 2013-08-15 00:34:12]

I can statistically reproduce python crashes in optimized builds.  Specifically,
these examples:

examples/routing/simple-routing-ping6.py      
examples/tutorial/first.py		      	
examples/wireless/wifi-ap.py		      	
src/bridge/examples/csma-bridge.py		
src/core/examples/sample-simulator.py		
src/flow-monitor/examples/wifi-olsr-flowmon.py

fail about 50% of the time on a moderately heavily used multi-core box (load
average ~2).

Assuming that it's a threading issue, Patch Set #8 protects modifications to the
Time tracking 
data structure with a SystemMutex and CriticalSections.

With this patch I get no failures when run those examples 100x each.

[Vedran Miletić, 2013-08-15 13:16:31]

On 2013/08/15 00:34:12, Peter Barnes wrote:
> I can statistically reproduce python crashes in optimized builds. 
Specifically,
> these examples:
> 
> examples/routing/simple-routing-ping6.py      
> examples/tutorial/first.py		      	
> examples/wireless/wifi-ap.py		      	
> src/bridge/examples/csma-bridge.py		
> src/core/examples/sample-simulator.py		
> src/flow-monitor/examples/wifi-olsr-flowmon.py
> 
> fail about 50% of the time on a moderately heavily used multi-core box (load
> average ~2).
> 
> Assuming that it's a threading issue, Patch Set #8 protects modifications to
the
> Time tracking 
> data structure with a SystemMutex and CriticalSections.
> 
> With this patch I get no failures when run those examples 100x each.

Same here. Does this have a measurable performance impact?

Regards,
Vedran

[Peter Barnes, 2013-08-17 00:54:11]

On 2013/08/15 13:16:31, Vedran Miletić wrote:
> Same here. Does this have a measurable performance impact?

I used the same benchmarks described in comment 14, above.


1.  Microbenchmark

After SetResolution,  I measure a difference of 2.1 ± 0.3 ns/ iteration 
(patch is slower).  Comment 14 had 0.6 ns/iteration, but there shouldn't be 
any difference, so this is unexplained.

Before SetResolution, the mutex-protected version takes 1.94 ± 0.05
mus/iteration,
compared to 0.123 mus/iteration in comment 14.  However, now ns-3-dev takes
19.3 ± 0.6 ns/event; in comment 14 it took 1.2 ns/event.


2.  Macrobenchmark

After SetResolution I measure a difference of -3.4 ± 2.0 ns/event, consistent
with zero (patch is faster).

Before SetResolution I measure a difference of -414 ± 56 ns/event, again 
patch is faster.

I conclude that the mutex has a significant effect before SetResolution (as
expected)
but no significant effect after (also as expected).

[Peter Barnes, 2013-08-22 00:04:58]

> On 2013/08/15 13:16:31, Vedran Miletić wrote:
> > Same here. Does this have a measurable performance impact?
> 
> I used the same benchmarks described in comment 14, above.
> 
> 
> 1.  Microbenchmark
> 
> After SetResolution,  I measure a difference of 2.1 ± 0.3 ns/ iteration 
> (patch is slower).  Comment 14 had 0.6 ns/iteration, but there shouldn't be 
> any difference, so this is unexplained.

I reran the benchmark with -d optimized in both cases, and the difference is
0.54 ± 0.13 ns/iteration, consistent with the prior result in comment 14, as
expected.  I must not have had one of the repos in optimized state for the
results
quoted in comment 46.

> Before SetResolution, the mutex-protected version takes 1.94 ± 0.05
> mus/iteration, compared to 0.123 mus/iteration in comment 14.  However, now
ns-3-dev takes
> 19.3 ± 0.6 ns/event; in comment 14 it took 1.2 ns/event.

With both repos in optimized, mutex-protected version takes 220 ± 1
ns/iteration,
compared to 123 ns/iteration with Time marking, but no mutex.  Prior to the
patch ns-3-dev takes
1.7 ± 0.1 ns/iteration, now consistent with comment 14.

> 2.  Macrobenchmark
> 
> After SetResolution I measure a difference of -3.4 ± 2.0 ns/event, consistent
> with zero (patch is faster).
> 
> Before SetResolution I measure a difference of -414 ± 56 ns/event, again 
> patch is faster.

With both repos in optimized the difference is 2.0 ± 1.1 ns/event (mutex slower
than ns-3-dev), consistent with zero and the result in comment 14.