Forum OpenACS Q&A: Re: OpenACS clustering setup and how it relates to xotcl-core.
Posted by
Marty Israelsen
on 09/14/21 01:08 AM
Thanks Gustaf,
Sorry for the late reply. I was out on vacation.
We appreciate your help and expertise. Your point is well taken that we should try to fine tune our configuration as much as we can. I will try to describe our setup and testing on our end so we can try to make sense of what we see. I work on the same naviserver instance as Tony Kirkham. I know you have worked with him on some of our setup so that may help you, to some degree, know what type of setup we have.
We did, at one time, have an extra connection thread pool set up for slow runners. However, after recently updating to the newest naviserver with xotcl we do not have one currently. It was our understanding that the new xotcl may take care of some of the long runners automatically without us defining a specific thread pool and telling xotcl about it. Is this not a good assumption? How would we go about telling the new core where our new long running pool(s) resides? Our current pool config is below.
ns_section ns/server/${server}/pools
ns_param monitor "Monitoring actions to check the health of the system"
ns_param image "Image file requests"
ns_section ns/server/${server}/pool/monitor
ns_param minthreads 3
ns_param maxthreads 5
ns_param map "GET /admin/nsstats"
ns_param map "GET /SYSTEM"
ns_param map "GET /ds"
ns_param map "POST /ds"
ns_section ns/server/${server}/pool/image
ns_param minthreads 3
ns_param maxthreads 5
ns_param map "GET /*.png"
ns_param map "GET /*.jpg"
ns_param map "GET /*.PNG"
ns_param map "GET /*.JPG"
ns_param map "GET /*.JPEG"
ns_param map "GET /*.jpeg"
ns_param map "GET /*.mp4"
ns_param map "GET /*.MP4"
ns_param map "GET /*.pdf"
ns_param map "GET /*.PDF"
ns_param map "GET /*.gif"
ns_param map "GET /*.GIF"
Our Server setup:
We have one VM that has 24 cores and 80 Gig of RAM which our live system resides. We also have a staging VM that has 16 cores and 200 Gig of RAM.
The tests below will be run against our staging server.I have been using a load testing tool called k6 (See: https://k6.io/) to set a base line test for our server and to do a quick 4 minute test.
The base test had the following ramp up options:
export const options = {
stages: [
{ target: 25, duration: '30s' }, // Ramp up to 25 concurrent users over the 30 seconds
{ target: 100, duration: '30s' }, // Then ramp up to 100 concurrent users for the next 30 seconds
{ target: 300, duration: '1m' }, // Then ramp up to 300 concurrent users for the next minute
{ target: 100, duration: '1m' }, // Then ramp down to 100 concurrent users for the next minute
{ target: 0, duration: '1m' }, // Finally ramp down to 0 concurrent users for the next minute
]
};
Each k6 session does the following things: 1. Go to login page 2. Verify that it got a status 200 from login page 3. Sleep 1 second 4. Submit the login form 5. Verify that it got a status 200 6. Sleep 3 seconds 7. Go to a quick loading page (~ under 1 second) 8. Verify that it got status 200 9. Sleep 3 seconds 10. Go to our highly dynamic server side rendered commonly used effort reporting page (normally takes a full 2 seconds to load) 11. Verify that it got status 200 12. Sleep 3 seconds
Test #1 on our Staging server
Nsstats over time
------------------------
No Load on system: 3:56pm
Connection Threads: min 2 max 10 current 2 idle 1 stopping 0 waiting 0
Request Handling: requests 7, queued 0 (0.00%), spooled 6 (85.71%)
Request Timing: avg queue time 98.57µs, avg filter time 183.63ms, avg run time 12.91ms avg trace time 3.92ms
Active Requests: cns6 172.31.6.115 running GET /z1 0.014718 0 .
Starting the test.
~3:58pm
140 VUs (Virtual Users)
Connection Threads: min 2 max 10 current 10 idle 0 stopping 0 waiting 73
Request Handling: requests 1.7K, queued 1K (61.48%), spooled 1K (62.24%)
Request Timing: avg queue time 660.56ms, avg filter time 5.44ms, avg run time 218.25ms avg trace time 1.31ms
Active Requests: cns1639 172.31.207.40 running GET /z2 5.408894 0 .
~3:59pm
300 VUs
Connection Threads: min 2 max 10 current 10 idle 0 stopping 0 waiting 90
Request Handling: requests 3.6K, queued 3K (77.81%), spooled 2K (64.06%)
Request Timing: avg queue time 1.39s, avg filter time 5.51ms, avg run time 224.59ms avg trace time 1.6ms
Active Requests: cns3397 172.31.207.40 running GET /z3 0.815387 0 .
~4:00pm
200 VUs
Connection Threads: min 2 max 10 current 10 idle 0 stopping 0 waiting 75
Request Handling: requests 4.9K, queued 4K (82.60%), spooled 3K (66.17%)
Request Timing: avg queue time 1.95s, avg filter time 5.77ms, avg run time 268.55ms avg trace time 1.71ms
Active Requests: cns4809 172.31.207.40 running GET /z4 0.932554 0 .
4:01pm
49 VUs
Connection Threads: min 2 max 10 current 10 idle 3 stopping 0 waiting 0
Request Handling: requests 6.1K, queued 5K (81.76%), spooled 4K (66.21%)
Request Timing: avg queue time 2.03s, avg filter time 5.84ms, avg run time 289.01ms avg trace time 1.74ms
Active Requests: cns6038 172.31.207.40 running GET /z5 7.99834 0 .
K6 summary
------------------
running (4m09.0s), 000/300 VUs, 964 complete and 86 interrupted iterations
default ✓ [======================================] 000/300 VUs 4m0s
✗ status is 200
↳ 99% — ✓ 4051 / ✗ 7
✗ page succeeded
↳ 99% — ✓ 4041 / ✗ 17
█ setup
█ teardown
checks.........................: 99.70% ✓ 8092 ✗ 24 << Note: We would like be 100% on our page check for status 200 and page succeeded.
data_received..................: 922 MB 3.7 MB/s
data_sent......................: 5.2 MB 21 kB/s
http_req_blocked...............: avg=2.6ms min=1.48µs med=7.01µs max=41.1ms p(90)=8.31ms p(95)=12.44ms
http_req_connecting............: avg=180.19µs min=0s med=0s max=34.22ms p(90)=419.21µs p(95)=465.91µs
✗ http_req_duration..............: avg=3.89s min=441.05µs med=1.15s max=35.08s p(90)=11.28s p(95)=17.46s << Note: It would be nice to be under 8 seconds in the 95th percentile.
{ expected_response:true }...: avg=3.89s min=4.6ms med=1.15s max=35.08s p(90)=11.28s p(95)=17.4s
http_req_failed................: 0.11% ✓ 7 ✗ 6143 << Note: We would like to have 0% failed http requests.
http_req_receiving.............: avg=1.16ms min=51.84µs med=178.08µs max=41.42ms p(90)=2.66ms p(95)=4.52ms
http_req_sending...............: avg=42.78µs min=8.58µs med=40.67µs max=513.41µs p(90)=76.4µs p(95)=88.37µs
http_req_tls_handshaking.......: avg=2.38ms min=0s med=0s max=39.85ms p(90)=7.75ms p(95)=11.64ms
http_req_waiting...............: avg=3.89s min=294.73µs med=1.15s max=35.08s p(90)=11.28s p(95)=17.46s
http_reqs......................: 6150 24.695368/s
iteration_duration.............: avg=32.34s min=2.31µs med=31.28s max=1m6s p(90)=54.78s p(95)=56.5s
iterations.....................: 964 3.870949/s
vus............................: 1 min=1 max=300
vus_max........................: 300 min=300 max=300
Error.log file shows we are out of available connections during this test.
--------------------
...
[13/Sep/2021:16:00:16][1.7f1a15c5a700][-driver:nsssl_v4:0-] Notice: [east_intrastage pool ] All available connections are used, waiting 90 idle 0 current 10
[13/Sep/2021:16:00:17][1.7f1a15c5a700][-driver:nsssl_v4:0-] Notice: [east_intrastage pool ] All available connections are used, waiting 90 idle 0 current 10
[13/Sep/2021:16:00:18][1.7f1a15c5a700][-driver:nsssl_v4:0-] Notice: [east_intrastage pool ] All available connections are used, waiting 90 idle 0 current 10
[13/Sep/2021:16:00:18][1.7f1a15c5a700][-driver:nsssl_v4:0-] Notice: [east_intrastage pool ] All available connections are used, waiting 90 idle 0 current 10
[13/Sep/2021:16:00:19][1.7f1a15c5a700][-driver:nsssl_v4:0-] Notice: [east_intrastage pool ] All available connections are used, waiting 90 idle 0 current 10
[13/Sep/2021:16:00:20][1.7f1a15c5a700][-driver:nsssl_v4:0-] Notice: [east_intrastage pool ] All available connections are used, waiting 90 idle 0 current 10
[13/Sep/2021:16:00:21][1.7f1a15c5a700][-driver:nsssl_v4:0-] Notice: [east_intrastage pool ] All available connections are used, waiting 90 idle 0 current 10
...
Some of the longer calls from request monitor during this time.
request-monitor/long-calls?lines=1000
... 14.371059 0.003934 1.550067 15.925060 2021 Sep 13 16:00:30 14.290415 0.006291 1.668398 15.965104 2021 Sep 13 16:00:30 14.062884 0.003386 0.007183 14.073453 2021 Sep 13 16:00:29 14.189928 0.003912 1.581149 15.774989 2021 Sep 13 16:00:29 14.176448 0.004008 0.018152 14.198608 2021 Sep 13 16:00:29 14.314284 0.003587 0.010584 14.328455 2021 Sep 13 16:00:29 14.265956 0.004304 1.653035 15.923295 2021 Sep 13 16:00:29 14.447920 0.005010 1.477352 15.930282 2021 Sep 13 16:00:29 14.803571 0.004733 1.380080 16.188384 2021 Sep 13 16:00:29 14.458517 0.004058 1.835248 16.297823 2021 Sep 13 16:00:29 14.572207 0.006749 1.628151 16.207107 2021 Sep 13 16:00:29 14.449219 0.003139 0.006589 14.458947 2021 Sep 13 16:00:28 14.402088 0.007025 1.514557 15.923670 2021 Sep 13 16:00:28 14.547796 0.005566 1.703462 16.256824 2021 Sep 13 16:00:28 14.278776 0.012663 1.880569 16.172008 2021 Sep 13 16:00:28 14.470381 0.019008 1.793124 16.282513 2021 Sep 13 16:00:28 14.950281 0.003875 1.816067 16.770223 2021 Sep 13 16:00:28 14.547664 0.004792 1.457710 16.010166 2021 Sep 13 16:00:28 14.418724 0.019254 0.008703 14.446681 2021 Sep 13 16:00:28 ...
From the data above it looks like we are running out of connections in our connection pool which I believe would cause requests to be put onto the queue to wait until another connection is available.
Note: When we put 5 servers behind a nginx server and the DB on a separate VM our status checks for page success was 100% and our wait times in the 95th percentile were around 7 seconds.
Any suggestions you have that would help us fine tune our configuration for one server would be greatly appreciated.
Thanks for your help, Marty
