Today was a great day.

An ordinary domestic weekend kind of a day, but blessed with great weather and no engagements for any of us.

A chance for me to catch up on many of the long neglected house and garden chores, and for our family to enjoy some chilled-out time around the house.

We’ve been burning more wood on the fire recently and the chimney was overdue a sweep. So I blocked up the fireplace with a bin bag and some foam, then climbed on the roof and swept down from the chimney pot. It was my first time sweeping a chimney and this method made it very simple. I just left the fireplace sealed up for a few hours for the dust to settle before opening it up and shovelling out the shoot along with the old ash.

 

My wife had seen a recipe for “Hedgerow Jelly” by Elisabeth Luard in a magazine, so she, and our two daughters, walked out down the local lanes to find the ingredients: 1kg crab apples or Bramleys; 250g blackberries, 250g sloes or bullaces or damsons, 250g rowan berries or elderberries, 125g hawthorn berries (haws), 125g rosehips (wild or cultivated), plus about 2 litres of water and about 2kg of granulated sugar.

(Our eldest daughter decided to take photographs of the process, which ultimately led to this blog post — I normally rarely post about home life.)

Meanwhile, after clearing gutters and sweeping the drive, I was working down by the lake front thinning out some trees. A few months ago we had a group of big old trees one corner of our garden cut down. Mostly pine with some silver birch and hazel. (You can see in the photo the large pile of wood I still need to chop, chop, chop.) That gave us a view of the lake again. Something we’d lost over the years since we moved in as the trees have grown up and bushed out.

Having got that narrow view of the lake I wanted to extend it through the trees to the right by thinning out their lower branches.

The summer weather in Ireland has been pretty poor the last few years. We seem to get a few lovely weeks in spring, then summer is a mostly washout with grey skies and regular showers. Then, just after the kids go back to school, we get a few bright weeks again—the Irish “Indian Summer”—around September/October. Fabulous days like today.

There’s a reason Ireland is so green. It rains. A lot. Especially in the west were we are. Despite the bright sunshine today the grass was squelching under my feet. The logs need to be stored or they’ll rot over the winter. I shifted a few wheelbarrow loads today and started clearing a space off the grass to store them.

A friend and I wielded axes a few weeks ago so we’ve a reasonable stockpile of split logs now, which I finished stacking today. I’ve been told the wood gets harder to split the longer its left, and I don’t fancy trying to split logs on dark wet winter nights, so I guess I need to keep at it.

Back indoors the domesticity continued with our eldest daughter making the topping for an Apple Crumble.

Our eating apple tree is still recovering from the pruning I gave it last winter (it’s first for many years) but our cooking apple tree seems very happy this year.

Yum!

That was the glossy edited version of the day. The uncut version includes me falling off the ladder into the lake, our youngest daughter having a tantrum and throwing handfuls of apple crumble onto the floor, and me pouring scalding hot Hedgerow Jelly over my hand. Ahh, domestic bliss!

At OSCON this year I gave a talk on my new pet project Devel::NYTProf v2 to a packed room. Turned out to be a lot of fun.

“The first thing I need to do is talk about Devel::DProf because it needs to be taken out and shot.”

I made a screencast of the 40 minute talk which you can watch on blip.tv here. Worth watching for the background on profilers, the demo of NYTProf, and the questions, not to mention the teasing I get along the way.

One of the final questions was about the size of the profile data file that NYTProf produces. One of the major drawbacks of statement-level profiling is the volume of data it generates while profiling your code. For every statement executed the profiler streams out the file id, the line number, and the time spent. For every statement! When trying to profile a full application doing real work the volume of data generated quickly becomes impractical to deal with. Multi-gigabyte files are common.

This was the major problem with Devel::SmallProf, which generated text files while profiling. Salvador Fandiño García addressed that in Devel::FastProf by writing the data in a compact binary form. A vast improvement that contributed to Devel::FastProf (on which Devel::NYTProf is based) being the first statement-level profiler worth using on large applications. Even so, the volume of data generated was still a problem when profiling all but short running applications.

NYTProf 2.03 was producing profile data at the rate of about 13MB per million statements executed. That might not sound too bad until you realise that on modern systems with cpu intensive code, perl can execute millions of statements every few seconds.

I could see a way to approximately halve the data volume by changing the format to optimize of the common case of consecutive statements being in the same file, but that wasn’t going to be enough. The best way forward would be to add zip compression. It would be easy enough to pipe the output stream through a separate zip process, but that approach has a problem: the zip process will be soaking up cpu time asynchronously from the app being profiled. That would affect the realtime measurements in an unpredictable way.

I realized back in June that a better approach would be to embed zip compression into NYTProf itself. Around the end of July Nicholas Clark, current Perl Pumpkin, got involved and was motivated to implement the internal zipping because he was “generating over 4Gb of profile data trying to profile the harness in the Perl 5 core running tests in parallel“.

He did a great job. The zlib library is automatically detected at build time and, if available, the code to dynamically route i/o through the zip library gets compiled in. The output stream starts in normal mode, so you can easily see and read the plain text headers in the data file, then switches to zip compression for the profile data. How well did it work out? This graph tells the story:

(The data relates to profiling perlcritic running on a portion of its own source code on my MacBook Pre 2GHz laptop. I only took one sample at each compression level so there may be some noise in the results.)

The data file size (red) plummets even at the lowest compression level. Also note the corresponding drop in system time (yellow) due to the reduction in context switches and file i/o.

I’ve set the default compression level to 6. I doubt you’ll want to change it, but you can by adding compression=N to the NYTPROF environment variable.

Here are the change notes for the 2.04 release:

  Fixed rare divide-by-zero error in reporting code.
  Fixed rare core dump in reporting code.
  Fixed detection of #line directives to be more picky.
  Fixed some compiler warnings thanks to Richard Foley.
  Added on-the-fly ~90% zip compression thanks to Nicholas Clark.
    Reduces data file size per million statements executed
    from approx ~13MB to ~1MB (depends on code being profiled).
  Added extra table of all subs sorted by inclusive time.
  No longer warns about '/loader/0x800d8c/...' synthetic file
    names perl assigns reading code from a CODE ref in @INC

Enjoy!

Dr. Albert Bartlett is emeritus Professor of Physics at the University of Colorado at Boulder, USA. He has given this lecture on “Arithmetic, Population, and Energy” over 1,500 times.

“The greatest shortcoming of the human race is our inability to understand the exponential function.”

A challenging statement. Having seen the lecture now I can understand why it has been so popular, and is so important. I came across it recently and felt it was worth sharing.

You can watch it on YouTube here as a series of bite-size 9 minute clips.

(After that you might like this unrelated take on applying risk management.)

I spent a very pleasant few days in Pisa, Italy, last week. I’d been invited to speak at the Fourth Italian Perl Workshop. The workshop was a great success. In fact calling it a “workshop” is selling it short. It’s more of a mini-conference:

“2 days of conference, 2 simultaneous tracks, more than 30 talks, 120 attendees, 20 sponsors and many international guests”

The whole event ran very smoothly thanks to a great team lead by Gianni Ceccarelli, Francesco Nitido, and Enrico Sorcinelli. I’ll echo the compliments of one attendee “Complimenti sinceri agli organizzatori! Bravissimi! Tutto perfetto!“

I gave short talk on Gofer on the Thursday, and then two 40 minutes talks on Friday: Perl Myths, and Devel::NYTProf. I hope to upload screencasts and slides next week. The talks were all recorded on video so I imagine they’ll be uploaded at some point. I’ll add links here to them when they are.

The majority of the sessions were in Italian so, since my Italian is practically non-existant, I had plenty of time to work.

Or at least try to. The one disappointment of the trip for me was the apparent poor quality of the Italian internet. Using mtr I’d regularly see over 20% packet loss within telecomitalia.it and interbusiness.it from my hotel room. Occasionally over 50%. It got much better at night, so I’d do more work then. At the conference venue the Italian academic network (garr.net) also regularly had over 20% packet loss at its link to the internet. All this was, of course, outside the control of the organisers.

The “corridoor track” at perl conferences is always good. I had a chance to talk to Rafel Garcia-Suarez (and meet his lovely wife and new baby son), Matt S Trout, Hakim Cassimally, Michel Rodriguez, Marcus Ramberg, and many others.

I had opted to take a very early fight so I’d have a day being a tourist in Pisa before the conference started. The weather was beautiful and I had a lovely time strolling though the streets of this ancient city.

I didn’t take my camera with me, but I did take my iPhone so I was able to capture a few snaps as I strolled around and climbed the tower. (Yes, it really does lean in a disconcerting “it must be about to fall down” way. All the more dramatic when you’re up close and can appreciate the massive scale of the tower.)

It felt strange when I first set up this blog. What would I write about? Who would care?

For several years now I’ve been giving talks at conferences and workshops. I’d generally upload a PDF of the slides somewhere, or at least email them to anyone that asked. I’ve now added a special page on the blog where I can list all the talks I’ve given. That now acts as a single location to find all my talks and links to slides any related materials. (It’s currently a work-in progress. I’ll be filling it in from time to time. Any major updates will be accompanied by a blog post.)

Slides, no matter how good, miss much of the real event. No ad-libs, no questions and answers. When writing slides I’m always caught between the desire write little, so the audience can pay attention to what I’m saying, and to write lots, so people reading the slides later still get a reasonably full picture.

There’s also the problem of notes. I often use ‘presenter notes’ on the slides to give extra information. Both to myself, if I may need it while presenting, and also for links to data sources and credits for images used. I’ve uploaded some talks to slideshare.net but I have to include a separate version with notes (which is useful for download and print, but almost unreadable in their viewer.

I tried making a video of a talk on a camcorder. The results weren’t great. Grainy, noisy, hard to read, and massive video files.

Then I decided to try using screencasting software. I bought a great wireless USB microphone and the amazing ScreenFlow screencasting software. Now I can to capture everything in fine detail and edit it easily afterwards.

Great. Now what? I needed somewhere to host the (very large) videos. I looked around and tried a few, like vimeo, but wasn’t happy with the results. Vimo, for example, transcode to quite a low resolution and don’t let viewers download the original.

Eventually I found the wonder that is blip.tv. A whole laundry list of great features. If you produce videos of any kind, give them a look.

So, now I have my own TV channel.

Strange world!

I gave a updated version of my earlier Perl Myths talk at OSCON this year. It includes updated numbers, updated job trend graphs (showing good growth in perl jobs) and slides for the perl6 portion that were missing from the upload of the previous talk.

Two versions of the slides are available: one with just the slides on a landscape page, and another with slides and notes on a portrait page.

I also have a screencast of the presentation which I hope to edit and upload before long. (I’ll update this page and post a new note when I do.)

This is a collection of links to things discussed, or just mentioned, at OSCON that I found interesting enough to note. Hopefully one of a series for OSCON 2008, as time allows.

These items are from a great talk on “A Streaming Database” by Rafael J. Fernández-Moctezuma at PDXPUG day.

Hancock is a C-based domain-specific language designed to make it easy to read, write, and maintain programs that manipulate large amounts of relatively uniform data. In addition to C constructs, Hancock provides domain-specific forms to facilitate large-scale data processing

The CQL continuous query language (google)

Borealis is a distributed stream processing engine. Borealis builds on previous efforts in the area of stream processing: Aurora and Medusa.

CEDR is the Complex Event Detection and Response project from Microsoft Research.

Google Protocol Buffers “allow you to define simple data structures in a special definition language, then compile them to produce classes to represent those structures in the language of your choice”.
Which seems like Thrift which is “a software framework for scalable cross-language services development. It combines a powerful software stack with a code generation engine to build services that work efficiently and seamlessly between langauges”.

This is the back story to the development of NYTProf v2.

Earlier this year (2008) I needed to do some performance profiling of the source code of a large application. Like many perl developers, my first instinct was to try using Devel::DProf (actually the Apache::DProf wrapper as it was a mod_perl application). It was not a great experience.

DProf

DProf seems easily confused by unusual control flow, spewing “… has unstacked calls” warnings. Also, the subroutines it said were taking the most time didn’t make sense to me. Eventually I worked out that Devel::DProf is effectively broken.

The application I was trying to profile has quite a few large subroutines, so knowing just the time spent in the subroutine as a whole didn’t help much for those. I wanted to know where in the subroutine the time was being spent.

FastProf

That led me to look at line-based profilers. At the time there as only one worth looking at, Devel::FastProf by Salvador Fandiño García (which was based on Devel::SmallProf by Ted Ashton).

Line profilers spit out a stream of “file id, line number, time spent” records to a file. The time between starting one statement and starting the next is measured and associated with the line number of the statement.

Devel::FastProf was great. Fast and effective. It gave me far more accurate timings, and when I made changes in the code it highlighted I could see an immediate effect on performance.

Devel::FastProf was great, but I wanted more. The lack of subroutine level timing was frustrating. When you have a ~100,000 lines of code, knowing the time spent on each, and how many times it was executed, is less useful than you may think - there’s just too much detail. Especially when looking for structural problems in the code, or for good places to add caching, or pass extra information down a call chain to save expensive calls deeper in the code. There’s a need for both subroutine and line level timings when profiling.

Idea

I’d had an idea: The line number output in the FastProf profile need not be the line number of the statement. It could output the line number of the subroutine containing the statement. Then you’d automatically get subroutine level timings! Simple.
Then I wondered if it was possible to find the line number of the block the statement was in. That would give block level timing! A first for any perl profiler.

My perl internals knowledge was getting rusty as it was a few years since I’d been Pumpkin for the 5.4.x release, so I asked the wizards on perl5-porters. They gave me hope and enough clues to get going.

Salvador kindly moved the Devel::FastProf code to a public svn, so I could contribute more easily, and I started hacking. I added code to find the nearest enclosing block or sub and it proved very useful.

When I’m optimizing I start by identifying “locally inefficient code”. That is, code you can optimize without significant structural changes. Without making changes outside the subroutine. Moving code outside loops is a common example. Subroutine timings identify the hot subs, then block and line timings pinpoint the hot spots in the code.

That’s the low hanging fruit. Easy pickings, and often very effective. But there’s a limit to how far that’ll take you.

Callers and Callees

There are two ways to optimize a hot piece of code: make it faster, or execute it less often. The former tends to get much more attention than the latter. It’s important to remember to keep stepping back. To keep looking for the bigger picture.

When I’m optimizing I often use a well defined chunk of work, like 10 requests to the same URL, so I can see of the number of times a subroutine is called “feels right”. That often shows subs being called “too often”. But what then? You need to know why the sub is being called too often, so you need to know where it’s being called from.

In Devel::FastProf I added counting of subroutine callers two-levels up the call stack. So I could see that foo() was called 10 times by bar() and that of those 10 calls from bar() 7 has come from baz() and 3 from boo(). It was very simplistic, slow (implemented in perl) and only had counts, not timings, but proved very useful.

Using these additions to Devel::FastProf I reduced the CPU usage of the application by over 40%. Not bad. (I could see another 10% or so to be gained fairly easily but had to draw the line somewhere.)

NYTProf

Meanwhile Adam Kaplan had forked Devel::FastProf, added a test harness and tests, made some internal improvements, grafted on an html report derived from Devel::Cover, and released it as Devel::NYTProf.

When I saw NYTProf I switched to working on that. Again, Adam was kind enough to move the code to a public svn repository. I was attracted not so much by the html report as by the test harness. A lesson to anyone wanting to attract developers to an open source project!

Testing profilers is hard and Adam had come up with a good basic testing framework which was easy to extend. NYTProf now has a strong test suite that profiles 19 different perl scripts with four different combinations of profiler options. The test suite has proven invaluable in identifying regressions during development, and for identifying portability issues between perl versions.

I re-implemented the block/sub level profiling and the subroutine caller tracking from FastProf in NYTProf, but with more care, more attention to performance, and now tests.

I was particularly pleased with the subroutine caller tracking. It intercepts the entersub opcode and uses the save stack for storage and to trigger a ‘destructor’ call to end the timing when the subroutine is exited by any means. The end result is an extremely fast and robust subroutine call profiler. I plan to add an option to disable the other profiler so you can just get subroutine profile details when you don’t need statement level details. It currently lacks the ability to give exclusive times but I think I’ve an efficient solution for that. (Update: Implemented in r340 and r343 so will be in the 2.02 release.)

Accuracy

Another key innovation was to fix a fundamental problem inherent in all statement profilers. Consider a statement that calls a subroutine and then performs some other work that doesn’t execute new statements, for example:

    foo(...) || mkdir(...);

In all other statement profilers the time spent in remainder of the expression (mkdir in the example) will be recorded as having been spent on the last statement executed in foo()! Here’s another example:

    while (<>) {
        ...
        1;
    }

After the first time around the loop, any further time spent evaluating the condition (waiting for input in this example) would be be recorded as having been spent on the last statement executed in the loop!

I fixed this in NYTProf by intercepting all the opcodes which indicate that control is returning into some previous statement and adjusting the profile accordingly.

Reporting

As much effort, if not more, went into the reporting side of the code. And there’s a lot more to be done there. My goal is to keep growing the data model classes to the point where any reporting code can get the information it needs easily enough that there’s no longer a need for the rather limiting Reporter class.

I’d like to see a single ‘nytprof’ command line tool that loads a class to generate the report. That would replace nytprofhtml and nytprofcsv. That would make it easy for other developers to release ‘nytprof reporting modules’ to CPAN.

For example, one very useful report that FastProf has but NTProf currently lacks is a list of most expensive lines (or blocks, or subs) output in the format used by compiler error messages. The format is important because most editors have a special mode for reading such files that means you can hop from one ‘most expensive line’ to the next with a single key stroke. (For vim that’s called quickfix mode.) That’s a wonderful way to browse the hotspots and make edits on the spot.

Future

There are many, many, ways NYTProf can be enhanced further. As I’ve worked on it I’ve dumped ideas, issues and random notes into the HACKING file.

Thanks

I’d like to end by expressing my thanks to Salvador Fandiño García and especially Adam Kaplan for allowing me to contribute to the modules they created and tolerating my strong ideas with understanding. Thank you both. It’s been quite a ride.

After much hacking, and just in time for OSCON, I’m delighted to announce the release of Devel::NYTProf version 2. A powerful, efficient, feature-rich perl source code profiler.

“If NYTProf 1 is a Toyota, then 2.0 is a Cadillac”
— Adam Kaplan, author of NYTProf 1.

The Short Story

(I’ve written up the long story, for the record, in another post.)

Adam forked Devel::FastProf (the best statement-level profiler at the time), added a test harness and tests, made some internal improvements, and grafted on an html report derived from Devel::Cover. The resulting Devel::NYTProf v1 was a big hit.

Meanwhile I’d been working on Devel::FastProf, contributing some interesting new profiling features, but it had no test harness and no html reports. When Adam released NYTProf I switched. Attracted not so much by the html report as by the test harness. (A lesson to anyone wanting to attract developers to an open source project.)

I started out by adding in the same new features I’d been adding to FastProf, albeit with more polish and tests. And then I got carried away…

“Holy shit! That is amazing.”
— Andy Lester, after using a recent development version.

Example Screen Shots

As an example I’ve used NYTProf to profile perlcritic 1.088 running on its own source code.

$ cd Perl-Critic-1.088
$ perl -d:NYTProf -S perlcritic .
$ nytprofhtml
$ open nytprof/index.html

The first image is the main index page, showing the top few subroutines and the start of the list of all source files.

Each source file has links to separate line-level, block-level, and sub-level reports (though I hope to merge them in future). Clicking on a subroutine name takes you to the line-level report for the file it’s defined in and positions you at the subroutine definition.

(The color coding is based on Median Absolute Deviation of all the values in the column, same as in NYProf v1.)

Here’s the all_perl_files() subroutine, for example:

The colored numbers show the number of statements executed, the total time taken, and the average. The statement times are always exclusive times. Time actually spent on that statement, the expressions and any built-in functions it uses. It doesn’t include any time spent executing statements elsewhere in subroutines called by it. In NYTProf subroutine timings are inclusive and statement timings are exclusive.

Where did you come from and where are you going?

Notice the grey text.

On lines that define a subroutine NYTProf now adds ‘comments’ giving the total number of times the sub was called, the inclusive time spent in that sub, and the average. Then it adds a break-down of the same details for every location that called the subroutine. Here’s a better example of that:

On lines that call subroutines NYTProf now adds ‘comments’ giving the name of the actual subroutines called (resolving code refs to subroutine names, including the class that handled a method call). It also tells you how many calls were made and how much time was spent in that subroutine for calls made from that line. Here’s an example:

When you mouse-over the grey text it turns black and you can click on embedded links to take you to the callers or callees. So with a few clicks you can run up and down the call stack exploring where the time is being spent and where the hot spots are being called from. The ability to explore the code so easily, guided by these performance signposts is incredibly useful.

Rolling up for a higher level view

Sometimes per-statement timing can overwhelming. In large subroutines it becomes “hard to see the wood for the trees”. So, for the first time in any Perl profiler, NYTProf now provides a block-level view of the timing data:

What’s happening here is that NYTProf is taking the same time measurements per statement, but instead of accumulating the time against the line the statement is on, it accumulates it against the line of the first statement in the enclosing block. (The actual line it accumulates it against isn’t ideal in some cases. I’m hoping to improve that soon.)

This report is a little more tricky to read but can be very useful, especially in large subroutines. (I hope to improve the readability with some css :hover magic in future.)

The subroutine-level report is very similar except that all the timings are accumulated against line of the first statement in the subroutine.

Have a Look

Back in June I gave a talk at the Irish Open Source Technology conference where I showed the first version of the annotated html report (which I’d been hacking on till 3am the night before while struggling with a cold - presentations are great motivators). You can see the 15 minute video here or here).

Explore for yourself

I’ve uploaded the full set of reports for you to explore here. Take a look. Let me know what you think.

“Measure twice, cut once.“

To measure the performance of your Perl code many developers instinctively reach for Devel::DProf. The venerable perl profiler dates back to 1995.

When profiling you have two broad choices: cpu-time vs wallclock time, and subroutine-level profiling vs line-level profiling. DProf is a subroutine-level profiler. (I’ll talk more about subroutine-level profiling vs line-level profiling in an upcoming post about the soon-to-be-released NYTProf 2.0.)

Measuring cpu-time should, in theory, give you a clear picture of the time spent by perl executing your code, independent of the load on the machine or delays waiting for i/o. Sadly life isn’t so simple.

The big problem is that on most systems cpu-time measurement has a resolution of 0.01 seconds (a HZ value of 100). That may not sound like much time, but you can execute a lot of perl code, and a lot of subroutine calls, in that time.

So any profiler using cpu-time with such a course granularity is going to give ‘noisy’ results. Some subroutines may appear to be slow because the cpu-time ‘tick’ happened to occur more while those subs were running. Other subroutines may appear to be fast because the cpu-time ‘tick’ doesn’t happen much while they’re running.

Try playing around with the venerable Devel::DProf like this:

$ perl -we 'print "sub s$_ { sqrt(42) for 1..100 }; s$_({});\n" for 1..1000' > x.pl
$ perl -d:DProf x.pl
$ dprofpp
Total Elapsed Time = 0.047999 Seconds
  User+System Time = 0.047999 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 20.8   0.010  0.010      1   0.0100 0.0100  main::s986
 20.8   0.010  0.010      1   0.0100 0.0100  main::s29
 20.8   0.010  0.010      1   0.0100 0.0100  main::s321
 0.00       - -0.000      1        -      -  main::s322
 0.00       - -0.000      1        -      -  main::s323
 0.00       - -0.000      1        -      -  main::s329
 0.00       - -0.000      1        -      -  main::s330

Clearly nonsense. Out of 1000 subroutines that would all take about the same length of time, a cpu-time ‘tick’ happened to occur in those three. The rest of the subroutines appear to be ‘free’. (If you play with this yourself you’ll probably need to adjust the 1..100 to see the effect on your system.)

Using dprofpp -r (to “display elapsed real times” instead of cpu-times) gives a very similar granular result. That’s because Devel::DProf artificially reduces the resolution of real time to match the granular cpu-time! It’s also odd that dprofpp doesn’t provide an option to sort by elapsed time, but there’d be little value anyway given the low resolution.

Many people have reported strange results from Devel::DProf over the years. Design decisions that made sense back in 1995 are now causing problems as CPUs have got so much faster. Several have implemented alternative profilers.

Using cpu-time is effectively a kind of statistical sampling. That’s fine as long as you remember it and interpret the results accordingly. The work-around for the course granularity is to execute the code for long enough for the effects to be averaged out. But that can be inconvenient, and how do you know how much is enough?

Personally I’d recommend using wallclock time for profiling. I want to know how much time was spent waiting for network, waiting for disk, waiting for cpu. Those are often significant factors in performance issues. Too many network round trips, or too many individual disk requests, for example, can easily kill performance. If you only profile cpu time you may not spot these kinds of problems. You may just be chasing the random ghosts of occasional cpu clock ticks.

So which profiler would I recommend? Stay tuned for an announcement in a day or so. Easy! NYTProf 2.0

Just found the excellent Concurrency and Erlang page by André Pang. (I’m not sure how I got there, but I started froma post by Pedro Melo.)

The page has great links to quality articles and resources with commentary and context for each. It also includes sections specific to C, Objective-C, C++, Java, Python, JavaScript, and Haskell.

What, no Perl? Well, using threads in Perl 5 is rather painful. I’ve never had to use threads with Perl 5 (beyond making DBI thread safe a few years ago) and I’d be happy to never have to.

On the other hand, I believe people are using threads successfully, though I’ve no handy links for you beyond pointing out that CPAN offers a number of solid Thread:: modules.

All this reminded me that I’d never got around to reading Parrot’s Concurrency design document. So I did. I liked it as a statement of direction, though it’s a little thin on the interaction between schedulers.

I couldn’t find many interesting links discussing both Parrot and Erlang. An O’Reilly Radar post called Parrot and Multi-threading from September 2007 was hopeful.

I’m still wondering if Parrot could act as a virtual machine for Erlang. I think that would be a valuable test case for the quality and scalability of the concurrency design.

Well, that’s put the cat among the pigeons¹.

Of the commentary I read, Breda O’Brien in the Irish Times rang most true for me.

If you enjoy his music and can possibly get a ticket for one of his world tour dates, do. Now. Stop reading and go buy them now.

I crossed the country to see the concert in Dublin on Friday night. I’m struggling against the urge to write a stream of superlatives. Others can do that better than I.

Got your tickets yet?

I’ll be speaking at the Irish Open Source Technology Conference this year. It’s on at Dublin’s CineWorld Complex, from June 18th for three days. They’re running a 2-for-1 offer on tickets at the moment.

I’ll be speaking about something Perl’ish, naturally.

The “Perl Myths” presentation I gave at IWTC earlier this year turned out to be a hit. (At least, it was after the event. There were less than ten people in the room at the time, including me! Perl clearly isn’t a hot topic among Irish web developers.)

My blog post, with embedded slides and video, has topped 7400 hits, plus another 3000 or so views on slideshare.

I’m upgrading my methods for this next talk. I’ve bought a great wireless USB microphone and the amazing
ScreenFlow screencasting software to capture everything in detail.

So I’m going all high-tech. No more “camcorder perched on a chair at the back” for me!

It’ll be a good trial run for OSCON where I’m speaking in July.

I’ve been working on a mod_perl2 based admin interface for a pool of Gofer servers recently.

I needed to secure it and PAM plus SSL was the simplest way to go.

The Authen::PAM module is old (2005), doesn’t have good reviews, and the test results are poor, but it worked for us.

That just left the question of how to interface with Apache 2. There’s an Apache::AuthPAM module but that’s even older (2002), has more failing test reports than passes, and was mod_perl 1 only.

I emailed the author but got no reply so I’ve gone ahead and hacked it into a new module for mod_perl2: Apache2::AuthPAM. The source code is hosted by google.

Realistically I’m unlikely to touch it again, unless we find problems, so I’d be delighted if anyone wants to take it over, or even just co-maintain it.

Just a quick note to echo Ovid and recommend Steve Yegge’s excellent talk on dynamic languages.

Great talk, interesting perspective, good references. Well worth a read if you’re interested in the evolution and future of programming languages.

Occasionally you may run across an odd warning like this:

   Use of uninitialized value in subroutine entry at X line Y

where the code at that line is a call to an XS subroutine (let’s call it xsub()) and you’re certain that the arguments you’re passing are not undefined.

Somewhere, deep in the XS/C code, an undefined value is being used. But where? And why is perl reporting that line?

Perl is reporting the last line of perl code that was executed at the same or higher level in the stack. So other perl code, such as a callback, may have been executed between entering xsub() and the warning being generated, but that perl code must have returned before the warning was triggered.

Assuming XS/C code is large and complex, like mod_perl, how can you locate the code that’s triggering the warning?

Here’s a trick I’ve used a few times over the years:

    $SUB{__WARN__} = sub {
        CORE::dump if $_[0] =~ /uninitialized value in subroutine entry/;
        warn @_;
    }

That make the program abort and generate a core dump file at the point the warning is generated. You can then use a debugger, or Devel::CoreStack, to report the C call stack at the time. It’s a savage but effective technique.

If the XS/C code was compiled with options to keep debug info (i.e., -g) then that’ll show you exactly where in the XS/C code the undefined value is being used. If not, then it’ll at least show you the name of the XS/C function and the overall call stack.

(The dump function is a curious vestige of old ways. You could use kill(9, $$). I’m not sure about the portability of either, for this purpose, beyond unix-like systems.)

I suggested the technique to Graham Barr recently and it proved effective in tracking down the source of that warning in a very large mod_perl application. The warning pointed the finger at a $r->internal_redirect($uri) call. The actual cause was a PerlInitHandler returning undef. (The handler was an old version of DashProfiler::start_sample_period_all_profiles.)

Anyway, it dawned on me this morning that I should update the technique. It doesn’t have to be so savage. On modern systems you don’t need to shoot the process dead to get a C stack trace.

A few approaches came to mind:

• spawn a “gcore $$” command (or similar) to get a core file from the running process
• spawn a “pstack $$” command (or similar) to directly dump the stack trace from the running process
• spawn a “gdb $$ &” (to attach to the running process) followed immediately by kill(17, $$) to send a SIGSTOP to the process to give time for the debugger to attach and for you to investigate the state of the live process.

I think the second of those would be most useful most of the time.

Hopefully this will be useful to someone.

So you’ve got some perl code that connects to a particular database via a particular DBI driver. You want it to connect to a different database or driver. But you can’t change that part of the code. What can you do?

I ran into this problem recently. A large application is using an old version of DBIx::HA which doesn’t support DBD::Gofer. DBIx::HA can’t be upgraded (long story, don’t ask) but I wanted to use DBD::Gofer to provide client-side caching via Cache::FastMmap. (I’ll save more details of that, and the 40% reduction in database requests it gave, for another post.)

I needed a way for DBIx::HA to think that it was connecting to a particular driver and database, but for it to actually connect to another. Using $ENV{DBI_AUTOPROXY} wasn’t an option because that has global effect whereas I needed fine control over which connections were affected. It’s also fairly blunt instrument in other ways.

It seemed like I was stuck. Then I remembered the DBI callback mechanism - it would provide an elegant solution to this. I added it to DBI 1.49 back in November 2005 and enhanced it further in 1.55. I’d never documented it though. I think I was never quite sure it had sufficient functionality to be really useful. Now I’m sure it has.

The DBI callback mechanism lets you intercept, and optionally replace, any method call on a DBI handle. At the extreme, it lets you become a puppet master, deceiving the application in any way you want.

Here’s how the code looked (with a few irrelevant details changed):

    # The following section of code uses the DBI Callback mechanism to
    # intercept connect() calls to DBD::Sybase and, where appropriate,
    # reroute them to DBD::Gofer.
    our $in_callback;

    # get Gofer $drh and make it pretend to be named Sybase
    # to keep DBIx::HA 0.62 happy
    my $gofer_drh  = DBI->install_driver("Gofer");
    $gofer_drh->{Name} = "Sybase";

    # get the Sybase drh and install a callback to intercept connect()s
    my $sybase_drh = DBI->install_driver("Sybase");
    $sybase_drh->{Callbacks} = {
        connect => sub {
            # protect against recursion when gofer itself makes a connection
            return if $in_callback; local $in_callback = 1;

            my $drh = shift;
            my ($dsn, $u, $p, $attr) = @_;
            warn "connect via callback $drh $dsn\n" if $DEBUG;

            # we're only interested in connections to particular databases
            return unless $dsn =~ /some pattern/;

            # rewrite the DSN to connect to the same DSN via Gofer
            # using the null transport so we can use Gofer caching
            $dsn = "transport=null;dsn=dbi:Sybase(ReadOnly=1):$dsn";

            my $dbh = $gofer_drh->connect($dsn, $u, $p, $attr);

            if (not $dbh) { # gofer connection failed for some reason
                warn "connect via gofer failed: $DBI::errstr\n"
                    unless our $connect_via_gofer_err++; # warn once
                return; # DBI will now call original connect method
            }

            undef $_;    # tell DBI not to call original connect method
            return $dbh; # tell DBI to return this $dbh instead
        },
    };

So the application, via DBIx::HA, executed

  $dbh = DBI->connect("dbi:Sybase:foo",...)

but what it got back was a DBD::Gofer dbh, as if the application has executed

  $dbh = DBI->connect("dbi:Gofer:transport=null;dsn=dbi:Sybase(ReadOnly=1):foo",...).

I guess I should document the callback mechanism now. Meanwhile the closest thing to documentation is the test file.

I’ve always enjoyed this kind of “plumbing”. If you come up with any interesting uses of DBI callbacks, do let me know.

Just in case it wasn’t clear, perl programming is one of my interests, so this is, at least partly, a perl blog.

I’m only spelling it out like this because, by saying “perl blog“, I help to keep Mr. Schwern happy, and I’m saying “perl programming” purely for my own amusement.

While I’m here I might as well spread some Link Love to other notable perl blogs and the like: use.perl.org, perlmonks.org, news.perlfoundation.org and of course planet.perl.org super blog which lists many more.

I started a related recent post with a quote that seems just as apt here:

“Figures often beguile me, particularly when I have the arranging of them myself; in which case the remark attributed to Disraeli would often apply with justice and force: ‘There are three kinds of lies: lies, damned lies, and statistics.
- Mark Twain

If you regularly use just one search engine, as I tend to do, it’s very easy to be lulled into a false sense of security about the quality and relevance of the results.

I was recently reminded of the significant differences that can occur in the results of different search engines. That, in turn, reminded me of tools I’d come across previously to highlight those differences. In particular one that gives a very clear picture of the differences in ranking. After a little digging I found it at langreiter.com (via list of tools at www.seocompany.ca).

As a demonstration, here’s a comparison of the top results for +”perl programming” at Google (top) and Yahoo (bottom):

and here’s the same for +”python programming”:

Each dot represents a result url, with the top ranked results on the left. Where a url appears in the top 100 results on both Google and Yahoo then a line is drawn between them to highlight the different rankings. On the site you can hover over the dots to see the corresponding url.

I remember being very surprised when I first saw these kinds of results a few years ago. I’m no less surprised now. If fact more so, as I’d had (naïvely) expected Yahoo and Google to have converged somewhat in their concept of relevancy. At least for top results.

The particular queries I used above are not exceptional. I couldn’t find any query that didn’t have significant differences in rankings. Don’t believe me? Go try it yourself at http://www.langreiter.com/exec/yahoo-vs-google.html.

That so many of the top 20 from one search engine don’t even appear in the top 100 of the other is… is… well, I’m not quite sure what to make of it. At first sight it seems like a bad thing, but I also have to admit that it’s a good thing. At least in some ways. Diversity is important in any ecosystem.

If you only use one major search engine then you have to accept that you’re getting just one view of the internet. Most of the time you may be happy with that. It’s worth keeping it in mind, though, for those times when you’re struggling to find good results.

One way to avoid the issue is to use a meta search engine that’ll query multiple search engines for you and merge the results. There are lots of them.