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

[HttpKernel] LoggerDataCollector: splitting logs on different sub-requests #23659

Merged
merged 1 commit into from Apr 20, 2018

Conversation

Projects
None yet
6 participants
@vtsykun
Contributor

vtsykun commented Jul 24, 2017

Q A
Branch? 4.1
Bug fix? yes
New feature? no
BC breaks? no
Deprecations? no
Tests pass? -
Fixed tickets #23620
License MIT
Doc PR -

This PR fixed performance problem in dev mode and prevent logs serialize several times for each sub-request.

STR:

  1. Install any symfony application v2.8-3.4
  2. Create a simple page with 20-50 sub-requests and 5k-10k logs
  3. Open page in dev mode

Actual

  • debug toolbar not open (404 not found)
  • sets of logs (in the logger debug panel) for different requests are same
  • log processing takes about 20-30s
  • gc also run about 50% of execution time

Expected

  • Debug toolbar should be open
  • As developer, I want to see in logger panel only those logs that are relevant to the given sub-request

Profile and performance

Tested on page with 7k logs and 70 sub-request.

Comparison:

@nicolas-grekas

This comment has been minimized.

Show comment
Hide comment
@nicolas-grekas

nicolas-grekas Jul 25, 2017

Member

Should the profile for the master request get all logs? At least yes when framework.profiler.only_master_requests is set.
Thinking about the toolbar/panel, having the total count for logs of all sub requests looks desirable to me also. On the implementation side, a simple implementation would require cloning values from collector twice. A better implem would looks for profiles of all subrequests and aggregate them for the master request.

Member

nicolas-grekas commented Jul 25, 2017

Should the profile for the master request get all logs? At least yes when framework.profiler.only_master_requests is set.
Thinking about the toolbar/panel, having the total count for logs of all sub requests looks desirable to me also. On the implementation side, a simple implementation would require cloning values from collector twice. A better implem would looks for profiles of all subrequests and aggregate them for the master request.

@nicolas-grekas nicolas-grekas added this to the 3.3 milestone Jul 25, 2017

@vtsykun

This comment has been minimized.

Show comment
Hide comment
@vtsykun

vtsykun Jul 26, 2017

Contributor

I guess that profile should for the master request get all logs

Contributor

vtsykun commented Jul 26, 2017

I guess that profile should for the master request get all logs

vtsykun referenced this pull request in oroinc/platform Jul 26, 2017

BAP-14658: LoggerDataCollector called over 500k times in dev mode (#1…
…1598)

- added local cache for a logger collector
- overwrite symfony`s data_collector.logger class
- added tests

@vtsykun vtsykun changed the title from [WIP] [HttpKernel] LoggerDataCollector: splitting logs on different sub-requests to [HttpKernel] LoggerDataCollector: splitting logs on different sub-requests Jul 29, 2017

@nicolas-grekas

This comment has been minimized.

Show comment
Hide comment
@nicolas-grekas

nicolas-grekas Aug 7, 2017

Member

I guess that profile should for the master request get all logs

@vtsykun same to me. OK to finish this PR then?

Member

nicolas-grekas commented Aug 7, 2017

I guess that profile should for the master request get all logs

@vtsykun same to me. OK to finish this PR then?

@nicolas-grekas

This comment has been minimized.

Show comment
Hide comment
@nicolas-grekas
Member

nicolas-grekas commented Aug 31, 2017

ping @vtsykun

@vtsykun

This comment has been minimized.

Show comment
Hide comment
@vtsykun

vtsykun Aug 31, 2017

Contributor

Hi @nicolas-grekas, this done, please review
Yes, I updated PR and squashed commit on Jul 29. So in this implementation I show all logs for master request.

Contributor

vtsykun commented Aug 31, 2017

Hi @nicolas-grekas, this done, please review
Yes, I updated PR and squashed commit on Jul 29. So in this implementation I show all logs for master request.

@ro0NL

ro0NL approved these changes Sep 17, 2017

@ro0NL

This comment has been minimized.

Show comment
Hide comment
@ro0NL

ro0NL Sep 21, 2017

Contributor

From #24275; do events have this same issue?

Contributor

ro0NL commented Sep 21, 2017

From #24275; do events have this same issue?

@nicolas-grekas nicolas-grekas modified the milestones: 3.3, 3.4 Oct 9, 2017

@vtsykun vtsykun changed the base branch from 3.3 to 3.4 Oct 13, 2017

@nicolas-grekas nicolas-grekas removed the Feature label Apr 9, 2018

@nicolas-grekas

This comment has been minimized.

Show comment
Hide comment
@nicolas-grekas

nicolas-grekas Apr 9, 2018

Member

@vtsykun thank you for this PR, and sorry I didn't manage to review it earlier. I just rebased it on top of the latest version of branch 3.4, with a few minor changes. The code looks to good to me. It sill misses a few unit tests. Would you be up for adding them? If yes, don't forget to fetch+rebase --hard on your remote patch-splitting-logs branch. If not, I'm sure someone else can take over. Please advise.

Member

nicolas-grekas commented Apr 9, 2018

@vtsykun thank you for this PR, and sorry I didn't manage to review it earlier. I just rebased it on top of the latest version of branch 3.4, with a few minor changes. The code looks to good to me. It sill misses a few unit tests. Would you be up for adding them? If yes, don't forget to fetch+rebase --hard on your remote patch-splitting-logs branch. If not, I'm sure someone else can take over. Please advise.

@nicolas-grekas

(I just pushed some unit tests)

@fabpot

fabpot approved these changes Apr 17, 2018

Looks like something for 4.1/master intead

@nicolas-grekas

This comment has been minimized.

Show comment
Hide comment
@nicolas-grekas

nicolas-grekas Apr 17, 2018

Member

Looks like something for 4.1/master instead

It could go on 4.1 for sure. The only thing that made me keep it for 3.4 is that the reported behavior affects 3.4 (sub-requests heavy pages suffer from a significant penalty because of log duplication.)

Member

nicolas-grekas commented Apr 17, 2018

Looks like something for 4.1/master instead

It could go on 4.1 for sure. The only thing that made me keep it for 3.4 is that the reported behavior affects 3.4 (sub-requests heavy pages suffer from a significant penalty because of log duplication.)

@nicolas-grekas nicolas-grekas changed the base branch from 3.4 to master Apr 20, 2018

@nicolas-grekas nicolas-grekas modified the milestones: 3.4, 4.1 Apr 20, 2018

@nicolas-grekas

This comment has been minimized.

Show comment
Hide comment
@nicolas-grekas

nicolas-grekas Apr 20, 2018

Member

Rebased on master, ready for 4.1.

Member

nicolas-grekas commented Apr 20, 2018

Rebased on master, ready for 4.1.

@nicolas-grekas

This comment has been minimized.

Show comment
Hide comment
@nicolas-grekas
Member

nicolas-grekas commented Apr 20, 2018

Thank you @vtsykun.

@nicolas-grekas nicolas-grekas merged commit d0cb1de into symfony:master Apr 20, 2018

1 of 3 checks passed

continuous-integration/appveyor/pr Waiting for AppVeyor build to complete
Details
continuous-integration/travis-ci/pr The Travis CI build is in progress
Details
fabbot.io Your code looks good.
Details

nicolas-grekas added a commit that referenced this pull request Apr 20, 2018

feature #23659 [HttpKernel] LoggerDataCollector: splitting logs on di…
…fferent sub-requests (vtsykun)

This PR was merged into the 4.1-dev branch.

Discussion
----------

[HttpKernel] LoggerDataCollector: splitting logs on different sub-requests

| Q             | A
| ------------- | ---
| Branch?       | 4.1
| Bug fix?      | yes
| New feature?  | no
| BC breaks?    | no
| Deprecations? | no
| Tests pass?   | -
| Fixed tickets | #23620
| License       | MIT
| Doc PR        | -

This PR fixed performance problem in dev mode and prevent logs serialize several times for each sub-request.

STR:
1) Install any symfony application v2.8-3.4
2) Create a simple page with 20-50 sub-requests and 5k-10k logs
3) Open page in dev mode

**Actual**
- debug toolbar not open (404 not found)
- sets of logs (in the logger debug panel) for different requests are same
- log processing takes about 20-30s
- gc also run about 50% of execution time

**Expected**
- Debug toolbar should be open
- As developer, I want to see in logger panel only those logs that are relevant to the given sub-request

### Profile and performance

Tested on page with 7k logs and 70 sub-request.

Comparison:
- v3.3.5 - this patch: https://blackfire.io/profiles/compare/b1d410b3-c4a7-4778-9b6d-514f72193e28/graph
- v3.3.5 - patch #23644 https://blackfire.io/profiles/compare/d0715b04-7834-4981-8da2-9f1dcb2ef90c/graph

Commits
-------

d0cb1de [HttpKernel] LoggerDataCollector: splitting logs on different sub-requests

@fabpot fabpot referenced this pull request May 7, 2018

Merged

Release v4.1.0-BETA1 #27181

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment