ray() calls causing seconds execution delay when ray app not running

[Polfo]

Describe the bug
After booting Windows 10, but not starting the Ray app, calls to ray() cause seconds delay in execution.

Versions
spatie/ray (1.19.1)
PHP 7.4.9

To Reproduce

Measure time required for ray() calls.<br>
<?php
require_once '../vendor/autoload.php';

$startTime = microtime(true);

ray();
measure($startTime, 'ray()');

ray();
measure($startTime, 'ray()');

ray($startTime);
measure($startTime, 'ray($startTime)');

ray()->newScreen();
measure($startTime, 'ray()->newScreen()');

ray()->measure();
measure($startTime, 'ray()->measure()');

ray()->measure();
measure($startTime, 'ray()->measure()');

ray($startTime)->green();
measure($startTime, 'ray($startTime)->green()');

function measure(float $startTime, string $name)
{
    static $previousTime;
    $previousTime = $previousTime ?? $startTime;
    $endTime = microtime(true);
    printf(
        "%0.3f seconds total, %0.3f seconds later for %s<br>\n",
        $endTime - $startTime,
        $endTime - $previousTime,
        $name,
    );
    $previousTime = $endTime;
}

Output;

Measure time required for ray() calls.
0.020 seconds total, 0.020 seconds later for ray()
0.020 seconds total, 0.000 seconds later for ray()
1.239 seconds total, 1.219 seconds later for ray($startTime)
2.464 seconds total, 1.225 seconds later for ray()->newScreen()
3.685 seconds total, 1.222 seconds later for ray()->measure()
4.910 seconds total, 1.225 seconds later for ray()->measure()
7.365 seconds total, 2.455 seconds later for ray($startTime)->green()

Expected behavior
Performance is independent of Ray App running.
It took me hours to figure out why my app was running slowly.
The promise of ray is that it runs on all machines whithout having to remove ray() statements.

Desktop:

• OS: Windows 10 64 bit x64
• Version 19041.746
• Without WSL
• Laragon stack

Additional context
This does not happen when the ray app is running. In that case, the results on the same machine are:

Measure time required for ray() calls.
0.004 seconds total, 0.004 seconds later for ray()
0.004 seconds total, 0.000 seconds later for ray()
0.016 seconds total, 0.012 seconds later for ray($startTime)
0.024 seconds total, 0.008 seconds later for ray()->newScreen()
0.032 seconds total, 0.008 seconds later for ray()->measure()
0.049 seconds total, 0.017 seconds later for ray()->measure()
0.072 seconds total, 0.023 seconds later for ray($startTime)->green()

[freekmurze]

I'll investigate this. Do you see slowdowns when added ray()->disable() at the start of your script?

[Polfo]

I see the same slowdown when adding ray()->disable() at the start of the test script.

Measure time required for ray() calls.
0.016 seconds total, 0.015818 seconds later for ray()->disable()
0.016 seconds total, 0.000097 seconds later for ray()
0.016 seconds total, 0.000042 seconds later for ray()
1.252 seconds total, 1.235825 seconds later for ray($startTime)
2.479 seconds total, 1.227035 seconds later for ray()->newScreen()
3.703 seconds total, 1.224305 seconds later for ray()->measure()
4.928 seconds total, 1.224870 seconds later for ray()->measure()
7.373 seconds total, 2.445502 seconds later for ray($startTime)->green()

[freekmurze]

What happens if you comment out the code of this function?

https://github.com/spatie/ray/blob/master/src/Client.php#L23-L43

[Polfo]

After commenting the code within Client.php function send() {}, the performance measurement is:

Measure time required for ray() calls.
0.002 seconds total, 0.001608 seconds for ray()->disable()
0.002 seconds total, 0.000066 seconds for ray()
0.002 seconds total, 0.000042 seconds for ray()
0.002 seconds total, 0.000713 seconds for ray($startTime)
0.003 seconds total, 0.000075 seconds for ray()->newScreen()
0.003 seconds total, 0.000095 seconds for ray()->measure()
0.003 seconds total, 0.000059 seconds for ray()->measure()
0.003 seconds total, 0.000511 seconds for ray($startTime)->green()

[Polfo]

When in Client.php, I replace
curl_setopt($curlHandle, CURLOPT_TIMEOUT, 2); by
curl_setopt($curlHandle, CURLOPT_TIMEOUT_MS, 200);, the performance measurement is:

Measure time required for ray() calls.
0.034 seconds total, 0.034444 seconds for ray()->disable()
0.035 seconds total, 0.000092 seconds for ray()
0.035 seconds total, 0.000046 seconds for ray()
0.201 seconds total, 0.166148 seconds for ray($startTime)
0.359 seconds total, 0.158748 seconds for ray()->newScreen()
0.519 seconds total, 0.159931 seconds for ray()->measure()
0.679 seconds total, 0.159987 seconds for ray()->measure()
0.993 seconds total, 0.313583 seconds for ray($startTime)->green()

[freekmurze]

What happens if you use

curl_setopt($curlHandle, CURLOPT_TIMEOUT_MS, 1);

[Polfo]

When using curl_setopt($curlHandle, CURLOPT_TIMEOUT_MS, 1);

0.003 seconds total, 0.002865 seconds for 'ray()->disable()'
0.003 seconds total, 0.000068 seconds for 'ray()'
0.003 seconds total, 0.000042 seconds for 'ray()'
0.006 seconds total, 0.003470 seconds for 'ray($startTime)'
0.009 seconds total, 0.002154 seconds for 'ray()->newScreen()'
0.012 seconds total, 0.002909 seconds for 'ray()->measure()'
0.014 seconds total, 0.002422 seconds for 'ray()->measure()'
0.019 seconds total, 0.005096 seconds for 'ray($startTime)->green()'

But when I start the ray app, it does not show measurements, which seems logical since there is not enough time to transmit the request.
34: curl_errno($curlHandle) == true when CURLOPT_TIMEOUT_MS == 1

In my environment, with
CURLOPT_TIMEOUT_MS == 10 it works about 50% of the sends
CURLOPT_TIMEOUT_MS == 20 it works about 95% of the sends
CURLOPT_TIMEOUT_MS == 50 it works probably 99.??% of the sends
It is difficult to measure, as the system is slower the first time after boot.

[patinthehat]

@freekmurze I have been working on a PR that may resolve this (it's nearly finished) - it acts as a type of circuit breaker if an initial cURL call fails. Should I submit this or do you have a fix in the works?

[freekmurze]

Please submit it 👍

[rubenvanassche]

Hi @Polfo,

Could you check again with ray versions 1.19.2? This one has the PR of @patinthehat merged that could possibly solve the problem. If that does not solve the problem we should try to tune the CURLOPT_TIMEOUT_MS parameter a bit.

[Polfo]

It defnitly improved, but still 1.2 seconds delay due to curl_setopt($curlHandle, CURLOPT_TIMEOUT, 2);.
I see a cache in the Client code. From the documentation, I understand it is assumed to work for 30 seconds. But the cache is only kept in the Client class, so it is not persistent between webpage requests and each webpage request has the 1.2 seconds delay.

Measure time required for ray() calls.
0.003 seconds total, 0.002754 seconds for 'ray()'
0.003 seconds total, 0.000069 seconds for 'ray()'
1.235 seconds total, 1.232128 seconds for 'ray($startTime)'
1.235 seconds total, 0.000219 seconds for 'ray()->newScreen()'
1.235 seconds total, 0.000214 seconds for 'ray()->measure()'
1.235 seconds total, 0.000067 seconds for 'ray()->measure()'
1.236 seconds total, 0.000651 seconds for 'ray($startTime)->green()'

[patinthehat]

@Polfo @rubenvanassche @freekmurze I can submit a supplemental PR for spatie/laravel-ray that uses the Laravel cache to persist the disabled state between page requests. The original "Throttle cURL after failed connections" PR was for spatie/ray, so there was no way to persist the state across page loads.

Any thoughts as to whether this will resolve the issue?

[Polfo]

Using the Laravel cache seems a good idea to me. It might be to complex though. There still will be a 1.5 seconds delay every 30 seconds for Laravel users and on each request for other users.

Can the timeout be shortened? Only during performAvailabilityCheck() probably to reduce risk.

Wouldn't it be good to warn users when the timeout occurs? Configurable, default = warning on.

[patinthehat]

Warn users in what way? I think that @freekmurze & team have avoided user warnings and the like, so that'd be their call.
As for the PR using the Laravel cache, I'll get it started and update this issue when it's ready to go. Not sure if reducing the timeout during performAvailabilityCheck() is realistic, but I'll look into it.

[freekmurze]

I'll convert this to a discussion, as there is a fix in placate by @patinthehat, but we could still discuss the details on further improvements.

[Polfo]

https://spatie.be/docs/ray/v1/the-ray-desktop-app/discovering-the-ray-app states

Should you forget to remove a ray() call in a Laravel app, and push your code to production, no worries.

That is a very nice feature, but we have reasons to worry when not Laravel. The current implementation can cause hundreds of milliseconds (up to 2 seconds) curl timeout delay on a page load (every page by default when the ray app is missing) and that is not acceptable.
Also, in production, there may be cases where ! app()->environment('production').
I would suggest the following to make sure developers are aware of the potential long delay in production.

• Echo a warning (similar to php's error reporting) when a curl timeout occurs. It must be active by default so that users are aware of the cause of the delay and don't spend many hours investigating (like I did).
• The ray.php configuration file must contain a - well documented - configuration option to disable the warning.
  > This may be as simple as adding documentation to the 'enable' => true part
• Optionally, the ray.php configuration file contains an option to redirect the warning to a curl error log file.
• Optionally, the ray.php configuration file allows to set the timeout for the first curl request (currently 2 seconds, but 100ms may work).

Additionally, implement #151 (comment)
Additionally, ensure no curl request is performed when ray is disabled. This does not seem the case.

[Vercoutere]

This one slipped into our production environment, which had us scratching our heads for a second. Suddenly had a lot of requests taking 2 seconds, much to the amusement of our customers. (-:

We've currently just removed all ray calls in our application and made sure the package is only installed in development environments. Would have preferred keeping the ray calls in our codebase for ease of use though.

[freekmurze]

Maybe you could add a ray()->disable() to your codebase that is executed whoever you're in a production environment.

This way you could leave calls in an nothing will be tried to transmit.

[Vercoutere]

Sounds good! 👌

Either way, I do think it's advisable to make note of the performance impact leaving Ray enabled in production can have.