Dtrace bites with tail optimisation

I really should have caught this when I was using shared shell on the customer's system. However I did not. If you want to dtrace the return values of tail call optimised functions you can't always trust what it says. Given this code:


	size_t size;
	int error;

	VERIFY(nvlist_size(nvl, &size, NV_ENCODE_NATIVE) == 0);

and I want to know what ends up getting written into size, I did the following:


dtrace -n '
fbt:genunix:nvlist_size:entry
{
        self->size = args[1];
        printf("size ret = %p %d", self->size, \*self->size);
}
fbt::nvlist_size:return                                                         
{                                                                               
        printf("size ret = %p %d", self->size, \*self->size);                                   
        self->size = 0;                                                         
}' -c "zlogin $ZONENAME /usr/sbin/zfs list"
dtrace: description '
fbt:genunix:nvlist_size:entry
' matched 2 probes
NAME              USED  AVAIL  REFER  MOUNTPOINT
tank              122M   134G  25.5K  /tank
tank/chris         51K   134G  26.5K  /tank/chris
tank/chris/spam  24.5K   134G  24.5K  /tank/chris/spam
dtrace: pid 19681 has exited
CPU     ID                    FUNCTION:NAME
 14  17668                nvlist_size:entry size ret = 2a100799770 7696589036160
 14  17669               nvlist_size:return size ret = 2a100799770 7696589036160

then scratched my head as to why it appeared that the value was not being written to. I expected the value highlighted in red above to contain my result so why had it not been written to?

int
nvlist_size(nvlist_t \*nvl, size_t \*size, int encoding)
{
	return (nvlist_common(nvl, NULL, size, encoding, NVS_OP_GETSIZE));
}

Looking at the source to nvlist_size() it is clearly going to get tail call optimised as the assembler shows:

> nvlist_size::dis
nvlist_size:                    sra       %o2, 0x0, %o3
nvlist_size+4:                  mov       %o1, %o5
nvlist_size+8:                  mov       %o5, %o2
nvlist_size+0xc:                mov       %o7, %g1
nvlist_size+0x10:               clr       %o1
nvlist_size+0x14:               mov       0x2, %o4
nvlist_size+0x18:               call      -0x168        <nvlist_common>
nvlist_size+0x1c:               mov       %g1, %o7
> 

Luckily tracing nvlist_common() can still get to the correct information:

dtrace -n '
fbt::nvlist_common:entry
{
        self->nvlist_common_size = args[2];
        printf("%p %d\\n",
                self->nvlist_common_size, \*self->nvlist_common_size);
}
fbt::nvlist_common:return
{
        printf("%p %d\\n",
                self->nvlist_common_size, \*self->nvlist_common_size);
}

fbt:genunix:nvlist_size:entry
{
        self->size = args[1];
        printf("size ret = %p %d", self->size, \*self->size);
}
fbt::nvlist_size:return
{
        printf("size ret = %p %d", self->size, \*self->size);

        self->size = 0;
}'  -c "zlogin $ZONENAME /usr/sbin/zfs list"
dtrace: description '
fbt::nvlist_common:entry
' matched 4 probes
NAME              USED  AVAIL  REFER  MOUNTPOINT
tank              122M   134G  25.5K  /tank
tank/chris         51K   134G  26.5K  /tank/chris
tank/chris/spam  24.5K   134G  24.5K  /tank/chris/spam
dtrace: pid 19654 has exited
CPU     ID                    FUNCTION:NAME
14  17668                nvlist_size:entry size ret = 2a1014e5680 2890534899393
 14  17669               nvlist_size:return size ret = 2a1014e5680 2890534899393
 14   9628              nvlist_common:entry 2a1014e5680 2890534899393

 14   9629             nvlist_common:return 2a1014e5680 944

Once you have been bitten the documentation tells you to beware of this. What would be nice would be a way of warning the user they are at risk.

Comments:

Post a Comment:
Comments are closed for this entry.
About

This is the old blog of Chris Gerhard. It has mostly moved to http://chrisgerhard.wordpress.com

Search

Archives
« April 2014
MonTueWedThuFriSatSun
 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
    
       
Today