May 6, 2011

Blast from the past : grpof

Filed under: history,programming,skills — Mark Dalrymple @ 1:48 pm
Tags: , ,

Dino rific

I stumbled across this little tutorial I wrote back in the mists of time, probably around 1996 or 1997.  And it was based on a tutorial I wrote at Visix, probably in 1993 during one of our Optimization Parties.  It describes how to read the output of gprof, a profiling tool available on most unix systems.  It’s even still there on Mac OS X.  So you kids with your fancy Shark and Instruments, here’s what some of your elders used.

gprof is not a GNU tool, even though it has the leading “g”.  That “g” probably stands for “call Graph” profiler. You’ll need to check your system’s documentation (e.g. man gprof) for exact instructions on getting gprof to work, but usually it just involves compiling and linking with -pg, running your program, and doing gprof gmon.out > oopack.

Here’s a 300K sample of output from gprof on the Dec Alpha if you want to take a look at it. This particular report is from a run of AOLServer 2.2.1 which involved fetching index.html 53,623 times.  The links that follow go to anchors in that 300K sample.  What was I wanting to profile?  I wanted a gut check to make sure that life in the server was sane, and if there were any obvious bottlenecks that maybe I could address if I had the time.  The test was to fetch index.html over and over again.

There’s 4 parts to gprof output:

  • Built-in documentation: Short form of everything here, and more.
  • Call-graph: Each function, who called it, whom it called, and how many times said calling happened.
  • Flat profile How many times each function got called, the total times involved, sorted by time consumed.
  • Index: Cross-reference of function names and gprof identification numbers numbers.

When I first start looking at gprof output, I go to the flat profile section. The big time consumers are usually pretty obvious. You’ll notice that each function has a [number] after it. You can search on that number throughout the file to see who called that function and what functions that function calls. Emacs incremental search is really nice for bouncing around the file like this.

Here you can see that DString is a big time gobbler:

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 17.7       3.72     3.72 13786208     0.00     0.00  Ns_DStringNAppend [8]
  6.1       5.00     1.28   107276     0.01     0.03  MakePath [10]
  2.9       5.60     0.60  1555972     0.00     0.00  Ns_DStringFree [35]
  2.7       6.18     0.58  1555965     0.00     0.00  Ns_DStringInit [36]
  2.3       6.67     0.49  1507858     0.00     0.00  ns_realloc [40]

Out of 21.05 seconds of total clock time, Ns_DStringNAppend consumed about 4 seconds, or about 18% of the time in and of itself. It was called 13 million times.

MakePath consumed one and a half seconds itself, and its children consumed three and a half seconds. At least one individual call to this consumed 0.01, and at least one individual call took a total of 0.03 seconds in MakePath and its children.

Handy tip – the function numbers in brackets are approximately sorted by time consumption, so a function with a [low number] will generally be more interesting than one with a [high number].

Now that you know that Ns_DStringNAppend is called a bunch of times, this could be a useful target for optimization, I’d look at its entry in the call graph section.

Before doing that, just for illustration, take a look at AllocateCa [33] since it has all of the interesting pieces of the call graph in a more compact size:

                0.04        0.18   53622/160866      Ns_CacheNewEntry [62]
                0.04        0.18   53622/160866      Ns_CacheDoStat [58]
                0.04        0.18   53622/160866      Ns_CacheLockURL [64]
[33]     3.0    0.11        0.53  160866         AllocateCa [33]
                0.16        0.17  160866/321890      Ns_DStringVarAppend [30]
                0.06        0.00  160866/1555972     Ns_DStringFree [35]
                0.06        0.00  160866/1555965     Ns_DStringInit [36]
                0.04        0.00  160866/1341534     Ns_LockMutex [43]
                0.03        0.00  160866/1341534     Ns_UnlockMutex [53]

The entries above AllocateCa [33] are the functions that call AllocateCa. The entries below that are the functions that AllocateCa calls. There are two numbers separated by a slash: the first number is the number of calls that the function has made, while the second number is the total number of invocations of that function.

In other words, for 160866/321890 Ns_DStringVarAppend [30], AllocateCa called Ns_DStringVarAppend 160866 times. Across all of AOLServer, Ns_DStringVarAppend was called 321890 times.

Similarly, for 53622/160866 Ns_CacheNewEntry [62], means that Ns_CacheNewEntry called AllocateCa 53622 times, and AllocateCa was called 160866 times total.

So, just by looking at this snippet, you know that the three Ns_Cache functions each call AllocateCa about once per serving of index.html, and that AllocateCa makes a single call to Ns_DStringVarAppend, Ns_DStringFree, etc… each time. What’s also interesting to note is that someone is calling Ns_DStringFree more than Ns_DStringInit. This may be (or may not) be a bug in AOLServer. You can go see Ns_DStringInit and Ns_DStringFree yourself and track down who the culprit is.

The floating “3.0” on the left is the percent of total time that the function consumed. The two columns of numbers are the amount of time (in seconds) that the function consumed itself (AllocateCa took 0.11 seconds of time total to run its own code) and the amount of time in the function’s children (0.53 seconds were spent in its children)

Getting back to real analysis of DStringNAppend, you can see that MakePath made 50% of the Ns_DStringNAppend calls. Since you know that there were 53623 fetches of index.html, that means that for each page, MakePath was called twice, and for each call to MakePath, Ns_DStringNAppend was called 64 times.

If one call to MakePath could be elided (since it’s getting called twice), or if fewer than 64 Ns_DStringNAppends could be done per call, we could see a performance boost.

Just browsing the gprof output can be an illuminating exercise. If you have a gut feeling that a particular function is a hot spot (say, Ns_LockMutex [43]), you can see the call graph for that function, see if it’s consuming lots of time, or if it’s being called a whole bunch.  Here it was called 1,341,534 times, or about 25 times per page serve. Maybe that’s high.  Maybe that’s right.  Sometimes a suspected culprit isn’t there, or you find a surprising time waster.

Because this sample gprof output was done on a Dec Alpha system, there was some suckage involved, such as no explicit time recorded for system calls. So we don’t know if, for example, select() blocked for a long time on each call.

(slightly edited and re-posted over at the miniblog)


April 6, 2011

The NeXT chapter

Filed under: 20-minute,history — Mark Dalrymple @ 3:12 pm
Tags: ,

Dans panel

I guess folks liked my little WWDC guide. I got more traffic from than than everything else around here gets, combined. Poring through my referrer logs I found one tumble about it from @alanQuatermain who said:

“I have a suspicion that someone at NeXT went around with a huge bucketful of awesome one day, because everyone I’ve met with a NeXT association seems to have a fair amount of it these days.”

I can’t argue with that. Everyone I’ve met with NeXT affiliations has been incredibly smart, and usually very kind and gracious as well. The funny thing is, NeXT wanted nothing to do with me at the time.

I remember when the NeXT cube first hit the mainstream press. BYTE Magazine had a cover story with the cube, along with a pretty in-depth article about the tech inside. The 68030 processor, the DSP, scads of memory, the advanced OS and the toolkit. There was even a centerfold. I was in love. I wanted one of those machines. Who cares if the optical drive was slow.  It was mag-NEATO! 256 megs of space! Who cares if the machine was $10,000? Somehow I managed to secure funding for it. Now all I needed was someone who would exchange a pile of money for a black cube of 2-bit graphic goodness.

The first NeXT machines were only sold to educational institutions. At the time, around 1989-90, I was still in college,  fairly small liberal arts college in central Arkansas you’ve probably never heard of. Hendrix College was too small to qualify for any kind of educational co-op with NeXT. UCA, the larger school across town, was large enough though. A friend of mine was the trombone professor over there even had a visit from a NeXT sales representative. I got an invite, and was blown away. I really wanted that machine. Unfortunately, I was told point-blank that there would be no way I could get a machine for myself through regular channels.

Plan B. I’m a programmer. They had a developer program. I got an application and sent it in. I didn’t have a huge number of qualifications (unix? Is that like VMS?), but I have programmed Macs since they first came out. I even had a couple of application ideas in mind, including a MacDraw-like diagramming app, and a medical database system similar to one I built in high school. About a month later I got my rejection letter. I think I still have it in my archives somewhere. I purchased the developer documentation anyway so I could live vicariously. Boy did Objective-C look weird. And Display Postscript.

And so there ended my dreams of being a NeXT programmer. I spent the money on a Mac IIci with an ungodly amount of memory (maybe 8 megs?) to continue my Mac programming. A little while later at my first job I discovered we had some NeXT cubes. They were in the corners being used for print servers. But dutifully I got a login, worked through the programing tutorials, had some fun, learned a lot, and then went back to my day job of unix and C because there was No Future in the NeXT technology.

Needless to say I was pretty happy when NeXT bought Apple for -429 million dollars. I now had all my favorite worlds in one place: Mac, Unix, and now NeXTstuff.

(slightly edited and re-posted over at the miniblog)

April 4, 2011

My first professional bug

Filed under: 20-minute,history,programming — Mark Dalrymple @ 12:10 am
Tags: , ,

Clearning with rooking grass

Mike Ash’s recent Friday Q&A mentioned SIGWINCH, the hearing of which always sends me down memory lane.  My first professional bug was centered around SIGWINCH.  By “professional bug”, I mean a bug that someone paid me actual money to fix during a period of employment.

Straight out of college in 1990 I went to work for a company called Visix, which at the time sold a product called Looking Glass, a file browser much like the Macintosh Finder but for Unix.  Looking Glass supported the major graphical windowing systems of the time: X11, Intergraph’s Environ V, and Sun’s SunView.  The image at the top of this posting is the only screen shot I could find of the version of Looking Glass I worked on running on SunView.

I was hired into tech support, and our team’s duties were phone support (typically debugging network configurations and X server font paths) and porting Looking Glass to other platforms.  Being the Lo Mein on the totem pole, I got given the old platform nobody wanted to touch any more: SunView.

SunOS 4.1.X had just come out, and Looking Glass would hang randomly.  It worked fine on 4.0.3.  My job was to find and fix this hang.  This was my first introduction to a lot of things: unix systems, windowing systems, navigating large code bases, debuggers, and vendor documentation that wasn’t Apple.  Luckily the SunView version didn’t sell terribly well any more because everyone was moving to X11, but there were a couple of customers bitten by this problem.

So what is SunView?  SunView is a windowing system.  Different programs run displaying graphical output into a window.  Nowadays that’s common place, but back when SunView came out it was pretty cool.  SunView was one of the earlier windowing systems, so it had a number of peculiarities: the biggest was that each window on the screen was represented by an honest-to-god device.  /dev/wnd5 is a window, as would be /dev/wnd12.  There were a finite number of these window devices, so once the system ran out of windows no more could be opened.

There was a definite assumption of “one window to one process” in SunView.  Your window was your only playground.  Looking Glass was different, it could open multiple windows.  Because of the finite number of windows available system-wide, on launch we created the alert that said “You can’t open any more windows because you’re out of windows”, thereby consuming a precious window resource, and hide it offscreen.  It was the only way we could reliably tell users why they couldn’t open any more windows.  Glad I wasn’t the one that had to make this work in the first place.

The other peculiarity is that you never got window events.  Even in the 1.0 version of the Macintosh toolbox you could figure out if the user dragged the window, or resized it, or changed its stacking order.  In SunView, you just got a signal. SIGWINCH, for Window Change, and hence the memory-lane trigger.  The user moved a window?  SIGWINCH.  The user resized it?  SIGWINCH.  The user changed the z-order?  SIGWINCH.

With just one window that’s not too bad.  Just query the window for its current size.  For us, though, we had to cache the window’s location, size, and stacking order.  Upon receipt of a SIGWINCH we’d have to walk all of our windows and compare it to the cached version, and see if anyone was resized, and then relayout the window views.

So, back to my bug.  It took me a solid month to fix.  Mainly because it was part time work in amongst my other responsibilities, and also because it was difficult to reproduce.  Spastic clicking and dragging could make it lock up, but not reliably.  Using the debugger was pointless – a 4 meg Sun 3/50 swapped eternally trying to get Looking Glass into gdb.  I ended up using a lot of caveman debugging.

Event queues

The architecture we used is shown in this diagram.  Each window had an event queue (remember that one window to one process assumption).  Upon receipt of events, we would walk our windows: read the events, handle them, then move on to the next window.

I was getting some printouts, though, showing an window receiving mouse-downs and mouse-drags, but no mouse-up.  Occasionally I would see a mouse-up, with no mouse-downs.  Ah-ha!  The mouse-up was being delivered to the wrong window’s event queue.  The fix was easy once I found it : just merge the events from all the windows first, and then process them.

It was then I learned how expensive malloc is.  I malloc’d and free’d event structures, but performance became dog-slow, especially during mouse drags.  Caching the structures made life fast again.

Memories like these make me so happy with the cool tech we get to play with these days.


(subsequently republished and edited quite heavily to the Miniblog)

Blog at