I got the crap beat out of me by references this weekend.

It started last week, when I began doing some code profiling (using Devel::Profile. I actually hadn't used a profiler before. After seeing how simple and useful it was, I can't believe I waited this long.

I noticed a number of issues with OpenPlugin that seemed relatively easy to deal with. For instance, Log4perl was taking up 33% of the execution time. I tried limiting the calls made to Log4perl by caching a whole bunch of stuff, but it was still incredibly high. So I just created a new Log driver, OpenPlugin::Log::Fast. So, your development code can use Log4perl, and production code can use the new Fast driver. It really does, in my environment, shave off 25-33% of the execution time.

I also found an oddity where "use" appears to be faster than "require". Chris promptly posted a question about that on Perlmonks, as this is unusual behavior. But I regularly found that "use" took significantly less startup time than "require". Perrin feels that it might actually be a bug or inacuracy in Devel::Profile, but I dunno.

Lastly, I found that it was spending a significant amount of time reading the config file each time the application ran. It was about 11% of the execution time. That's silly, because under mod_perl, we can read it once when Apache starts up, and just cache it for future use. We shouldn't have to read it more than once unless it changes.

So, I made a hash for caching the config. It took two minutes to add the caching code. It was great, only two minutes for such a significant speed increase.

Only it didn't work like that. The code awoke, and spanked me for trying to change it.

I spent the entire weekend (minus my sister-in-law's birthday party, which was fun) fighting with this code. Whenever I was using the cache, values were mysteriously changing, causing all kinds of havoc. And not just any values, just a few values, in a deeply nested hash. It took a long time to track down what in the world was going on.

It turns out that my nested data structure had a reference to it laying around somewhere (I'm still not sure where yet). So the first item cached worked fine. But when another item was being cached, any similarities to the first data structure caused the original values to be overwritten.

For example, some of the config files contain a key called "include". So we cache a config file with the key "include". When pulling up the next config file, if it also contained a key named save, it ended up overwriting the first include value.

While I still haven't found the exact spot the reference was being abused, I got around that by using Clone::PP. Clone::PP makes copies of data structures. Anything going into or out of the cache must be cloned.

The good news is that everything seems back to normal now. What took 650ms to run last week now takes 250-300ms... profiling is cool :-)