PHP (poor man's profiler) incorrect hrtime() difference

Question

I'm implementing so-called poor man's profiling in PHP and doing it pretty straightforward way as you would expect:

$start = hrtime(true);

// API request is more than 1 second long
$response = $this->getClient($cfg)->request($method, $url, ['query' => $query]);

// Exec time calculated in milliseconds
$end = round((hrtime(true) - $start) / 1E+6, 3);

// Result: $end = 2.642

Calculated execution time is always around very minor values like few ms which is unbelievably untrue, bec. endpoint has strict timeout of 1s. hrtime() before and after API request reports very minor difference whether API request itself is not that fast. microtime() gives similar results. cURL in turn returns valid response time.

I can't understand what I'm doing wrong. Interesting fact is that script total exec time seems to be valid, but profiling points like these are strangely small. What is my problem?

---

I'm using

• symfony/http-client: ^5.4
• Docker php:7.4-fpm image with nginx
• x64

Answer 1

The reason for such behavior as mentioned by @AlexHowansky in comments is indeed the HTTP client I'm using - symfony/http-client. I completely missed that point from very beginning.

As docs state:

Responses are always asynchronous, so that the call to the method returns immediately instead of waiting to receive the response.

... unassigned responses will fallback to synchronous requests.

I switched API client to bare cURL requests what took a bit more lines, but wasn't too tricky to do.