Jon Haslam's Weblog

As my old friend He-Man often tells me, I have the Power. Now I may have had a few too many cartoons recently (I'm blaming the children) but when it comes to debugging application issues with DTrace then I never cease to be amazed at the power available to me. A problem I've been looking at today reminded me of this and deserves reference here.

An application, that shall remain nameless for the good of the people, has been giving me serious grief recently. Basically, I have a library which bolts into this application. This library ends up using the excellent compression library zlib - no problem so far. However, when used the library throws out errors relating to incompatible versions of zlib being used. Odd as I thought that my library was the only source of zlib use. Ha-Ha.

I know that the function failing is inflateInit2_() and it is returning the error code of -6 (meaning "Incompatible Version"). The code that is failing looks like this:

int ZEXPORT inflateInit2_(z, w, version, stream_size)
z_streamp z;
int w;
const char *version;
int stream_size;
{
  if (version == Z_NULL || version[0] != ZLIB_VERSION[0] ||
      stream_size != sizeof(z_stream))
      return Z_VERSION_ERROR;

However, which of the three conditions are failing? It's easy to see whether or not 'version == Z_NULL' but the other two are not so easy (especially not the third one). However, with DTrace all things are possible. With the pid provider we can keep a track of every instruction that is executed and this is what I'll do here to see what instructions are executed when inflateInit2_() returns -6. From that I'll be able to locate which condition is failing. Awesome!

We'll need to use a facility in DTrace called speculations to do this. Speculations give you the ability to record a sequence of events and only keep them if they are deemed to be interesting at some time in the future (i.e a certain return code generated from a function as is here). The script looks like this:

pid$1:a.out:inflateInit2_:entry
{
        self->spec = speculation();
        speculate(self->spec);
        printf("%s: version = %s, stream size = %d\n",
                 probefunc, stringof(copyinstr(arg2)), arg3);
}

pid$1::inflateInit2_:
/self->spec/
{
        speculate(self->spec);
}

pid$1::inflateInit2_:return
/self->spec && arg1 != -6/
{
        discard(self->spec);
        self->spec = 0;
}

pid$1::inflateInit2_:return
/self->spec && arg1 == -6/
{
        commit(self->spec);
        self->spec = 0;
}

All we do is to instrument every instruction in the inflateInit2_() function and, if -6 is returned, commit the instructions we executed getting there or, if the return is not -6 then discard them. Sample output of a run looks like;

  0  32854              inflateInit2_:entry inflateInit2_: version = 1.1.4, stream size = 112
  0  32854              inflateInit2_:entry
  0  32857                  inflateInit2_:4
  0  32858                  inflateInit2_:8
  0  32859                  inflateInit2_:c
  0  32860                 inflateInit2_:10
  0  32861                 inflateInit2_:14
  0  32862                 inflateInit2_:18
  0  32863                 inflateInit2_:1c
  0  32864                 inflateInit2_:20
  0  32865                 inflateInit2_:24
  0  32866                 inflateInit2_:28
  0  32867                 inflateInit2_:2c
  0  32868                 inflateInit2_:30
  0  32869                 inflateInit2_:34
  0  32870                 inflateInit2_:38
  0  32871                 inflateInit2_:3c
  0  32872                 inflateInit2_:40
  0  32873                 inflateInit2_:44
  0  32874                 inflateInit2_:48
  0  32875                 inflateInit2_:4c
  0  33020                inflateInit2_:290
  0  33021                inflateInit2_:294
  0  33022                inflateInit2_:298
  0  33023                inflateInit2_:29c
  0  32855             inflateInit2_:return

So, the above are instructions that are executed for a call that returned -6. Next we need to tie the instructions above to the code so we'll disassemble the relevant instructions:

inflateInit2_:  save      %sp, -0xb0, %sp
inflateInit2_+4:call      +8            
inflateInit2_+8:sethi     %hi(0x106000), %g3
inflateInit2_+0xc:              sethi     %hi(0x800), %g2
inflateInit2_+0x10:             add       %g3, 0x344, %g3
inflateInit2_+0x14:             add       %g2, 0x10, %g2
inflateInit2_+0x18:             add       %g3, %o7, %l1
inflateInit2_+0x1c:             orcc      %g0, %i2, %g3
inflateInit2_+0x20:             be,pn     %xcc, +0x270  < inflateInit2_+0x290>
inflateInit2_+0x24:             sra       %i1, 0, %l0
inflateInit2_+0x28:             ldx       [%l1 + %g2], %g2
inflateInit2_+0x2c:             ldsb      [%i2], %g3
inflateInit2_+0x30:             ldsb      [%g2], %g2
inflateInit2_+0x34:             cmp       %g3, %g2
inflateInit2_+0x38:             bne,pt    %icc, +0x25c  < inflateInit2_+0x294>
inflateInit2_+0x3c:             mov       -6, %g2
inflateInit2_+0x40:             sra       %i3, 0, %g2
inflateInit2_+0x44:             cmp       %g2, 0x58
inflateInit2_+0x48:             bne,pn    %xcc, +0x248  < inflateInit2_+0x290>
inflateInit2_+0x4c:             cmp       %i0, 0
 - chopped here -
inflateInit2_+0x290:            mov       -6, %g2
inflateInit2_+0x294:            sra       %g2, 0, %i0
inflateInit2_+0x298:            ret
inflateInit2_+0x29c:            restore

Cutting to the chase it can be seen that the cmp on inflateInit2_+0x44 is what is failing. Tying this back to the source (as %i3 is the fouth argument) we can see this is the stream_size != sizeof(z_stream) condition that is failing. However, what are the values being compared here. Well, as we captured the stream size at the start (112 bytes) we can see that the cmp fails because 112 != 88 (0x58 is 88 in hex). However, we can just verify that this is absolutely what is happening by looking at the register contents when we execute this line.

pid$1::inflateInit2_:44
{
        printf("reg g2 = %d\n", uregs[R_G2]);
}

So, when we hit inflateInit2_+0x44 we print out register %g2. How cool is that! Running the above produces output like:

  0  32854                 inflateInit2_:44 reg g2 = 112

  0  32854                 inflateInit2_:44 reg g2 = 112

So, we know for sure the exact conditions that cause the error but the question is now why. Well this is a whole other story that boils down to the application in question having it's own local versions of these zlib routines which were being linked instead of the ones everything else is using ...

Sorting that out is going to be a bit more difficult. For more details on Speculations and user-level traing with the pid provider check out the fabulous DTrace answerbook.