-
Notifications
You must be signed in to change notification settings - Fork 291
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Logging in requests is very slow #724
Comments
What does your logging configuration look like? |
stderr so the messages will not be formatted by octane. |
I found an workaround.
|
Great that you found a workaround @NiroDeveloper. It does seem you're using a custom logger so I'm not sure this is something we can provide support for sorry. |
@driesvints This are classes of monolog or wdym with custom logger? What is the recommended way to log on stdout? |
We already have an stderr logger configured here: https://github.com/laravel/laravel/blob/10.x/config/logging.php#L97 Is that not working for you? |
That is exactly the same configuration (I just added the json formatter). |
It does seem to be missing the processor. I'm also not sure we extensively tested the JsonFormatter to be used with octane. |
The processor and JsonFormatter are just the ways how the string will be generated. |
Right. I guess right now, this doesn't play well with Octane. If you want, we'd appreciate a PR to the docs about this 👍 |
What is the solution to this? Using the example above with ProcessHandler and cat can result in logs getting intermangled if the server is logging a lot.
|
@LauJosefsen Maybe another monolog handler is useful for you e.g. SocketHandler or RedisHandler. |
This continues to be an issue for us. We are logging quite a bit, and we cannot log to stdout, as Octane will apply some formatting to that. The workaround provided here causes intermangled logs, so it is not really an option. Would it be a solution to disable the formatting of stdout with an env variable, or maybe not to do it by default? It is a bit unexpected that a non octane laravel application will not format stdout, but Octane will. |
Hi @LauJosefsen. Yeah maybe we can. Can you send in a PR for Taylor to review? |
Care my workaround generates endless linux processes! @driesvints Logging in octane is still a critical, unstable and undocumented use case, at least the issue should be open so that it gets attention. Maybe there will be someone who knows about it and can fix it better than me. |
Will just reopen this for now. PR's welcome. |
Thank you for reporting this issue! As Laravel is an open source project, we rely on the community to help us diagnose and fix issues as it is not possible to research and fix every issue reported to us via GitHub. If possible, please make a pull request fixing the issue you have described, along with corresponding tests. All pull requests are promptly reviewed by the Laravel team. Thank you! |
Here is a further analysis from me on this problem. There are basically 3 approaches here:
@LauJosefsen Is your only problem the formatting or also the performance? |
@NiroDeveloper The problem is currently you either can achieve fast logging through the Not using the work around introduces a 200ms latency bump on our most busy services - defeating the point of Octane. Logging to stderr is not a problem for us. - I had the assumption that stdout was not experiencing the slowness, but I guess that was a misunderstanding from my side. The comment on stdout vs stderr, was simply that it was unexpected the logs are formatted in an octane application, but not in a non-octane Laravel application. This main issue is the performance penalty of many workers writing to either stdout/stderr at the same time. I am sorry for the confusion 🤗 I will have a look at the symfony process class. |
It seems that the stdout and stderr buffer of the pipes are too small which leads to a blocking subprocess.
But decreasing this usleep only ensures that the limit occurs later. |
Making this value configurable would be awesome |
Good finding! Is it correctly understood the buffers are defined here? https://github.com/symfony/symfony/blob/7.0/src/Symfony/Component/Process/Process.php#L1426 I.e. 1MB i assume? Do i understand correctly that we have a limit of logging 2MB per second with the current sleep amount? |
@LauJosefsen In my tests i was able to generate log output of ~22 MB per Second, but I can't explain to you how this value comes about. |
Given there's no activity here for a month I'm going to close this one now. |
Sorry for the inactivity, I got busy with other tasks. I just tested a clean Laravel Octane (on FrankenPHP) project with an API route that logs 10k ( I worked it with
Then i worked again but with
I then removed the usleep linked in InteractsWithServers in my vendor folder and tested again.
I have not conducted any extensive testing of how much logging throughput can be achieved without the sleep, but it definitely fixes the issue completely for this test. So am I wondering two things now.
I will happily contribute it myself, if we can agree on a solution. 🤗 |
Oups i accidentally pasted the wrong results, now they are correct. Notice the 50x increase in throughput by emptying the buffer more often. |
Octane Version
2.0.2
Laravel Version
10.15.0
PHP Version
8.1
What server type are you using?
Swoole
Server Version
5.0.3
Database Driver & Version
No response
Description
In my tests i can achieve over 2000 RPS with Laravel Octane and Swoole.
But if i add an log message to every request, the Performance drops dramatically to under 100 RPS.
What I have already found out:
This is a critical problem!
You can say now that you shouldn't log so much ... however, many error messages with exceptions would immediately paralyze the service.
Steps To Reproduce
The text was updated successfully, but these errors were encountered: