• Global community
    • Language:
      • Deutsch
      • English
      • Español
      • Français
      • Português
  • 日本語コミュニティ
    Dedicated community for Japanese speakers
  • 한국 커뮤니티
    Dedicated community for Korean speakers
Exit
0

CF10 debugging slow performance

New Here ,
Jul 05, 2012 Jul 05, 2012

Copy link to clipboard

Copied

I'm working on a CF7 to CF10 migration. If I turn on debugging in CF10 I'm seeing high page rendering times of the order of 100 seconds per page. This didn't happen in CF7. The CPU goes to 100% for the duration of the request. It seems the debug rendering is the culprit.

I've traced a correlation with custom tag mappings. If I remove the mappings, the page render times become acceptable. The behaviour is the same whether the application calls custom tags or not.

What's causing the slow page loads here and is there a work around?

Views

3.2K

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines

correct answers 1 Correct answer

LEGEND , Jul 09, 2012 Jul 09, 2012

OK, I've tracked it down.

It seems expandPath() is REALLY REALLY REALLY slow if you have custom tag paths set that have a lot of files in them.

I added my scratch dir to my custom tag path (6000 files, 2000 dirs), and this caused expandPath() to take about 1.5sec per path to execute (and it's called for every template having its debug output displayed, so that could be really a lot of hits to it.  One might think that's a horrendous sized dir to have in a custom tag path, but the thing is, running

...

Votes

Translate

Translate
New Here ,
Jul 06, 2012 Jul 06, 2012

Copy link to clipboard

Copied

Debug Rendering Time: 147333 ms

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
LEGEND ,
Jul 06, 2012 Jul 06, 2012

Copy link to clipboard

Copied

Good analysis.  Just one question: when you say it's got something to do with debug rendering, do you mean that if you have debug rendering on, it'll take (for example) that 147sec to render a page, but with debug off the page renders at an acceptable speed?

Question: are you sure it's the debug rendering, or simply the debug processing?  If you replace the debug output template (in WEB-INF/debug) with an empty file, do you still get the poor performance?  I suspect it's the capturingof the debug info that is the culprit here, not the rendering of the results.

And I'm not sure what to suggest to mitigate it, sorry.  But I am scratching my head...

--

Adam

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
New Here ,
Jul 06, 2012 Jul 06, 2012

Copy link to clipboard

Copied

Thanks Adam, that's really helpful. It does appear to be the rendering of the debug output that's causing the problem.

The page loads quickly with debugging turned off. Turn debugging on and the page takes more that 2 mins to load.

As you suggested, I swapped the debug template for a blank one, and the page loads quickly again.

I might have a dig around inside the debug template to see if I can isolate the part that is running slowly.

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
New Here ,
Jul 09, 2012 Jul 09, 2012

Copy link to clipboard

Copied

Switching off Report Execution Times in the debugger settings allows the debug page to load normally (Debugging Time: 10ms). With this setting enabled, the debugging time is reported as 214000ms for my application

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
LEGEND ,
Jul 09, 2012 Jul 09, 2012

Copy link to clipboard

Copied

What about in a pared-back repro case, wherein you're just hitting a single single file, or a file which does an include or calls a CFC method or something?

I'm just trying to work out whether it's a vagary fo what it's outputting for your situation, or just in general.


Also, are you using the flat view or the tree field for the execution times?

--

Adam

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
New Here ,
Jul 09, 2012 Jul 09, 2012

Copy link to clipboard

Copied

Thanks Adam, good question. Using this test template: helloWorld.cfm

<html>

    <head>

        <title>Test page</title>

    </head>

    <body>

         <h1>Hello World</h1>

    </body>

</html>

With execution times setting enabled. Debugging Time: 26131ms

With execution times setting disabled. Debugging Time: 31ms

The behaviour is the same whether the classic or dockable debug outputs are used.

If I remove the custom tag paths...

With execution times setting enabled. Debugging Time: 46ms

With execution times setting disabled. Debugging Time: 31ms

So there appears to be an interaction between reporting execution times and custom tag mappings. The more custom tags configured, the slower the debug output when reporting execution times.

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
LEGEND ,
Jul 09, 2012 Jul 09, 2012

Copy link to clipboard

Copied

If I remove the custom tag paths...

Are these ones set in CFAdmin or in Application.cfc?

And how many mappings are there, and how many files / directories are in the directory structure you're pointing to?  Is it the same with ANY custom tag mappings, or is it just specific ones?  Like for example if you have a single mapping to C:\someEmptyDir, is the problem the same?

I'm just needing to reinstall CF10 to troubleshoot another problem, but it's almost done so will have a look at this shortly and see if I can replicate.

--

Adam

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
LEGEND ,
Jul 09, 2012 Jul 09, 2012

Copy link to clipboard

Copied

OK, I've tracked it down.

It seems expandPath() is REALLY REALLY REALLY slow if you have custom tag paths set that have a lot of files in them.

I added my scratch dir to my custom tag path (6000 files, 2000 dirs), and this caused expandPath() to take about 1.5sec per path to execute (and it's called for every template having its debug output displayed, so that could be really a lot of hits to it.  One might think that's a horrendous sized dir to have in a custom tag path, but the thing is, running the same code with the same config on CF9 causes no discernable delay at all.

So I think, Matt, you've found a serious bug in CF10 there.  This isn't just going to impact debugging, it's going to impact any code using expandPath() in conjunction with custom tag paths (not an edgecase, I think!)

YIKES

Would you like to raise a bug: https://bugbase.adobe.com/  ?  You discovered it, 'n' all.

I'm amidst some communications with one of the CF10 engineers @ the mo', so I'll bring it to his attention as soon as you post back the bug ref.

I will also say... that code in the classic.cfm debug template is HORRENDOUS.  It should be binned and rewritten by someone competent.  But that's nothing to do with this bug, it's just an observation.

--

Adam

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
New Here ,
Jul 09, 2012 Jul 09, 2012

Copy link to clipboard

Copied

I've created the bug report.

Thanks Adam for all your help

Cheers

Matt

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
LEGEND ,
Jul 09, 2012 Jul 09, 2012

Copy link to clipboard

Copied

I've created the bug report.

For others that are interested, the direct link to the ticket is https://bugbase.adobe.com/index.cfm?event=bug&id=3279677.

--

Adam

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
LEGEND ,
Jul 10, 2012 Jul 10, 2012

Copy link to clipboard

Copied

I've created the bug report.

For others that are interested, the direct link to the ticket is https://bugbase.adobe.com/index.cfm?event=bug&id=3279677.

And, indeed, an already-existing bug for this is under: https://bugbase.adobe.com/index.cfm?event=bug&id=3207170.

I've cross-referenced the two.

--

Adam

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
Engaged ,
Jul 10, 2012 Jul 10, 2012

Copy link to clipboard

Copied

Adam Cameron. wrote:

I've created the bug report.

For others that are interested, the direct link to the ticket is https://bugbase.adobe.com/index.cfm?event=bug&id=3279677.

Hi Matt and Adam,

Good detective work there.  +1, voted (for the new ticket) as follows:  I've verified this as well.  I created THIS.customTagPaths="c:\path\to\dir" where "dir" contains approx 500 folders and 2,000 files of any type.  Then I enabled CF Admin's "Report Execution Times" debug output setting and the resultant "Debug Rendering Time" was approx 15 seconds for the request.  Then I disabled the Report Execution Times setting and the resultant Debug Rendering Time was approx 60ms.  Repeated both scenarios a few times to be sure, and yes, 100% reproducible.  Window 7 64-bit.  I wasn't using expandPath() for the customTagPath btw, fwiw.

Thanks,

-Aaron

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
Engaged ,
Jul 10, 2012 Jul 10, 2012

Copy link to clipboard

Copied

Maybe this is expected behavior, but if the THIS.customTagPaths points to a folder outside webroot, then CF doesn't seem to be able to locate the tags in that folder.  Even when no expandPath() is used.  I always use THIS.mappings/cfmodule, so I never noticed this before.  I'll mess w/ this later and compare to other versions of CF.  Just mentioning it FWIW.

Thanks,

-Aaron

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
LEGEND ,
Jul 10, 2012 Jul 10, 2012

Copy link to clipboard

Copied

I wasn't using THIS.customTagPaths, I was just setting 'em in CFAdmin (not this this is here or there, they'd behave the same way, I should think?).  And I do not expect this behaviour, because doing exactly the same thing in previous versions of CF doesn't exhibit this performance hit.  My expectation is that subsequent versions of CF show improvement in areas that change, not degradation.

--

Adam

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
Engaged ,
Jul 10, 2012 Jul 10, 2012

Copy link to clipboard

Copied

LATEST

Hi Adam,

By "Maybe this is expected behavior" I wasn't referring to this performance issue at all.  I was referring to a tangent that my mind went on, about a possible issue w/ THIS.customTagPaths="c:\some\path\above\webroot" not being able to locate tags in that 'outside of root' folder.  Regarding my tangent 'possible' issue, I'll start a new thread if I find anything new regarding it.

Regarding this issue, it looks like the performance degrades as the total size of a request's custom tag "tree" (CF Admin defined paths + THIS.customTagPaths) increases.  Interesting.  I totally agree that this performance issue is not expected behavior and should be fixed of course.  And exactly, CF should always be improving and not the opposite.

Thanks,

-Aaron

Votes

Translate

Translate

Report

Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
Resources
Documentation