PHP FPM shutdown behavior

Lets say your php script takes a lot of time to process but nginx closes the connection and you see a 502 screen. What happens to your php execution? Here, we want to understand php processes shutdown behavior.

In this context, exploring register_shutdown_function behavior is relevant.

We will explore 6 scenarios for php program:

1. we restart php-fpm while the script is still executing
2. nginx terminates the connection because of fastcgi_timeout
3. you send sigkill to fpm worker processes using kill command
4. a fatal error occurs
5. php runs out of allocated memory.
6. max_execution_time is exceeded. (Is max_execution_time wall time or time spent executing processes AKA virtual time.)

I have php7.2 fpm + nginx stack setup on my local. I configure nginx fastcgi timeout to be 2 seconds. My php script will look something like:

Setup:

The gist above shows a simple setup. We create php file which mocks a redis connection class.. We log output totest.log file which will be created in the same directory as our fpm.php

CASE 1: WHILE OUR SCRIPT IS EXECUTING, LETS RESTART FPM

Because of sleep(3) our script takes more than 3 seconds to execute. I go to browser refresh the page and immedietly restart php-fpm by running

sudo systemctl restart php7.2-fpm

I see only CONSTRUCT CALLED in my test.log. Normal php shutdown process was not executed. To dig a little deeper, I strace the process. To do that, first I find out pid’s of all the running workers

ps aux | grep php-fpm

As you can see there are two workers and your request might be routed to any one of them. You don’t know which one. You can go to fpm pool config and set pm.start_servers = 1 . Then:

sudo strace -p 223438

strace output

Notice how strace output ends. The process was killed with SIGKILL.

Logs also show that only constrcutor was called. register_shutdown_function was not called at all.

Case 2: Nginx fastcgi_read_timeout IS GREATER THAN THE TIME OUR SCRIPT TAKES.

We expect all the logs to be logged to test.log file.

I see following output.

CONSTRUCT CALLED
TEST END
SHUTDOWN CALLED
DESTRUCT CALLED

This also means register_shutdown_function is always called before destructing objects.

CASE 3: WHEN YOU SEND SIGKILL TO FPM WORKER PROCESS USING KILL COMMAND

strace output when kill command is used

Notice how this behaviour is similar to restarting fpm. Since I used kill <pid> command you will notice the end says “killed by SIGTERM”. By default kill sends “SIGTERM”. If you were to use

kill -SIGKILL <pid>

you would see the output “Killed by SIGKILL”

CASE 4: FATAL ERROR HAPPENS

To simulate this we throw an exception in while loop. You will see following output.

public function connect(){
         throw new \Exception('Something went wrong');
  }

CONSTRUCT CALLED
SHUTDOWN CALLED

Destructor was expected to be called after shutdown. To my surprise, it wasn’t called at all.

CASE 5: WHEN PHP RUNS OUT OF ALLOCCATED MEMORY

Our connect will look like

public function connect(){
          $count = 0;
          while($count<1000000){
                  $this->data[]='abhishek J';
                  $count++;
          }
  }

To simulate this, we will set memory_limit 4MB and then we will start filling up the array in while loop. In the test log you will see

CONSTRUCT CALLED
SHUTDOWN CALLED

Running out of memory is a fatal error hence output is similar to CASE 4

CASE 6: WHEN MAX_EXECUTION_TIME IS EXCEEDED

I’m going to set max execution time in php ini to 3 seconds. Then restart and let’s verify that by modifying connect to look like

public function connect(){
          while(true){
            $count = 0;
          }
  }

and you see an error

“Fatal error: Maximum execution time of 3 seconds exceeded in /var/www/fpm.php on line 25” .

Since it’s a fatal error the output in the test log remains as CASE 4 and CASE 5.

Now lets change connect to look like.

public function connect(){
        $s = time();
        sleep(60);
        $e = time();
        echo $e-$s;
  }

We are doing this to figure out if max_execution_time is time consumed when process was using CPU or it is “Clock” time.

When you run the script you see that although the execution limit is set to 3, the script will go on running for 60 seconds.

That means max_execution_time is applied with respect to CPU time consumed by the processes.

So if you are writing some cleanup process in destruct method you gotta be aware that destruct will not called when a error occurs.