Diagnosing periodic high ping times on macOS

Background

Up until a few months ago, my home network setup was pretty terrible. The entire house ran off the WiFi provided by an OpenWRT-powered TP-Link WDR3600 from 2013 in the far corner of the house. So when I fired up a game on my laptop via Steam in-home streaming and got unplayable lag and stuttering, I just figured that the issue was the network and left it at that. After all, the gaming PC was connected via WiFI from the opposite corner of the house with no shortage of walls in between.

In November 2018, I finally got serious about the network upgrade I had been planning. I'll probably do a more in-depth post about this at some point, but to make a long story short: Most things are wired and what isn't is connected via a modern, centrally-located access point. Performance is noticeably better in general and amazingly better for high-bandwidth tasks like transferring files.

So when I excitedly fired up the same game on my laptop, I was pretty surprised that it was still unplayable. At this point I should clarify that the game was not something that requires a CRT and wired controller for super-low response times. So when I say unplayable, I mean legitimately unplayable. I'm talking periodic lag spikes that caused the video to drop a few seconds or more behind the inputs. Even turn-based games would have issues with the amount of lag.

Narrowing the scope

To make sure it wasn't an issue with the streaming software, the gaming PC, or the network, I used ping to test the latency to the gateway from a few hosts. All the computers except my laptop had normal ping times. Running it on my laptop looked like this:

$ ping pfsense.lan | tee >(grep -oP 'time=\K\S*' | spark)
PING pfsense.lan (192.168.1.1): 56 data bytes
bytes from 192.168.1.1: icmp_seq=0 ttl=64 time=1.574 ms
bytes from 192.168.1.1: icmp_seq=1 ttl=64 time=0.996 ms
bytes from 192.168.1.1: icmp_seq=2 ttl=64 time=1.568 ms
bytes from 192.168.1.1: icmp_seq=3 ttl=64 time=92.153 ms
bytes from 192.168.1.1: icmp_seq=4 ttl=64 time=39.079 ms
bytes from 192.168.1.1: icmp_seq=5 ttl=64 time=14.307 ms
bytes from 192.168.1.1: icmp_seq=6 ttl=64 time=1.570 ms
bytes from 192.168.1.1: icmp_seq=7 ttl=64 time=1.636 ms
bytes from 192.168.1.1: icmp_seq=8 ttl=64 time=1.698 ms
bytes from 192.168.1.1: icmp_seq=9 ttl=64 time=1.568 ms
bytes from 192.168.1.1: icmp_seq=10 ttl=64 time=1.550 ms
bytes from 192.168.1.1: icmp_seq=11 ttl=64 time=1.106 ms
bytes from 192.168.1.1: icmp_seq=12 ttl=64 time=1.832 ms
bytes from 192.168.1.1: icmp_seq=13 ttl=64 time=1.816 ms
bytes from 192.168.1.1: icmp_seq=14 ttl=64 time=36.598 ms
bytes from 192.168.1.1: icmp_seq=15 ttl=64 time=42.863 ms
bytes from 192.168.1.1: icmp_seq=16 ttl=64 time=20.747 ms
bytes from 192.168.1.1: icmp_seq=17 ttl=64 time=3.112 ms
bytes from 192.168.1.1: icmp_seq=18 ttl=64 time=1.695 ms
bytes from 192.168.1.1: icmp_seq=19 ttl=64 time=1.795 ms
bytes from 192.168.1.1: icmp_seq=20 ttl=64 time=1.504 ms
bytes from 192.168.1.1: icmp_seq=21 ttl=64 time=1.644 ms
bytes from 192.168.1.1: icmp_seq=22 ttl=64 time=1.732 ms
bytes from 192.168.1.1: icmp_seq=23 ttl=64 time=1.581 ms
bytes from 192.168.1.1: icmp_seq=24 ttl=64 time=1.794 ms
bytes from 192.168.1.1: icmp_seq=25 ttl=64 time=33.367 ms
bytes from 192.168.1.1: icmp_seq=26 ttl=64 time=124.282 ms
bytes from 192.168.1.1: icmp_seq=27 ttl=64 time=97.719 ms
bytes from 192.168.1.1: icmp_seq=28 ttl=64 time=76.501 ms
bytes from 192.168.1.1: icmp_seq=29 ttl=64 time=1.734 ms
bytes from 192.168.1.1: icmp_seq=30 ttl=64 time=1.622 ms
bytes from 192.168.1.1: icmp_seq=31 ttl=64 time=1.758 ms
bytes from 192.168.1.1: icmp_seq=32 ttl=64 time=1.578 ms
bytes from 192.168.1.1: icmp_seq=33 ttl=64 time=1.527 ms
bytes from 192.168.1.1: icmp_seq=34 ttl=64 time=1.017 ms
^C
 ▁▁▁▆▃▁▁▁▁▁▁▁▁▁▃▃▂▁▁▁▁▁▁▁▁▂█▆▅▁▁▁▁▁▁

(sweet graph at the end courtesy of spark)

Notice the periodic spikes. Clearly there's something going on with the network connection on my laptop. Connecting via a wired connection and running it again confirmed that it was only happening on WiFi.

WiFi debugging

Now that I had narrowed the issue down to an issue with the WiFi, I could start trying to debug it.

After coming across this very helpful post explaining how, I enabled WiFi debug logging by running:

sudo /System/Library/PrivateFrameworks/Apple80211.framework/Versions/A/Resources/airport en0 debug +AllUserland

(remember to turn this off after, airport is pretty chatty with debug logs enabled)

I then watched the wifi log (sudo tail -f /var/log/wifi.log) as I ran the same ping command. Whenever I saw ping times spike, I also saw the following entries in the WiFi log:

Tue Nov 27 02:01:33.764 IPC: <airportd[68]> ADDED XPC CLIENT CONNECTION [QSyncthingTray (pid=14397, euid=501, egid=20)]
Tue Nov 27 02:01:33.765 Info: <airportd[68]> SCAN request received from pid 14397 (QSyncthingTray) with priority 0
Tue Nov 27 02:01:33.766 Scan: <airportd[68]> Cache-assisted scan request for QSyncthingTray on channel 1 does not require a live scan
Tue Nov 27 02:01:33.766 Scan: <airportd[68]> Cache-assisted scan request for QSyncthingTray on channel 2 does not require a live scan
Tue Nov 27 02:01:33.766 Scan: <airportd[68]> Cache-assisted scan request for QSyncthingTray on channel 3 does not require a live scan
Tue Nov 27 02:01:33.766 Scan: <airportd[68]> Cache-assisted scan request for QSyncthingTray on channel 4 does not require a live scan
Tue Nov 27 02:01:33.766 Scan: <airportd[68]> Cache-assisted scan request for QSyncthingTray on channel 5 does not require a live scan
Tue Nov 27 02:01:33.766 Scan: <airportd[68]> Cache-assisted scan request for QSyncthingTray on channel 6 does not require a live scan
Tue Nov 27 02:01:33.766 Scan: <airportd[68]> Cache-assisted scan request for QSyncthingTray does not require a live scan
Tue Nov 27 02:01:33.766 AutoJoin: <airportd[68]> Successful cache-assisted scan request for QSyncthingTray with channels {(
Tue Nov 27 02:01:33.766     <CWChannel: 0x7f9073514e70> [channelNumber=1(2GHz), channelWidth={20MHz}, active],
Tue Nov 27 02:01:33.766     <CWChannel: 0x7f90735507b0> [channelNumber=2(2GHz), channelWidth={20MHz}, active],
Tue Nov 27 02:01:33.766     <CWChannel: 0x7f9073526370> [channelNumber=3(2GHz), channelWidth={20MHz}, active],
Tue Nov 27 02:01:33.766     <CWChannel: 0x7f9073526420> [channelNumber=4(2GHz), channelWidth={20MHz}, active],
Tue Nov 27 02:01:33.766     <CWChannel: 0x7f907354ddb0> [channelNumber=5(2GHz), channelWidth={20MHz}, active],
Tue Nov 27 02:01:33.766     <CWChannel: 0x7f907354c6c0> [channelNumber=6(2GHz), channelWidth={20MHz}, active]
Tue Nov 27 02:01:33.766 )} took 0.0007 seconds, returned 5 results
< insert logs like above for all channels all the way up to 144 in batches of 6 >
Tue Nov 27 02:01:33.779 IPC: <airportd[68]> INVALIDATED XPC CLIENT CONNECTION [QSyncthingTray (pid=14397, euid=501, egid=20)]
< 10 seconds pass>
Tue Nov 27 02:01:43.847 IPC: <airportd[68]> ADDED XPC CLIENT CONNECTION [QSyncthingTray (pid=14397, euid=501, egid=20)]
< same scanning logs as above >
Tue Nov 27 02:01:46.741 IPC: <airportd[68]> INVALIDATED XPC CLIENT CONNECTION [QSyncthingTray (pid=14397, euid=501, egid=20)]
< ... and repeat >

This pretty clearly indicates that the QSyncthingTray application (a tray icon to monitor Syncthing) was periodically requesting WiFi scans which, in turn, caused the bursts of latency. After quitting the application and running ping again, the times were all <2ms, even after running for a few minutes. Also, when I started up the game again to test it, the lag was completely gone!

Digging deeper

Since QSyncthingTray is open source, I filed a bug report on the project and dug into the code to see if I could pinpoint the issue. After finding nothing out of the ordinary and doing a bunch of searching the internet, it turns out that it's not an issue with QSyncthingTray at all, but with Qt, a cross-platform SDK that QSyncthingTray and many other programs use. Some classmates and I actually used it to make a game called ParticleStorm back in university.

There are open bug reports against this issue from 2013, 2014, and 2015. Additionally, there are loads of blog posts and per-program workarounds. It's a little disappointing that just running a network-enabled Qt application can seriously disrupt real-time applications on the same system. Granted, I have no knowledge of the complexities of this issue, but at the very least it seems the documentation could be clearer on the issue so developers stop getting surprised by it.

Anyway, the "fix" is to set QT_BEARER_POLL_TIMEOUT=-1 as an environment variable on your system. Honestly, I've just stopped using QSyncthingTray instead. Not that it's not useful, I just realized that I didn't really need it. Syncthing works well enough that I don't find myself ever worrying about it. If a Qt application ever becomes an essential part of my setup I guess I'll have to revisit this.

Takeaways

When macOS scans for networks (as it does when requested by an application, when you click the WiFi icon, or when you request your location) it causes high ping times and dropped packets. According to bug reports, scanning for WiFi networks on other OS's causes the same issues. This is something I didn't really expect, but good to know going forward.
Qt has a bug where instantiating a QNetworkConfigurationManager causes it to scan for WiFi networks every 10 seconds by default. Some applications set the QT_BEARER_POLL_TIMEOUT environment variable themselves to disable this behaviour, but the majority probably have no idea that it's even an issue until a user reports it.

So if you're seeing regular latency spikes, audit what programs you have running. Specifically look for programs built with Qt. Setting the QT_BEARER_POLL_TIMEOUT environment variable to -1 can help with these. Applications that use your location could also be the culprit. Who knew keeping your ping down to an acceptable level was such a minefield...

Posted Jan 22, 2019 by Carey Metcalfe

Tags: macOS, networking