RRD Quality Delay values wrong after updating to 2.2
-
I've upgraded a 2.1.5 Nano system using the automatic update feature. Looks like everything is working ok except that the "Delay" values on the RRD quality graphs have gone from about 25 mS to around 0.5 mS.
The gateway monitor IP is set to my ISPs first-hop gateway and the ping diagnostic to this is reported as about 25 mS.
Has anything changed that I need to look at to get this working again?
Chris
-
FWIW I've noticed the same issue on my system. Real RTT is about 25ms, but RTT reported is showing mid to low single digits and sometimes less than 1ms. Yours is the first post I've noticed about it, so I'm guessing it's not a wirespread issue. Mine was a full install to a SSD and then I restored a 2.1.5 backup.
-
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.