0

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

halfer
  • 19,824
  • 17
  • 99
  • 186
Paul T. Rawkeen
  • 3,994
  • 3
  • 35
  • 51
  • 1
    Looks like you're using Guzzle, maybe it's doing an async request? Try using the built-in [on_stats](https://docs.guzzlephp.org/en/latest/request-options.html#on-stats) feature to collect timing? – Alex Howansky May 02 '22 at 16:02
  • @AlexHowansky indeed. I'm using `symfony/http-client` which is asynchronous. Is there any recommendation on how I can deal with it going with such profiling approach? – Paul T. Rawkeen May 03 '22 at 10:29

1 Answers1

0

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.

Paul T. Rawkeen
  • 3,994
  • 3
  • 35
  • 51