8000 Performance Related Issues in 3.3 on Windows · Issue #22712 · symfony/symfony · GitHub
[go: up one dir, main page]
Skip to content
8000

Performance Related Issues in 3.3 on Windows #22712

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.

Sign up for GitHub

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

Jump to bottom
Closed
ChadSikorra opened this issue May 14, 2017 · 24 comments
Closed

Performance Related Issues in 3.3 on Windows #22712

ChadSikorra opened this issue May 14, 2017 · 24 comments
Labels
Bug Status: Needs Review Unconfirmed WebServerBundle
Milestone
3.3

Comments

@ChadSikorra
Copy link
Contributor
ChadSikorra commented May 14, 2017 •
edited
Loading
Q A
Bug report? yes
Feature request? no
BC Break report? no
RFC? no
Symfony version 3.3.0-BETA1

The built-in web server run command does not seem to work for me on Windows. At first I thought it might have something to do with my setup, but I'm starting to doubt that. It works fine from the same Windows box with Symfony 3.2 using the same version of PHP (7.1 -- though I have tried others and get the same problem).

Edit: After more testing the issue seems to be performance related on Windows.
@xabbuh
Copy link
Member
xabbuh commented May 15, 2017

Do you have any other error handlers besides the one provided by Symfony?

@stof
Copy link
Member
stof commented May 15, 2017

Well, the output does not look broken. The server is properly running. But it looks like you send logs to the console, and these logs include the logging of silenced warnings too (but a silenced warning here is normal. The command tries to connect to the port to know whether it is already used or no. So failing to connect is expected)

@ChadSikorra
Copy link
Contributor Author

I don't have any other error handlers configured. This is straight from creating a new project via composer, then starting up the built-in web server with the server:run command.

@stof is correct. It seems like the server runs, but it times out without ever displaying anything trying to hit the default homepage. I'm testing a bit more today from a different workstation. But I ran the same commands/steps on an Ubuntu box and it worked without issue.

@ChadSikorra
Copy link
Contributor Author

I tested from a completely separate Windows 10 machine. The issue still happens. It works fine with 3.2, but not with 3.3.

This is all I do to test at the moment:

composer.bat create-project symfony/framework-standard-edition web_server_test "3.3.*" -s dev
cd web_server_test/
php bin/console server:run

Those same steps worked fine from my Ubuntu machine.

@ChadSikorra ChadSikorra changed the title [WebServerBundle] fsockopen Fails on Windows Performance Related Issues in 3.3 on Windows May 17, 2017
@ChadSikorra
8000 Copy link
Contributor Author
ChadSikorra commented May 17, 2017 •
edited
Loading

After some testing I've realized that the issue is performance related on Windows (On Windows 10 v1607 anyway). It takes way longer for the kernel to handle the request in 3.3 than it did in 3.2. It just hangs then timesout. I was able to get the page to display once after several dozen attempts after I was messing with different things, but even then it took extremely long for the demo page to come up.

@ChadSikorra
Copy link
Contributor Author

The issue seems to be related to the monlog handler that was added here:

symfony/symfony-standard@53396e4#diff-9d592f57989b96cb71c5cc53d2c0e92d

If I comment out the following in config_dev.yml the speed goes back to normal:

        server_log:
            type:   server_log
            process_psr_3_messages: false
           host: 0:9911

ping @lyrixx

@lyrixx
Copy link
Member
lyrixx commented May 17, 2017

Could you tried to make a blackfire profile of this? I don't have windows :/

@ChadSikorra
Copy link
Contributor Author
ChadSikorra commented May 18, 2017 •
edited
Loading

Currently attempting to...can't seem to get the profiling data to show up on the blackfire site :/ Have double-checked my config and everything looks fine. I was able to generate a debug using xdebug which is how I narrowed it down to a monolog handler. I think the root cause of the slowdown is related to the WindowsPipes in the Process component, though I'm not completely sure.

@lyrixx
Copy link
Member
lyrixx commented May 18, 2017

The process component is not used in that part of the code. It looks strange to me.

@ChadSikorra
Copy link
Contributor Author

Yeah, that may have been my mistake 😅 hah. I think I was looking at the wrong cachegrind file for a bit. Still need to finish my morning coffee. Doesn't help that I'm trying to trace a process within a process, which would also explain why I'm not getting blackfire results. The builtin webserver process is kicked off via the process component which is where the slow-down is happening. Would have to play with the arguments to get blackfire to work there I guess?

@lyrixx
Copy link
Member
lyrixx commented May 18, 2017

You can just profile a page directly from your browser. it will be much simpler ;)

@ChadSikorra ChadSikorra mentioned this issue May 18, 2017
Closed
@ChadSikorra
Copy link
Contributor Author
ChadSikorra commented May 18, 2017 •
edited
Loading

I narrowed down the issue and created a PR in symfony-standard, explaining the issue there. Ultimately I think the monolog ServerLogHandler needs to throw an exception if it can't create the socket initially, or just not try thereafter (or maybe attempt a different port?). Or perhaps extend the SocketHandler from monolog and use its functions.

@netsuo
Copy link
netsuo commented May 19, 2017

I can confirm the problem. On a fresh windows server install.
It's not only with server:run but also on Apache 2.4 with php 7.1, with default parameters.

If I comment the same lines in config_dev.yml, the page loads without problems.

@lyrixx
Copy link
Member
lyrixx commented May 19, 2017

Hi.

Can you confirm that the 2 PR fix the issue ?

Thanks

@netsuo
Copy link
netsuo commented May 19, 2017

It works with 0.0.0.0 and with 127.0.0.1 but it's still very very slow, 8 seconds to show the page compared to 200ms when commenting the lines.
Don't know if normal or not, first projet on windows using symfony

@stof
Copy link
Member
stof commented May 19, 2017

@netsuo please provide us a Blackfire profile to help debug the performance issue then, it will make things much easier.

@netsuo
Copy link
netsuo commented May 19, 2017

It was my first time using blackfire so i'm sorry if I didn't use it correctly, but anyway here's the profile on a fresh install of php 7.1 thread safe on Win 10, using server:run with 0.0.0.0 as address in config_dev.yml.

https://blackfire.io/profiles/5fb40f05-4d50-4afb-97d8-773aae9d5293/graph

@lyrixx
Copy link
Member
lyrixx commented May 19, 2017

@netsuo Thanks a lot.

So it looks like the issue comes from https://github.com/symfony/symfony/blob/master/src/Symfony/Bridge/Monolog/Handler/ServerLogHandler.php#L58

I occurs when it's not possible write to the socket. So I guess the socket could not be opened.

@nicolas-grekas Do you have a hint here ?

@netsuo Could you juste comment this line https://github.com/symfony/symfony/blob/master/src/Symfony/Bridge/Monolog/Handler/ServerLogHandler.php#L48 so see what is the real error ? Thanks.

@ChadSikorra
Copy link
Contributor Author
ChadSikorra commented May 19, 2017 •
edited
Loading

The problem as I understand it is two-fold on Windows (in regards to the different slow-down times). By leaving the host at the name 0 there is a DNS/lookup resolution failure timeout. By changing it to 0.0.0.0 it will resolve to a meta-address, so there would be no resolution timeout. However, using 0.0.0.0 for that address in config_dev.yml is not valid in that context on Windows. It's not valid to write via TCP to that address. No name resolution timeout, but you do get a brief timeout as Windows attempts to open a TCP socket to a port that will never work (and it happens for every logging attempt).

I think the following for config_dev.yml for this would make the most sense:

  • Use 127.0.0.1:9911 as the default host.
  • In the ServerLogHandler only attempt to create the socket once. If it cannot open it, ignore it for the rest of the request.

Edit: I was mistaken. The timeout is related to writing to the socket (as described by @netsuo below). There is no timeout opening the socket because of the STREAM_CLIENT_ASYNC_CONNECT option. But apparently there is still some sort of related lag writing to it? I can make that go away be removing the STREAM_CLIENT_ASYNC_CONNECT option and only attempting to create the socket once if successful.

@netsuo
Copy link
netsuo commented May 19, 2017

@lyrixx Notice: fwrite(): send of 2425 bytes failed with errno=10057 A request to send or receive data was disallowed because the socket is not connected and (when sending on a datagram socket using a sendto call) no address was supplied.

@lyrixx
Copy link
Member
lyrixx commented May 19, 2017

But IIRC, it could not work on windows? It can work if and only if the server is already listening?

@nicolas-grekas nicolas-grekas added this to the 3.3 milestone May 19, 2017
@ChadSikorra
Copy link
Contributor Author
ChadSikorra commented May 19, 2017 •
edited
Loading

I think the trick here is to use:

stream_socket_sendto($this->socket, $recordFormatted);

...instead of fwrite(). That resolves the hanging for me, even with the STREAM_CLIENT_ASYNC_CONNECT option in place.

@ChadSikorra ChadSikorra mentioned this issue May 19, 2017
Closed
@ChadSikorra
Copy link
Contributor Author

I opened the above PR that resolves this. Seems like to avoid the hanging the way to go is the stream_socket_* functions and not fwrite or fclose, as it respects the asynchronous mode option.

fabpot added a commit that referenced this issue May 20, 2017
@fabpot
bug #22787 [MonologBridge] Fix the Monlog ServerLogHandler from Hangi…
159f3c5 
…ng on Windows (ChadSikorra)

This PR was squashed before being merged into the 3.3 branch (closes #22787).

Discussion
----------

[MonologBridge] Fix the Monlog ServerLogHandler from Hanging on Windows

| Q             | A
| ------------- | ---
| Branch?       | 3.3
| Bug fix?      | yes
| New feature?  | no
| BC breaks?    | no
| Deprecations? | no
| Tests pass?   | -
| Fixed tickets | #22712
| License       | MIT

This resolves the issue discussed in #22712. This works on both Windows and Linux. Specifically it removes the additional hanging that was caused on Windows when attempting to write/close a TCP socket that's not open on the other end in asynchronous mode.

Commits
-------

be60aa4 [MonologBridge] Fix the Monlog ServerLogHandler from Hanging on Windows
@fabpot fabpot closed this as completed May 20, 2017
@ChadSikorra
Copy link
Contributor Author

Just a FYI that this isn't completely resolved until config_dev.yml is modified in symfony-standard:

symfony/symfony-standard#1077

It will still hang (1-2 seconds each time) trying to resolve 0 as a hostname via DNS on Windows in stream_socket_client. You can replicate a similar slowness in Linux by changing the host from 0:9911 to something completely unresolvable. Though the slowness on Linux is still less than Windows in that case for whatever reason.

@robfrawley robfrawley mentioned this issue Jul 21, 2017
Closed
@KoenPasman KoenPasman mentioned this issue Aug 7, 2017
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug Status: Needs Review Unconfirmed WebServerBundle
Projects
None yet
Milestone
3.3
Development

No branches or pull requests
9 participants
@fabpot @javiereguiluz @nicolas-grekas @ChadSikorra @lyrixx @stof @xabbuh @netsuo @carsonbot
0