3

I just started using xdebug to profile my application and immediately noticed something strange in the results. One of the require_once functions is shown to be taking around 12% of the processing time. There are quite a few other calls to require_once throughout the application and they're all taking less than 1% of the processing time.

The poorly-performing require_once is including a file that's not significantly different or larger than any of the other files, so I'm not sure what could be causing the problem. Has anybody else ever experienced something like this?

Edit: Wanted to provide a little more info. I'm doing the profiling on windows using XAMPP. Normally the application runs on a unix box. I haven't got an easy way to get xdebug onto the box, so it may not be feasible for me to try and compare the results that way.

One last edit: Here's an idea of the code in case that helps (intentionally being vague for the standard CYA legal reasons blah blah blah):

This class is the one with the slow include (test.inc):

require_once('/xx/yy/zz/dao/basedao.inc');
require_once('/xx/yy/zz/vo/test.inc');

class TestDAO extends BaseDAO {
  // bunch of code to handle database records and return VO objects

And this is the file being included:

require_once('/xx/yy/zz/vo/basevo.inc');

class Test extends BaseVO {
  // bunch of properties, getters/setters, that kinda stuff

I have quite a few other VO/DAO objects that are built the exact same way, without any issue. All are located within the same respective paths.

cdwhatcott
  • 454
  • 2
  • 4
  • 14
  • one last thing: you mention that you can't debug on your Linux platform. You could try creating a VM on your local PC so you can run a copy of Linux locally. It might give you a slightly more accurate picture of how your code is running remotely than your Windows system. – Spudley Jul 16 '12 at 21:52
  • Great suggestion, I'll try that tomorrow! – cdwhatcott Jul 17 '12 at 00:58
  • I've finally got some profiler results from the code on Linux and everything is looking how I expected in the first place... :| Most of the processing time is spent in places you'd expect like database calls and disk IO. The include that stood out before is still slightly slower, but not by such a huge margin. It appears that this file is the first to include some other common files so it makes sense that it would be just slightly slower. I'll avoid benchmarking on Windows like the plague from now on as I've got no explanation for the differing results. – cdwhatcott Jul 18 '12 at 14:55

1 Answers1

0

That does indeed sound odd. Definitely worth pursuing, though it'll be hard to work it out for sure without seeing the actual code. 12% of the total program time for a single require_once() does sound very excessive.

But here are some thoughts on possible avenues of investigation:

  1. require_once() keeps a lookup table of files that have been included, so perhaps it's slowing things down having to refer to that lookup table. If this is the cause, you could solve it by using require() rather than require_once() wherever possible.

  2. Perhaps it's the path lookup? Are you including a path with the filename? If not, it'll be checking in a number of places to find the file; perhaps it isn't in the first place it looks, it'll be taking longer to find the file before it can include it. If this is the cause, you could solve it by being more specific about the path in your code.

Hope that helps. Would be interested to hear how this pans out.

Oh, and by the way -- if your biggest problem area in your code is require_once(), then it sounds like you've done a good job with your code! I dream of the day require_once() even shows up in my profiler reports, let alone with an significant effect.

Spudley
  • 166,037
  • 39
  • 233
  • 307
  • Thanks for the quick response. I'll look into #1 on your list to see if that changes anything. As for #2, I am using an absolute path to the file so I can't imagine it's having to do any searching. – cdwhatcott Jul 16 '12 at 20:58
  • No change, now the require function is showing up as having taken the ~12%. This is definitely one of the stranger problems I've come across. – cdwhatcott Jul 16 '12 at 21:02
  • @cdwhatcott - yep. very very odd. Is the file in the same directory as other files you're including? is there something specific about the directory it's in that's a problem? – Spudley Jul 16 '12 at 21:08
  • It is in the same directory as quite a few other includes, about 7 or 8 other files come from that path. Permissions all look the same as well. – cdwhatcott Jul 16 '12 at 21:13
  • stranger and stranger. :-/ Try creating a new file to include in the same place, with just a stub of code. Add a `require_once` for it in the same place. Does it also take a long time? What if you copy+paste the code in the problem file over to the new file? Does anything change? – Spudley Jul 16 '12 at 21:18
  • A new 'empty' test file was fast. Adding the content of the slow file into the test file, it was still fast. Both the slow file and test file were in the same directory being included by the same file. – cdwhatcott Jul 16 '12 at 21:27
  • 1
    so to complete the test, if you copy+paste all the code from slow file A to fast file B, and then remove the line that includes the original file, what happens? in other words, the new file is now a direct replacement for the old one. Is it still just as fast? Maybe you had a disk error on the file which was causing it to struggle to load it? A fresh copy might solve it. (but if this is the case, you'll want to be careful of possible drive failure) – Spudley Jul 16 '12 at 21:31
  • That didn't change anything... in fact, I left the filename as test.inc and just updated the class name to be correct. Then removed the include of the slow file, and now the new 'fast' file is just as slow. I am stumped. :| – cdwhatcott Jul 16 '12 at 21:40
  • Wow. I'm also pretty stumped now. I'm going to have to call it a night anyway. Really sorry I haven't been able to resolve this one. Hope I've at least helped you rule a few things out, but I'd love to hear how this one pans out if you do manage to resolve it in the end. – Spudley Jul 16 '12 at 21:44
  • @Spudley, " ... I dream of the day require_once() even shows up ..." Maybe that's because you've got Xcache/APC/whatever running by default ;-) – TerryE Jul 16 '12 at 22:46