Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-19881

Improve cost of logging

    XMLWordPrintable

Details

    Description

      From an email I circulated to the Query team...
      (to iterate - an average of an extra 200us per request for a single line of logging only shows under load: the impact while dealing with a single request is much less).

      _While testing MB-18841, I added a single line of logging to be output at each request.
      Over 10 clients x 10k executions, this is what it averages to:

      W/O

      {{ {
      "prepareds":

      { "avgElapsedTime": "1.968675ms", "avgServiceTime": "1.925649ms", "encoded_plan": "H4sIAAAJbogA/5xRwVLbMBD9Fc/2Ahm7k8QU4nR64ABTZjhkkmNhko29stXKkivJTSjjfntXLjQ4nOCm3X16+97bRyCdm4KKdaNQwxwgBo018SsVAsV2fJ5M6OIsObtIMdlOZ0WC0xmKT5hlk3HKaNOQRW8szB/hw6GAFf1smZsY8ievpCosMf+3Ieiy9ZWx8ndA9aB3sdzogvarnPXHIMObe3L/XKwls0ImZuMtjs+zdCrSWZbx9Ac9uAbz4HVLZBOHdaPoKYDnSUECW+W5yx3t+t1L1CUFpV9lWXEH7uAWd97oO4D7mOXkqnXSsNA0hluzO4Z0HaMYoUteUDoJXTw0tECLSpH67/pdsVyTz6u3+jyWci2VJxvOY3Qhfe8KTk42L5g2Hze59A+b0+hLdLB5+orqRvN/VAtrvlMeErXkeOWa+et/wdK+CUBHSoTAPXLlbUvd/WtZ+sDUhUS7GBorf0lFJbmQ15Oj+UvP80l3zLTylrCGnsDJUqNvbX/cEQ9HbAI87X04yvJqcbm8ilgdL41GkbCmjgZBRLuKLEUhjUEWn6H7GwAA///jLqz0aQMAAA==", "lastUse": "2016-05-26 08:23:50.705932263 +0100 BST", "name": "3ffafb06-1e74-473a-b28d-a28af5a99103", "statement": "PREPARE select * from `beer-sample` where city = \"Lawton\";", "uses": 10000 }

      },}}

      With

      {{ {
      "prepareds":

      { "avgElapsedTime": "2.189799ms", "avgServiceTime": "2.132166ms", "encoded_plan": "H4sIAAAJbogA/5xRQW/bPAz9Kwa/SxvYH9o4GeIMO/TQYgV6CJLjWiSMRNvaZMmT5CVd4f32UV67NOlpvYnk0+N7j09ARlhJct1qNDAHSMFgQ/yi6aXIy/E2kzjOs4nM82xGNMnkdCKmRS6lmCCjbUsOg3Uwf4L/DgWs6HvH3MSQX6JWWjpi/i/HoKsu1NapnxE1gN7Fcmsk7VeC9aeg4pt7av9SrBWzQlHOLrZ48aHIx2U+KwqefqNH36KIXrdELvPYtJqeA3iZSCqx04G73DF+2L1EU1FU+llVNXfgHu5wF6y5B3hIWY7QnVeWheYp3NndKaTvGcUIU/GCyivo02NDC3SoNem/rt8Vyw0FUf+rz1MpN0oHcvE81kgVBldwdrZ5xbT5fyNUeNycJ5+Sg83zN1S3hv+jXjj7lURM1JHnlWvmb/4ES/s2Aj3pMgYekKvgOuof3soyB6Y+Jtqn0Dr1Q2mqyMe8nh3NX3ueX/anTKvgCBsYCLyqDIbODccd8XDEJiDQPsSjLK8XV8vrhNXx0mSUlM42yVEQya4mR0lM4yiLj9D/DgAA//+/D3Y9aQMAAA==", "lastUse": "2016-05-26 08:28:46.71972367 +0100 BST", "name": "e51c3f2b-da23-4d33-8ee4-d54c593ddc4a", "statement": "PREPARE select * from `beer-sample` where city = \"Lawton\";", "uses": 10000 }

      }}}

      That's right – with all cores running at full blast, a single line of logging adds 200us, or, rephrased, adds 10% to the execution time.
      By comparison, with a single client running, this adds 25us over 765us, or 3%.
      This is probably down to the logging lock – here's probably some low hanging performance fruit we could pick…_

      Attachments

        For Gerrit Dashboard: MB-19881
        # Subject Branch Project Status CR V

        Activity

          People

            Donald.haggart Donald Haggart
            marco.greco Marco Greco (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Gerrit Reviews

                There are no open Gerrit changes

                PagerDuty