Slow key loading in hashicorp

[jframe]

There has been a degradation in the key loading times for Web3Signer as of 9cc5008. Previously is loaded 100 keys per second, now it is only 10 keys per second.

Current performance of hashicorp key loading as of 9cc5, 10 keys in a second:
2023-05-11 14:22:31.156+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1060 signing metadata processed 2023-05-11 14:22:32.142+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1070 signing metadata processed 2023-05-11 14:22:33.137+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1080 signing metadata processed 2023-05-11 14:22:34.249+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1090 signing metadata processed 2023-05-11 14:22:35.446+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1100 signing metadata processed 2023-05-11 14:22:36.689+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1110 signing metadata processed 2023-05-11 14:22:37.827+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1120 signing metadata processed 2023-05-11 14:22:38.868+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1130 signing metadata processed 2023-05-11 14:22:39.958+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1140 signing metadata processed 2023-05-11 14:22:40.991+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1150 signing metadata processed 2023-05-11 14:22:41.991+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1160 signing metadata processed 2023-05-11 14:22:42.956+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1170 signing metadata processed 2023-05-11 14:22:43.922+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1180 signing metadata processed 2023-05-11 14:22:44.892+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1190 signing metadata processed 2023-05-11 14:22:45.868+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1200 signing metadata processed 2023-05-11 14:22:46.858+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1210 signing metadata processed 2023-05-11 14:22:47.833+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1220 signing metadata processed 2023-05-11 14:22:48.810+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1230 signing metadata processed 2023-05-11 14:22:49.790+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1240 signing metadata processed 2023-05-11 14:22:50.757+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1250 signing metadata processed 2023-05-11 14:22:51.730+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1260 signing metadata processed 2023-05-11 14:22:52.711+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1270 signing metadata processed 2023-05-11 14:22:53.706+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1280 signing metadata processed 2023-05-11 14:22:54.692+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1290 signing metadata processed 2023-05-11 14:22:55.667+00:00 | pool-2-thread-1 | INFO | SignerLoader | 1300 signing metadata processed

Previous performance loading 100 keys per second:
2023-05-11 14:29:51.374+00:00 | ForkJoinPool-1-worker-4 | INFO | SignerLoader | 10 metadata configuration files processed 2023-05-11 14:29:51.652+00:00 | ForkJoinPool-1-worker-3 | INFO | SignerLoader | 20 metadata configuration files processed 2023-05-11 14:29:51.952+00:00 | ForkJoinPool-1-worker-4 | INFO | SignerLoader | 30 metadata configuration files processed 2023-05-11 14:29:52.220+00:00 | ForkJoinPool-1-worker-3 | INFO | SignerLoader | 40 metadata configuration files processed 2023-05-11 14:29:52.494+00:00 | ForkJoinPool-1-worker-1 | INFO | SignerLoader | 50 metadata configuration files processed 2023-05-11 14:29:52.760+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 60 metadata configuration files processed 2023-05-11 14:29:53.030+00:00 | ForkJoinPool-1-worker-3 | INFO | SignerLoader | 70 metadata configuration files processed 2023-05-11 14:29:53.273+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 80 metadata configuration files processed 2023-05-11 14:29:53.542+00:00 | ForkJoinPool-1-worker-4 | INFO | SignerLoader | 90 metadata configuration files processed 2023-05-11 14:29:53.814+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 100 metadata configuration files processed 2023-05-11 14:29:54.083+00:00 | ForkJoinPool-1-worker-4 | INFO | SignerLoader | 110 metadata configuration files processed 2023-05-11 14:29:54.329+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 120 metadata configuration files processed 2023-05-11 14:29:54.583+00:00 | ForkJoinPool-1-worker-4 | INFO | SignerLoader | 130 metadata configuration files processed 2023-05-11 14:29:54.879+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 140 metadata configuration files processed 2023-05-11 14:29:55.131+00:00 | ForkJoinPool-1-worker-1 | INFO | SignerLoader | 150 metadata configuration files processed 2023-05-11 14:29:55.382+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 160 metadata configuration files processed 2023-05-11 14:29:55.636+00:00 | ForkJoinPool-1-worker-4 | INFO | SignerLoader | 170 metadata configuration files processed 2023-05-11 14:29:55.906+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 180 metadata configuration files processed 2023-05-11 14:29:56.129+00:00 | ForkJoinPool-1-worker-4 | INFO | SignerLoader | 190 metadata configuration files processed 2023-05-11 14:29:56.386+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 200 metadata configuration files processed 2023-05-11 14:29:56.622+00:00 | ForkJoinPool-1-worker-4 | INFO | SignerLoader | 210 metadata configuration files processed 2023-05-11 14:29:56.852+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 220 metadata configuration files processed 2023-05-11 14:29:57.109+00:00 | ForkJoinPool-1-worker-4 | INFO | SignerLoader | 230 metadata configuration files processed 2023-05-11 14:29:57.340+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 240 metadata configuration files processed 2023-05-11 14:29:57.586+00:00 | ForkJoinPool-1-worker-4 | INFO | SignerLoader | 250 metadata configuration files processed 2023-05-11 14:29:57.848+00:00 | ForkJoinPool-1-worker-1 | INFO | SignerLoader | 260 metadata configuration files processed 2023-05-11 14:29:58.124+00:00 | ForkJoinPool-1-worker-3 | INFO | SignerLoader | 270 metadata configuration files processed 2023-05-11 14:29:58.347+00:00 | ForkJoinPool-1-worker-2 | INFO | SignerLoader | 280 metadata configuration files processed

[jframe]

This optimisation might no longer be working
You can add that we have such setting for faster key load: JAVA_OPTS=-Xms256m -Xmx1024m -Djava.util.concurrent.ForkJoinPool.common.parallelism=4

[jframe]

This occurred when loading 30,000 hashicorp key config files not using hashicorp bulk loading

[usmansaleem]

AWS instances (Ohio)
Web3Signer: t3.medium
Hashicorp Vault: t3.medium (with TLS enabled)

5000 keys loaded in 11 seconds.

2023-05-30 14:23:20.925+00:00 | main | INFO  | Web3SignerApp | Version = web3signer/v23.3.1+17-g055bb4a/linux-x86_64/-ubuntu-openjdk64bitservervm-java-11
...
2023-05-30 14:23:23.573+00:00 | pool-2-thread-1 | INFO  | SignerLoader | Signer configuration metadata files read in memory 5000 in 00:00:00.186
2023-05-30 14:23:24.459+00:00 | pool-2-thread-1 | INFO  | SignerLoader | Converting signing metadata to Artifact Signer using sequential streams ...
...
2023-05-30 14:23:35.404+00:00 | pool-2-thread-1 | INFO  | SignerLoader | 4990 signing metadata processed
2023-05-30 14:23:35.419+00:00 | pool-2-thread-1 | INFO  | SignerLoader | 5000 signing metadata processed
2023-05-30 14:23:35.427+00:00 | pool-2-thread-1 | INFO  | SignerLoader | Total Artifact Signer loaded via configuration files: 5000
Error count 0
Time Taken: 00:00:11.853.
2023-05-30 14:23:35.495+00:00 | pool-2-thread-1 | INFO  | DefaultArtifactSignerProvider | Total signers (keys) currently loaded in memory: 5000

[usmansaleem]

Re-enabling parallel processing.
AWS instances (Ohio)

5000 keys loaded in 7 seconds.

2023-05-31 08:25:52.107+00:00 | ForkJoinPool-1-worker-3 | INFO  | SignerLoader | 5000 signing metadata processed
2023-05-31 08:25:52.127+00:00 | pool-2-thread-1 | INFO  | SignerLoader | Total Artifact Signer loaded via configuration files: 5000
Error count 0
Time Taken: 00:00:07.037.
2023-05-31 08:25:52.223+00:00 | pool-2-thread-1 | INFO  | DefaultArtifactSignerProvider | Total signers (keys) currently loaded in memory: 5000

[usmansaleem]

Parallel processing with additional JAVA_OPTS (same code as before sequential refactoring).
JAVA_OPTS=-Djava.util.concurrent.ForkJoinPool.common.parallelism=4 ./web3signer --config-file /path/to/config/config.yaml eth2

Time taken: 7 seconds

2023-05-31 08:29:45.718+00:00 | pool-2-thread-1 | INFO  | SignerLoader | Total Artifact Signer loaded via configuration files: 5000
Error count 0
Time Taken: 00:00:07.043.
2023-05-31 08:29:45.805+00:00 | pool-2-thread-1 | INFO  | DefaultArtifactSignerProvider | Total signers (keys) currently loaded in memory: 5000

[usmansaleem]

Sequential Processing using experimental flag

./web3signer --config-file /path/to/config/config.yaml --Xkey-store-parallel-processing-enabled=false eth2

2023-06-02 01:28:30.149+00:00 | pool-2-thread-1 | INFO  | SignerLoader | Loading signer configuration metadata files from /home/usman/config/keys
2023-06-02 01:28:30.372+00:00 | pool-2-thread-1 | INFO  | SignerLoader | Signer configuration metadata files read in memory 5000 in 00:00:00.220
2023-06-02 01:28:31.250+00:00 | pool-2-thread-1 | INFO  | SignerLoader | Converting signing metadata to Artifact Signer using sequential streams ...

2023-06-02 01:28:42.037+00:00 | pool-2-thread-1 | INFO  | SignerLoader | 5000 signing metadata processed
2023-06-02 01:28:42.043+00:00 | pool-2-thread-1 | INFO  | SignerLoader | Total Artifact Signer loaded via configuration files: 5000
Error count 0
Time Taken: 00:00:11.670.
2023-06-02 01:28:42.115+00:00 | pool-2-thread-1 | INFO  | DefaultArtifactSignerProvider | Total signers (keys) currently loaded in memory: 5000