Adobe Community: CF10 debugging slow performance

Currently Being Moderated

1. Matt Usher,

Jul 6, 2012 5:50 AM in reply to Matt Usher

Report

Debug Rendering Time: 147333 ms

|

Mark as:

Currently Being Moderated

2. Adam Cameron.,

Jul 6, 2012 6:03 AM in reply to Matt Usher

Report

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

|

Mark as:

Currently Being Moderated

3. Matt Usher,

Jul 6, 2012 7:19 AM in reply to Adam Cameron.

Report

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.

|

Mark as:

Currently Being Moderated

4. Matt Usher,

Jul 9, 2012 8:19 AM in reply to Matt Usher

Report

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

|

Mark as:

Currently Being Moderated

5. Adam Cameron.,

Jul 9, 2012 8:36 AM in reply to Matt Usher

Report

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

|

Mark as:

Currently Being Moderated

6. Matt Usher,

Jul 9, 2012 9:44 AM in reply to Adam Cameron.

Report

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

<html>

<head>

</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.

|

Mark as:

Currently Being Moderated

7. Adam Cameron.,

Jul 9, 2012 10:40 AM in reply to Matt Usher

Report

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

|

Mark as:

Currently Being Moderated

8. Adam Cameron.,

Jul 9, 2012 11:34 AM in reply to Adam Cameron.

Report

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

|

Mark as:

Currently Being Moderated

9. Matt Usher,

Jul 9, 2012 12:42 PM in reply to Adam Cameron.

Report

I've created the bug report.

Thanks Adam for all your help

Cheers

Matt

|

Mark as:

Currently Being Moderated

10. Adam Cameron.,

Jul 9, 2012 4:07 PM in reply to Matt Usher

Report

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

|

Mark as:

Currently Being Moderated

11. Adam Cameron.,

Jul 10, 2012 12:18 AM in reply to Adam Cameron.

Report

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

|

Mark as:

Currently Being Moderated

12. itisdesign,

Jul 10, 2012 2:51 AM in reply to Adam Cameron.

Report

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

|

Mark as:

Currently Being Moderated

13. itisdesign,

Jul 10, 2012 3:00 AM in reply to itisdesign

Report

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

|

Mark as:

Currently Being Moderated

14. Adam Cameron.,

Jul 10, 2012 3:18 AM in reply to itisdesign

Report

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

|

Mark as:

Currently Being Moderated

15. itisdesign,

Jul 10, 2012 4:20 AM in reply to Adam Cameron.

Report

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

|

Mark as:

ColdFusion

CF10 debugging slow performance

Jul 5, 2012 12:30 PM

More Like This

Bookmarked By (0)

Answers + Points = Status