Details
-
Bug
-
Resolution: Done
-
P3: Somewhat important
-
5.10.1, 5.14.1
-
None
-
Ubuntu 18.04 / Linux 3.13.0
MacOS 10.15.7
-
Linux/Other display system,
macOS
-
85cfbae1d62617fdc452680813f993e812bb55dd (qt/qtbase/dev)
Description
I have a console app that uses QNAM to make http(s) connections. The app originally worked fine by instantiating a separate QNAM for each connection, however I wanted to be able to reuse connections so I switched to a single global QNAM which is when I ran into some interesting behavior:
At any given time the app may have 80-100 active tcp connections to lots of different services. From what I can tell, any time one of these connections gets timed out by the app from inactivity (hard-coded 120s timeout) I see 15-20s of 50-90% CPU usage on the QNetworkAccessManager thread. Looking at syscalls on that thread, I see approximately 600k poll() calls/sec.
I made a simple reproduction test (attached) that just opens one connection a second for 90s and then waits. As the connections start hitting their 120s timeout, the extra CPU load begins. AFAICT this seems to be dependent on how many connections I have open at the time. The test seems to reproduce with any set of servers.
Logging the test case with signals + some debug statements enabled, I see the connections first disconnect, as expected:
QDEBUG : TestQNAM::testConnect() QAbstractSocket::close() INFO : TestQNAM::testConnect() Signal: QTcpSocket(7f7f4c004e20) aboutToClose () QDEBUG : TestQNAM::testConnect() QAbstractSocket::disconnectFromHost() QDEBUG : TestQNAM::testConnect() QAbstractSocket::disconnectFromHost() emits stateChanged()(ClosingState) INFO : TestQNAM::testConnect() Signal: QTcpSocket(7f7f4c004e20) stateChanged () QDEBUG : TestQNAM::testConnect() QAbstractSocket::disconnectFromHost() disconnecting immediately QDEBUG : TestQNAM::testConnect() QAbstractSocketPrivate::resetSocketLayer() INFO : TestQNAM::testConnect() Signal: QTcpSocket(7f7f4c004e20) stateChanged () INFO : TestQNAM::testConnect() Signal: QTcpSocket(7f7f4c004e20) readChannelFinished () INFO : TestQNAM::testConnect() Signal: QTcpSocket(7f7f4c004e20) disconnected () QDEBUG : TestQNAM::testConnect() QAbstractSocket::disconnectFromHost() disconnected! QDEBUG : TestQNAM::testConnect() QTcpSocket::~QTcpSocket() QDEBUG : TestQNAM::testConnect() QAbstractSocket::~QAbstractSocket() ...
Then after they disconnect, I see the flood of hundreds of thousands of polling events:
INFO : TestQNAM::testConnect() Signal: QEventDispatcherGlib(7f7f4c0008c0) awake () INFO : TestQNAM::testConnect() Signal: QEventDispatcherGlib(7f7f4c0008c0) aboutToBlock () INFO : TestQNAM::testConnect() Signal: QEventDispatcherGlib(7f7f4c0008c0) awake () INFO : TestQNAM::testConnect() Signal: QEventDispatcherGlib(7f7f4c0008c0) aboutToBlock () INFO : TestQNAM::testConnect() Signal: QEventDispatcherGlib(7f7f4c0008c0) awake () INFO : TestQNAM::testConnect() Signal: QEventDispatcherGlib(7f7f4c0008c0) aboutToBlock () INFO : TestQNAM::testConnect() Signal: QEventDispatcherGlib(7f7f4c0008c0) awake () INFO : TestQNAM::testConnect() Signal: QEventDispatcherGlib(7f7f4c0008c0) aboutToBlock () INFO : TestQNAM::testConnect() Signal: QEventDispatcherGlib(7f7f4c0008c0) awake () INFO : TestQNAM::testConnect() Signal: QEventDispatcherGlib(7f7f4c0008c0) aboutToBlock () ...
The poll syscalls are all to the same fd:
650985 02:55:38.623192214 1 QNetworkAccessM (798) > poll fds=9:e1 timeout=0 650986 02:55:38.623193225 1 QNetworkAccessM (798) < poll res=0 fds= 650987 02:55:38.623196357 1 QNetworkAccessM (798) > poll fds=9:e1 timeout=0 650988 02:55:38.623197310 1 QNetworkAccessM (798) < poll res=0 fds= 650989 02:55:38.623200257 1 QNetworkAccessM (798) > poll fds=9:e1 timeout=0 650990 02:55:38.623201257 1 QNetworkAccessM (798) < poll res=0 fds= 650991 02:55:38.623204167 1 QNetworkAccessM (798) > poll fds=9:e1 timeout=0 650992 02:55:38.623205157 1 QNetworkAccessM (798) < poll res=0 fds= 650993 02:55:38.623208087 1 QNetworkAccessM (798) > poll fds=9:e1 timeout=0 650994 02:55:38.623208937 1 QNetworkAccessM (798) < poll res=0 fds= 650995 02:55:38.623211974 1 QNetworkAccessM (798) > poll fds=9:e1 timeout=0 650996 02:55:38.623212827 1 QNetworkAccessM (798) < poll res=0 fds= 650997 02:55:38.623215859 1 QNetworkAccessM (798) > poll fds=9:e1 timeout=0 650998 02:55:38.623216697 1 QNetworkAccessM (798) < poll res=0 fds= 650999 02:55:38.623219744 1 QNetworkAccessM (798) > poll fds=9:e1 timeout=0