Users-search-filter test report Honeysuckle
https://folio-org.atlassian.net/browse/PERF-130
Overview
The purpose of this test is to define system behavior under load with user-search-filter workflow.
During test we find that weak point of this workflow is resource usage, more specifically it's CPU usage on DataBase side.
Version
mod-users:17.2.1
okapi:4.2.2
Test
Test # | Virtual Users | Duration (sec) |
|---|---|---|
1 | 5 | 1800 |
2 | 8 | 1800 |
Results
Test 1
Response times:
Requests | Total | Response times (seconds) | |||||
Min | 50th pct | 75th pct | 95th pct | 99th pct | Max | ||
|---|---|---|---|---|---|---|---|
authn/login HTTP Request | 1 | 0.293 | 0.293 | 0.293 | 0.293 | 0.293 | 0.293 |
GET_/Departments | 931 | 0.015 | 0.023 | 0.027 | 0.058 | 0.689 | 1.441 |
GET_/groups?limit=40 sortby group | 931 | 0.022 | 0.031 | 0.038 | 0.087 | 0.588 | 3.063 |
GET_/tags | 931 | 0.015 | 0.022 | 0.025 | 0.036 | 0.086 | 9.527 |
GET_/users?limit=100 offset=100 query=(active="true") | 929 | 2.905 | 4.751 | 5.018 | 5.472 | 5.883 | 9.457 |
GET_/users?limit=100 query=(active="true") | 931 | 2.299 | 4.749 | 4.961 | 5.347 | 5.786 | 6.700 |
User transaction | 929 | 7.335 | 9.625 | 9.996 | 10.682 | 11.393 | 21.193 |
Service CPU usage
Most used modules:
Mod-Users - 14-15% (default usage 3%);
Mod-OKAPI - 12-13% (default usage 4%).
Service RAM usage
There's no visible memory usage for any of modules.
DB CPU usage
as you may see from screenshots below, there's high CPU usage caused by (according to performance insights) slow query SELECT jsonb,id from <tenant>_mod_users_users
Database load by wait
Database load by SQL
According to RDS performance insights to wait is CPU and it's 3.63 seconds.
Test 2
Response times:
Requests | Total | Response times (seconds) | |||||
Min | 50th pct | 75th pct | 95th pct | 99th pct | Max | ||
|---|---|---|---|---|---|---|---|
authn/login HTTP Request | 1 | 0.257 | 0.257 | 0.257 | 0.257 | 0.257 | 0.257 |
GET_/Departments | 890 | 0.016 | 0.034 | 0.400 | 3.919 | 5.652 | 6.781 |
GET_/groups?limit=40 sortby group | 890 | 0.024 | 0.053 | 0.541 | 3.815 | 5.241 | 8.141 |
GET_/tags | 890 | 0.016 | 0.028 | 0.037 | 0.082 | 0.353 | 1.785 |
GET_/users?limit=100 offset=100 query=(active="true") | 887 | 3.223 | 7.292 | 8.005 | 10.384 | 12.315 | 14.151 |
GET_/users?limit=100 query=(active="true") | 890 | 3.808 | 7.175 | 7.997 | 10.390 | 12.096 | 13.721 |
User transaction | 887 | 9.615 | 15.884 | 17.944 | 21.010 | 22.903 | 26.565 |
Services CPU usage:
Services memory usage:
As in previous sample memory usage are not visible for relevant modules (mod-users. and okapi-b);
DB CPU usage:
DB load bu waits:
DB load by sql:
According to RDS performance insights to wait is CPU and it's 5.25 seconds.
Errors in logs:
2020-11-09 09:54:00.310,"09:54:00 ERROR PostgresClient query with count: function supertenant_mod_users.count_estimate(unknown) does not exist - SELECT supertenant_mod_users.count_estimate('SELECT * FROM supertenant_mod_users.users WHERE (lower(f_unaccent(users.jsonb->>''active'')) LIKE lower(f_unaccent(''true''))) AND (CASE WHEN length(''2020-11-09T09:54:00.309Z'') <= 600 THEN left(users.jsonb->>''expirationDate'',600) < ''2020-11-09T09:54:00.309Z'' ELSE left(users.jsonb->>''expirationDate'',600) < left(''2020-11-09T09:54:00.309Z'',600) AND users.jsonb->>''expirationDate'' <= ''2020-11-09T09:54:00.309Z'' END)')"
2020-11-09 09:54:00.310,io.vertx.pgclient.PgException: function supertenant_mod_users.count_estimate(unknown) does not exist
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.ErrorResponse.toException(ErrorResponse.java:29) ~[ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.QueryCommandBaseCodec.handleErrorResponse(QueryCommandBaseCodec.java:57) ~[ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.PgDecoder.decodeError(PgDecoder.java:236) ~[ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.PgDecoder.decodeMessage(PgDecoder.java:122) [ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.PgDecoder.channelRead(PgDecoder.java:102) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [ms.jar:?]
2020-11-09 09:54:00.310, at java.lang.Thread.run(Thread.java:834) [?:?]
2020-11-09 09:54:00.310,"09:54:00 ERROR ExpirationTool Error executing postgres query for tenant supertenant: 'active == true AND expirationDate < 2020-11-09T09:54:00.309Z', function supertenant_mod_users.count_estimate(unknown) does not exist"
2020-11-09 09:54:00.310,io.vertx.pgclient.PgException: function supertenant_mod_users.count_estimate(unknown) does not exist
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.ErrorResponse.toException(ErrorResponse.java:29) ~[ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.QueryCommandBaseCodec.handleErrorResponse(QueryCommandBaseCodec.java:57) ~[ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.PgDecoder.decodeError(PgDecoder.java:236) ~[ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.PgDecoder.decodeMessage(PgDecoder.java:122) [ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.PgDecoder.channelRead(PgDecoder.java:102) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [ms.jar:?]
2020-11-09 09:54:00.310, at java.lang.Thread.run(Thread.java:834) [?:?]
2020-11-09 09:54:00.310,09:54:00 ERROR ExpirationTool Attempt to expire records for tenant supertenant failed: function supertenant_mod_users.count_estimate(unknown) does not exist
2020-11-09 09:54:00.310,io.vertx.pgclient.PgException: function supertenant_mod_users.count_estimate(unknown) does not exist
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.ErrorResponse.toException(ErrorResponse.java:29) ~[ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.QueryCommandBaseCodec.handleErrorResponse(QueryCommandBaseCodec.java:57) ~[ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.PgDecoder.decodeError(PgDecoder.java:236) ~[ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.PgDecoder.decodeMessage(PgDecoder.java:122) [ms.jar:?]
2020-11-09 09:54:00.310, at io.vertx.pgclient.impl.codec.PgDecoder.channelRead(PgDecoder.java:102) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [ms.jar:?]
2020-11-09 09:54:00.310, at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [ms.jar:?]
2020-11-09 09:54:00.310, at java.lang.Thread.run(Thread.java:834) [?:?]