The Benefits of Profiling

I run the Fake Name Gen­er­a­tor, a fairly pop­u­lar web­site that gen­er­ates fake names and addresses. The web­site offers free bulk orders of up to 40,000 names.

For years I’ve been strug­gling to make this fea­ture run quickly. The best I’ve been able to get it down to is about 40,000 records in 37 min­utes. ~1,000 records per minute isn’t that great.

So yes­ter­day I decided I’d try doing some pro­fil­ing using xde­bug. I set up the test to gen­er­ate a 40,000 record file. Within a few min­utes, the pro­filer gen­er­ated a 2GB file and promptly crashed. Hmm. Some­thing was def­i­nitely not right.

I dropped the test to 100 records. Within just a cou­ple min­utes, a 300MB pro­file file was gen­er­ated. Hmm. That seems odd. 300MB pro­file file for gen­er­at­ing 100 records? Hmm…

I loaded it up in Win­CacheGrind (which took 15 min­utes) and was shocked to see that a date gen­er­at­ing func­tion was tak­ing up 90% of the script’s exe­cu­tion time. What the heck is going on?

So I opened up my code and found a glar­ingly obvi­ous, hor­rific mis­take. My code gen­er­ates a ran­dom month num­ber, day num­ber, num­ber of sec­onds, etc. How­ever, instead of doing a mt_rand(1,12) — min month to max month– my code was doing mt_rand(1,86400) — min month to max sec­onds. It then checks if the date is valid, and tries again if it isn’t. This means this func­tion had to run thou­sands of times before it came even close to gen­er­at­ing a valid date.

So the results of fix­ing the bug? 40,000 records in 3.2 min­utes (even bet­ter under PHP 5.3: 2.2 minutes).

Moral of the story? Pro­file your code!