Slow worker startup using k8s + Laravel Octane

[jacovdbergh]

We're trying out FrankenPHP for a Laravel App that previously ran on Octane with OpenSwoole.

After switching to FrankenPHP, we're seeing the first requests to workers take ~8s to boot / start up the worker.
Is this normal or are we doing something stupid?

Below is the first log lines of a pod after starting up:

{"level":"info","ts":1730210793.3096776,"msg":"using config from file","file":"/app/vendor/laravel/octane/src/Commands/stubs/Caddyfile"}
{"level":"info","ts":1730210793.3110359,"msg":"adapted config to JSON","adapter":"caddyfile"}
{"level":"info","ts":1730210793.3120553,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//localhost:2019","//[::1]:2019","//127.0.0.1:2019"]}
{"level":"info","ts":1730210793.3123615,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc000554a80"}
{"level":"info","ts":1730210793.3125987,"logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2","h3"]}
{"level":"info","ts":1730210793.3212593,"logger":"tls","msg":"cleaning storage unit","storage":"FileStorage:/data/caddy"}
{"level":"info","ts":1730210793.3217015,"logger":"tls","msg":"finished cleaning storage units"}
{"level":"info","ts":1730210793.4099793,"msg":"FrankenPHP started 🐘","php_version":"8.3.13","num_threads":5}
{"level":"info","ts":1730210793.4105043,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}
{"level":"info","ts":1730210793.4105136,"msg":"serving initial configuration"}
{"level":"info","ts":1730210812.7767856,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"10.42.1.1","remote_port":"44154","client_ip":"10.42.1.1","proto":"HTTP/1.1","method":"GET","host":"10.42.1.60:3000","uri":"/health?liveness","headers":{"Connection":["close"],"User-Agent":["kube-probe/1.31"],"Accept":["*/*"]}},"bytes_read":0,"user_id":"","duration":8.406879236,"size":78,"status":200,"resp_headers":{"Server":["Caddy"],"X-Powered-By":["PHP/8.3.13"],"Cache-Control":["no-cache, private"],"Date":["Tue, 29 Oct 2024 14:06:52 GMT"],"Content-Type":["text/html; charset=UTF-8"]}}
{"level":"info","ts":1730210813.4995446,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"10.42.1.1","remote_port":"44156","client_ip":"10.42.1.1","proto":"HTTP/1.1","method":"GET","host":"10.42.1.60:3000","uri":"/health?readiness","headers":{"Accept":["*/*"],"Connection":["close"],"User-Agent":["kube-probe/1.31"]}},"bytes_read":0,"user_id":"","duration":9.129654861,"size":78,"status":200,"resp_headers":{"Server":["Caddy"],"X-Powered-By":["PHP/8.3.13"],"Cache-Control":["no-cache, private"],"Date":["Tue, 29 Oct 2024 14:06:53 GMT"],"Content-Type":["text/html; charset=UTF-8"]}}
{"level":"info","ts":1730210814.5374932,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"10.42.1.1","remote_port":"38696","client_ip":"10.42.1.1","proto":"HTTP/1.1","method":"GET","host":"10.42.1.60:3000","uri":"/health?readiness","headers":{"Connection":["close"],"User-Agent":["kube-probe/1.31"],"Accept":["*/*"]}},"bytes_read":0,"user_id":"","duration":0.003423463,"size":78,"status":200,"resp_headers":{"X-Powered-By":["PHP/8.3.13"],"Cache-Control":["no-cache, private"],"Date":["Tue, 29 Oct 2024 14:06:54 GMT"],"Content-Type":["text/html; charset=UTF-8"],"Server":["Caddy"]}}
{"level":"info","ts":1730210814.5386224,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"10.42.1.1","remote_port":"38698","client_ip":"10.42.1.1","proto":"HTTP/1.1","method":"GET","host":"10.42.1.60:3000","uri":"/health?liveness","headers":{"User-Agent":["kube-probe/1.31"],"Accept":["*/*"],"Connection":["close"]}},"bytes_read":0,"user_id":"","duration":0.004303421,"size":78,"status":200,"resp_headers":{"Server":["Caddy"],"X-Powered-By":["PHP/8.3.13"],"Cache-Control":["no-cache, private"],"Date":["Tue, 29 Oct 2024 14:06:54 GMT"],"Content-Type":["text/html; charset=UTF-8"]}}
{"level":"info","ts":1730210816.7755747,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"10.42.1.1","remote_port":"38670","client_ip":"10.42.1.1","proto":"HTTP/1.1","method":"GET","host":"10.42.1.60:3000","uri":"/health?readiness","headers":{"Connection":["close"],"User-Agent":["kube-probe/1.31"],"Accept":["*/*"]}},"bytes_read":0,"user_id":"","duration":7.323194317,"size":78,"status":200,"resp_headers":{"Date":["Tue, 29 Oct 2024 14:06:56 GMT"],"Content-Type":["text/html; charset=UTF-8"],"Server":["Caddy"],"X-Powered-By":["PHP/8.3.13"],"Cache-Control":["no-cache, private"]}}
{"level":"info","ts":1730210816.8125048,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"10.42.1.1","remote_port":"38682","client_ip":"10.42.1.1","proto":"HTTP/1.1","method":"GET","host":"10.42.1.60:3000","uri":"/health?liveness","headers":{"Connection":["close"],"User-Agent":["kube-probe/1.31"],"Accept":["*/*"]}},"bytes_read":0,"user_id":"","duration":7.360134064,"size":78,"status":200,"resp_headers":{"Server":["Caddy"],"X-Powered-By":["PHP/8.3.13"],"Cache-Control":["no-cache, private"],"Date":["Tue, 29 Oct 2024 14:06:56 GMT"],"Content-Type":["text/html; charset=UTF-8"]}}
{"level":"info","ts":1730210819.3724113,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"10.42.1.1","remote_port":"37858","client_ip":"10.42.1.1","proto":"HTTP/1.1","method":"GET","host":"10.42.1.60:3000","uri":"/health?liveness","headers":{"User-Agent":["kube-probe/1.31"],"Accept":["*/*"],"Connection":["close"]}},"bytes_read":0,"user_id":"","duration":0.003191491,"size":78,"status":200,"resp_headers":{"Server":["Caddy"],"X-Powered-By":["PHP/8.3.13"],"Cache-Control":["no-cache, private"],"Date":["Tue, 29 Oct 2024 14:06:59 GMT"],"Content-Type":["text/html; charset=UTF-8"]}}
{"level":"info","ts":1730210819.373243,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"10.42.1.1","remote_port":"37856","client_ip":"10.42.1.1","proto":"HTTP/1.1","method":"GET","host":"10.42.1.60:3000","uri":"/health?readiness","headers":{"User-Agent":["kube-probe/1.31"],"Accept":["*/*"],"Connection":["close"]}},"bytes_read":0,"user_id":"","duration":0.003990348,"size":78,"status":200,"resp_headers":{"Server":["Caddy"],"X-Powered-By":["PHP/8.3.13"],"Cache-Control":["no-cache, private"],"Date":["Tue, 29 Oct 2024 14:06:59 GMT"],"Content-Type":["text/html; charset=UTF-8"]}}

With OpenSwoole, we used pods that got 0.2 CPU request, 1 CPU limit and 900MB memory request, 1200MB limit.

Using the exact same pod spec for FrankenPHP, our readiness probes failed and pods never got to ready, as the timeout was set to the default of 1s.

Increasing CPU request to 2 and RAM to 2000MB, and fixing the worker count to 1 did not make a difference, the first request still takes ~8 seconds.

Is there anything we can do to bring down the worker startup time?

[AlliBalliBaba]

Caddy should be starting pretty fast from my experience. According to your logs Caddy is ready to handle requests at 1730210793, but the first health check only finishes 9 seconds later at 1730210812.

Does your Laravel application maybe do some complicated setup that takes that long? The main difference in Octane between Swoole and FrankenPHP ist that Swoole will boot all workers immediately, but FrankenPHP will boot workers when they receive their first request (not sure why it was implemented that way in Octane).

[jacovdbergh]

Ah that might explain it, we have a 10s initialDelay configured in k8s before the readinessProbe starts, so with Swoole the workers would boot in that time.

But now with FrankenPHP it's sitting basically idle in those 10s and only when the readinessProbes starts the boot up happens.