DTracing off-CPU time

In this entry I'll demonstrate DTracing off-CPU time.

On my way back from OSCON 2007, I found myself in Portland airport with a laptop, no Internet and half an hour to kill. In fact, the same laptop that I used during the SVOSUG talk in April. It was a chance to finish the demo that I started back then.

For those that were there or listened in, the talk had an unfortunate start with over an hour of audiovisual issues - including problems with the laptop video driver, laptop boot process, the data projector, lights and microphone. Alan DuBoff did a good job of fixing things while I began plan B (presenting from a SunRay), and he fixed the video driver such that it works better with data projectors than any other Acer Ferrari I've tried.

One issue we didn't fix that night was a 20 second wait when starting up certain applications, such as gnome-terminal. It was to make a great live DTrace demo to finish with, but I ran out of time to do it properly (we finished at around 11:30pm). Here it is as a blog entry instead.

The problem

When running gnome-terminal, there is a 20 second wait before the terminal appears on the screen.

Initial check

During the 20 second wait,
  • vmstat 1 showed idle CPUs
  • prstat -m showed that gnome-terminal was not on-CPU

DTrace investigation

The gnome-terminal application is off-CPU for some reason, and the CPUs are otherwise idle. There are numerous different ways to begin the investigation with DTrace, including,
  • using the sched provider to trace off-CPU to on-CPU event time
  • using the syscall provider to trace elapsed time for syscalls
  • using the pid provider to trace elapsed time for application binary and library calls
I'll start with the sched provider (the syscall provider would also make a good starting point). I'll keep restarting gnome-terminal, so that I can DTrace all the events (this is harder if you are trying to DTrace something that is already off-CPU).

The following one-liner runs gnome-terminal and measures the time from that process leaving the CPU to when it returns, and only prints user stack traces if that time was over 1 second,

# dtrace -n 'sched:::off-cpu /pid == $target/ { self->start = timestamp; }
  sched:::on-cpu /self->start && ((timestamp - self->start) > 1000000000)/
  { printf("waited: %d ms\\n", (timestamp - self->start) / 1000000); ustack(); }
' -c gnome-terminal
dtrace: description 'sched:::off-cpu ' matched 6 probes
CPU     ID                    FUNCTION:NAME
  0  48718                    resume:on-cpu waited: 20034 ms

              libc.so.1`door_call+0x1a
              libc.so.1`_nsc_trydoorcall+0x213
              libnsl.so.1`_door_getipnodebyname_r+0x8f
              libnsl.so.1`_get_hostserv_inetnetdir_byname+0xb62
              libnsl.so.1`getipnodebyname+0xdf
              libsocket.so.1`get_addr+0x126
              libsocket.so.1`_getaddrinfo+0x414
              libsocket.so.1`getaddrinfo+0x19
              libORBit-2.so.0.1.0`get_netid+0x91
              libORBit-2.so.0.1.0`link_get_local_hostname+0x35
              libORBit-2.so.0.1.0`link_server_setup+0x56
              libORBit-2.so.0.1.0`giop_server_new+0x5e
              libORBit-2.so.0.1.0`ORBit_ORB_start_servers+0x1d8
              libORBit-2.so.0.1.0`IOP_generate_profiles+0x67
              libORBit-2.so.0.1.0`ORBit_marshal_object+0x8e
              libORBit-2.so.0.1.0`ORBit_marshal_value+0x391
              libORBit-2.so.0.1.0`orbit_small_marshal+0xf7
              libORBit-2.so.0.1.0`ORBit_small_invoke_stub+0x11c
              libORBit-2.so.0.1.0`ORBit_small_invoke_stub_n+0x43
              libORBit-2.so.0.1.0`ORBit_c_stub_invoke+0x132

\^C
Hmm - looks like that user stack trace was truncated. Time to boost the ustackframes value,
# dtrace -x ustackframes=64 -n '
  sched:::off-cpu /pid == $target/ { self->start = timestamp; }
  sched:::on-cpu /self->start && ((timestamp - self->start) > 1000000000)/
  { printf("waited: %d ms\\n", (timestamp - self->start) / 1000000); ustack(); }
' -c gnome-terminal
dtrace: description 'sched:::off-cpu ' matched 6 probes
dtrace: pid 101415 has exited
CPU     ID                    FUNCTION:NAME
  0  48720                    resume:on-cpu waited: 20038 ms

              libc.so.1`door_call+0x1a
              libc.so.1`_nsc_trydoorcall+0x213
              libnsl.so.1`_door_getipnodebyname_r+0x8f
              libnsl.so.1`_get_hostserv_inetnetdir_byname+0xb62
              libnsl.so.1`getipnodebyname+0xdf
              libsocket.so.1`get_addr+0x126
              libsocket.so.1`_getaddrinfo+0x414
              libsocket.so.1`getaddrinfo+0x19
              libORBit-2.so.0.1.0`get_netid+0x91
              libORBit-2.so.0.1.0`link_get_local_hostname+0x35
              libORBit-2.so.0.1.0`link_server_setup+0x56
              libORBit-2.so.0.1.0`giop_server_new+0x5e
              libORBit-2.so.0.1.0`ORBit_ORB_start_servers+0x1d8
              libORBit-2.so.0.1.0`IOP_generate_profiles+0x67
              libORBit-2.so.0.1.0`ORBit_marshal_object+0x8e
              libORBit-2.so.0.1.0`ORBit_marshal_value+0x391
              libORBit-2.so.0.1.0`orbit_small_marshal+0xf7
              libORBit-2.so.0.1.0`ORBit_small_invoke_stub+0x11c
              libORBit-2.so.0.1.0`ORBit_small_invoke_stub_n+0x43
              libORBit-2.so.0.1.0`ORBit_c_stub_invoke+0x132
              libgconf-2.so.4.1.0`ConfigServer_add_client+0x4f
              libgconf-2.so.4.1.0`gconf_get_config_server+0xb9
              libgconf-2.so.4.1.0`gconf_engine_connect+0x24f
              libgconf-2.so.4.1.0`gconf_engine_get_default+0x4c
              libgconf-2.so.4.1.0`gconf_client_get_default+0x2a
              libgnomeui-2.so.0.1401.0`libgnomeui_post_args_parse+0x187
              libgnome-2.so.0.1401.0`gnome_program_postinit+0x61
              libgnome-2.so.0.1401.0`gnome_program_init_common+0x37b
              libgnome-2.so.0.1401.0`gnome_program_initv+0x4d
              libgnome-2.so.0.1401.0`gnome_program_init+0x56
              gnome-terminal`main+0x2d5
              gnome-terminal`_start+0x7a
Good. This stack trace is likely to have led to the process leaving the CPU for the measured 20038 ms (the system was otherwise idle, so it is unlikely to have been kicked off due to scheduling). Reading through the lines, it looks like it is resolving a hostname - a common source of latencies when DNS is misconfigured.

There are a number of lines we could begin studying to confirm what is happening (and arrive at the same answer); I'll start with libnsl.so.1`getipnodebyname+0xdf, which should have a man page entry,

# man getipnodebyname
[...]
     struct hostent \*getipnodebyname(const char  \*name,  int  af,
     int flags, int \*error_num);
[...]
Now to check what hostname is being resolved,
# dtrace -n 'pid$target:libnsl:getipnodebyname:entry { trace(copyinstr(arg0)); }'
  -c gnome-terminal
dtrace: description 'pid$target:libnsl:getipnodebyname:entry ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0  50488            getipnodebyname:entry   marlin
\^C
dtrace: pid 101758 terminated by SIGINT
Oh - "marlin" is the hostname of this laptop, which should resolve just fine. Checking related configuration files,
# grep hosts /etc/nsswitch.conf
hosts:      files dns
#
# cat -n /etc/hosts
     1  #
     2  # Copyright 2006 Sun Microsystems, Inc.  All rights reserved.
     3  # Use is subject to license terms.
     4  #
     5  #ident  "@(#)hosts      1.1     06/08/04 SMI"
     6  #
     7  127.0.0.1       localhost
     8  192.168.1.166   marlin marlin.sf.fw.jpn.com
Hmm - the name service switch file should cause /etc/hosts (/etc/inet/hosts) to be read first, which contains a valid entry for "marlin".

Lets take a closer look at the getipnodebyname() call, and trace the address family and flags arguments,

# dtrace -n 'pid$target:libnsl:getipnodebyname:entry { printf("%s af=%d flags=%d",
  copyinstr(arg0), arg1, arg2); }' -c gnome-terminal
dtrace: description 'pid$target:libnsl:getipnodebyname:entry ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0  50488            getipnodebyname:entry marlin af=26 flags=19
\^C
dtrace: pid 101821 terminated by SIGINT
Ok, address family 26 is,
# grep 26 /usr/include/sys/socket.h
#define AF_INET6        26              /\* Internet Protocol, Version 6 \*/
IPv6! Should have checked earlier,
# grep ipnodes /etc/nsswitch.conf
ipnodes:    files dns
#
# cat -n /etc/inet/ipnodes
     1  #
     2  # Copyright 2006 Sun Microsystems, Inc.  All rights reserved.
     3  # Use is subject to license terms.
     4  #
     5  #ident  "@(#)ipnodes    1.1     06/08/04 SMI"
     6  #
     7  ::1             localhost
     8  127.0.0.1       localhost
Adding an entry to the ipnodes file for "marlin" fixed the issue.

Take 2

Was using the sched provider and then pid to trace getipnodebyname() the best path to take? It's hard to say - there are many different ways DTrace can help you solve problems. Lets try some other paths.

Here I'll trace elapsed times from the syscall provider - since if we have an off-CPU issue on an idle system, it will almost certainly be visible at the syscall layer.

The procsystime tool from the DTraceToolkit performs different types of syscall time analysis. I'm using it as it saves a minute or so of typing. Here it runs the gnome-terminal command and produces a report of elapsed times by syscall,

# /opt/DTT/procsystime -e gnome-terminal

Elapsed Times for command gnome-terminal,

         SYSCALL          TIME (ns)
           gtime               1882
      sigpending               1921
     priocntlsys               4200
          sysi86               4354
          getgid               5152
       sysconfig               5606
     getsockname               5904
      systeminfo               7040
      setcontext               7342
          fxstat               7943
     getpeername               9393
       getrlimit              11717
          getuid              13927
           uname              14661
       sigaction              14698
          getpid              19241
      setsockopt              23743
          getcwd              33784
            fsat              41700
          stat64              43024
           readv              45937
          listen              49874
          llseek              52341
           mkdir              52633
            pipe              64612
           chmod              65684
           fcntl              70864
           utime              76677
         fstat64             109420
           ioctl             133301
          access             157803
          unlink             165703
          open64             221120
          accept             276863
            bind             281026
          writev             343976
             brk             344410
         memcntl             347475
           write             358764
      getdents64             422206
          munmap             486137
         connect             588166
     resolvepath             686768
       so_socket             748039
           close             846782
            open            1127761
            read            1191102
            mmap            1592314
           xstat            8521257
         pollsys            9817661
          doorfs        20035299808
The doorfs() call takes the door descriptor as the first argument,
# dtrace -n 'syscall::doorfs:entry /pid == $target/ { trace(arg0); }' -c gnome-terminal
dtrace: description 'syscall::doorfs:entry ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0    572                     doorfs:entry                 3
  0    572                     doorfs:entry                 3
  0    572                     doorfs:entry                 3
  0    572                     doorfs:entry                 3
\^C
dtrace: pid 101833 terminated by SIGINT
#
# dtrace -n 'syscall::doorfs:entry /pid == $target/ { trace(fds[arg0].fi_pathname); }'
  -c gnome-terminal
dtrace: description 'syscall::doorfs:entry ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0    572                     doorfs:entry   /var/run/name_service_door
  0    572                     doorfs:entry   /var/run/name_service_door
  0    572                     doorfs:entry   /var/run/name_service_door
  0    572                     doorfs:entry   /var/run/name_service_door
\^C
dtrace: pid 101835 terminated by SIGINT
The door calls were to /var/run/name_service_door, pointing to name resolution and the nscd process (which can be confirmed with more DTrace).

Running procsystime on nscd produces,

# /opt/DTT/procsystime -e -n nscd
Hit Ctrl-C to stop sampling...
\^C

Elapsed Times for processes nscd,

         SYSCALL          TIME (ns)
           ioctl               2452
          llseek               2615
         fstat64               3996
       sysconfig              13933
            open              15416
            read              26336
           gtime              52980
       so_socket             323066
           close             349885
           xstat             430465
            send             454944
         connect             795246
          doorfs          360127347
        lwp_park        10009952745
         pollsys        20032365315
       nanosleep       153088010532
nscd is multi-threaded, with many threads sleeping as they wait for work - meaning that large off-CPU elapsed times may have nothing to do with gnome-terminal. The time for pollsys() is interesting, as at 20 seconds it matches the measured time in gnome-terminal.

Analysing pollsys() further (the poll() manpage is similar),

# man poll
[...]
     int poll(struct pollfd fds[], nfds_t nfds, int timeout);
[...]
The first argument is an array with length specified by the second argument. Looping over an array is difficult from DTrace (due to lack of loops), but this doesn't really present a difficulty when troubleshooting. Here I'll dump the struct in hex, and the other values as ints,
# dtrace -n 'syscall::pollsys:entry /execname == "nscd"/ { printf("nfds=%d", arg1);
  tracemem(copyin(arg0, 16), 16); }' -c gnome-terminal
dtrace: description 'syscall::pollsys:entry ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0    542                    pollsys:entry nfds=1
             0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f  0123456789abcdef
         0: 05 00 00 00 40 00 00 00 00 00 00 00 00 00 00 00  ....@...........

  0    542                    pollsys:entry nfds=1
             0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f  0123456789abcdef
         0: 05 00 00 00 40 00 00 00 00 00 00 00 00 00 00 00  ....@...........

  0    542                    pollsys:entry nfds=1
             0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f  0123456789abcdef
         0: 05 00 00 00 40 00 42 fd 0b 7b ab 46 f0 d7 c0 0d  ....@.B..{.F....

  0    542                    pollsys:entry nfds=1
             0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f  0123456789abcdef
         0: 05 00 00 00 40 00 00 00 0b 7b ab 46 f0 d7 c0 0d  ....@....{.F....

dtrace: pid 102041 has exited
Don't worry - DTrace lets you cast variables as structs if you like; I'm just dumping the data in hex as this is a short one-liner.

The nfds value shows that there is only ever one file descriptor in the array; and the hex dump (on this little endian architecture) shows that the file descriptor number is "5" (the first member of struct pollfd).

Now DTrace is used to print the pathname for that file descriptor,

# dtrace -n 'syscall::pollsys:entry /execname == "nscd"/ 
  { trace(fds[\*(uint32_t \*)copyin(arg0, 4)].fi_pathname); }' -c gnome-terminal
dtrace: description 'syscall::pollsys:entry ' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0    542                    pollsys:entry   <unknown>
  0    542                    pollsys:entry   <unknown>
\^C
dtrace: pid 102063 terminated by SIGINT
Well, that didn't work. Not all file descriptors have pathnames, of course. It will save some time to borrow pfiles for the next step,
# pfiles `pgrep -x nscd`
101917: /usr/sbin/nscd
  Current rlimit: 256 file descriptors
   0: S_IFCHR mode:0666 dev:270,0 ino:6815752 uid:0 gid:3 rdev:13,2
      O_RDWR
      /devices/pseudo/mm@0:null
   1: S_IFCHR mode:0666 dev:270,0 ino:6815752 uid:0 gid:3 rdev:13,2
      O_RDWR
      /devices/pseudo/mm@0:null
   2: S_IFCHR mode:0666 dev:270,0 ino:6815752 uid:0 gid:3 rdev:13,2
      O_RDWR
      /devices/pseudo/mm@0:null
   3: S_IFDOOR mode:0777 dev:279,0 ino:0 uid:0 gid:0 size:0
      O_RDWR FD_CLOEXEC  door to nscd[101917]
   4: S_IFSOCK mode:0666 dev:277,0 ino:17874 uid:0 gid:0 size:0
      O_RDWR
        SOCK_RAW
        SO_SNDBUF(8192),SO_RCVBUF(8192)
        sockname: AF_ROUTE
        peername: AF_ROUTE
   5: S_IFSOCK mode:0666 dev:277,0 ino:53988 uid:0 gid:0 size:0
      O_RDWR
        SOCK_DGRAM
        SO_DGRAM_ERRIND,SO_SNDBUF(57344),SO_RCVBUF(57344)
        sockname: AF_INET 192.168.1.78  port: 51697
        peername: AF_INET 192.168.1.5  port: 53
File descriptor 5 was a socket to the remote host 192.168.1.5 port 53 (DNS). This shows that nscd is waiting for 20 seconds on a DNS socket, and we know that gnome-terminal has a 20 second wait on the /var/run/name_service_door file. They are probably related.

Proving that they are related, if needed, is simply more DTrace. This time I'll borrow a script from /usr/demo/dtrace, which shows who is waiting for nscd and how long for,

# dtrace -s /usr/demo/dtrace/nscd.d -c gnome-terminal
dtrace: script '/usr/demo/dtrace/nscd.d' matched 27 probes
dtrace: pid 101594 has exited

  nscd                                                gnome-session
           value  ------------- Distribution ------------- count
           16384 |                                         0
           32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
           65536 |                                         0

  nscd                                                gnome-terminal
           value  ------------- Distribution ------------- count
           16384 |                                         0
           32768 |@@@@@@@@@@                               1
           65536 |@@@@@@@@@@@@@@@@@@@@                     2
          131072 |                                         0
          262144 |                                         0
          524288 |                                         0
         1048576 |                                         0
         2097152 |                                         0
         4194304 |                                         0
         8388608 |                                         0
        16777216 |                                         0
        33554432 |                                         0
        67108864 |                                         0
       134217728 |                                         0
       268435456 |                                         0
       536870912 |                                         0
      1073741824 |                                         0
      2147483648 |                                         0
      4294967296 |                                         0
      8589934592 |                                         0
     17179869184 |@@@@@@@@@@                               1
     34359738368 |                                         0
In the 17.1 to 34.3 second bucket is gnome-terminal waiting for nscd - our 20 second wait.

The /usr/demo/dtrace/nscd.d script works by tracing who is nscd is waking up via the sched:::wakeup probe, after having traced the time when threads sleep (see the "sched" chapter in the Dynamic Tracing Guide on docs.sun.com).

The wrap

DTrace provides many ways to solve performance issues or for troubleshooting. Above were only a few techniques for analysing off-CPU time, but there are more available.

Some techniques can get very complex, and require much systems knowledge. Don't worry: if you only figure out one way to solve your problem - you've still solved your problem. (Systems knowledge should help you solve system problems faster).

Comments:

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

Brendan Gregg, Fishworks engineer

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
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