search

luigirizzo / netmap

Automatically exported from code.google.com/p/netmap
BSD 2-Clause "Simplified" License
1.86k stars 537 forks source link

Ping phenomenon with sawtooth roundtrip time #494

Open ramaza opened 6 years ago

ramaza commented 6 years ago

I'm testing a pretty simple zerocopy Netmap application that is bridging packets between two VLANs. I'm experiencing an interesting phenomenon in the results of a basic test with 1 ping per second.

The roundtrip-time is steadily shrinking from a pretty high level of 10ms to a rather normal level of less than 1ms over a period of about 100 seconds. Then it's jumping back to 10ms and the cycle starts again. There's no packet loss or any other problem. Also the throughput under high load is looking good. It's just this periodic sawtooth pattern in the roundtrip-time that I can't stop thinking about.

It reminds me a little bit about the superimposition of two timers with slightly different frequency. Maybe it's the ping interval in combination with some NAPI polling timer?

I'm thankful for any idea to narrow down this problem.

CYCLE STARTS HERE

64 bytes from 172.17.0.13: seq=245 ttl=64 time=10.545 ms
64 bytes from 172.17.0.13: seq=246 ttl=64 time=10.487 ms
64 bytes from 172.17.0.13: seq=247 ttl=64 time=10.433 ms
64 bytes from 172.17.0.13: seq=248 ttl=64 time=10.290 ms
64 bytes from 172.17.0.13: seq=249 ttl=64 time=10.274 ms
64 bytes from 172.17.0.13: seq=250 ttl=64 time=10.119 ms
64 bytes from 172.17.0.13: seq=251 ttl=64 time=10.038 ms
64 bytes from 172.17.0.13: seq=252 ttl=64 time=10.075 ms
64 bytes from 172.17.0.13: seq=253 ttl=64 time=9.898 ms
64 bytes from 172.17.0.13: seq=254 ttl=64 time=9.752 ms
64 bytes from 172.17.0.13: seq=255 ttl=64 time=9.597 ms
64 bytes from 172.17.0.13: seq=256 ttl=64 time=9.515 ms
64 bytes from 172.17.0.13: seq=257 ttl=64 time=9.466 ms
64 bytes from 172.17.0.13: seq=258 ttl=64 time=9.325 ms
64 bytes from 172.17.0.13: seq=259 ttl=64 time=9.247 ms
64 bytes from 172.17.0.13: seq=260 ttl=64 time=9.070 ms
64 bytes from 172.17.0.13: seq=261 ttl=64 time=8.967 ms
64 bytes from 172.17.0.13: seq=262 ttl=64 time=8.880 ms
64 bytes from 172.17.0.13: seq=263 ttl=64 time=8.795 ms
64 bytes from 172.17.0.13: seq=264 ttl=64 time=8.583 ms
64 bytes from 172.17.0.13: seq=265 ttl=64 time=8.547 ms
64 bytes from 172.17.0.13: seq=266 ttl=64 time=8.457 ms
64 bytes from 172.17.0.13: seq=267 ttl=64 time=8.346 ms
64 bytes from 172.17.0.13: seq=268 ttl=64 time=8.239 ms
64 bytes from 172.17.0.13: seq=269 ttl=64 time=8.159 ms
64 bytes from 172.17.0.13: seq=270 ttl=64 time=7.991 ms
64 bytes from 172.17.0.13: seq=271 ttl=64 time=7.988 ms
64 bytes from 172.17.0.13: seq=272 ttl=64 time=7.876 ms
64 bytes from 172.17.0.13: seq=273 ttl=64 time=7.812 ms
64 bytes from 172.17.0.13: seq=274 ttl=64 time=7.662 ms
64 bytes from 172.17.0.13: seq=275 ttl=64 time=7.623 ms
64 bytes from 172.17.0.13: seq=276 ttl=64 time=7.519 ms
64 bytes from 172.17.0.13: seq=277 ttl=64 time=7.506 ms
64 bytes from 172.17.0.13: seq=278 ttl=64 time=7.264 ms
64 bytes from 172.17.0.13: seq=279 ttl=64 time=7.283 ms
64 bytes from 172.17.0.13: seq=280 ttl=64 time=7.175 ms
64 bytes from 172.17.0.13: seq=281 ttl=64 time=7.026 ms
64 bytes from 172.17.0.13: seq=282 ttl=64 time=7.025 ms
64 bytes from 172.17.0.13: seq=283 ttl=64 time=6.819 ms
64 bytes from 172.17.0.13: seq=284 ttl=64 time=6.700 ms
64 bytes from 172.17.0.13: seq=285 ttl=64 time=6.511 ms
64 bytes from 172.17.0.13: seq=286 ttl=64 time=6.440 ms
64 bytes from 172.17.0.13: seq=287 ttl=64 time=6.351 ms
64 bytes from 172.17.0.13: seq=288 ttl=64 time=6.261 ms
64 bytes from 172.17.0.13: seq=289 ttl=64 time=6.128 ms
64 bytes from 172.17.0.13: seq=290 ttl=64 time=6.075 ms
64 bytes from 172.17.0.13: seq=291 ttl=64 time=5.950 ms
64 bytes from 172.17.0.13: seq=292 ttl=64 time=5.911 ms
64 bytes from 172.17.0.13: seq=293 ttl=64 time=5.746 ms
64 bytes from 172.17.0.13: seq=294 ttl=64 time=5.681 ms
64 bytes from 172.17.0.13: seq=295 ttl=64 time=5.594 ms
64 bytes from 172.17.0.13: seq=296 ttl=64 time=5.516 ms
64 bytes from 172.17.0.13: seq=297 ttl=64 time=5.416 ms
64 bytes from 172.17.0.13: seq=298 ttl=64 time=5.322 ms
64 bytes from 172.17.0.13: seq=299 ttl=64 time=5.225 ms
64 bytes from 172.17.0.13: seq=300 ttl=64 time=5.091 ms
64 bytes from 172.17.0.13: seq=301 ttl=64 time=5.011 ms
64 bytes from 172.17.0.13: seq=302 ttl=64 time=1.054 ms
64 bytes from 172.17.0.13: seq=303 ttl=64 time=4.713 ms
64 bytes from 172.17.0.13: seq=304 ttl=64 time=2.844 ms
64 bytes from 172.17.0.13: seq=305 ttl=64 time=4.550 ms
64 bytes from 172.17.0.13: seq=306 ttl=64 time=4.400 ms
64 bytes from 172.17.0.13: seq=307 ttl=64 time=4.307 ms
64 bytes from 172.17.0.13: seq=308 ttl=64 time=4.168 ms
64 bytes from 172.17.0.13: seq=309 ttl=64 time=4.084 ms
64 bytes from 172.17.0.13: seq=310 ttl=64 time=4.063 ms
64 bytes from 172.17.0.13: seq=311 ttl=64 time=3.933 ms
64 bytes from 172.17.0.13: seq=312 ttl=64 time=3.871 ms
64 bytes from 172.17.0.13: seq=313 ttl=64 time=3.760 ms
64 bytes from 172.17.0.13: seq=314 ttl=64 time=3.690 ms
64 bytes from 172.17.0.13: seq=315 ttl=64 time=3.540 ms
64 bytes from 172.17.0.13: seq=316 ttl=64 time=3.509 ms
64 bytes from 172.17.0.13: seq=317 ttl=64 time=3.515 ms
64 bytes from 172.17.0.13: seq=318 ttl=64 time=3.136 ms
64 bytes from 172.17.0.13: seq=319 ttl=64 time=3.016 ms
64 bytes from 172.17.0.13: seq=320 ttl=64 time=2.855 ms
64 bytes from 172.17.0.13: seq=321 ttl=64 time=2.814 ms
64 bytes from 172.17.0.13: seq=322 ttl=64 time=2.751 ms
64 bytes from 172.17.0.13: seq=323 ttl=64 time=2.627 ms
64 bytes from 172.17.0.13: seq=324 ttl=64 time=2.475 ms
64 bytes from 172.17.0.13: seq=325 ttl=64 time=2.371 ms
64 bytes from 172.17.0.13: seq=326 ttl=64 time=2.280 ms
64 bytes from 172.17.0.13: seq=327 ttl=64 time=2.164 ms
64 bytes from 172.17.0.13: seq=328 ttl=64 time=2.044 ms
64 bytes from 172.17.0.13: seq=329 ttl=64 time=1.978 ms
64 bytes from 172.17.0.13: seq=330 ttl=64 time=1.812 ms
64 bytes from 172.17.0.13: seq=331 ttl=64 time=1.670 ms
64 bytes from 172.17.0.13: seq=332 ttl=64 time=1.571 ms
64 bytes from 172.17.0.13: seq=333 ttl=64 time=1.454 ms
64 bytes from 172.17.0.13: seq=334 ttl=64 time=1.368 ms
64 bytes from 172.17.0.13: seq=335 ttl=64 time=1.211 ms
64 bytes from 172.17.0.13: seq=336 ttl=64 time=1.129 ms
64 bytes from 172.17.0.13: seq=337 ttl=64 time=1.012 ms
64 bytes from 172.17.0.13: seq=338 ttl=64 time=0.922 ms
64 bytes from 172.17.0.13: seq=339 ttl=64 time=0.725 ms

NEXT CYCLE STARTS HERE

64 bytes from 172.17.0.13: seq=340 ttl=64 time=10.742 ms
64 bytes from 172.17.0.13: seq=341 ttl=64 time=10.663 ms
64 bytes from 172.17.0.13: seq=342 ttl=64 time=10.536 ms
64 bytes from 172.17.0.13: seq=343 ttl=64 time=10.433 ms
64 bytes from 172.17.0.13: seq=344 ttl=64 time=10.377 ms
64 bytes from 172.17.0.13: seq=345 ttl=64 time=10.399 ms
64 bytes from 172.17.0.13: seq=346 ttl=64 time=10.116 ms
64 bytes from 172.17.0.13: seq=347 ttl=64 time=9.861 ms
64 bytes from 172.17.0.13: seq=348 ttl=64 time=9.801 ms
64 bytes from 172.17.0.13: seq=349 ttl=64 time=9.685 ms
64 bytes from 172.17.0.13: seq=350 ttl=64 time=9.632 ms
vmaffione commented 6 years ago

Your program should be very similar to bridge, so maybe you should see if the same happens with bridge. Also, you should add timestamps at poll/ioctl to check where the delay is introduced (input from VLAN A, input from VLAN B, output to VLAN A, output to VLAN B.