https://www.ory.com/ logo
Join Slack
Powered by
probably makes sense to get tracing to work first,...
# contributors
h
probably makes sense to get tracing to work first, then you can check out why performance is worse?
s
Friday evening I could produce several postgresql query duration log files using the master and the migrate_to_pop branches. I'm now checking if I can point out something from those logs without tracing
h
awesome 🙂
s
@high-optician-2097 A quick stat about SQL queries. This shows the number of queries finished within a given time
h
ok so individual queries are slower?
in pop
s
However lot more of queries finished on master within certain amount of time I think it doesn't completely explain the huge difference in response time increase
I haven't checked the pop usage in hydra so just asking: does it use connection pooling?
Create connection to DB could easily explain the huge increase what I could experience in API level testing
I've experienced a significant hydra API response time decrease after increased connection pool from 50 to 250
or maybe connection string parameters have been changed?
h
hm
my gut says yes to connection pooling
ahhhh yes
I found a replacement statement at the end of the go.mod - current hydra master uses jackc/pgx and current pop master also, but it seems like we’re using a fixed git hash which might still be using lib/pg instead of jackc/pgx
the jackc driver is much better - this might explain the issue
if you remove the “replace” statement at the bottom of the go.mod file and retry, you might get better results
s
will test it
h
thank you!
s
the replacement was due to this https://github.com/gobuffalo/pop/pull/594 not beeing released yet
but yea, that replacement results in lib/pg being used instead of jackc/pgx
I've setup a branch that uses the latest pop release https://github.com/ory/hydra/tree/next-sql-performance-test but expect there to be some bugs as it is missing some of my fixes. That should use jackc/pgx
s
Thanks, testing of this will be my first task tomorrow
h
s
Cool, great job!
@steep-lamp-91158 I rebased to next-sql-performance-test and wanted to start testing. a) when started this new version after master version - so that DB was already initialized - I've received the following error:
Copy code
time=2020-10-13T07:44:19Z level=error msg=An error occurred audience=application error=map[message:ERROR: column "id" of relation "hydra_oauth2_authentication_request" does not exist (SQLSTATE 42703)] http_request=map[headers:map[accept:*/* user-agent:python-requests/2.24.0 x-forwarded-for:192.168.1.23,100.100.33.64 x-forwarded-proto:https x-request-id:821c3dff-51a2-47e2-b7e6-f8b83d52c47f] host:<http://szilard-stange.devtenant.strivacity.com|szilard-stange.devtenant.strivacity.com> method:GET path:/oauth2/auth query:Value is sensitive and has been redacted. To see the value set config key "log.leak_sensitive_values = true" or environment variable "LOG_LEAK_SENSITIVE_VALUES=true". remote:127.0.0.1:50002 scheme:http]
b) then I've started this new version with a clean psql database which resulted the following
Copy code
time=2020-10-13T07:54:08Z level=warning msg=JSON Web Key Set "hydra.openid.id-token" does not exist yet, generating new key pair... audience=application service_name= service_version=
time=2020-10-13T07:54:09Z level=fatal msg=Could not ensure that signing keys for "hydra.openid.id-token" exists. If you are running against a persistent SQL database this is most likely because your "secrets.system" ("SECRETS_SYSTEM" environment variable) is not set or changed. When running with an SQL database backend you need to make sure that the secret is set and stays the same, unless when doing key rotation. This may also happen when you forget to run "hydra migrate sql".. audience=application error=map[message:Could not persist JSON Web Key Set "hydra.openid.id-token".: ERROR: column "id" does not exist (SQLSTATE 42703)] service_name= service_version=
SECRETS_SYSTEM is set and haven't changed Did I miss something or made a mistake on my side (which is possible of course 🙂 ) or is there an issue on this branch?
h
@swift-secretary-83973 maybe it’s a problem with the branch. I fixed the tracing issue (it works now) and a few more other things. the PR is: https://github.com/ory/hydra/pull/2129 I recommend tearing down the test env and restarting it to ensure that everything works. Also what DB were you using here?
hm yeah, I see similar problems:
Copy code
hydra_1          | time=2020-10-13T08:13:49Z level=info msg=Jaeger tracer configured! audience=application service_name= service_version=
hydra_1          | time=2020-10-13T08:13:49Z level=warning msg=JSON Web Key Set "hydra.openid.id-token" does not exist yet, generating new key pair... audience=application service_name= service_version=
postgresd_1      | ERROR:  syntax error at or near "," at character 85
postgresd_1      | STATEMENT:  INSERT INTO "hydra_jwk" ("created_at", "keydata", "kid", "sid", "version") VALUES (?, ?, ?, ?, ?) returning pk
hydra_1          | time=2020-10-13T08:13:55Z level=fatal msg=Could not ensure that signing keys for "hydra.openid.id-token" exists. If you are running against a persistent SQL database this is most likely because your "secrets.system" ("SECRETS_SYSTEM" environment variable) is not set or changed. When running with an SQL database backend you need to make sure that the secret is set and stays the same, unless when doing key rotation. This may also happen when you forget to run "hydra migrate sql".. audience=application error=map[message:Could not persist JSON Web Key Set "hydra.openid.id-token".: ERROR: syntax error at or near "," (SQLSTATE 42601)] service_name= service_version=
s
I'm using psql now
h
hm so it seems to be a problem with tracing somehow. without tracing, there is no syntax error
not quite sure what the problem is..
s
I can confirm, reverted that commit resolved the issue here also
@high-optician-2097 are you using latest pop on sql-next branch? (the one that uses the new psql lib) because the performance of the sql-next branch is still ~40-50 % slower than the master
s
yes, that uses the other driver last update we had on that branch was 5h ago, check that your's is up to date locally 😉
s
I think I'm using the latest one, commit id is 15d1dfa
s
hm damn, I think we will have to do some performance optimization then
s
It seems my version doesn't use the other driver as I had to revert feat: add support for instrumentation because it produces the above startup issue for me (experienced by @high-optician-2097 also) and it seems that this commit contains the switch to the other driver. So with that driver it could be faster but I still couldn't start the testing with that
s
I see, @high-optician-2097 is working on a fix
h
yeah trying to figure it out..quite tricky unfortunately
s
@high-optician-2097 @steep-lamp-91158 I've made further comparison of master and sql-next branch but just turned off tracing in registry_sql.go instead of reverting that patch. The numbers in the filename represents the max pool and max idle pool. It seems that • sql-next branch is slower if pool setting is lower (maybe because this branch uses transaction which "locks" a connection for longer time) • after increased the pool/idlepool then overall auth/s seems equal with the master branch • with increased connection pool parameters still response time of some of the hydra queries are higher: the initial /oauth2/auth, the /oath2/auth call after login provider, and get login session and accept consents in the consent provider
s
thanks for all your valuable evaluation, really appreciate 👏 we will discuss how we best approach this and will sum everything up in an issue we will mention you there so you get a notification
h
@swift-secretary-83973 I’ll be working now on the instrumentation bug in the most recent commit again
👍 1
s
so https://github.com/ory/hydra/pull/2131 reverts all additional transactions, let's see if that was the problem
the isolation level is definitely only elevated where it is on the current master as well
s
@steep-lamp-91158 Slightly better but still bigger response time compared to master. However I'm still checking to make sure it's not affected by our environment
50/10 and 200/200 are the sql connection pool settings
s
in my opinion it would now have to have a very similar performance, as all sql requests are basically the same we will have to wait for tracing to prove it but we basically have a) the same driver b) same isolation level and c) same transaction usage as before maybe there is also some other bottleneck
but it looks like increasing the connection pool with the less transaction branch actually worsens the performance slightly now?
s
I've made further tests. We are using pgpool on top of postgresql and it seems increased response times mostly occured because of pgpool. I still don't understand why but after removed pgpool and talking directly to postgre then it's close to master performance, however still there is difference in the response time of hydra related endpoints (eg. first and last four on the list)
@steep-lamp-91158 I went over a 
PUT /oauth2/auth/requests/consent/accept
request details. It took 285ms to serve. From this 285ms * ~57ms spent in handler.goAcceptConsentRequest 
cr, err := h.r.ConsentManager().GetConsentRequest(r.Context(), challenge)
* ~227ms spent in handler.goAcceptConsentRequest 
hr, err := h.r.ConsentManager().HandleConsentRequest(r.Context(), challenge, &p)
Further checking 
h.r.ConsentManager().HandleConsentRequest(r.Context(), challenge, &p)
call in persister_consent.goHandleConsentRequest The ~227ms composed from these items: * ~180ms spent in 
err := sqlcon.HandleError(c.Create(r))
* ~26ms in 
return p.GetConsentRequest(ctx, challenge)
and here is the relevant SQL side log for Create:
Copy code
2020-10-15T14:01:32+02:00 {} 2020-10-15 12:01:32.031 GMT [12139] LOG:  duration: 0.083 ms  bind pgx_3707: INSERT INTO "hydra_oauth2_consent_request_handled" ("authenticated_at", "challenge", "error", "granted_at_audience", "granted_scope", "handled_at", "remember", "remember_for", "requested_at", "session_access_token", "session_id_token", "was_used") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12)
2020-10-15T14:01:32+02:00 {} 2020-10-15 12:01:32.031 GMT [12139] DETAIL:  parameters: $1 = NULL, $2 = 'f73dbf2e65ef4c229aaed81b301de9d6', $3 = '{}', $4 = '', $5 = 'openid', $6 = '2020-10-15 12:01:31.96667', $7 = 'f', $8 = '0', $9 = '2020-10-15 12:01:26.391577', $10 = 'null', $11 = '{"client_id":"d57cf01c0bfb4be5a40c211ec58db421","user_id":"2628deb7-2ee4-43f7-a4c8-a7134e798fc4","username":"bd87645d"}', $12 = 'f'
2020-10-15T14:01:32+02:00 {} 2020-10-15 12:01:32.031 GMT [12139] LOG:  duration: 0.126 ms  execute pgx_3707: INSERT INTO "hydra_oauth2_consent_request_handled" ("authenticated_at", "challenge", "error", "granted_at_audience", "granted_scope", "handled_at", "remember", "remember_for", "requested_at", "session_access_token", "session_id_token", "was_used") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12)
2020-10-15T14:01:32+02:00 {} 2020-10-15 12:01:32.031 GMT [12139] DETAIL:  parameters: $1 = NULL, $2 = 'f73dbf2e65ef4c229aaed81b301de9d6', $3 = '{}', $4 = '', $5 = 'openid', $6 = '2020-10-15 12:01:31.96667', $7 = 'f', $8 = '0', $9 = '2020-10-15 12:01:26.391577', $10 = 'null', $11 = '{"client_id":"d57cf01c0bfb4be5a40c211ec58db421","user_id":"2628deb7-2ee4-43f7-a4c8-a7134e798fc4","username":"bd87645d"}', $12 = 'f'
So that SQL side seems fast and it lost the remaining eg. ~179ms somewhere between... (the flow includes other services also and I didn't experience such huge response time between other services just between Hydra's Create call and PostgreSQL db) Do you have a quick idea how can I make sure that it uses connection pooling? I've configured that via DSN but not using connection pooling could easily explain that response time.
s
the connection is created here: https://github.com/ory/hydra/blob/sql-tx-isolation/driver/registry_sql.go#L71-L78 you might add some hardcoded values there for testing
s
it seems it was using connection pooling
I would hate to dig into the pop layer to determine if the issue is related to that or in the environment but I'm afraid I have no other choice... 🙂
s
I feel you, we have the same fate when we fix the tracing bug tomorrow...
h
@swift-secretary-83973 I think the response times are generally pretty high. It would be interesting to see what’s causing them to be that slow - and once identified it would be my priority to improve that also!
s
It's generally high because I was lazy and were running pertests remotely, 10000 km far away from the clusters 🙂 So there is a "base" response times because of that. However if there is a significant peak on a specific APIs then we can see it also just need to compare the response times to the other APIs response times.
h
Ahhh ok I see!
So I found the tracing issue, resolving it atm
It was a pretty dumb oversight on my part. We rename the driver for instrumentation and 
sqlx
simply fails to detect what database type we’re dealing with because the driver name is 
instrumented-postgres
. That causes 
sqlx.Rebind
to fail which would usually translate 
?
to 
$1
SQL arguments
s
oh, nice catch I'm now adding dumb "tracing" to a local copy of pop and continue checking where is the missing 180ms 🙂
h
Nice 🙂 My gut says it’s just network latency from the db to your local instance
s
I have the same feeling but I don't understand how it could happen. All services are located in the same k8s cluster and I haven't experienced such high latency between other services eg. between our login provider ad hydra, ... However I think you can move forward with the pop migration as it's already confirmed that SQL side queries are not the root cause of these, with less transactions fix the response times are not that higher even with lower connection pool settings. Then if I can point out something that is related to pop not to my infra then we can file an another PR
h
ok sounds good 🙂
s
@steep-lamp-91158 @high-optician-2097 finally I think I have a conclusion... The "missing" 180ms was connection pool related if there was no enough open connection in the pool and/or postgre reached the max open connection. In the test I had 200 max. conn in hydra and 200 max on postgres side (other admin services are using ~10 conns) and it seems master never reached the max settings but sql-next does so that 200+10 was over the postgre side max. which caused some of the queries had to wait longer. So it seems the new branch requires a slightly higher connection pool settings to achieve the same performance/response times but apart from that it works like a charm. The difference was higher between the branches if the max_idle_conns settings was higher but that was easy to "fix" in the configuration.
h
hm ok that’s interesting! could you quickly (remove the host of course and pw user) post the two DSNs?
tracing works now
👏 1
s
postgres://<redacted>:5432/hydra?sslmode=disable&max_conns=50&max_idle_conns=10&max_conn_lifetime=1h
-> sql-next produces sligtly longer response times 
postgres://<redacted>:5432/hydra?sslmode=disable&max_conns=50&max_idle_conns=50&max_conn_lifetime=1h
-> perf of master and sql-next seems the same 
postgres://<redacted>:5432/hydra?sslmode=disable&max_conns=200&max_idle_conns=200&max_conn_lifetime=1h
-> perf of master and sql-next seems the same IF PostgreSQL has at least 200 free connection. If PostgreSQL side there is only ~190 free connection then sql-next branch produces a slightly longer response times compared to master.
h
ok cool, thank you for the details! I just pushed my changes to https://github.com/ory/hydra/pull/2129
Copy code
make docker; docker tag oryd/hydra:latest-sqlite oryd/hydra:v1.8.5; docker tag oryd/hydra:latest-sqlite oryd/hydra:v1.8.5-sqlite
 docker-compose -f quickstart.yml -f quickstart-tracing.yml -f quickstart-postgres.yml up
this brings up the quickstart environment with postgres if you want to test locally
Open in Slack
PreviousNext
Powered by