Clojurians Log v2
aws
Hi. I'm in the process of deploying a Clojure webapp to Elastic Beanstalk as per https://clojureverse.org/t/running-a-clojure-application-on-aws-elastic-beanstalk-with-clojure-cli-tools/4161 (cc: @orestis 🙏)
And it's working, it's up and running... but CPU utilization Idle% hovers near 100% and page load times are (consequently) super sluggish.
Granted, it's a single t2.small instance (up from the t2.micro that I started with). But still!
Any general thoughts as to why, before I dive into figuring out monitoring and profiling and such on AWS (all ~new to me) and hopefully get to the root of it? E.g. is it expected that running Clojure apps this way is more CPU-intensive than running an Uberjar? 🤔
A nice way to tail logs on AWS EB is using the aws command-line tool:
aws logs tail /aws/elasticbeanstalk/<env-name>/var/log/web.stdout.log --follow
For troubleshooting performance issues I use https://github.com/steffan-westcott/clj-otel along with service providers such as Honeycomb and New Relic. I’m sure you can use X-Ray too.
Fuck yeah. ~10x faster page loads (e.g. see first and last foo?single=true req in screenshot) after ruling out the DB connection as slow, some profiling with https://github.com/clojure-goes-fast/clj-async-profiler identifying page parsing/generation as the likely culprit, and implementing caching.
https://clojurians.slack.com/archives/C09N0H1RB/p1675263604685469?thread_ts=1675263104.785889&cid=C09N0H1RB
Shouldn't you see idle% close to 100%?
That means it's an idle instance 🙂
For the first few ~seconds, you might still be compiling (but you wouldn't see a response just yet).
Have you checked whether it's the database that's slow? If you have a page that just does CPU-only stuff (just rendering some html without touching network/filesystem) you should be able to see if it's the CPU that's slow or something else.
Our staging environment runs on a t3.medium and it's very acceptable performance wise.
> Shouldn't you see idle% close to 100%? D'oh if so! 😄 But it's not just the (maybe misread) CPU usage that's throwing me off. Health stuff keeps dipping into 'Severe' more generally:
Also not a first few secs (or first request) vs subsequent requests problem. It's every page load that's slow. (Perhaps because I'm generating/parsing each page anew from markdown stored in the DB, and this would be the time to look into doing some caching...? 😅 )
> Have you checked whether it's the database that's slow? If you have a page that just does CPU-only stuff (just rendering some html without touching network/filesystem) you should be able to see if it's the CPU that's slow or something else. Hmm, I'll give this a shot. 🙂
Can you check perhaps if your application is restarting all the time? Do you see anything suspicious in the logs?
Looks like you had only 2 requests, so probably it's not the requests that are causing this.
One suspicious thing is that it looks like there are constant GETs of /:
Feb 1 14:32:24 ip-172-31-80-204 web: system started
Feb 1 14:32:28 ip-172-31-80-204 web: [qtp1843774765-17] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:32:28 ip-172-31-80-204 web: [qtp1843774765-22] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:32:30 ip-172-31-80-204 web: [qtp1843774765-21] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:32:43 ip-172-31-80-204 web: [qtp1843774765-23] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:32:43 ip-172-31-80-204 web: [qtp1843774765-24] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:32:45 ip-172-31-80-204 web: [qtp1843774765-17] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:32:58 ip-172-31-80-204 web: [qtp1843774765-22] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:32:58 ip-172-31-80-204 web: [qtp1843774765-21] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:00 ip-172-31-80-204 web: [qtp1843774765-23] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:13 ip-172-31-80-204 web: [qtp1843774765-24] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:13 ip-172-31-80-204 web: [qtp1843774765-17] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:15 ip-172-31-80-204 web: [qtp1843774765-22] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:28 ip-172-31-80-204 web: [qtp1843774765-21] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:28 ip-172-31-80-204 web: [qtp1843774765-23] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:28 ip-172-31-80-204 web: [qtp1843774765-24] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:28 ip-172-31-80-204 web: [qtp1843774765-22] INFO io.pedestal.http - {:msg "GET /words/1C67kb9It/home", :line 80}
Feb 1 14:33:30 ip-172-31-80-204 web: [qtp1843774765-17] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:36 ip-172-31-80-204 web: [qtp1843774765-21] INFO io.pedestal.http - {:msg "GET /words/FC9iGu9V5/foo", :line 80}
Feb 1 14:33:43 ip-172-31-80-204 web: [qtp1843774765-20] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:43 ip-172-31-80-204 web: [qtp1843774765-23] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:45 ip-172-31-80-204 web: [qtp1843774765-22] INFO io.pedestal.http - {:msg "GET /", :line 80}
Feb 1 14:33:58 ip-172-31-80-204 web: [qtp1843774765-24] INFO io.pedestal.http - {:msg "GET /", :line 80}Sounds like the health check
We've set the health check endpoint to something like _health so that it's obvious in the logs. We just reach out to the database (to check connectivity, a simple "SELECT 1" does the trick) and return a 200.
Hmm, makes sense! Maybe the health check doesn't like that / returns a 302? 🤔
/var/log/nginx/access.log
----------------------------------------
172.31.67.190 - - [01/Feb/2023:14:57:59 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.94.1 - - [01/Feb/2023:14:58:01 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.34.70 - - [01/Feb/2023:14:58:14 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.67.190 - - [01/Feb/2023:14:58:14 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.94.1 - - [01/Feb/2023:14:58:16 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.34.70 - - [01/Feb/2023:14:58:29 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.67.190 - - [01/Feb/2023:14:58:29 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.94.1 - - [01/Feb/2023:14:58:31 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.67.190 - - [01/Feb/2023:14:58:44 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.34.70 - - [01/Feb/2023:14:58:44 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.94.1 - - [01/Feb/2023:14:58:46 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.67.190 - - [01/Feb/2023:14:58:59 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.34.70 - - [01/Feb/2023:14:58:59 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.94.1 - - [01/Feb/2023:14:59:01 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.67.190 - - [01/Feb/2023:14:59:14 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
172.31.34.70 - - [01/Feb/2023:14:59:15 +0000] "GET / HTTP/1.1" 302 5 "-" "ELB-HealthChecker/2.0" "-"
...
----------------------------------------
/var/log/nginx/error.log
----------------------------------------
2023/02/01 14:24:00 [error] 20449#20449: *259 connect() failed (111: Connection refused) while connecting to upstream, client: 172.31.94.1, server: , request: "GET / HTTP/1.1", upstream: "> We've set the health check endpoint to something like _health so that it's obvious in the logs. We just reach out to the database (to check connectivity, a simple "SELECT 1" does the trick) and return a 200.
Neat!
Yep, I think it’s best to always have an explicit health check path that can do exactly what you need it to, without authentication and other concerns.
It's possible that's the only reason I'm getting health warnings.
But still there's the question of slow loads, hmm... Out of interest @orestis, how would you go about monitoring/profiling such a project? (E.g. is it worth setting up X-Ray?)
You get a lot of nginx errors too
We use cloud watch. X-ray is for tracing individual requests which is useful but at another level.
In the beginning, the easiest way is to ssh in and tail the log files.
> You get a lot of nginx errors too Hmm... still need to confirm the 302 hunch of course, but I assumed this was the same problem?
It's curious that nginx reports "connection refused" too. You should see this during application startup but not any more.
No, the 302 you see in the pedestal logs which means it's already past the nginx and into your Clojure code. The 500 means nginx can't connect to your app. It seems that the timestamps are different though (14:25 for the errors, 14:59 for the 302)
> It's curious that nginx reports "connection refused" too. You should see this during application startup but not any more. Hmm, ^that might be exactly it actually... looking more carefully at the timestamps. :))
Gotcha!
And ha, yeah. Beat me to noticing the timestamps. 😛
Brill, okay. I have some stuff to dig into. Thanks a bunch @orestis!
🙌
Been away from this for a little while. But the dedicated health check endpoint is working a treat! 🙂