[Ns-developers] Problem with transmission delays

Tue Nov 8 10:17:27 PST 2011

Hi Carlos,

from what I see you might have an interpretation issue.

The four events you marked in your mail are not all happening at the same time, only the two "central" ones are, and those are both from STA1, so it's possible they're at the same time.

The problem in this case it's the precision the time is printed with. If you check the nanoseconds time, you can see for the four marked events:
100011995454.0ns
100012181470.0ns
100012181470.0ns
100012393000.0ns

Close, but not the same time.

Consider that the first timestamp printed in the debug log is purely indicative and is not meant to gather precise data. if you want praise timing data it's best to add your own log and/or parse the nanoseconds time stamp.

I hope to have interpreted the data in the right way. Else feel free to ask again.

Cheers,

Tommaso

Tommaso Pecorella - Ph.D.

Assistant professor
Dpt. Elettronica e Telecomunicazioni
Università di Firenze

CNIT - Università di Firenze Unit

via di S. Marta 3
50139, Firenze
ITALY

email: tommaso.pecorella at unifi.it
       tommaso.pecorella at cnit.it

phone : +39-055-4796412
mobile: +39-320-4379803
fax   : +39-055-494569

On 07 Nov, 2011,at 05:01 PM, Carlos Viegas <cmdviegas at gmail.com> wrote:

Dear all,

I sent this e-mail to ns-users list, but I think it is more related to a
NS-3 problem.
I have a simulation that when it exceeds 100 seconds, the transmission
delays get a weird behavior.
Can you take a look at this problem? Please, read the e-mail below.

My best regards,

Eng.º Carlos Viegas

Engenheiro de Pesquisa e Desenvolvimento
Faculdade de Engenharia da Universidade do Porto

---------- Forwarded message ----------
From: Carlos Viegas <cmdviegas at gmail.com>
Date: Fri, Nov 4, 2011 at 19:06
Subject: Problem with transmission delays
To: ns-3-users at googlegroups.com

Dear all,

I'm facing a problem related to the transmission delays. I hope that you
can help me.

I'm using NS-3.12.1 and I have a setup of 3 stations (1, 2 and 3), where
all of them run in adhoc mode with 802.11g at 54Mbps (constant rate). The
setup is configured as follows: station 2 sends packets of 1000 bytes,
every 22ms, directly to station 1 and station 3 sends packets of 1000
bytes, every 1097us, in broadcast (without specific destination, where its
objective is to create background interference in sta 2 -> sta 1
communication).

The setup runs fine, but I noticed something weird in the log timestamps.
I'm generating the log based on YansWifiPhy, YansWifiChannel, DcfManager
and MacLow information.

At some "random" time, the station 2 sends a data packet to station 1, but
exactly at the same time station 1 answers with ACK and also station 3
starts its broadcast transmission. It is not normal to happen, because
there are delays missing. Unfortunately, it happens after a certain amount
of successful transmissions (without any problem related to delays). But
once it occurs, it happens everytime.

I extracted a part of the generated log with the related problem.
To make it "easier" to read, I marked the most important parts with
'------->' and commented above it.

(...)
100.012s 1 DcfManager:UpdateBackoff(): +100011995454.0ns 0x1166740 dcf 0
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100011995454.0ns 0x1166970
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100011995454.0ns 0x1166740 dcf 1
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100011995454.0ns 0x1166c50
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100011995454.0ns 0x1166740 dcf 2
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100011995454.0ns 0x11670f0
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100011995454.0ns 0x1166740 dcf 3
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100011995454.0ns 0x11675a0
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100011995454.0ns 0x1166740 dcf 4
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100011995454.0ns 0x1167a40
update slots=0 slots, backoff=0
100.012s 1 DcfManager:DoGrantAccess(): +100011995454.0ns 0x1166740 dcf 0
needs access. backoff expired. access granted. slots=0
(HERE WE HAVE THE STATION 2 STARTING ITS TRANSMISSION TO STATION 1):
-------> 100.012s 1 [mac=00:00:00:00:00:02] MacLow:StartTransmission():
startTx size=1064, to=00:00:00:00:00:01, listener=0x1166950
-------> 100.012s 1 [mac=00:00:00:00:00:02] MacLow:ForwardDown(): send
DATA, to=00:00:00:00:00:01, size=1064, mode=ErpOfdmRate54Mbps,
duration=+44000.0ns, seq=0x1c10
100.012s 1 DcfManager:NotifyTxStartNow(): +100011995454.0ns 0x1166740 tx
start for +186000.0ns
100.012s 1 YansWifiChannel:Send(): propagation: txPower=17.0206dbm,
rxPower=-50.6262dbm, distance=5m, delay=+16.0ns
100.012s 1 YansWifiChannel:Send(): propagation: txPower=17.0206dbm,
rxPower=-50.6262dbm, distance=5m, delay=+16.0ns
100.012s 0 YansWifiPhy:StartReceivePacket(): sync to signal
(power=1.08988e-08W)
100.012s 0 DcfManager:NotifyRxStartNow(): +100011995470.0ns 0x11643a0 rx
start for=+186000.0ns
100.012s 0 DcfManager:UpdateBackoff(): +100011995470.0ns 0x11643a0 dcf 0
dec backoff slots=0
100.012s 0 DcfManager:UpdateBackoffSlotsNow(): +100011995470.0ns 0x1163ad0
update slots=0 slots, backoff=0
100.012s 0 DcfManager:UpdateBackoff(): +100011995470.0ns 0x11643a0 dcf 1
dec backoff slots=0
100.012s 0 DcfManager:UpdateBackoffSlotsNow(): +100011995470.0ns 0x1164880
update slots=0 slots, backoff=0
100.012s 0 DcfManager:UpdateBackoff(): +100011995470.0ns 0x11643a0 dcf 2
dec backoff slots=0
100.012s 0 DcfManager:UpdateBackoffSlotsNow(): +100011995470.0ns 0x1164d20
update slots=0 slots, backoff=0
100.012s 0 DcfManager:UpdateBackoff(): +100011995470.0ns 0x11643a0 dcf 3
dec backoff slots=0
100.012s 0 DcfManager:UpdateBackoffSlotsNow(): +100011995470.0ns 0x11651d0
update slots=0 slots, backoff=0
100.012s 0 DcfManager:UpdateBackoff(): +100011995470.0ns 0x11643a0 dcf 4
dec backoff slots=0
100.012s 0 DcfManager:UpdateBackoffSlotsNow(): +100011995470.0ns 0x1165670
update slots=0 slots, backoff=0
100.012s 2 YansWifiPhy:StartReceivePacket(): sync to signal
(power=1.08988e-08W)
100.012s 2 DcfManager:NotifyRxStartNow(): +100011995470.0ns 0x1168af0 rx
start for=+186000.0ns
100.012s 2 DcfManager:UpdateBackoff(): +100011995470.0ns 0x1168af0 dcf 0
dec backoff slots=14
100.012s 2 DcfManager:UpdateBackoffSlotsNow(): +100011995470.0ns 0x1168d20
update slots=14 slots, backoff=0
100.012s 2 DcfManager:UpdateBackoff(): +100011995470.0ns 0x1168af0 dcf 1
dec backoff slots=0
100.012s 2 DcfManager:UpdateBackoffSlotsNow(): +100011995470.0ns 0x1169000
update slots=0 slots, backoff=0
100.012s 2 DcfManager:UpdateBackoff(): +100011995470.0ns 0x1168af0 dcf 2
dec backoff slots=0
100.012s 2 DcfManager:UpdateBackoffSlotsNow(): +100011995470.0ns 0x11694a0
update slots=0 slots, backoff=0
100.012s 2 DcfManager:UpdateBackoff(): +100011995470.0ns 0x1168af0 dcf 3
dec backoff slots=0
100.012s 2 DcfManager:UpdateBackoffSlotsNow(): +100011995470.0ns 0x1169950
update slots=0 slots, backoff=0
100.012s 2 DcfManager:UpdateBackoff(): +100011995470.0ns 0x1168af0 dcf 4
dec backoff slots=0
100.012s 2 DcfManager:UpdateBackoffSlotsNow(): +100011995470.0ns 0x1169df0
update slots=0 slots, backoff=0
100.012s 0 YansWifiPhy:EndReceive(): mode=54000000, snr=27163, per=0,
size=1064
100.012s 0 DcfManager:NotifyRxEndOkNow(): +100012181470.0ns 0x11643a0 rx
end ok
(HERE WE HAVE THE STATION 1 CONFIRMING ITS RECEIPT):
-------> 100.012s 0 [mac=00:00:00:00:00:01] MacLow:ReceiveOk():
duration/id=+44000.0ns
-------> 100.012s 0 [mac=00:00:00:00:00:01] MacLow:ReceiveOk(): rx
unicast/sendAck from=00:00:00:00:00:02
100.012s 2 YansWifiPhy:EndReceive(): mode=54000000, snr=27163, per=0,
size=1064
100.012s 2 DcfManager:NotifyRxEndOkNow(): +100012181470.0ns 0x1168af0 rx
end ok
100.012s 2 [mac=00:00:00:00:00:03] MacLow:ReceiveOk():
duration/id=+44000.0ns
100.012s 2 DcfManager:NotifyNavStartNow(): +100012181470.0ns 0x1168af0 nav
start for=+44000.0ns
(HERE WE HAVE THE STATION 1 SENDING ACK TO STATION 2):
-------> 100.012s 0 [mac=00:00:00:00:00:01] MacLow:ForwardDown(): send
CTL_ACK, to=00:00:00:00:00:02, size=14, mode=ErpOfdmRate24Mbps,
duration=+0.0ns, seq=0x0
100.012s 0 DcfManager:NotifyTxStartNow(): +100012191470.0ns 0x11643a0 tx
start for +34000.0ns
100.012s 0 YansWifiChannel:Send(): propagation: txPower=17.0206dbm,
rxPower=-50.6262dbm, distance=5m, delay=+16.0ns
100.012s 0 YansWifiChannel:Send(): propagation: txPower=17.0206dbm,
rxPower=-59.6571dbm, distance=10m, delay=+33.0ns
100.012s 1 YansWifiPhy:StartReceivePacket(): sync to signal
(power=1.08988e-08W)
100.012s 1 DcfManager:NotifyRxStartNow(): +100012191486.0ns 0x1166740 rx
start for=+34000.0ns
100.012s 2 YansWifiPhy:StartReceivePacket(): sync to signal
(power=1.36235e-09W)
100.012s 2 DcfManager:NotifyRxStartNow(): +100012191503.0ns 0x1168af0 rx
start for=+34000.0ns
100.012s 1 YansWifiPhy:EndReceive(): mode=24000000, snr=27163, per=0,
size=14
100.012s 1 DcfManager:NotifyRxEndOkNow(): +100012225486.0ns 0x1166740 rx
end ok
100.012s 1 [mac=00:00:00:00:00:02] MacLow:ReceiveOk(): duration/id=+0.0ns
100.012s 1 [mac=00:00:00:00:00:02] MacLow:ReceiveOk(): receive ack
from=00:00:00:00:00:01
100.012s 1 DcfManager:StartBackoffNow(): +100012225486.0ns 0x1166970 start
backoff=8 slots
100.012s 2 YansWifiPhy:EndReceive(): mode=24000000, snr=3395.38, per=0,
size=14
100.012s 2 DcfManager:NotifyRxEndOkNow(): +100012225503.0ns 0x1168af0 rx
end ok
100.012s 2 [mac=00:00:00:00:00:03] MacLow:ReceiveOk(): duration/id=+0.0ns
100.012s 2 DcfManager:NotifyNavStartNow(): +100012225503.0ns 0x1168af0 nav
start for=+0.0ns
100.012s 2 [mac=00:00:00:00:00:03] MacLow:ReceiveOk(): rx drop CTL_ACK
100.012s 1 DcfManager:UpdateBackoff(): +100012393000.0ns 0x1168af0 dcf 0
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393000.0ns 0x1168d20
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393000.0ns 0x1168af0 dcf 1
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393000.0ns 0x1169000
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393000.0ns 0x1168af0 dcf 2
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393000.0ns 0x11694a0
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393000.0ns 0x1168af0 dcf 3
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393000.0ns 0x1169950
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393000.0ns 0x1168af0 dcf 4
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393000.0ns 0x1169df0
update slots=0 slots, backoff=0
100.012s 1 DcfManager:DoGrantAccess(): +100012393000.0ns 0x1168af0 dcf 0
needs access. backoff expired. access granted. slots=0
(HERE WE HAVE STATION 3 STARTING ITS BCAST TRANSMISSION):
-------> 100.012s 1 [mac=00:00:00:00:00:03] MacLow:StartTransmission():
startTx size=1064, to=ff:ff:ff:ff:ff:ff, listener=0x1168d00
-------> 100.012s 1 [mac=00:00:00:00:00:03] MacLow:ForwardDown(): send
DATA, to=ff:ff:ff:ff:ff:ff, size=1064, mode=ErpOfdmRate54Mbps,
duration=+0.0ns, seq=0x4200
100.012s 1 DcfManager:NotifyTxStartNow(): +100012393000.0ns 0x1168af0 tx
start for +186000.0ns
100.012s 1 DcfManager:UpdateBackoff(): +100012393000.0ns 0x1168af0 dcf 0
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393000.0ns 0x1168d20
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393000.0ns 0x1168af0 dcf 1
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393000.0ns 0x1169000
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393000.0ns 0x1168af0 dcf 2
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393000.0ns 0x11694a0
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393000.0ns 0x1168af0 dcf 3
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393000.0ns 0x1169950
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393000.0ns 0x1168af0 dcf 4
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393000.0ns 0x1169df0
update slots=0 slots, backoff=0
100.012s 1 YansWifiChannel:Send(): propagation: txPower=17.0206dbm,
rxPower=-59.6571dbm, distance=10m, delay=+33.0ns
100.012s 1 YansWifiChannel:Send(): propagation: txPower=17.0206dbm,
rxPower=-50.6262dbm, distance=5m, delay=+16.0ns
100.012s 1 DcfManager:StartBackoffNow(): +100012393000.0ns 0x1168d20 start
backoff=0 slots
100.012s 1 YansWifiPhy:StartReceivePacket(): sync to signal
(power=1.08988e-08W)
100.012s 1 DcfManager:NotifyRxStartNow(): +100012393016.0ns 0x1166740 rx
start for=+186000.0ns
100.012s 1 DcfManager:UpdateBackoff(): +100012393016.0ns 0x1166740 dcf 0
dec backoff slots=5
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393016.0ns 0x1166970
update slots=5 slots, backoff=3
100.012s 1 DcfManager:UpdateBackoff(): +100012393016.0ns 0x1166740 dcf 1
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393016.0ns 0x1166c50
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393016.0ns 0x1166740 dcf 2
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393016.0ns 0x11670f0
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393016.0ns 0x1166740 dcf 3
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393016.0ns 0x11675a0
update slots=0 slots, backoff=0
100.012s 1 DcfManager:UpdateBackoff(): +100012393016.0ns 0x1166740 dcf 4
dec backoff slots=0
100.012s 1 DcfManager:UpdateBackoffSlotsNow(): +100012393016.0ns 0x1167a40
update slots=0 slots, backoff=0
100.012s 0 YansWifiPhy:StartReceivePacket(): sync to signal
(power=1.36235e-09W)
100.012s 0 DcfManager:NotifyRxStartNow(): +100012393033.0ns 0x11643a0 rx
start for=+186000.0ns
100.012s 0 DcfManager:UpdateBackoff(): +100012393033.0ns 0x11643a0 dcf 0
dec backoff slots=0
100.012s 0 DcfManager:UpdateBackoffSlotsNow(): +100012393033.0ns 0x1163ad0
update slots=0 slots, backoff=0
100.012s 0 DcfManager:UpdateBackoff(): +100012393033.0ns 0x11643a0 dcf 1
dec backoff slots=0
100.012s 0 DcfManager:UpdateBackoffSlotsNow(): +100012393033.0ns 0x1164880
update slots=0 slots, backoff=0
100.012s 0 DcfManager:UpdateBackoff(): +100012393033.0ns 0x11643a0 dcf 2
dec backoff slots=0
100.012s 0 DcfManager:UpdateBackoffSlotsNow(): +100012393033.0ns 0x1164d20
update slots=0 slots, backoff=0
100.012s 0 DcfManager:UpdateBackoff(): +100012393033.0ns 0x11643a0 dcf 3
dec backoff slots=0
100.012s 0 DcfManager:UpdateBackoffSlotsNow(): +100012393033.0ns 0x11651d0
update slots=0 slots, backoff=0
100.012s 0 DcfManager:UpdateBackoff(): +100012393033.0ns 0x11643a0 dcf 4
dec backoff slots=0
100.012s 0 DcfManager:UpdateBackoffSlotsNow(): +100012393033.0ns 0x1165670
update slots=0 slots, backoff=0
(...)

As you can see in the log, the events occur at the same time:
100.012seconds.
I'm interested in measuring round trip time (tx data duration - tx ack
duration), but as these values are the same, the round trip time is 0. How
is it possible?
Does anyone know why is it happening?

If you want to test and analyze my problem, the source code is attached.
To run my example: ./waf --run "cena01 --trace=1" > trace-log.txt 2>&1
Be advised of log size: ~650mb.

My best regards,

Eng.º Carlos Viegas

Engenheiro de Pesquisa e Desenvolvimento
Faculdade de Engenharia da Universidade do Porto