|
Bugzilla – Full Text Bug Listing |
| Summary: | DcfManager does not handle AckTimeout properly when there are multiple queues | ||
|---|---|---|---|
| Product: | ns-3 | Reporter: | Mathieu Lacage <mathieu.lacage> |
| Component: | wifi | Assignee: | ns-bugs <ns-bugs> |
| Status: | RESOLVED FIXED | ||
| Severity: | normal | CC: | kirillano |
| Priority: | P5 | ||
| Version: | ns-3-dev | ||
| Hardware: | All | ||
| OS: | All | ||
| Attachments: |
the first version of patch
Second version of patch: changed names Final version of patch Full patch: bugfix + test-cases Infinite loop in shedule method example |
||
|
Description
Mathieu Lacage
2009-04-24 08:43:16 UTC
Created attachment 429 [details]
the first version of patch
I have fixed this bug, but have not written a test for it. I would like to You to make somecomments about it. As soon as I modify dcf-manager-test, I will post another patch
Comment on attachment 429 [details] the first version of patch I don't know if the basic idea of adding a couple of extra 'end' variables is correct: if the regression tests pass, then, it probably is fine. Small details: This should change should be completely unneeded, right ? >- if (tmp > Simulator::Now ()) >+ if (tmp.GetNanoSeconds () > Simulator::Now ().GetNanoSeconds ()) NS_LOG_UNCOND should not be used in the final patch: >@@ -283,6 +283,7 @@ > bool oneRunning = false; > if (m_normalAckTimeoutEvent.IsRunning ()) > { >+ NS_LOG_UNCOND(Simulator::Now ()); > m_normalAckTimeoutEvent.Cancel (); > oneRunning = true; > } How about prefixing these method names with "Notify" ? Don't forget to change the name of the type NavListeners+CI too. >+void >+MacLow::AckTimeoutStartNow (Time duration) >+{ >+ for (NavListenersCI i = m_navListeners.begin (); i != m_navListeners.end (); i++) >+ { >+ (*i)->AckTimeoutStart (duration); >+ } >+} >+void >+MacLow::AckTimeoutResetNow () >+{ >+ for (NavListenersCI i = m_navListeners.begin (); i != m_navListeners.end (); i++) >+ { >+ (*i)->AckTimeoutReset (); >+ } >+} >+void >+MacLow::CtsTimeoutStartNow (Time duration) >+{ >+ for (NavListenersCI i = m_navListeners.begin (); i != m_navListeners.end (); i++) >+ { >+ (*i)->CtsTimeoutStart (duration); >+ } >+} >+void >+MacLow::CtsTimeoutResetNow () >+{ >+ for (NavListenersCI i = m_navListeners.begin (); i != m_navListeners.end (); i++) >+ { >+ (*i)->CtsTimeoutReset (); >+ } >+} Here: s/NavListeners/DcfListeners/ >- typedef std::vector<MacLowNavListener *>::const_iterator NavListenersCI; >- typedef std::vector<MacLowNavListener *> NavListeners; >+ typedef std::vector<MacLowDcfListener *>::const_iterator NavListenersCI; >+ typedef std::vector<MacLowDcfListener *> NavListeners; > NavListeners m_navListeners; I would like to tell some words about yhe following changes:
>- if (tmp > Simulator::Now ())
>+ if (tmp.GetNanoSeconds () > Simulator::Now ().GetNanoSeconds ())
When I have not added this, the tmp was grater than Simulator::Now (), but when I have printed the moments of time, the nanoseconds value turned out to be equal. I have observed it because while (1) caused. That was strange a bit(I did not look at the code of Time reailzation and how operator > was implemented).
OK, all variables I will fix and attach another version of patch.
(In reply to comment #3) > I would like to tell some words about yhe following changes: > >- if (tmp > Simulator::Now ()) > >+ if (tmp.GetNanoSeconds () > Simulator::Now ().GetNanoSeconds ()) > When I have not added this, the tmp was grater than Simulator::Now (), but when > I have printed the moments of time, the nanoseconds value turned out to be > equal. I have observed it because while (1) caused. That was strange a bit(I Time stores values with 64.64 precision and GetNanoSeconds throws away the fractional part. It would be nice to know exactly why that behavior is problematic in your use-case. Created attachment 433 [details]
Second version of patch: changed names
I have still now way to solve the problem with comparsion between Time. I still have to compare nanoseconds values rather than compare Time. I will think about this problem.
Well, it seems to me that I know why it does not work without GetNanoSeconds () incomparsion.
When we compare Time and Time - we use the whole 128 bits of data, and when we call Schedule (...), it uses only 64 bits of data (it uses GetTimeStep ()), when it inserts an event.
So. it occurs that we schedule event immediately and catch while(1), but the moments of time we compared before were different, so the following code: (in DcfManager::DoRestartAccessTimeoutIfNeeded)
m_accessTimeout = Simulator::Schedule (expectedBackoffDelay,
&DcfManager::AccessTimeout, this);
shall be executed all the time.
So, as I think, replacing GetNanoSeconds () with GetTimeStap() is true solution
Created attachment 435 [details]
Final version of patch
(In reply to comment #7) > Created an attachment (id=435) [details] > Final version of patch > ok, but as I said before, I won't apply any patch to this code without an associated reduced testcase/patch in dcf-manager-test.cc. any news on trying to get a reduced testcase ? (In reply to comment #9) > any news on trying to get a reduced testcase ? > Well, I was away all last week, and I need to pass some exams. But as soon as I can returtn to work with NS, I will write a testcase (I think, I need about a week to do it). Sorry for delay Created attachment 455 [details]
Full patch: bugfix + test-cases
Test cases are described in picture in comments. All previous tests are filled with ack-timeout starting and cancelling
(In reply to comment #11) > Created an attachment (id=455) [details] > Full patch: bugfix + test-cases > > Test cases are described in picture in comments. All previous tests are filled > with ack-timeout starting and cancelling > Thank you very much: this looks totally awesome. A couple more comments (the idea of touching that piece of code makes me crazy which is why I am so super careful): 1) ./waf --regression does not pass: I am looking into it but you can beat me to it. 2) I know that you are going to hate me but if I remove your calls to GetTimeStep, "./waf check" still passes ("./waf --regression hangs"). If you really want me to take these 2 lines in the patch, you would have to put together a testcase which fails without these 2 lines so that we understand really why they are here. (In reply to comment #12) > 1) ./waf --regression does not pass: I am looking into it but you can beat me > to it. here is the change in output: --- a 2009-06-08 10:13:20.000000000 +0200 +++ b 2009-06-08 10:13:44.000000000 +0200 @@ -3,10 +3,10 @@ 02:00:00.000291 291us tsft 6.0 Mb/s 2437 MHz (0x00c0) Acknowledgment RA:00:00:00:00:00:04 (oui Ethernet) 02:00:00.000369 369us tsft 6.0 Mb/s 2437 MHz (0x00c0) Assoc Response AID(0) :: Succesful 02:00:00.000513 513us tsft 6.0 Mb/s 2437 MHz (0x00c0) -50dB signal -66dB noise Acknowledgment RA:00:00:00:00:00:03 (oui Eth ernet) -02:00:00.000950 950us tsft 6.0 Mb/s 2437 MHz (0x00c0) -59dB signal -101dB noise Assoc Request () [6.0 9.0 12.0 18.0 24.0 36 .0 48.0 54.0 Mbit] -02:00:00.000966 966us tsft 6.0 Mb/s 2437 MHz (0x00c0) Acknowledgment RA:00:00:00:00:00:05 (oui Ethernet) -02:00:00.001044 1044us tsft 6.0 Mb/s 2437 MHz (0x00c0) Assoc Response AID(0) :: Succesful -02:00:00.001188 1188us tsft 6.0 Mb/s 2437 MHz (0x00c0) -59dB signal -101dB noise Acknowledgment RA:00:00:00:00:00:03 (oui E thernet) +02:00:00.000965 965us tsft 6.0 Mb/s 2437 MHz (0x00c0) -59dB signal -101dB noise Assoc Request () [6.0 9.0 12.0 18.0 24.0 36 .0 48.0 54.0 Mbit] +02:00:00.000981 981us tsft 6.0 Mb/s 2437 MHz (0x00c0) Acknowledgment RA:00:00:00:00:00:05 (oui Ethernet) +02:00:00.001059 1059us tsft 6.0 Mb/s 2437 MHz (0x00c0) Assoc Response AID(0) :: Succesful +02:00:00.001203 1203us tsft 6.0 Mb/s 2437 MHz (0x00c0) -59dB signal -101dB noise Acknowledgment RA:00:00:00:00:00:03 (oui E thernet) 02:00:00.508948 508948us tsft 6.0 Mb/s 2437 MHz (0x00c0) -48dB signal -101dB noise 00:00:00:00:00:07 (oui Ethernet) > 00:00 :00:00:00:04 (oui Ethernet) SNAP Unnumbered, ui, Flags [Command], length 524 02:00:00.508964 508964us tsft 6.0 Mb/s 2437 MHz (0x00c0) Acknowledgment RA:00:00:00:00:00:04 (oui Ethernet) 02:00:00.517140 517140us tsft 6.0 Mb/s 2437 MHz (0x00c0) -48dB signal -101dB noise 00:00:00:00:00:07 (oui Ethernet) > 00:00 :00:00:00:04 (oui Ethernet) SNAP Unnumbered, ui, Flags [Command], length 524 This is the only meaningful change: the assoc req is sent exactly 15us later -02:00:00.000950 950us tsft 6.0 Mb/s 2437 MHz (0x00c0) -59dB signal -101dB noise Assoc Request () [6.0 9.0 12.0 18.0 24.0 36.0 48.0 54.0 Mbit] +02:00:00.000965 965us tsft 6.0 Mb/s 2437 MHz (0x00c0) -59dB signal -101dB noise Assoc Request () [6.0 9.0 12.0 18.0 24.0 36.0 48.0 54.0 Mbit] (In reply to comment #14) > This is the only meaningful change: the assoc req is sent exactly 15us later > > -02:00:00.000950 950us tsft 6.0 Mb/s 2437 MHz (0x00c0) -59dB signal -101dB > noise Assoc Request () [6.0 9.0 12.0 18.0 24.0 36.0 48.0 54.0 Mbit] > +02:00:00.000965 965us tsft 6.0 Mb/s 2437 MHz (0x00c0) -59dB signal -101dB > noise Assoc Request () [6.0 9.0 12.0 18.0 24.0 36.0 48.0 54.0 Mbit] > In both cases, we observe the same scenario: ":05" sends assoc req twice to ":03", first fails with ack timeout because ":03" is busy receiving another req from ":04", second is the one we see here. the difference between the two scenarios is 15.666us. Created attachment 457 [details]
Infinite loop in shedule method example
I have written a short example, which repeats inifinite loop situation in wifi. Shedule simply ignores precision less than 1 nanosecond (GetTimeStep -- see line 183 in rc/simulator/default-simulator-impl.cc). Similar sitation was casued when Ack timeout expires.
(In reply to comment #15) > (In reply to comment #14) > > This is the only meaningful change: the assoc req is sent exactly 15us later > > > > -02:00:00.000950 950us tsft 6.0 Mb/s 2437 MHz (0x00c0) -59dB signal -101dB > > noise Assoc Request () [6.0 9.0 12.0 18.0 24.0 36.0 48.0 54.0 Mbit] > > +02:00:00.000965 965us tsft 6.0 Mb/s 2437 MHz (0x00c0) -59dB signal -101dB > > noise Assoc Request () [6.0 9.0 12.0 18.0 24.0 36.0 48.0 54.0 Mbit] > > > > In both cases, we observe the same scenario: ":05" sends assoc req twice to > ":03", first fails with ack timeout because ":03" is busy receiving another req > from ":04", second is the one we see here. the difference between the two > scenarios is 15.666us. > Ok, this change is indeed compatible with the specification I believe: 15.666 = 9 (slot) + 2*1000 / 300000000 (round trip of 1000m if speed of light is 300000000m/s for max propagation delay) is the extra time which an ack timeout lasts compared to the nav setting. changeset b2654e0f071d The patch I finally pushed gets rid of the GetTimeStep calls and, instead, modifies wifi-mac.cc: the problem was simply that all these values were expected to be rounded to microseconds diff -r 3135a5c24358 -r b2654e0f071d src/devices/wifi/wifi-mac.cc --- a/src/devices/wifi/wifi-mac.cc Mon Jun 08 09:43:47 2009 +0200 +++ b/src/devices/wifi/wifi-mac.cc Mon Jun 08 13:37:30 2009 +0200 @@ -63,7 +63,7 @@ */ Time ctsTimeout = GetDefaultSifs (); ctsTimeout += GetDefaultCtsAckDelay (); - ctsTimeout += GetDefaultMaxPropagationDelay () * Scalar (2); + ctsTimeout += MicroSeconds (GetDefaultMaxPropagationDelay ().GetMicroSeconds () * 2); ctsTimeout += GetDefaultSlot (); return ctsTimeout; } |