Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

High Latency with id_token mutator and RS256 keys #364

Closed
paulbdavis opened this issue Feb 19, 2020 · 8 comments
Closed

High Latency with id_token mutator and RS256 keys #364

paulbdavis opened this issue Feb 19, 2020 · 8 comments

Comments

@paulbdavis
Copy link
Contributor

Describe the bug

I am having latency issues, presumably from signing the jwt for the id token?

Reproducing the bug

Oathkeeper rule

    [
      {
        "upstream": {
          "url": "http://devteam-gateway:8080",
          "preserve_host": false
        },
        "id": "backoffice-read-lists.devteam-dev",
        "match": {
          "url": "\u003chttps?\u003e://devteam.dev.myco.com/\u003c.*\u003e",
          "methods": [
            "GET",
            "POST",
            "PUT",
            "PATCH",
            "DELETE"
          ]
        },
        "authenticators": [
          {
            "handler": "oauth2_introspection",
            "config": {
              "introspection_request_headers": {
                "x-forwarded-proto": "https"
              },
              "introspection_url": "http://devteam-ory-hydra-admin:4445/oauth2/introspect"
            }
          }
        ],
        "authorizer": {
          "handler": "allow",
          "config": {}
        },
        "mutators": [
          {
            "handler": "id_token",
            "config": {
              "issuer_url": "http://devteam-ory-oathkeeper-proxy",
              "jwks_url": "file:///etc/secrets/mutator.id_token.jwks.json"
            }
          }
        ],
        "configMapName": "devteam-ory-oathkeeper-rules"
      }
    ]

Server logs

(in this instance it did not add too much, but it varies from 300-1500 ms generally, much higher when multiple requests come in at once)

time="2020-02-19T20:23:47Z" level=info msg="started handling request" method=GET remote=*** request=/user request_id=9178d863f830c0d35fb0f7a5f716d17e
time="2020-02-19T20:23:47Z" level=warning msg="Access request granted" granted=true http_host="devteam-gateway:8080" http_method=GET http_url="http://devteam-gateway:8080/user" http_user_agent="Mozilla/5.0 (X11; Linux x86_64; rv:73.0) Gecko/20100101 Firefox/73.0" subject="myco.com:subjects:admins:1"
time="2020-02-19T20:23:47Z" level=info msg="completed handling request" measure#oathkeeper-proxy.latency=273220929 method=GET remote=*** request=/user request_id=9178d863f830c0d35fb0f7a5f716d17e status=200 text_status=OK took=273.220929ms

Server configuration

Oathkeeper config (configmap)

    access_rules:
      repositories:
      - file:///etc/rules/access-rules.json
    authenticators:
      oauth2_introspection:
        config:
          introspection_url: http://noop
        enabled: true
    authorizers:
      allow:
        enabled: true
      keto_engine_acp_ory:
        config:
          base_url: http://noop
          flavor: glob
          required_action: myco.com:read:$1
          required_resource: myco.com:$1:$2
        enabled: true
    mutators:
      header:
        config:
          headers:
            x-subject: '{{ print .Subject}}'
            x-user-id: '{{ print .Extra.admin_id }}'
            x-username: '{{ print .Extra.admin_username }}'
        enabled: true
      id_token:
        config:
          claims: |
            { "admin_id":"{{ print .Extra.admin_id }}", "admin_username": "{{ print .Extra.admin_username }}", "user_id":"{{ print .Extra.user_id }}", "user_phone": "{{ print .Extra.user_phone }}
" }
          issuer_url: http://noop
          jwks_url: file:///etc/secrets/mutator.id_token.jwks.json
        enabled: true
      noop:
        enabled: true
    serve:
      api:
        port: 4456
      proxy:
        port: 4455

Environment

  • Version: Docker image oryd/oathkeeper:v0.36.0-beta.4
  • Environment: k8s

Additional context
top 10 from cpu profile for a single proxied request

      flat  flat%   sum%        cum   cum%
      50ms 20.00% 20.00%       50ms 20.00%  math/big.addMulVVW
      40ms 16.00% 36.00%       70ms 28.00%  strconv.appendEscapedRune
      30ms 12.00% 48.00%      100ms 40.00%  strconv.appendQuotedWith
      20ms  8.00% 56.00%       20ms  8.00%  runtime.memmove
      10ms  4.00% 60.00%      180ms 72.00%  fmt.(*pp).printValue
      10ms  4.00% 64.00%       30ms 12.00%  internal/fmtsort.compare
      10ms  4.00% 68.00%       10ms  4.00%  reflect.(*MapIter).Value
      10ms  4.00% 72.00%       10ms  4.00%  reflect.Value.String
      10ms  4.00% 76.00%       10ms  4.00%  reflect.Value.Type
      10ms  4.00% 80.00%       10ms  4.00%  runtime.findObject

for multiple requests

Showing top 10 nodes out of 104
      flat  flat%   sum%        cum   cum%
     2.86s 85.37% 85.37%      2.86s 85.37%  math/big.addMulVVW
     0.15s  4.48% 89.85%      3.02s 90.15%  math/big.nat.montgomery
     0.05s  1.49% 91.34%      0.08s  2.39%  strconv.appendEscapedRune
     0.03s   0.9% 92.24%      0.03s   0.9%  runtime.memmove
     0.02s   0.6% 92.84%      0.02s   0.6%  runtime.memequal
     0.02s   0.6% 93.43%      0.03s   0.9%  runtime.scanobject
     0.02s   0.6% 94.03%      0.10s  2.99%  strconv.appendQuotedWith
     0.01s   0.3% 94.33%      0.02s   0.6%  encoding/asn1.parseField
     0.01s   0.3% 94.63%      0.03s   0.9%  internal/fmtsort.compare
     0.01s   0.3% 94.93%      0.03s   0.9%  runtime.mallocgc
@aeneasr
Copy link
Member

aeneasr commented Feb 19, 2020

May I ask what the JWKs key type you're using and also how many bits (e.g. RS256 with 2048 bit entropy)?

@aeneasr
Copy link
Member

aeneasr commented Feb 19, 2020

It would also be helpful if you could create a call graph, that way it's easier to debug. It looks like this is caused by the signing algorithm though (because math/big).

You can do that on the existing data file you have, more info: https://blog.golang.org/profiling-go-programs

@paulbdavis
Copy link
Contributor Author

The jwks key is generated with the following code:

package main

import (
	"encoding/json"
	"fmt"
	"os"

	"github.com/ory/hydra/jwk"
)

func main() {

	if len(os.Args) != 2 {
		fmt.Println("key name argument required")
		os.Exit(1)
	}
	gen := jwk.RS256Generator{}

	ks, err := gen.Generate(os.Args[1], "sig")
	if err != nil {
		panic(err)
	}

	enc := json.NewEncoder(os.Stdout)
	// enc.SetIndent("", "  ")
	if err := enc.Encode(ks); err != nil {
		panic(err)
	}

}

pprof

@aeneasr
Copy link
Member

aeneasr commented Feb 19, 2020

@aeneasr aeneasr changed the title High Latency with id_token mutator High Latency with id_token mutator and RS256 keys Feb 19, 2020
@aeneasr
Copy link
Member

aeneasr commented Feb 19, 2020

Ok, looked into this a bit more. It's generally recommended to use P256 as that is implemented in ASM in Go, as opposed to RSA which is written in Go. We can definitely improve performance with some caching (same session gives same JWT until it expires).

I'll write a patch that makes use of caching to tackle this.

@aeneasr aeneasr closed this as completed in 47e9fee Mar 5, 2020
@aeneasr
Copy link
Member

aeneasr commented Mar 5, 2020

Hi Paul, I pushed a fix to master just now. The latency was greatly (I think factor was in the thousands :) ) reduced in the benchmarks. I generally recommend using ECDSA as it is faster than RSA and with the new caching even more so but both RSA and ECDSA should get same performance results.

@aeneasr
Copy link
Member

aeneasr commented Mar 5, 2020

Can you maybe check it out and see how it behaves? I will release a new version probably next week once some more PRs are merged.

@paulbdavis
Copy link
Contributor Author

@aeneasr I should have a chance to check that out in the next week or so, I'll report back.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants