RRD Quality Delay values wrong after updating to 2.2
-
Could you enable gateway monitoring debug logging under System>Advanced, Misc, check "Enable gateway monitoring debug logging", and post your apinger logs?
-
Sure, not sure how much data you need to see, but here's a short section of the log. Let me know if you'd like to see more. Right now the gateway widget is showing a RTT of 5.4ms, but it's going up and down.
Jan 29 21:45:05 apinger: Polling, timeout: 0.953s
Jan 29 21:45:05 apinger: (avg. loss: 0.0%)
Jan 29 21:45:05 apinger: (avg: 6.866ms)
Jan 29 21:45:05 apinger: #441487 from WAN_PPPOE(67.41.239.70) delay: 46.566ms/22.347ms/68.662ms received = 441484
Jan 29 21:45:04 apinger: Polling, timeout: 0.999s
Jan 29 21:45:04 apinger: Recently lost packets: 0
Jan 29 21:45:04 apinger: Sending ping #441487 to WAN_PPPOE (67.41.239.70)
Jan 29 21:45:04 apinger: Polling, timeout: 0.977s
Jan 29 21:45:04 apinger: (avg. loss: 0.0%)
Jan 29 21:45:04 apinger: (avg: 4.444ms)
Jan 29 21:45:04 apinger: #441486 from WAN_PPPOE(67.41.239.70) delay: 22.040ms/27.757ms/44.443ms received = 441483
Jan 29 21:45:03 apinger: Polling, timeout: 0.999s
Jan 29 21:45:03 apinger: Recently lost packets: 0
Jan 29 21:45:03 apinger: Sending ping #441486 to WAN_PPPOE (67.41.239.70)
Jan 29 21:45:02 apinger: Polling, timeout: 0.975s
Jan 29 21:45:02 apinger: (avg. loss: 0.0%)
Jan 29 21:45:02 apinger: (avg: 5.016ms)
Jan 29 21:45:02 apinger: #441485 from WAN_PPPOE(67.41.239.70) delay: 24.748ms/22.494ms/50.160ms received = 441482
Jan 29 21:45:02 apinger: Polling, timeout: 0.999s
Jan 29 21:45:02 apinger: Recently lost packets: 0
Jan 29 21:45:02 apinger: Sending ping #441485 to WAN_PPPOE (67.41.239.70)
Jan 29 21:45:01 apinger: Polling, timeout: 0.977s
Jan 29 21:45:01 apinger: (avg. loss: 0.0%)
Jan 29 21:45:01 apinger: (avg: 4.791ms)
Jan 29 21:45:01 apinger: #441484 from WAN_PPPOE(67.41.239.70) delay: 22.048ms/21.727ms/47.906ms received = 441481
Jan 29 21:45:01 apinger: Polling, timeout: 0.999s
Jan 29 21:45:01 apinger: Recently lost packets: 0
Jan 29 21:45:01 apinger: Sending ping #441484 to WAN_PPPOE (67.41.239.70)
Jan 29 21:45:01 apinger: Polling, timeout: 0.375s
Jan 29 21:45:00 apinger: Polling, timeout: 0.544s
Jan 29 21:45:00 apinger: (avg. loss: 0.0%)
Jan 29 21:45:00 apinger: (avg: 4.758ms)
Jan 29 21:45:00 apinger: #441483 from WAN_PPPOE(67.41.239.70) delay: 45.166ms/21.892ms/47.585ms received = 441480
Jan 29 21:45:00 apinger: Polling, timeout: 0.589s
Jan 29 21:45:00 apinger: Recently lost packets: 0
Jan 29 21:45:00 apinger: Sending ping #441483 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:59 apinger: Polling, timeout: 0.977s
Jan 29 21:44:59 apinger: (avg. loss: 0.0%)
Jan 29 21:44:59 apinger: (avg: 2.431ms)
Jan 29 21:44:59 apinger: #441482 from WAN_PPPOE(67.41.239.70) delay: 21.904ms/21.893ms/24.311ms received = 441479
Jan 29 21:44:59 apinger: Polling, timeout: 0.999s
Jan 29 21:44:59 apinger: Recently lost packets: 0
Jan 29 21:44:59 apinger: Sending ping #441482 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:58 apinger: Polling, timeout: 0.978s
Jan 29 21:44:58 apinger: (avg. loss: 0.0%)
Jan 29 21:44:58 apinger: (avg: 2.430ms)
Jan 29 21:44:58 apinger: #441481 from WAN_PPPOE(67.41.239.70) delay: 21.739ms/57.132ms/24.300ms received = 441478
Jan 29 21:44:58 apinger: Polling, timeout: 0.999s
Jan 29 21:44:58 apinger: Recently lost packets: 0
Jan 29 21:44:58 apinger: Sending ping #441481 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:57 apinger: Polling, timeout: 0.975s
Jan 29 21:44:57 apinger: (avg. loss: 0.0%)
Jan 29 21:44:57 apinger: (avg: 5.969ms)
Jan 29 21:44:57 apinger: #441480 from WAN_PPPOE(67.41.239.70) delay: 24.143ms/23.919ms/59.693ms received = 441477
Jan 29 21:44:57 apinger: Polling, timeout: 0.999s
Jan 29 21:44:57 apinger: Recently lost packets: 0
Jan 29 21:44:57 apinger: Sending ping #441480 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:56 apinger: Polling, timeout: 0.977s
Jan 29 21:44:56 apinger: (avg. loss: 0.0%)
Jan 29 21:44:56 apinger: (avg: 5.947ms)
Jan 29 21:44:56 apinger: #441479 from WAN_PPPOE(67.41.239.70) delay: 22.045ms/21.900ms/59.469ms received = 441476
Jan 29 21:44:56 apinger: Polling, timeout: 0.999s
Jan 29 21:44:56 apinger: Recently lost packets: 0
Jan 29 21:44:56 apinger: Sending ping #441479 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:56 apinger: Polling, timeout: 0.213s
Jan 29 21:44:55 apinger: Polling, timeout: 0.706s
Jan 29 21:44:55 apinger: (avg. loss: 0.0%)
Jan 29 21:44:55 apinger: (avg: 5.932ms)
Jan 29 21:44:55 apinger: #441478 from WAN_PPPOE(67.41.239.70) delay: 34.800ms/21.587ms/59.324ms received = 441475
Jan 29 21:44:55 apinger: Polling, timeout: 0.741s
Jan 29 21:44:55 apinger: Recently lost packets: 0
Jan 29 21:44:55 apinger: Sending ping #441478 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:54 apinger: Polling, timeout: 0.977s
Jan 29 21:44:54 apinger: (avg. loss: 0.0%)
Jan 29 21:44:54 apinger: (avg: 4.611ms)
Jan 29 21:44:54 apinger: #441477 from WAN_PPPOE(67.41.239.70) delay: 22.347ms/23.689ms/46.111ms received = 441474
Jan 29 21:44:54 apinger: Polling, timeout: 0.999s
Jan 29 21:44:54 apinger: Recently lost packets: 0
Jan 29 21:44:54 apinger: Sending ping #441477 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:53 apinger: Polling, timeout: 0.972s
Jan 29 21:44:53 apinger: (avg. loss: 0.0%)
Jan 29 21:44:53 apinger: (avg: 4.745ms)
Jan 29 21:44:53 apinger: #441476 from WAN_PPPOE(67.41.239.70) delay: 27.757ms/22.194ms/47.453ms received = 441473
Jan 29 21:44:53 apinger: Polling, timeout: 0.999s
Jan 29 21:44:53 apinger: Recently lost packets: 0
Jan 29 21:44:53 apinger: Sending ping #441476 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:52 apinger: Polling, timeout: 0.977s
Jan 29 21:44:52 apinger: (avg. loss: 0.0%)
Jan 29 21:44:52 apinger: (avg: 4.189ms)
Jan 29 21:44:52 apinger: #441475 from WAN_PPPOE(67.41.239.70) delay: 22.494ms/21.745ms/41.890ms received = 441472
Jan 29 21:44:52 apinger: Polling, timeout: 0.999s
Jan 29 21:44:52 apinger: Recently lost packets: 0
Jan 29 21:44:52 apinger: Sending ping #441475 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:51 apinger: Polling, timeout: 0.978s
Jan 29 21:44:51 apinger: (avg. loss: 0.0%)
Jan 29 21:44:51 apinger: (avg: 4.114ms)
Jan 29 21:44:51 apinger: #441474 from WAN_PPPOE(67.41.239.70) delay: 21.727ms/21.726ms/41.141ms received = 441471
Jan 29 21:44:51 apinger: Polling, timeout: 0.999s
Jan 29 21:44:51 apinger: Recently lost packets: 0
Jan 29 21:44:51 apinger: Sending ping #441474 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:51 apinger: Polling, timeout: 0.066s
Jan 29 21:44:50 apinger: Polling, timeout: 0.857s
Jan 29 21:44:50 apinger: (avg. loss: 0.0%)
Jan 29 21:44:50 apinger: (avg: 4.114ms)
Jan 29 21:44:50 apinger: #441473 from WAN_PPPOE(67.41.239.70) delay: 21.892ms/22.039ms/41.140ms received = 441470
Jan 29 21:44:50 apinger: Polling, timeout: 0.879s
Jan 29 21:44:50 apinger: Recently lost packets: 0
Jan 29 21:44:50 apinger: Sending ping #441473 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:49 apinger: Polling, timeout: 0.977s
Jan 29 21:44:49 apinger: (avg. loss: 0.0%)
Jan 29 21:44:49 apinger: (avg: 4.129ms)
Jan 29 21:44:49 apinger: #441472 from WAN_PPPOE(67.41.239.70) delay: 21.893ms/22.098ms/41.287ms received = 441469
Jan 29 21:44:49 apinger: Polling, timeout: 0.999s
Jan 29 21:44:49 apinger: Recently lost packets: 0
Jan 29 21:44:49 apinger: Sending ping #441472 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:48 apinger: Polling, timeout: 0.942s
Jan 29 21:44:48 apinger: (avg. loss: 0.0%)
Jan 29 21:44:48 apinger: (avg: 4.149ms)
Jan 29 21:44:48 apinger: #441471 from WAN_PPPOE(67.41.239.70) delay: 57.132ms/21.738ms/41.492ms received = 441468
Jan 29 21:44:48 apinger: Polling, timeout: 0.999s
Jan 29 21:44:48 apinger: Recently lost packets: 0
Jan 29 21:44:48 apinger: Sending ping #441471 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:47 apinger: Polling, timeout: 0.975s
Jan 29 21:44:47 apinger: (avg. loss: 0.0%)
Jan 29 21:44:47 apinger: (avg: 0.610ms)
Jan 29 21:44:47 apinger: #441470 from WAN_PPPOE(67.41.239.70) delay: 23.919ms/27.593ms/6.098ms received = 441467
Jan 29 21:44:47 apinger: Polling, timeout: 0.999s
Jan 29 21:44:47 apinger: Recently lost packets: 0
Jan 29 21:44:47 apinger: Sending ping #441470 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:46 apinger: Polling, timeout: 0.977s
Jan 29 21:44:46 apinger: (avg. loss: 0.0%)
Jan 29 21:44:46 apinger: (avg: 0.977ms)
Jan 29 21:44:46 apinger: #441469 from WAN_PPPOE(67.41.239.70) delay: 21.900ms/46.395ms/9.772ms received = 441466
Jan 29 21:44:46 apinger: Polling, timeout: 0.999s
Jan 29 21:44:46 apinger: Recently lost packets: 0
Jan 29 21:44:46 apinger: Sending ping #441469 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:45 apinger: Polling, timeout: 0.973s
Jan 29 21:44:45 apinger: (avg. loss: 0.0%)
Jan 29 21:44:45 apinger: (avg: 3.427ms)
Jan 29 21:44:45 apinger: #441468 from WAN_PPPOE(67.41.239.70) delay: 21.587ms/27.604ms/34.267ms received = 441465
Jan 29 21:44:45 apinger: Polling, timeout: 0.995s
Jan 29 21:44:45 apinger: Recently lost packets: 0
Jan 29 21:44:45 apinger: Sending ping #441468 to WAN_PPPOE (67.41.239.70)
Jan 29 21:44:44 apinger: Polling, timeout: 0.976s
Jan 29 21:44:44 apinger: (avg. loss: 0.0%)
Jan 29 21:44:44 apinger: (avg: 4.028ms)
Jan 29 21:44:44 apinger: #441467 from WAN_PPPOE(67.41.239.70) delay: 23.689ms/22.175ms/40.284ms received = 441464 -
In case it helps I'll attach a copy of the quality graph for the last week. You can see where I installed 2.2 on Saturday.
To be clear, I'm quite happy with 2.2, this is really a minor issue for me.
-
5ms seems good. See that on comcast and TWC all the time. For years.
You sure its not just working correctly now where it wasn't before?
-
My problem went the other way: from around 5ms to 35ms. Capturing the pings shows that there is not actually anything wrong:
08:36:46.496455 ICMP echo request, id 3767, seq 53505, length 44
08:36:46.500664 ICMP echo reply, id 3767, seq 53505, length 44
08:36:47.496452 ICMP echo request, id 3767, seq 53761, length 44
08:36:47.501089 ICMP echo reply, id 3767, seq 53761, length 44
08:36:48.497399 ICMP echo request, id 3767, seq 54017, length 44
08:36:48.501712 ICMP echo reply, id 3767, seq 54017, length 44
08:36:49.498143 ICMP echo request, id 3767, seq 54273, length 44
08:36:49.502348 ICMP echo reply, id 3767, seq 54273, length 44
08:36:50.498388 ICMP echo request, id 3767, seq 54529, length 44
08:36:50.502767 ICMP echo reply, id 3767, seq 54529, length 44
08:36:51.499141 ICMP echo request, id 3767, seq 54785, length 44
08:36:51.503391 ICMP echo reply, id 3767, seq 54785, length 44
08:36:52.499137 ICMP echo request, id 3767, seq 55041, length 44
08:36:52.503104 ICMP echo reply, id 3767, seq 55041, length 44Here is the apinger log. I guess the 60ms value is raising the average?
Jan 30 08:46:36 apinger: Polling, timeout: 0.692s
Jan 30 08:46:36 apinger: (avg. loss: 0.0%)
Jan 30 08:46:36 apinger: (avg: 5.866ms)
Jan 30 08:46:36 apinger: #1055 from WAN_PPPOE(62.3.84.23) delay: 4.280ms/6.347ms/58.662ms received = 1054
Jan 30 08:46:36 apinger: Polling, timeout: 0.697s
Jan 30 08:46:36 apinger: Recently lost packets: 0
Jan 30 08:46:36 apinger: Sending ping #1055 to WAN_PPPOE (62.3.84.23)
Jan 30 08:46:35 apinger: Polling, timeout: 0.993s
Jan 30 08:46:35 apinger: (avg. loss: 0.0%)
Jan 30 08:46:35 apinger: (avg: 6.073ms)
Jan 30 08:46:35 apinger: #1054 from WAN_PPPOE(62.3.84.23) delay: 4.648ms/4.398ms/60.729ms received = 1053
Jan 30 08:46:35 apinger: Polling, timeout: 0.998s
Jan 30 08:46:35 apinger: Recently lost packets: 0
Jan 30 08:46:35 apinger: Sending ping #1054 to WAN_PPPOE (62.3.84.23)
 -
In my case the ping command shows around 22ms, whereas the RTT in the gateway widget at the same time is showing 0.7ms. I think it was correctly displayed in 2.1.5 but 2.2 is too low.
-
Sorry man - That graph looks like 4 or 5 ms to me, which seems good but not too good to be true.
(I am sipping wine as I critique the post though - It's a good strong Cabernet, so itt may be influencing my judgement)
-
I've never logged the apinger data before, but it looks like lines that list the "delay:" is showing the average/min/max and this looks correct. I'm guessing that the RTT showing in the gateway widget is showing the data from the "avg:" lines which doesn't seem to correlate. This is a home connection via dsl 20down/0.8up. For some reason I think that dsl tends to have higher latencies than cable.
-
I just noticed this post.
https://forum.pfsense.org/index.php?topic=87835.0
Restarting the apinger service seems to have fixed this issue on my system.
-
I'm seeing the same thing. Fresh installation, ping is 5-6ms, apinger is showing 0.5ms. After restarting apinger it looks fine.
-
Thanks to wbond for letting me know about this thread. I've noticed the same thing; apinger delays are much less than a manual ping or traceroute will show; and restarting apinger corrects the problem.
-
It looks like in my case restarting apinger only worked for couple of hours, and now it's back to underreporting the RTT.
-
wbond, RRD is showing about 5ms, it's supposed to be about 25ms? Are you sure you're pinging the same IP address?
-
Harvy66, yes, same ip address and it usually measures in the mid 20's using ping and was consistently in that range in 2.1.5
I just pinged from pfsense and results were:
PING 67.41.239.70 (67.41.239.70): 56 data bytes
64 bytes from 67.41.239.70: icmp_seq=0 ttl=64 time=22.187 ms
64 bytes from 67.41.239.70: icmp_seq=1 ttl=64 time=22.040 ms
64 bytes from 67.41.239.70: icmp_seq=2 ttl=64 time=23.700 ms
64 bytes from 67.41.239.70: icmp_seq=3 ttl=64 time=21.708 ms
64 bytes from 67.41.239.70: icmp_seq=4 ttl=64 time=25.904 ms
64 bytes from 67.41.239.70: icmp_seq=5 ttl=64 time=39.864 ms
64 bytes from 67.41.239.70: icmp_seq=6 ttl=64 time=46.233 ms
64 bytes from 67.41.239.70: icmp_seq=7 ttl=64 time=22.777 ms
64 bytes from 67.41.239.70: icmp_seq=8 ttl=64 time=21.835 ms
64 bytes from 67.41.239.70: icmp_seq=9 ttl=64 time=21.580 ms–- 67.41.239.70 ping statistics ---
10 packets transmitted, 10 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 21.580/26.783/46.233/8.347 msThe dashboard is show 2.6ms at the same time.
-
Sorry - didn't get any notifications that anyone had replied to this.
Anyway - restarting apinger has put the stats back to normal. I'll keep an eye on it and see how long it looks sensible ;-)
-
Restarting apinger only seemed to fix it for a couple of hours for me. I ended up changing the probe interval on the gateway to 2 seconds and changed the Down value to 20 and the RTT has been running at normal levels for 2 days now. No idea why this would make any difference, but it seems to.
-
Just to let you I tried a workaround to restart apinger when monitoring alarm goes off and it seems to do the trick for 2 days now:
https://forum.pfsense.org/index.php?topic=87835.msg487013#msg487013 -
@cmb:
Could you enable gateway monitoring debug logging under System>Advanced, Misc, check "Enable gateway monitoring debug logging", and post your apinger logs?
I think I may have a clue here…
I restarted apinger and cleared the logs.The RRD RTT values where then ok for some time, but the reported values "went silly" when the log showed:
Feb 15 22:01:35 apinger: alarm canceled: GW_WAN(###) *** delay ***
Feb 15 22:01:22 apinger: ALARM: GW_WAN(###) *** delay ***
Feb 15 19:27:16 apinger: alarm canceled: GW_WAN(###) *** delay ***The graphs changed at the same time as the first "alarm canceled" event, so it looks like its related to the alarm clearing rather than triggering.
-
I have the same problem, a VSAT wan (supposed to be always more than 500ms) and a WIMAX (supposed to be always more than 120ms), after 2.2 upgrade (well, fresh installation) are 20/10/0ms