Main menu

Post navigation

May – Using the APD debugger

Far to long I have wanted a simple way to dump a call stack or retrieve
a simple profile. How long does this group of functions run? Which ones are
hit the most frequently? You know how it is…you use print statements
or logging to find your way. No longer…now there is a better way. Now, there
is APD: This month in PUG.

Caveats

I must clear the air first. There are a couple of things to keep in mind before
you try to use this.

Some things to keep in mind

Part of PECL (the C library counterpart to PEAR) but does not ship with PHP.

Being a compiled zend extension you will need access to your php.ini. This may be a problem if you are using a hosting provider

It will work on Windows, but you will most likely need MSVC. I can’t attest to this though…It does work well on RedHat Linux 8. 😉

Remember: as with all Zend Extensions, take care if you are running this on your production server. It will be getting intimate with your engine…and it is version 0.6. 😉

So, what does this do?

APD may save your life. It may feed your cat. It might even help you take our your land-lady’s garbage.

At the very least, php-apd WILL produce a trace of your running PHP script. That alone, is a big deal. In addition to a human-readable trace of your program’s execution, php-apd also comes with a “reporting” tool to digest the info for you.

Not quite following? Well, that’s what examples are for!

Here is a typical run for a pice of content where most of the dynamically generated content has already been cached. To get something similar, just put the following at the start of your program:

apd_trace(99);

Then hit your page as usual. You will get a trace file, ready for analysis. Just point pprofp at it:

Not to shabby. We made 879 database calls…which seems a little excessive. But, it is MySql: The down and dirty fastest database on the planet (IMHO). Keep in mind, this is a pretty large framework that has never really had any optimizing. So, what do things look like when that same piece of content is not cached?

Oh, my! When I saw this the first time, my jaw almost hit the floor! I’m spending almost 2 full seconds calling STRLEN??? There has got to be something going on.

So, I found a problem…what now?

Well, you will need to fire up those deductive reasoning skills they pay you for: Ok, so I know that this is happening when the main pane of content is being generated since it isn’t showing up when that content is cached. I doubt I use strlen THAT many times…maybe if I do a recursive grep on my source tree I can look for something that may suggest something.

Well, it turned up one hit that may be causing it. My gut says that it isn’t related and sure enough it was a dead end. So, time to go the distance. Time to see the log.

If I generate a “calltree” from my log (which takes a very long time on a 2.5M log) I see the problem right away. The log is filled with little gems like this:

All of my prepares are hitting strlen anywhere between 100 and 500 times!! Notice that I’m hitting strlen here 371 times, but I’m calling getone…which means I wanted something tiny RIGHT NOW. Tisk, tisk…it’s in PEAR_DB. Well, let’s crack it open and take a peak.

First I look in DB/mysql.php. However, there is not a prepare function defined in there…it must be in DB/common.php.

Not too bad for 5 minutes of work! (I opened a bug report the next day and it is now fixed, btw.) Of course, the next culprit is now reveled. Again, looking at the tree it is in the same function! This time, it’s the second half.

Which, brings us to the second half of performance tuning: Sometimes, you just can’t do a darn thing. Essentially, their prepare_tokens array only contains a few elements, but by the end of the program they are spaced pretty far apart. This makes end run for a while. It might be helpful to track the index of the last element…but I’ll cop out and just say “this ain’t my library.” 😉

It’s so cool! It must be impossible to install!

Not at all. Just follow the directions in the readme. It’s no more difficult to build and install (in UNIX anyway) than a simple little C program. 🙂

Restart apache and poof! Add a comment if/how you got this running in windows. 😉

What about the callstack?

Perhaps one of it’s coolest functions for you development pleasure is apd_callstack (and the related apd_cluck and apd_croak). If I know it is blowing up somewhere, but I just can’t for the live of me figure out how it got there…you can have it die with a callstack. For instance, If I add the following line in some obscure module:

apd_croak();

Then, what I get as output is a callstack just before it dies.

croaked at /vol1/home/dholmes/site_html/www.remote-clean/admin/lib/catalog.inc line 204
courses->courses() called at /site_html/www/admin/lib/catalog.inc line 142
acadofferingsrender->_renderclasses() called at /site_html/www/admin/modules/catalog/AcadofferingsRender.mod line 106
acadofferingsrender->modulethink() called at /site_html/www/admin/modules/catalog/AcadofferingsRender.mod line 258
acadofferingsrender->run() called at /usr/local/lib/php/siteManager-2.2.0/lib/modules.inc line 93
resourcerender->modulethink() called at /site_html/www/admin/modules/resource/ResourceRender.mod line 258
resourcerender->run() called at /usr/local/lib/php/siteManager-2.2.0/lib/modules.inc line 434
sm_layouttemplate->_runmodules() called at /usr/local/lib/php/siteManager-2.2.0/lib/layoutTemplate.inc line 152
pagedefault->_runmodules() called at /usr/local/lib/php/siteManager-2.2.0/lib/codePlate.inc line 506
sm_sitemanagerroot->completepage() called at /usr/local/lib/php/siteManager-2.2.0/lib/smRoot.inc line 69
???() called at //site_html/www/htdocs/home/catalog/index.php line 0

Oh, of course! It was getting there from the constructor method of the courses object being created by the acadOfferingsRenderer! Now, why didn’t I just see that? 😉 Interestingly enough, you can track the calls through our framework library right to the index.php script that was called in the first place…now that’s handy!!.

Some other status dumping functions (which work great inside a print_r, by the way) include:

apd_dump_regular_resources - Returns an array of resource types (oci8 statement, mysql link) indexed by resource number
apd_dump_persistent_resources - Just about the same thing.
dump_function_table - Should be apd_dump_function table...
override_function - You guessed it, great for replacing php functions with "one liner" replacements
rename_function - Renames functions in the symbol table. Oh, yeah.

Interactive Debugging

So, if you are not impressed yet…go get yourself a copy of the tcputils. Those of you with Debian or BSD probably already have them. Those of us RH users…have to pull them from here.

Once you have the tool tcplisten in your path, fire up an xterm and type:

$ tcplisten -r localhost 7112

Or any other available port number that you wish.

Now, add the following somewhere towards the top of your source code:

apd_set_session_trace_socket("127.0.0.1",APD_AF_INET,7112,99);

You should see it stream a bunch of stuff (if there is a lot more “running” to do” to your terminal. Nice, huh? It get’s better. This time, start up your term with the following:

$ while tcplisten -r localhost 7112; do echo END OF SESSION...; done

and add a apd_breakpoint(1); to your php script.

You should get a rather dangerous command line into your php session. You can echo back values using apd_echo(), set variables in real time, call functions, output to the browser…all the evil things you may want to do. Just type apd_continue(1); to move your script again.

Just to point out, apd_echo() works in your program as well as a simple way to have your “debugging info” go to another window. This works well, but it may be easier to have a function like debugLog() that only calls apd_echo if the module is loaded. You wouldn’t want your production code blowing up when it gets to your non-apd server!

If the command line isn’t your thing, you can also try the PHP-GTK based php mole.