Uploaded image for project: 'Qt'
  1. Qt
  2. QTBUG-91440

Very high CPU on socket timeouts when QNAM has lots of connections

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: P3: Somewhat important
    • Resolution: Done
    • Affects Version/s: 5.10.1, 5.14.1
    • Fix Version/s: 6.3.0 Alpha
    • Component/s: Network: Sockets
    • Labels:
      None
    • Environment:
      Ubuntu 18.04 / Linux 3.13.0
      MacOS 10.15.7
    • Platform/s:
      Linux/Other display system, macOS
    • Commits:
      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 
      

        Attachments

        For Gerrit Dashboard: QTBUG-91440
        # Subject Branch Project Status CR V

          Activity

            People

            Assignee:
            tpochep Timur Pocheptsov
            Reporter:
            mnutt Michael Nutt
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:

                Gerrit Reviews

                There is 1 open Gerrit change