Timer 'max-execution-time' works strangely

[alexpts]

I have worker process with sleep(2 sec). Option max-execution-time is 4 sec. I see error Maximum execution time exceeded sometime.

My config and extend log:
+---------------------+-----------------------------------------+
| bridge | PHPPM\Bridges\Psr15Middleware |
| host | 0.0.0.0 |
| port | 9001 |
| workers | 1 |
| app-env | production |
| debug | 1 |
| logging | 1 |
| bootstrap | DdMonitoring\PmmAdapter |
| max-requests | 20 |
| populate-server-var | |
| max-execution-time | 4 |
| memory-limit | 24 |
| ttl | 3600 |
| reload-timeout | 5 |
| static-directory | |
| socket-path | .ppm/run/ |
| pidfile | .ppm/ppm.pid |
| cgi-path | /usr/local/Cellar/php/7.4.0/bin/php-cgi |
+---------------------+-----------------------------------------+
Starting PHP-PM with 1 workers, using StreamSelectLoop ...
1 workers (starting at 5501) up and ready. Application is ready at http://0.0.0.0:9001/
Method RequestHandler::SlaveClose -> cancelTimer
[06/Dec/2019:07:06:45 +0000] 127.0.0.1 - - "GET /asterisk/connect/ HTTP/1.1" 200 291 "-"
Method RequestHandler::maxExecutionTimeExceeded
Maximum execution time of 4 seconds exceeded. Closing worker.
Method RequestHandler::SlaveClose -> cancelTimer
Method RequestHandler::maxExecutionTimeExceeded
Maximum execution time of 4 seconds exceeded. Closing worker.
Method RequestHandler::SlaveClose -> cancelTimer
Method RequestHandler::maxExecutionTimeExceeded
Maximum execution time of 4 seconds exceeded. Closing worker.
Method RequestHandler::SlaveClose -> cancelTimer
Method RequestHandler::maxExecutionTimeExceeded
Maximum execution time of 4 seconds exceeded. Closing worker.
Method RequestHandler::SlaveClose -> cancelTimer
Method RequestHandler::maxExecutionTimeExceeded
Maximum execution time of 4 seconds exceeded. Closing worker.
Method RequestHandler::SlaveClose -> cancelTimer
Method RequestHandler::maxExecutionTimeExceeded
Maximum execution time of 4 seconds exceeded. Closing worker.
Method RequestHandler::SlaveClose -> cancelTimer
Method RequestHandler::SlaveClose -> cancelTimer
[06/Dec/2019:07:07:09 +0000] 127.0.0.1 - - "GET /asterisk/connect/ HTTP/1.1" 200 291 "-"
Method RequestHandler::maxExecutionTimeExceeded
Maximum execution time of 4 seconds exceeded. Closing worker.
Method RequestHandler::SlaveClose -> cancelTimer
Method RequestHandler::maxExecutionTimeExceeded
Maximum execution time of 4 seconds exceeded. Closing worker.
Method RequestHandler::SlaveClose -> cancelTimer

Screenshot with response timers and status code from chrome network - https://www.dropbox.com/s/qikg27y9dwkqbep/%D0%A1%D0%BA%D1%80%D0%B8%D0%BD%D1%88%D0%BE%D1%82%202019-12-06%2010.07.55.png?dl=0

Please check it. I expected give response with status code is 200 for all request after ~2 sec delay. But I have 504 after 3ms - 1.62sec delay.

[andig]

Did you add the additional logging statements yourself?

[alexpts]

Yes, I added 2 extra log Method RequestHandler::SlaveClose -> cancelTimer and Method RequestHandler::maxExecutionTimeExceeded

[andig]

Related to #470?