symfony 1.3 : debug stack slow

please do not open tickets as notification for the forum. feel free to send in patches via ticket

Sorry, I don't understand what you mean. This is a DEFECT and unfortunately I don't really have much more details to add to it except the details saying the configuration stage is very lengthy:

type calls time (ms) time (%) Configuration 12 6203.31 80 Factories 1 286.90 3 Database (Doctrine) 2 0.04 0 Action "act/index" 1 46.92 0 View "Success" for "act/index" 1 6429.44 83

If you find the links to the forum annoying, I won't use them but rather copy the content.

i agree on this being a bug or atleast something to look at.

i did some benchmarks : http://groups.google.com/group/symfony-users/browse_thread/thread/12033215a7b481bc (crosspost to forum @ http://forum.symfony-project.org/index.php/t/24707/)

please provide an xdebug cachegrind profile for us to look at.

Sorry, I don't use xdebug cachegrind. Are we the only 2 developers to complain about it?

Here is an xdebug cachegrind

http://dump.digitalbase.eu/symfony/xdebug_profile_sf12.cachegrind.zip http://dump.digitalbase.eu/symfony/xdebug_profile_sf13.cachegrind.zip

Note that xdebug in sf1.2 is slower then in 1.3. Without xdebug i posted benchmarks in the post above.

Sf1.2 :

Sf1.3 :

I notice the 1.3 stack is connecting to debug somehow where 1.2 isn't. This could have something todo with xdebug being faster in 1.3

as I have expected the debug stack display takes a lot of time. we should find out why. thanks

The reason for the slowness is the toggable debug stacktrace. its rendered for every logged line when xdebug is available. This consumes 50% of the time in the profiled dump. You can turn it off by configuring the logging factory

  logger:
    class: sfAggregateLogger
    param:
      level: debug
      loggers:
        sf_web_debug:
          class: sfWebDebugLogger
          param:
            level: debug
            condition:       %SF_WEB_DEBUG%
            xdebug_logging:  false
            web_debug_class: sfWebDebug
        sf_file_debug:
          class: sfFileLogger
          param:
            level: debug
            file: %SF_LOG_DIR%/%SF_APP%_%SF_ENVIRONMENT%.log

The important part is xdebug_logging: false

We will check if the default should be true, or we should render much less debug information.

Fabian,

Please note that this bugticket/request was opened/benchmarked without xdebug available. Your comment helps for the xdebug part, but fact stays that 1.3 default symfony in development environment is about 400% slower then sf1.2, and that has nothing todo with xdebug, does it ?

Fabian, this did NOT solve the issue for me. Although I have made the proposed change to my factories.yml and erased the cache, the speed is still about the same where the configuration part still takes ~5-6 seconds on EVERY request.

Timers
type	calls	time (ms)	time (%)
Configuration	11	5388.67	73
Factories	1	554.34	7
Database (Doctrine)	4	0.14	0
Action "help/index"	1	6054.65	82
View "Success" for "help/index"	1	218.45	2

colnector, I was replying to DigitalBase?. I cannot judge on your issue until you can provide me a xdebug trace.

What I see from the one from DigitalBase?: The template with the slots take 590 ms to render. Injecting the toolbar takes 876 ms. in sum those two actions are 1.466ms The whole profiled call took 1.491ms

This means that we have 25ms in everything else besides rendering slots and injecting web debug toolbar. This means there is no problem in any other area, but either of both actions is slow.

to eliminate the skew produced by xdebug for the web debug toolbar, please turn it off as instructed and rerun the benchmark.

colnector, I would like to find out why your config phase is so slow, but without details i cannot

Replying to FabianLange:

What I see from the one from DigitalBase?: The template with the slots take 590 ms to render. Injecting the toolbar takes 876 ms. in sum those two actions are 1.466ms The whole profiled call took 1.491ms

i do not agree. same code, only difference is symfony version (1.2 vs 1.3)

look @ the timings

+-600ms vs +-1700ms, something is different, right ?

While we are at it, could you explain me this timings debug information. It doesn't make sense, if i add up all the timings (after collapsing) i still do not end up with the total figure as displayed in the debug bar (without collapsing) ?!

This means that we have 25ms in everything else besides rendering slots and injecting web debug toolbar. This means there is no problem in any other area, but either of both actions is slow. to eliminate the skew produced by xdebug for the web debug toolbar, please turn it off as instructed and rerun the benchmark.

I came up with this problem when upgrading my sf1.2 app to 1.3. I will do this upgrade again and provide you with profile/cachegrind for these calls.

i just noted memory usage is also x10 in the 1.3.1 version. (5MB vs 58MB) Code i am using to display this action :

for($i = 1;$i < 1000;$i ++) {
  slot("slotnr" . $i);
        echo "hier zet ik wat rommel in...<br />";
  end_slot();

  echo get_slot("slotnr" . $i);

} 

oké here we go again, trying to provide as much information as possible

so i tried to upgrade my application again to sf1.3 and comparing totals. I am focussing on 2 different pages (home-dashboard & profile) both doing alot of database interaction. I think i used most of symfony's functionality (components/partial/custom config handler/event hooks/helpers/form system) so i guess this is a pretty good test.

SF1.2 home/dashboard

SF1.3 home/dashboard

SF1.2 userprofile page

SF1.3 userprofile page

Note the big time/memory difference in 1.2 vs 1.3. I guess propel upgrade is reducing the query count by one.

i provided xdebug cachegrind files for all actions, i compressed them all into one archive over at http://dump.digitalbase.eu/symfony/cachegrind.tar.gz

some more information :

* linux (ubunu karmic) with 2.6.31-16-generic kernel * PHP 5.2.10-2 * apache 2.2.11 * xdebug disabled

Replying to DigitalBase:

Replying to FabianLange:

What I see from the one from DigitalBase?: The template with the slots take 590 ms to render. Injecting the toolbar takes 876 ms. in sum those two actions are 1.466ms The whole profiled call took 1.491ms

i do not agree. same code, only difference is symfony version (1.2 vs 1.3)

I know but the is no room for agreement. My statement is on your sf 1.3 cachegrind file and the contained numbers.

The numbers displayed on the web debug toolbar do not have the precision as the results from profiling tools. There are time precision, rounding and summing problems that make the web debug timings not very accurate. they are good enough for a rough guess. also it is not possible to directly compare the timings of 1.2 and 1.3 because changes were made affecting the precision.

Please note that I am not saying we might not have a problem, but the web debug numbers are just not good enough for tracking it down. Ill have a look at your second cachgrind files.

i don't see a problem on the home action. the profile is the 100 slots? that one has 47000 log messages that are processed which takes up most of the time. while we should take care to improve speed on the log line formatting, this is not a relalistic use case to look at. PS The profile timings say for homepage: 29ms for 1.3 77ms for 1.2

Hi again, playing any tricks on me? xdebug_profile_sf13.cachegrind is for sure symfony 1.2 code, not symfony 1.3 I can tell because it contains calls to sfWebDebugPanelLogs->formatLogLine from line 59 and 71 of that class. In 1.3 there is only one call from line 60.

I really want to find an issue, but be careful wen providing information to me. currently it is only wasting my time hunting phantoms.

both (12 and 13) dumps load the symfony stuff from /w1/lib/symfony are you sure you have replaced this with 1.3?

Replying to FabianLange:

Hi again, playing any tricks on me? xdebug_profile_sf13.cachegrind is for sure symfony 1.2 code, not symfony 1.3 I can tell because it contains calls to sfWebDebugPanelLogs->formatLogLine from line 59 and 71 of that class. In 1.3 there is only one call from line 60. I really want to find an issue, but be careful wen providing information to me. currently it is only wasting my time hunting phantoms.

Sorry for that. I guess i wasn't paying attention when renaming the cachegrind files.

I recreated all files & uploaded them @ http://dump.digitalbase.eu/symfony/symfonycachegrind.tar.gz . You can see i seperated 1.2 from 1.3 profiles (seperate directory), i also profiled a third action.

This code doesn't have the slots loop but has code of an old project i am converting into 1.3.

Fabian, I've attached (above) the cachegrind file of 4 subsequent runs of the same (relatively simple) request. With xdebug it takes at least 8 seconds for the configuration part

Timers
type	calls	time (ms)	time (%)
Configuration	11	8108.89	71
Factories	1	365.45	3
Action "help/index"	1	29.00	0
View "Success" for "help/index"	1	9314.56	82

Replying to DigitalBase:

I recreated all files & uploaded them @ http://dump.digitalbase.eu/symfony/symfonycachegrind.tar.gz . You can see i seperated 1.2 from 1.3 profiles (seperate directory), i also profiled a third action.

You might be suprised but the profiled data shows that symfony 1.3 is significantly faster.

Replying to colnector:

Fabian, I've attached (above) the cachegrind file of 4 subsequent runs of the same (relatively simple) request. With xdebug it takes at least 8 seconds for the configuration part

You have attached the profile from a file called combine_js_css.php which is pretty fast 1,9 ms :) I would recommend triggering xdebug profiling using a request parameter, so you only get what you want

Fabian, sorry and I've reattached the correct ZIP. I have no idea why it previously saved only the JavaScript merging script request (which BTW doesn't use Symfony at all).

We too were experiencing the exact same problem as described in this ticket, i.e. a multiple seconds delay during the Configuration stage.

Due to some related difficulties we moved the symfony files from a custom location inside a plugin to the recommended default path at /lib/vendor, and that fixed this problem as well.

Changing the path to /lib/vendor instead of the previous /plugins did not make any difference. Thank you mleonhartsberger for the suggestion but seems the problem is somewhere else.

Replying to FabianLange:

You might be suprised but the profiled data shows that symfony 1.3 is significantly faster.

I already said that (comment:7 in this ticket). The profiled data shows it's faster, but without profiling the debug bar + apache benchmarks + personal observation clearly show it's slower.

Replying to mleonhartsberger:

Due to some related difficulties we moved the symfony files from a custom location inside a plugin to the recommended default path at /lib/vendor, and that fixed this problem as well.

All bencmarks/profiles were performed using /lib/vendor/symfony as the core path. I am quite sure this is the correct way. Changing the path doesn't have any effect on timings.

Replying to DigitalBase:

Replying to FabianLange:

You might be suprised but the profiled data shows that symfony 1.3 is significantly faster.

I already said that (comment:7 in this ticket). The profiled data shows it's faster, but without profiling the debug bar + apache benchmarks + personal observation clearly show it's slower.

Thats a bit of a problem here. Letting the web debug numbers alone, we are down to what ab reports. did the size of the transmitted data increase in such a magnitude that downloading them (even from localhost) is slower? What we see in the profiled data is everything that happens inside php. so everything that happens inside symfony. if 1.3 is faster there, but appears to be slower, I am not sure where to look at

Perhaps somewhere the logging slightly changed and now produces 1MB of log information instead of 10k. The observed slowness could be related to this without any impact on php performance

Replying to FabianLange:

Replying to DigitalBase:

Replying to FabianLange:

You might be suprised but the profiled data shows that symfony 1.3 is significantly faster.

I already said that (comment:7 in this ticket). The profiled data shows it's faster, but without profiling the debug bar + apache benchmarks + personal observation clearly show it's slower.

Thats a bit of a problem here. Letting the web debug numbers alone, we are down to what ab reports. did the size of the transmitted data increase in such a magnitude that downloading them (even from localhost) is slower?

I am fully aware of the fact that the web debug has precision & rounding problems. But wouldn't these problems be in both versions ? How can we then explain sf1.3 web debug timings are 3/4x slower ?

As for the data (from firebug) : * sf12home 38KB * sf12profile 39KB * sf13home 55KB * sf13profile 56KB

ab reports it being ALOT slower, could have anything todo with those 10KB could it ?

What we see in the profiled data is everything that happens inside php. so everything that happens inside symfony. if 1.3 is faster there, but appears to be slower, I am not sure where to look at

most of users reporting this problem say the "configuration" part in the webdebug_bar timings is alot higher. Has anything changed in this part going to sf1.3 ?

Replying to FabianLange:

Perhaps somewhere the logging slightly changed and now produces 1MB of log information instead of 10k. The observed slowness could be related to this without any impact on php performance

you call 10k to 1MB log "slightly" ?

Fabian, it seems like there might be different reasons for the problem I'm experiencing and the one by DigitalBase?. If that is the case, perhaps a new ticket should be opened for "slow configuration loading in debug mode"?

I dont see from your profile that config loading is slow. I will check how the timings are generated

So what do you see as the reason? It's the same with

  xdebug_logging:  false

as suggested above.

My apologies, with

xdebug_logging:  false

the time for configuration has become less than 200ms. I accidentally applied the parameter to my test rather than dev env... oops.

Anyway, with such performance difference (6 seconds to 0.2 seconds) this should definitely not be the default.

i tried this aswell, this seems to resolve all timing issues. The timings are now about the same as in sf1.2.

Just a suggestion, shouldn't the xdebug logging check for xdebug availability before being activated ? Eventhough i disabled xdebug, xdebugging still needs to be turned off in factories.

I agree with colnector this shouldn't be default behavior.

Tnx for the lookup&feedback. I can upgrade my project now :-)

(In [26867]) [1.3, 1.4] turned off xdebug_logging by default as it can make the dev env very very slow (closes #8085)