Poor performance when using request modifier plugin

Hello,

I have written a simple request modifier plugin (based on the sample provided by kpacha) which adds the Basic Authentication header using environment variables. I don't want to use the martian-modifier, since that requires hard-coding the base64 encoded credentials into config file, krakend.json.Unfortunately, I'm seeing a huge performance degradation.

Here are some times for a sample query on my laptop (quad-core with 8 hyper-threads, 16GB RAM, running Ubuntu 20.04 and using docker-compose)

Without req-modifier plugin:

DB query execution time: 335 usec (postgresql seems to be retieving from its cache)
Backend service API handling time: 551 usec (time added by my backend service: +216 usec, within the same process)
KrakenD log: [GIN] 2022/04/06 - 04:37:57 | 200 |    1.665101ms |      172.27.0.1 | GET    "/v1/movies/?sortby=raey&pagesz=5&offset=25"  (time added by krakend: +1114 usec)

With req-modifier plugin:

DB query execution time: 469 usec
Backend service API handler time: 695 usec (+226)
KrakendD log: [GIN] 2022/04/06 - 04:47:17 | 200 |   51.598993ms |      172.28.0.1 | GET      "/v1/movies/?sortby=raey&pagesz=5&offset=25" (+50903)

As you can see, the request processing time goes up from about 1msec to 51msec! My req-modifier plugin code, is almost identical to the sample provided. Below is a snippet of my modifier().

func modifier(req RequestWrapper) reqWrap {

    raw := os.Getenv("USERNAME") + ":" + os.Getenv("PASSWORD")
    encoded := base64.StdEncoding.EncodeToString([]byte(raw))

    headers := req.Headers()
    headers["Authorization"] = []string{"Basic " + encoded}

    return reqWrap {
        method:     req.Method(),
        url:        req.URL(),
        query:      req.Query(),
        path:       req.Path(),
        body:       req.Body(),
        params:     req.Params(),
        headers:    headers,
    }
}

This is observed across the board for all HTTP methods. Here's some numbers for POST while using the req-modifier plugin.

DB query execution time: 887 usec Backend service API handler time: 1171 usec (+284) [GIN] 2022/04/06 - 04:46:00 | 201 | 222.887471ms | 172.28.0.1 | POST "/v1/movies/" (+221716)

The degradation for POST requests is even worse. Not knowing much about KrakenD, it is difficult to understand why the processing time would degrade so much more for POST as compared to GET.

I would appreciate any help to improve the performance. In the very least, I hope this information is useful for you to fix any latent issues. As mentioned earlier, my plugin code is almost identical to the sample provided.

My krakend.json

{
  "$schema": "https://www.krakend.io/schema/v3.json",
  "version": 3,
  "plugin": {
      "pattern":".so",
      "folder": "/opt/krakend/plugins/"
  },
  "extra_config": {
    "telemetry/logging": {
      "level": "DEBUG",
      "prefix": "[KRAKEND]",
      "syslog": false,
      "stdout": true,
      "format": "default"
    }
  },
  "timeout": "3000ms",
  "cache_ttl": "300s",
  "output_encoding": "json",
  "name": "api-gw",
  "endpoints": [
    {
      "endpoint": "/v1/movies/",
      "method": "POST",
      "output_encoding": "no-op",
      "extra_config": {
        "plugin/req-resp-modifier": {
          "name": ["req-modifier"]
        },
        "auth/validator": {
          "operation_debug": true,
          "alg": "RS256",
          "jwk_url": "http://authserver:8080/auth/realms/movies/protocol/openid-connect/certs",
          "disable_jwk_security": true,
          "cache": true,
          "cache_duration": 10,
          "propagate_claims": [
              ["email", "X-UserEmail"]
          ]
        }
      },
      "input_headers": [
        null,
        "Content-Type",
        "Authorization",
        "X-UserEmail"
      ],
      "backend": [
        {
          "url_pattern": "/movies/",
          "encoding": "no-op",
          "sd": "static",
          "method": "POST",
          "host": [
            "http://appserver:8080"
          ],
          "disable_host_sanitize": false
        }
      ]
    },
    {
      "endpoint": "/v1/movies/{id}",
      "method": "GET",
      "output_encoding": "no-op",
      "extra_config": {
        "plugin/req-resp-modifier": {
          "name": ["req-modifier"]
        },
        "auth/validator": {
          "operation_debug": true,
          "alg": "RS256",
          "jwk_url": "http://authserver:8080/auth/realms/movies/protocol/openid-connect/certs",
          "disable_jwk_security": true,
          "cache": true,
          "cache_duration": 10,
          "propagate_claims": [
              ["email", "X-UserEmail"]
          ]
        }
      },
      "input_headers": [
        "Authorization",
        "X-UserEmail"
      ],
      "backend": [
        {
          "url_pattern": "/movies/{id}",
          "encoding": "no-op",
          "sd": "static",
          "method": "GET",
          "host": [
            "http://appserver:8080"
          ],
          "disable_host_sanitize": false
        }
      ]
    },
    {
      "endpoint": "/v1/movies/{id}",
      "method": "PUT",
      "output_encoding": "no-op",
      "extra_config": {
        "plugin/req-resp-modifier": {
          "name": ["req-modifier"]
        },
        "auth/validator": {
          "operation_debug": true,
          "alg": "RS256",
          "jwk_url": "http://authserver:8080/auth/realms/movies/protocol/openid-connect/certs",
          "disable_jwk_security": true,
          "cache": true,
          "cache_duration": 10,
          "propagate_claims": [
              ["email", "X-UserEmail"]
          ]
        }
      },
      "input_headers": [
        "Content-Type",
        "Authorization",
        "X-UserEmail"
      ],
      "backend": [
        {
          "url_pattern": "/movies/{id}",
          "encoding": "no-op",
          "sd": "static",
          "method": "PUT",
          "host": [
            "http://appserver:8080"
          ],
          "disable_host_sanitize": false
        }
      ]
    },
    {
      "endpoint": "/v1/movies/{id}",
      "method": "DELETE",
      "output_encoding": "no-op",
      "extra_config": {
        "plugin/req-resp-modifier": {
          "name": ["req-modifier"]
        },
        "auth/validator": {
          "operation_debug": true,
          "alg": "RS256",
          "jwk_url": "http://authserver:8080/auth/realms/movies/protocol/openid-connect/certs",
          "disable_jwk_security": true,
          "cache": true,
          "cache_duration": 10,
          "propagate_claims": [
              ["email", "X-UserEmail"]
          ]
        }
      },
      "backend": [
        {
          "url_pattern": "/movies/{id}",
          "encoding": "no-op",
          "sd": "static",
          "method": "DELETE",
          "host": [
            "http://appserver:8080"
          ],
          "disable_host_sanitize": false
        }
      ],
      "input_headers": [
        "Authorization",
        "X-UserEmail"
      ]
    },
    {
      "endpoint": "/v1/movies/",
      "method": "GET",
      "output_encoding": "no-op",
      "extra_config": {
        "qos/ratelimit/router": {
          "max_rate": 50
        },
        "plugin/req-resp-modifier": {
          "name": ["req-modifier"]
        },
        "auth/validator": {
          "operation_debug": true,
          "alg": "RS256",
          "jwk_url": "http://authserver:8080/auth/realms/movies/protocol/openid-connect/certs",
          "disable_jwk_security": true,
          "cache": true,
          "cache_duration": 10,
          "propagate_claims": [
              ["email", "X-UserEmail"]
          ]
        }
      },
      "backend": [
        {
          "url_pattern": "/movies/",
          "encoding": "no-op",
          "sd": "static",
          "method": "GET",
          "host": [
            "http://appserver:8080"
          ],
          "disable_host_sanitize": false
        }
      ],
      "input_headers": [
        "Authorization",
        "X-UserEmail"
      ],
      "input_query_strings": [
        "pagesz",
        "offset",
        "sortby",
        "title",
        "year",
        "director"
      ]
    }
  ]
}

This is not an issue with KrakenD. For some reason, the basic auth middleware handler in my backend service is taking longer to finish! :(

@tusharsdesai keep in mind the example is just a demonstration and it's not intended to be used in production without giving it some love.

take this as an example:

    raw := os.Getenv("USERNAME") + ":" + os.Getenv("PASSWORD")
    encoded := base64.StdEncoding.EncodeToString([]byte(raw))

    headers := req.Headers()
    headers["Authorization"] = []string{"Basic " + encoded}

doing this for every request is not efficient. this is something you could precalculate at the modifierFactory, before returning the modifier function, so in your func modifier(req RequestWrapper) reqWrap you just need to add the precalculated value to the headers

    raw := os.Getenv("USERNAME") + ":" + os.Getenv("PASSWORD")
    encoded := base64.StdEncoding.EncodeToString([]byte(raw))
    authorizationHeader = "Basic " + encoded

...

    headers := req.Headers()
    headers["Authorization"] = []string{authorizationHeader}

Thanks for the tip, @kpacha . I've incorporated it in my code. The earlier high latency was coming from computing hash of basic auth password using bcrypt with bcrypt.DefaultCost (i.e. 10). On changing it to crypt.MinCost (4), the latency has come down from about 50ms to about 0.9ms. Not good, but not too bad either.

Here are some numbers for your reference. Do they look ok to you?

I'm also seeing an issue randomly when the plugin is enabled, where in KrakenD suddenly reports error 405 (Method Not Allowed). Although it seems to only happen when the plugin is present, it does not all happen all the time and no Debug messages from the plugin are printed and the request is not forwarded to the backend.

BASIC AUTH DISABLED(PLUGIN DISABLED in KRAKEND, CHECK DISABLED IN BACKEND SERVICE)
-------------------------------------------------------------------------------------
appserver_1   | 05:29:25.64PM UTC INF --> GET:/movies/ user=jdoe@example.com
appserver_1   | 05:29:25.641PM UTC INF <--  | 200 |    1.463587ms | GET /movies/ user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:29:25 | 200 |   13.103859ms |    192.168.48.1 | GET      "/v1/movies/?pagesz=5"
appserver_1   | 05:29:25.648PM UTC INF --> POST:/movies/ user=jdoe@example.com
appserver_1   | 05:29:25.658PM UTC INF <--  | 201 |   10.284103ms | POST /movies/ user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:29:25 | 201 |   15.579741ms |    192.168.48.1 | POST     "/v1/movies/"
appserver_1   | 05:29:25.663PM UTC INF --> GET:/movies/2320b890-99b8-4149-a832-5ba075a6fe84 user=jdoe@example.com
appserver_1   | 05:29:25.664PM UTC INF <--  | 200 |    0.705013ms | GET /movies/2320b890-99b8-4149-a832-5ba075a6fe84 user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:29:25 | 200 |    5.553267ms |    192.168.48.1 | GET      "/v1/movies/2320b890-99b8-4149-a832-5ba075a6fe84"
appserver_1   | 05:29:25.669PM UTC INF --> PUT:/movies/2320b890-99b8-4149-a832-5ba075a6fe84 user=jdoe@example.com
appserver_1   | 05:29:25.673PM UTC INF <--  | 200 |    3.588096ms | PUT /movies/2320b890-99b8-4149-a832-5ba075a6fe84 user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:29:25 | 200 |    8.453763ms |    192.168.48.1 | PUT      "/v1/movies/2320b890-99b8-4149-a832-5ba075a6fe84"
appserver_1   | 05:29:25.674PM UTC INF --> GET:/movies/ user=jdoe@example.com
appserver_1   | 05:29:25.674PM UTC INF <--  | 200 |     426.523µs | GET /movies/ user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:29:25 | 200 |     875.402µs |    192.168.48.1 | GET      "/v1/movies/?year=1997&pagesz=5"
appserver_1   | 05:29:25.679PM UTC INF --> DELETE:/movies/2320b890-99b8-4149-a832-5ba075a6fe84 user=jdoe@example.com
appserver_1   | 05:29:25.687PM UTC INF <--  | 200 |    7.761524ms | DELETE /movies/2320b890-99b8-4149-a832-5ba075a6fe84 user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:29:25 | 200 |   12.305474ms |    192.168.48.1 | DELETE   "/v1/movies/2320b890-99b8-4149-a832-5ba075a6fe84"

BASIC AUTH IGNORED(PLUGIN ENABLED in KRAKEND, CHECK DISABLED IN BACKEND SERVICE)
-------------------------------------------------------------------------------------
appserver_1   | 05:33:36.301PM UTC INF --> GET:/movies/ user=jdoe@example.com
appserver_1   | 05:33:36.302PM UTC INF <--  | 200 |    1.491595ms | GET /movies/ user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:33:36 | 200 |    12.22773ms |    192.168.64.1 | GET      "/v1/movies/?pagesz=5"
appserver_1   | 05:33:36.307PM UTC INF --> POST:/movies/ user=jdoe@example.com
appserver_1   | 05:33:36.31PM UTC INF <--  | 201 |    2.783365ms | POST /movies/ user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:33:36 | 201 |    7.054462ms |    192.168.64.1 | POST     "/v1/movies/"
appserver_1   | 05:33:36.315PM UTC INF --> GET:/movies/c42c855c-355e-4c3e-9d7a-9809ff84a73b user=jdoe@example.com
appserver_1   | 05:33:36.316PM UTC INF <--  | 200 |     492.584µs | GET /movies/c42c855c-355e-4c3e-9d7a-9809ff84a73b user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:33:36 | 200 |    5.304569ms |    192.168.64.1 | GET      "/v1/movies/c42c855c-355e-4c3e-9d7a-9809ff84a73b"
appserver_1   | 05:33:36.32PM UTC INF --> PUT:/movies/c42c855c-355e-4c3e-9d7a-9809ff84a73b user=jdoe@example.com
appserver_1   | 05:33:36.322PM UTC INF <--  | 200 |    1.540190ms | PUT /movies/c42c855c-355e-4c3e-9d7a-9809ff84a73b user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:33:36 | 200 |    5.869164ms |    192.168.64.1 | PUT      "/v1/movies/c42c855c-355e-4c3e-9d7a-9809ff84a73b"
appserver_1   | 05:33:36.322PM UTC INF --> GET:/movies/ user=jdoe@example.com
appserver_1   | 05:33:36.323PM UTC INF <--  | 200 |     305.407µs | GET /movies/ user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:33:36 | 200 |      709.97µs |    192.168.64.1 | GET      "/v1/movies/?year=1997&pagesz=5"
appserver_1   | 05:33:36.327PM UTC INF --> DELETE:/movies/c42c855c-355e-4c3e-9d7a-9809ff84a73b user=jdoe@example.com
appserver_1   | 05:33:36.328PM UTC INF <--  | 200 |    0.788368ms | DELETE /movies/c42c855c-355e-4c3e-9d7a-9809ff84a73b user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:33:36 | 200 |    4.860383ms |    192.168.64.1 | DELETE   "/v1/movies/c42c855c-355e-4c3e-9d7a-9809ff84a73b"

BASIC AUTH ENABLED(PLUGIN ENABLED in KRAKEND, CHECK ENABLED IN BACKEND SERVICE)
-------------------------------------------------------------------------------------
appserver_1   | 05:54:35.62PM UTC INF --> GET:/movies/ user=jdoe@example.com
appserver_1   | 05:54:35.622PM UTC INF <--  | 200 |    2.086901ms | GET /movies/ user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:54:35 | 200 |   13.698516ms |   192.168.192.1 | GET      "/v1/movies/?pagesz=5"
appserver_1   | 05:54:35.628PM UTC INF --> POST:/movies/ user=jdoe@example.com
appserver_1   | 05:54:35.639PM UTC INF <--  | 201 |   11.464611ms | POST /movies/ user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:54:35 | 201 |   16.827376ms |   192.168.192.1 | POST     "/v1/movies/"
appserver_1   | 05:54:35.644PM UTC INF --> GET:/movies/edc29272-f964-4c52-8b2d-b1693bec5eb1 user=jdoe@example.com
appserver_1   | 05:54:35.646PM UTC INF <--  | 200 |    1.483731ms | GET /movies/edc29272-f964-4c52-8b2d-b1693bec5eb1 user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:54:35 | 200 |    6.269109ms |   192.168.192.1 | GET      "/v1/movies/edc29272-f964-4c52-8b2d-b1693bec5eb1"
appserver_1   | 05:54:35.651PM UTC INF --> PUT:/movies/edc29272-f964-4c52-8b2d-b1693bec5eb1 user=jdoe@example.com
appserver_1   | 05:54:35.654PM UTC INF <--  | 200 |    2.390241ms | PUT /movies/edc29272-f964-4c52-8b2d-b1693bec5eb1 user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:54:35 | 200 |    7.200873ms |   192.168.192.1 | PUT      "/v1/movies/edc29272-f964-4c52-8b2d-b1693bec5eb1"
appserver_1   | 05:54:35.655PM UTC INF --> GET:/movies/ user=jdoe@example.com
appserver_1   | 05:54:35.656PM UTC INF <--  | 200 |    1.393513ms | GET /movies/ user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:54:35 | 200 |    2.072955ms |   192.168.192.1 | GET      "/v1/movies/?year=1997&pagesz=5"
appserver_1   | 05:54:35.661PM UTC INF --> DELETE:/movies/edc29272-f964-4c52-8b2d-b1693bec5eb1 user=jdoe@example.com
appserver_1   | 05:54:35.663PM UTC INF <--  | 200 |    2.049350ms | DELETE /movies/edc29272-f964-4c52-8b2d-b1693bec5eb1 user=jdoe@example.com
apigateway_1  | [GIN] 2022/04/06 - 17:54:35 | 200 |    6.783411ms |   192.168.192.1 | DELETE   "/v1/movies/edc29272-f964-4c52-8b2d-b1693bec5eb1"

load tests can't be based just on 4 or 5 requests. In order to get significant figures, you should use more elaborate benchmarks. I'd use tools such as https://github.com/tsenart/vegeta with a set of different request and payloads in order to get a more reliable throughput metric for the gateway

on the other hand, if you found some issue with the plugin injector/mw, please let us know what your plugin was doing so we can reproduce the scenario and tackle it

Mucho gracias Senor for the pointer on vegeta. I'll check it out.

Meanwhile, I've created issue #472 for the intermittent 405 error. It seems to happen on endpoints of the form /v1/movies/{id} about 1 in 5 tries.

This issue was marked as resolved a long time ago and now has been automatically locked as there has not been any recent activity after it. You can still open a new issue and reference this link.

krakend / krakend-ce

Poor performance when using request modifier plugin #468