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:
$ pprofp -u pprof.01581
Trace for /vol1/home/dholmes/site_html/www.remote-clean/admin/common.inc
Total Elapsed Time = 1.14
Total System Time = 0.05
Total User Time = 0.79
Real User System secs/ cumm
%Time (excl/cumm) (excl/cumm) (excl/cumm) Calls call s/call Memory Usage Name
--------------------------------------------------------------------------------------
25.3 0.23 0.23 0.20 0.20 0.01 0.01 879 0.0002 0.0002 199816 mysql_fetch_array
17.7 0.17 0.17 0.14 0.14 0.00 0.00 2239 0.0001 0.0001 3048 strlen
7.6 0.07 0.07 0.06 0.06 0.00 0.00 5 0.0120 0.0120 701608 require_once
5.1 0.02 0.02 0.04 0.04 0.00 0.00 192 0.0002 0.0002 51008 is_object
5.1 0.04 0.04 0.04 0.04 0.00 0.00 114 0.0004 0.0004 40 is_resource
3.8 0.08 0.08 0.03 0.03 0.00 0.00 53 0.0006 0.0006 568 mysql_query
3.8 0.04 0.15 0.03 0.12 0.00 0.01 15 0.0020 0.0080 352048 include_once
2.5 0.18 0.18 0.02 0.02 0.00 0.00 182 0.0001 0.0001 32616 sizeof
2.5 0.01 0.01 0.02 0.02 0.00 0.00 183 0.0001 0.0001 -2760 is_array
2.5 0.00 0.00 0.02 0.02 0.01 0.01 53 0.0004 0.0004 848 mysql_select_db
2.5 0.04 0.28 0.02 0.23 0.00 0.02 871 0.0000 0.0003 6104 db_mysql->fetchrow
2.5 0.02 0.02 0.02 0.02 0.01 0.01 2 0.0100 0.0100 278768 define
2.5 0.01 0.01 0.02 0.02 0.00 0.00 79 0.0003 0.0003 -130896 get_class
2.5 0.02 0.02 0.02 0.02 0.00 0.00 159 0.0001 0.0001 9776 preg_match
1.3 0.01 0.01 0.01 0.01 0.00 0.00 53 0.0002 0.0002 2536 mysql_num_rows
1.3 0.00 0.00 0.01 0.01 0.00 0.00 123 0.0001 0.0001 10128 preg_match_all
1.3 0.01 0.25 0.01 0.21 0.00 0.02 881 0.0000 0.0002 148016 db_mysql->fetchinto
1.3 0.01 0.01 0.01 0.01 0.00 0.00 23 0.0004 0.0004 2440 split
1.3 0.00 0.00 0.01 0.01 0.00 0.00 1 0.0100 0.0100 -3408 resourcerendertoolsbox->getjs
1.3 0.00 0.00 0.01 0.01 0.00 0.00 17 0.0006 0.0006 3272 method_exists
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?
$ pprofp -u pprof.01171
Trace for /vol1/home/dholmes/site_html/www.remote-clean/admin/common.inc
Total Elapsed Time = 5.04
Total System Time = 0.12
Total User Time = 3.46
Real User System secs/ cumm
%Time (excl/cumm) (excl/cumm) (excl/cumm) Calls call s/call Memory Usage Name
--------------------------------------------------------------------------------------
54.0 2.04 2.04 1.87 1.87 0.03 0.03 27917 0.0001 0.0001 25728 strlen
5.8 0.24 0.24 0.20 0.20 0.00 0.00 958 0.0002 0.0002 268008 mysql_fetch_array
4.6 0.11 0.11 0.16 0.16 0.00 0.00 686 0.0002 0.0002 65320 get_class
2.9 0.31 0.31 0.10 0.10 0.00 0.00 825 0.0001 0.0001 102424 sizeof
2.6 0.11 0.11 0.09 0.09 0.00 0.00 1317 0.0001 0.0001 45320 is_array
1.7 0.06 0.06 0.06 0.06 0.00 0.00 137 0.0004 0.0004 37960 split
1.7 0.02 0.02 0.06 0.06 0.00 0.00 415 0.0001 0.0001 5560 is_resource
1.7 0.12 0.12 0.06 0.06 0.01 0.01 578 0.0001 0.0001 8936 file_exists
1.4 0.04 0.04 0.05 0.05 0.00 0.00 329 0.0002 0.0002 13608 trim
1.4 0.20 0.27 0.05 0.12 0.02 0.03 22 0.0023 0.0055 885720 include_once
1.4 0.04 0.04 0.05 0.05 0.01 0.01 4 0.0125 0.0125 586632 require_once
1.2 0.05 0.05 0.04 0.04 0.00 0.00 571 0.0001 0.0001 -61280 in_array
0.9 0.80 0.80 0.03 0.03 0.01 0.01 156 0.0002 0.0002 776 mysql_query
0.9 0.07 0.07 0.03 0.03 0.00 0.00 424 0.0001 0.0001 24600 preg_match
0.9 0.03 0.03 0.03 0.03 0.00 0.00 156 0.0002 0.0002 -33720 db_mysql->modifyquery
0.9 0.07 0.07 0.03 0.03 0.01 0.01 1028 0.0000 0.0000 72280 is_object
0.9 0.04 0.29 0.03 0.26 0.00 0.00 871 0.0000 0.0003 6152 db_mysql->fetchrow
0.9 0.00 0.28 0.03 0.11 0.00 0.00 327 0.0001 0.0003 -1192 sm_sitetag->getvar
0.9 0.02 0.28 0.03 0.23 0.00 0.00 984 0.0000 0.0002 159352 db_mysql->fetchinto
0.6 0.01 0.01 0.02 0.02 0.00 0.00 161 0.0001 0.0001 8632 mysql_escape_string
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:
$ pprofp -t pprof.01171 > calltree.txt
--------SNIP---------
db_mysql->getone
settype
sizeof
db_mysql->prepare
split
strlen (371x)
end
key
db->iserror
is_object
db_mysql->execute
--------SNIP---------
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.
// ------------SNIP--------------
function prepare($query)
{
$tokens = split("[&?!]", $query);
$token = 0;
$types = array();
for ($i = 0; $i !!!!!!!!!modifyquery
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.
$this->prepare_tokens[] = &$tokens;
end($this->prepare_tokens);
$k = key($this->prepare_tokens);
$this->prepare_types[$k] = $types;
$this->prepared_queries[$k] = &$query;
return $k;
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. 🙂
First untar it:
$ tar -xzf apd-xxxx.tgz $ cd apd-xxxx $ phpize $ ./configure $ su -c "make install" (as root)
You can use your phpinfo() to find your extension dir. If I recall I had to manually copy my apd.so by hand. So make sure it exists in your extension directory.
Next, open your php.ini. Again, use your phpinfo to make sure you have the right one.
Check the readme for the proper usage, but in my case I added:
zend_extension = /usr/local/lib/php/extensions/no-debug-non-zts-20020429/apd.so apd.dumpdir = /tmp/dump_dir
Again, this is for my case only…your milage WILL vary.
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!!.
We can a few other related methods. All three are summarized below
apd_croak - Prints a callstack and dies. apd_cluck - Prints a callstack with a warning. apd_callstack - Returns a callstack as an array (for FANCY user-side formatting)
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.
You can look at an example of using apd_breakpoint();
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.
Cool Commands
Here are a couple of little helpers I recommend using:
Does a standard profile on the most recent pprof dump (presuming you are in your dump directory) $ pprofp -u `ls -t pprof* Generates your calltree off of the most recent pprof dump $ pprofp -t `ls -t pprof* | head -1 ` > calltree.txt Repeatedly opens a monitor console for your apd_set_session_trace_socket() $ while tcplisten -r localhost 7112; do echo END OF SESSION...; done
More Links
More Debuggers
This is just a sampling of the ones I bumped into…feel free to add more in the comments.
- Zend Studio
- Actice State’s Komodo
- Xdebug extension (Very Cool…much like apd. A MUST SEE.)
Happy Debugging!!!
This month we will about a little class for generating reports using php. If you are really interested in new and exciting ways to separate your data layer from your presentation layer…read on.