php-fpm version: 7.4 nginx version: 1.19.0
We run on gke, kubernetes; our nodes have 10 cpu and 24G of ram and we request 2 CPUs (limit 3) to our pods that run our Laravel stack (nginx + php-fpm). The two services share a pod, but are separate containers (one for nginx, one for php). The reason they share a pod is because it clogs up our network to communicate php -> nginx from separate pods (we used to run nginx / php in separate services/deployments)
Additionally, nginx and php share a connection through a shared file that is shared as a volume: e
- name: php-socket
emptyDir: {}
volumeMounts:
- name: php-socket
mountPath: /sock
this seemed to be even better than a local network connection within the pod, and we believe it to be a best practice.
But that brings me to my question: why is this specific request so slow? I know that it is a lot of data, but it's not big data. I believe it's 3MB uncompressed but ends up coming out gzipped <1MB:
But it takes a long time, over our original 30s timeout.
We knew it would be a lot on our database to export a year's worth of data for 3000 users, so we cache this response in Redis. And looking at the PHP logs, we access the cache and begin returning the response in less than 1/4s.
Somewhere between php -> nginx -> client is taking waay too long.
At first I thought it was because we were gzipping a large amount of data; disabling gzip did not help. I even thought that it was the file buffering nginx may have to do, so I upgraded our node disks from 100GB to 200GB and even from HDD to SSD. That did not help. We have even learned repeatedly that we are often the edge case when it comes to config, so I tried setting the fastcgi_buffers, proxy_buffers, and gzip_buffers to insanely high memory values:
keepalive_timeout 300;
fastcgi_send_timeout 300;
fastcgi_read_timeout 300;
fastcgi_connect_timeout 120;
# Try higher buffer size for large assesment loading
fastcgi_buffering on;
fastcgi_buffers 50000 4k;
fastcgi_busy_buffers_size 4098k;
client_max_body_size 128M;
client_body_buffer_size 45M;
client_header_buffer_size 16k;
large_client_header_buffers 32 4k;
proxy_buffers 50000 4k;
proxy_buffer_size 4098k;
proxy_busy_buffers_size 4098k;
##
# Gzip Settings
##
gzip on;
gzip_disable "msie6";
gzip_vary on;
gzip_proxied any;
gzip_comp_level 6;
gzip_buffers 50000 4k;
gzip_http_version 1.1;
gzip_min_length 64;
gzip_types text/plain text/css application/json application/x-javascript text/xml application/xml application/xml+rss text/javascript application/vnd.ms-fontobject application/x-font-ttf font/opentype image/svg+xml image/x-icon;
but this didn't seem to help either.
PHP slowlog:
[08-Jul-2021 18:09:48] [pool www] pid 120 - -
Jul 8, 2021 @ 11:09:48.478 script_filename = /var/www/public/index.php - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81baf0] runQueryCallback() /var/www/vendor/laravel/framework/src/Illuminate/Database/Connection.php:629 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81b9b0] run() /var/www/vendor/laravel/framework/src/Illuminate/Database/Connection.php:338 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81b910] select() /var/www/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php:2159 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81b860] runSelect() /var/www/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php:2147 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81b760] Illuminate\Database\Query\{closure}() /var/www/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php:2619 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81b660] onceWithColumns() /var/www/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php:2148 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81b540] get() /var/www/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php:546 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81b3c0] getModels() /var/www/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Builder.php:530 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81b240] get() /var/www/vendor/laravel/framework/src/Illuminate/Database/Concerns/BuildsQueries.php:143 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81b1b0] first() /var/www/app/Models/User.php:232 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81b070] getAccountAttribute() /var/www/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Concerns/HasAttributes.php:454 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81afc0] mutateAttribute() /var/www/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Concerns/HasAttributes.php:350 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81ae90] getAttributeValue() /var/www/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Concerns/HasAttributes.php:323 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81ada0] getAttribute() /var/www/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Model.php:1550 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81acb0] offsetExists() /var/www/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Model.php:1595 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81ac40] __isset() unknown:0 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fff466902c0] ???() /var/www/app/Models/User.php:236 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81abb0] getAccountTypeAttribute() /var/www/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Concerns/HasAttributes.php:454 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81ab00] mutateAttribute() /var/www/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Concerns/HasAttributes.php:466 - -
Jul 8, 2021 @ 11:09:48.478 [0x00007fe3cc81aa40] mutateAttributeForArray() /var/www/vendor/laravel/framework/src/Illuminate/Database/Eloquent/Concerns/HasAttributes.php:111 - -
Jul 8, 2021 @ 11:09:48.478 [08-Jul-2021 18:09:48] NOTICE: finished trace of 120 - -
Jul 8, 2021 @ 11:09:48.477 [08-Jul-2021 18:09:48] WARNING: [pool www] child 120, script '/var/www/public/index.php' (request: "GET /index.php?clientTimezone=America%2FLos_Angeles") executing too slow (6.203325 sec), logging - -
Jul 8, 2021 @ 11:09:48.477 [08-Jul-2021 18:09:48] NOTICE: child 120 stopped for tracing - -
Jul 8, 2021 @ 11:09:48.477 [08-Jul-2021 18:09:48] NOTICE: about to trace 120
Does anyone have any other ideas?
