something new and very useful from kernel tnf

Turning on all kernel's TNF probes gathers you a big blob of data about what is going inside the kernel. Prior to Solaris 10 this is the only way to get accurate timing information for system calls. Recently, as in last night, I was trying to work out from one of these blobs why a write into a ufs filesystem might take a long time. I had the pid of the writing process so I could find all its threads, I could see one of them issue the write() system call, then I kept seeing the thread block and almost wake up before blocking again. It did this a number of times, obviously it was competing for a resource like a semaphore or a condvar or a mutex and not getting it. All tnfdump gives you is the address of the resource.

But if you use tnfdump -rx you see a bit more.

Here is what tnfdump gives you..

1995.449700  0.010800 10768     3 0x3002ec894a0   4 thread_block  reason: 0x3002ec89632 stack: 

but here is what tnfdump -rx gives on a solaris 8 system
0x63f8e8  : {
                 tnf_tag 0x22f8     thread_block
             tnf_tag_arg 0x63f840   
              time_delta 0x4fd198
                  reason 0x3002ec89632
                   stack 0x63f900   
        }
0x63f900  : {
                 tnf_tag 0x2358     tnf_symbols
           tnf_self_size 0x38
                       0 0x1011c800
                       1 0x100448cc
                       2 0x1007d5f8
                       3 0x1007d9e4
                       4 0x100adaa4
                       5 0x100adc68
        }

On solaris 9 the stack is compressed two addresses to a line. That looks like a kernel stack trace to me, but the challenge is turn that into a symbolic stack trace. You could on the machine where the prex was run do
echo "0x1011c800/i" | mdb -k
But to be portable I think you should gather from the machine where the prex was run
/usr/ccs/bin/nm -fx /dev/ksyms > file or a live crashdump.

So time for a modified tnfdump or another awk script to glue these things together so we can see why threads might block in the kernel.

so more on that when I have it working but until then if you have to gather kernel prex data, send in the raw output file from tnfxtract, a live dump or the nm of /dev/ksyms so we don't loose any information from the data.

Comments:

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

timatworkhomeandinbetween

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
News

No bookmarks in folder

Blogroll

No bookmarks in folder