The Observation Deck

Search
Close this search box.

Month: November 2013

As I have often remarked, DTrace is a workhorse, not a show horse: the features that we have added to DTrace over the years come not from theoretical notions but rather from actual needs in production environments. This is as true now as it was a decade ago, and even in core abstractions, extensive use of DTrace seems to give rise to new ways of thinking about them. In particular, Brendan recently had a couple of feature ideas for aggregation processing that have turned out to be really interesting…

agghist

When one performs a count() or sum() aggregating action, the result is a table that consists of values and numbers, e.g.:

# dtrace -n syscall:::entry'{@[execname] = count()}'
dtrace: description 'syscall:::entry' matched 233 probes
^C

  utmpd                                                             2
  metadata                                                          5
  pickup                                                           14
  ur-agent                                                         18
  epmd                                                             20
  fmd                                                              20
  jsontool.js                                                      33
  vmadmd                                                           33
  master                                                           41
  mdnsd                                                            41
  intrd                                                            45
  devfsadm                                                         52
  bridged                                                          81
  mkdir                                                            83
  ipmgmtd                                                          95
  cat                                                              96
  ls                                                              100
  truss                                                           101
  ipmon                                                           106
  sendmail                                                        111
  dirname                                                         115
  svc.startd                                                      125
  svc.configd                                                     153
  ksh93                                                           164
  zoneadmd                                                        165
  svcprop                                                         258
  sshd                                                            262
  bash                                                            291
  zpool                                                           436
  date                                                            448
  cron                                                            470
  lldpd                                                           584
  dump-minutely-sd                                                611
  haproxy                                                         760
  nscd                                                           1275
  zfs                                                            1966
  zoneadm                                                        2414
  java                                                           2916
  tail                                                           3750
  postgres                                                       6702
  redis-server                                                  21283
  dtrace                                                        28308
  node                                                          39836
  beam.smp                                                      55940

Brendan’s observation was that it would be neat to (optionally) use the histogram-style aggregation printing with these count()/sum() aggregations to be able to more easily differentiate values. For that, we have the new “-x agghist” option:

# dtrace -n syscall:::entry'{@[execname] = count()}' -x agghist
dtrace: description 'syscall:::entry' matched 233 probes
^C


              key  ------------- Distribution ------------- count
            utmpd |                                         2
         metadata |                                         5
           pickup |                                         14
             epmd |                                         20
              fmd |                                         23
         ur-agent |                                         25
             init |                                         27
            mdnsd |                                         30
      jsontool.js |                                         33
           vmadmd |                                         36
           master |                                         41
            intrd |                                         45
         devfsadm |                                         52
          bridged |                                         78
            mkdir |                                         83
              cat |                                         96
          ipmgmtd |                                         97
               ls |                                         100
         sendmail |                                         101
            ipmon |                                         102
          dirname |                                         115
       svc.startd |                                         125
            truss |                                         140
      svc.configd |                                         153
            ksh93 |                                         164
             sshd |                                         248
          svcprop |                                         258
             bash |                                         290
         zoneadmd |                                         387
            zpool |                                         436
             date |                                         448
             cron |                                         470
            lldpd |                                         562
 dump-minutely-sd |                                         615
          haproxy |                                         622
             nscd |                                         808
              zfs |                                         1966
          zoneadm |@                                        2414
             java |@                                        3003
             tail |@                                        3607
         postgres |@                                        5728
     redis-server |@@@@@                                    20611
           dtrace |@@@@@@                                   26966
             node |@@@@@@@@@@                               39825
         beam.smp |@@@@@@@@@@@@@                            55942

It’s obviously the same information, but presented with a quicker visual cue as to the distribution. Now, one may well note that this output has a lot of dead whitespace in it — read on.

aggzoom

The DTrace histogram-style output came directly from lockstat, which proceeded it by several years. lockstat was important for DTrace in several ways: aside from showing the power of production instrumentation, lockstat pointed to the need for first-class aggregations, for disjoint instrumentation providers and for multiplexed consumers (for which it was repaid by having its guts ripped out, being reimplemented as both a DTrace provider and a DTrace consumer). Due to some combination of my laziness and my reverence for the lockstat-style histogram, I simply lifted the lockstat processing code — which means I inherited (or stole, depending on your perspective) the decisions Jeff had made with regard to histogram rendering. In particular, lockstat determines the height of a bar by taking the bucket’s share of the total and multiplying it by the full height of the histogram. That is, if you add up all of the heights of all of the bars, they will add up to the full height of the histogram. The benefit of this is that it quickly tells you relative distribution: if you see a full-height bar, you know that that bucket represents essentially all of the values. But the problem is that if the number of buckets is large and/or the values of those buckets are relatively evenly distributed, the result is a bunch of very short bars (or worse, zero height bars) and dead whitespace. This can become so annoying to DTrace users that Brendan has been known to observe that this is the one improvement over DTrace that he can point to in SystemTap: that instead of dividing the height of the histogram among all of the bars, each bar has a height in proportion to the histogram height that is its value in proportion to the bucket of greatest value. Of course, the shape of the distribution doesn’t change — one simply is automatically scaling the height of the highest bar to the height of the histogram and adjusting all other bars accordingly.

To allow for this behavior, I added “-x aggzoom“; running the same example as above with this new option:

# dtrace -n syscall:::entry'{@[execname] = count()}' -x agghist -x aggzoom
dtrace: description 'syscall:::entry' matched 233 probes
^C

              key  ------------- Distribution ------------- count
            utmpd |                                         2
         metadata |                                         7
           pickup |                                         14
         ur-agent |                                         20
              fmd |                                         25
             epmd |                                         26
      jsontool.js |                                         33
            mdnsd |                                         39
           master |                                         41
           vmadmd |                                         44
         rsyslogd |                                         57
         devfsadm |                                         66
            mkdir |                                         83
            intrd |                                         90
              cat |                                         96
          bridged |                                         99
               ls |                                         100
          dirname |                                         115
            truss |                                         125
            ipmon |                                         130
         sendmail |                                         131
          ipmgmtd |                                         133
            ksh93 |                                         164
       svc.startd |                                         179
             init |                                         189
             sshd |                                         253
          svcprop |                                         258
             bash |                                         283
            zpool |                                         436
             date |                                         448
             cron |                                         470
 dump-minutely-sd |                                         611
            lldpd |                                         716
      svc.configd |@                                        939
          haproxy |@                                        1097
         zoneadmd |@                                        1455
              zfs |@                                        1966
          zoneadm |@@                                       2414
             nscd |@@                                       2867
             java |@@@                                      4277
             tail |@@@                                      4579
         postgres |@@@@@@                                   9389
     redis-server |@@@@@@@@@@@@@@@@@@                       26177
           dtrace |@@@@@@@@@@@@@@@@@@@@@@@                  34530
             node |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        48151
         beam.smp |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   55940

It’s zoomtastic!

aggpack

If you follow Brendan’s blog, you know that he’s always experimenting with ways of visually communicating a maximal amount of system data. One recent visualization that has been particularly interesting are his frequency trails — a kind of stacked sparkline. Thinking about density of presentation sparked Brendan to observe that he often needs to try to visually correlate multiple quantize()/lquantize() aggregation keys, e.g. this classic DTrace “one-liner” to show the distribution of system call time (in nanoseconds) by system call:

# dtrace -n syscall:::entry'{self->ts = timestamp}' \
    -n syscall:::return'/self->ts/{@[probefunc] = \
    quantize(timestamp - self->ts); self->ts = 0}'
dtrace: description 'syscall:::entry' matched 233 probes
dtrace: description 'syscall:::return' matched 233 probes
^C

  sigpending
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
            2048 |                                         0

  llseek
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@@@@@@@@@@@@@@@@@@@@                     1
            1024 |@@@@@@@@@@@@@@@@@@@@                     1
            2048 |                                         0

  fstat
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
            4096 |                                         0

  setcontext
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
            4096 |                                         0

  fstat64
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@@@@@@@@@@@@@@@@@@@@                     2
            1024 |@@@@@@@@@@@@@@@@@@@@                     2
            2048 |                                         0

  sigaction
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@@@@@@@@@@@@@@@@@@@@                     2
            1024 |@@@@@@@@@@@@@@@@@@@@                     2
            2048 |                                         0

  getuid
           value  ------------- Distribution ------------- count
             128 |                                         0
             256 |@@@@@@@@@@@@@@@@@@@@                     1
             512 |                                         0
            1024 |                                         0
            2048 |                                         0
            4096 |@@@@@@@@@@@@@@@@@@@@                     1
            8192 |                                         0

  accept
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@@@@@@@@                     1
            4096 |@@@@@@@@@@@@@@@@@@@@                     1
            8192 |                                         0

  sysconfig
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@@@@@@@@@@@@@                            2
            1024 |@@@@@@@@@@@@@@@@@@@@                     3
            2048 |@@@@@@@                                  1
            4096 |                                         0

  bind
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
            8192 |                                         0

  lwp_sigmask
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@       11
            1024 |@@@                                      1
            2048 |@@@                                      1
            4096 |                                         0

  recvfrom
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 5
            4096 |                                         0

  setsockopt
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@                               1
            2048 |@@@@@@@@@@                               1
            4096 |@@@@@@@@@@@@@@@@@@@@                     2
            8192 |                                         0

  fcntl
           value  ------------- Distribution ------------- count
             128 |                                         0
             256 |@@@                                      1
             512 |@@@@@@@@@@@@@@@@@@@@                     8
            1024 |@@@@@@@@@@@@@@@                          6
            2048 |@@@                                      1
            4096 |                                         0

  systeminfo
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@@@@@@                          3
            2048 |@@@@@@@@@@@@@@@@@@@@@@@@@                5
            4096 |                                         0

  schedctl
           value  ------------- Distribution ------------- count
            8192 |                                         0
           16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
           32768 |                                         0

  getsockopt
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@          11
            2048 |@@@@@@@@@                                3
            4096 |                                         0

  stat
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              4
            4096 |                                         0
            8192 |@@@@@@@@@@@@@                            2
           16384 |                                         0

  recvmsg
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        15
            4096 |@@@@                                     2
            8192 |@@                                       1
           16384 |                                         0

  connect
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              4
            8192 |                                         0
           16384 |@@@@@@@@@@@@@                            2
           32768 |                                         0

  brk
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@                               2
            2048 |@@@@@@@@@@@@@@@                          3
            4096 |                                         0
            8192 |@@@@@@@@@@                               2
           16384 |                                         0
           32768 |@@@@@                                    1
           65536 |                                         0

  so_socket
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@@@@@@@@@@                   5
            4096 |                                         0
            8192 |@@@@@@@@@                                2
           16384 |@@@@@@@@@                                2
           32768 |                                         0

  mmap
           value  ------------- Distribution ------------- count
           32768 |                                         0
           65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
          131072 |                                         0

  putmsg
           value  ------------- Distribution ------------- count
           32768 |                                         0
           65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
          131072 |                                         0

  p_online
           value  ------------- Distribution ------------- count
             128 |                                         0
             256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  250
             512 |@                                        5
            1024 |                                         0
            2048 |                                         1
            4096 |                                         0

  getpid
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@                               9
            2048 |@@@@@@@@@@@@@@@@@@@@@@@                  21
            4096 |@@                                       2
            8192 |@@@@                                     4
           16384 |                                         0

  close
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@@@@@@@@@@                      13
            2048 |@@@@@@@                                  5
            4096 |@@@@@@@                                  5
            8192 |@@@                                      2
           16384 |@@@@                                     3
           32768 |                                         0

  lseek
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@@@@@                           22
            2048 |@@@@@@@@@@@@@@@@@@@@@@@                  37
            4096 |@@                                       3
            8192 |@                                        2
           16384 |                                         0

  open
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@                            6
            4096 |@@@@@@@                                  3
            8192 |@@@@@@@@@@@@@                            6
           16384 |@@                                       1
           32768 |@@@@                                     2
           65536 |                                         0

  lwp_cond_signal
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@@@@@                                   2
            8192 |                                         0
           16384 |@@@@@@@@@@@@@@@@@@@@@@@                  8
           32768 |@@@@@@@@@@@                              4
           65536 |                                         0

  sendmsg
           value  ------------- Distribution ------------- count
            8192 |                                         0
           16384 |@@@@                                     1
           32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              6
           65536 |@@@@@@@@@                                2
          131072 |                                         0

  gtime
           value  ------------- Distribution ------------- count
             128 |                                         0
             256 |@@@@@@@@@@@@@@@@@@@@                     576
             512 |@@@@@@@@@@@@@@@@                         452
            1024 |@@                                       56
            2048 |@                                        34
            4096 |                                         3
            8192 |                                         8
           16384 |                                         1
           32768 |                                         1
           65536 |                                         0

  read
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |                                         1
            1024 |@@@@@@                                   19
            2048 |@@@@@@@@@@                               34
            4096 |@@@@@                                    15
            8192 |@@@@@@@@@@@@@@@@@@                       61
           16384 |@                                        2
           32768 |                                         0

  stat64
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@                                        2
            4096 |@                                        1
            8192 |@@@                                      5
           16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@          52
           32768 |@@@@                                     7
           65536 |                                         0

  send
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@                                       2
            4096 |@                                        1
            8192 |@@@@@@@@@@@@@@@@@@                       22
           16384 |@@@@@@@@@@                               12
           32768 |@@@@@                                    6
           65536 |@@@                                      4
          131072 |@@                                       3
          262144 |                                         0

  write
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@@                                       5
            1024 |@@@@                                     8
            2048 |                                         0
            4096 |@@@                                      6
            8192 |@@@@@@@@@@@                              23
           16384 |@@@@@@@@                                 16
           32768 |@@@@@@@@@@                               22
           65536 |@@                                       4
          131072 |                                         0
          262144 |                                         1
          524288 |                                         0

  doorfs
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@@@@@@@@@@@@@@@@@@@                     1
            8192 |                                         0
           16384 |                                         0
           32768 |                                         0
           65536 |                                         0
          131072 |                                         0
          262144 |                                         0
          524288 |                                         0
         1048576 |                                         0
         2097152 |@@@@@@@@@@@@@@@@@@@@                     1
         4194304 |                                         0

  yield
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@@@@@@@@@@@@                    198
            2048 |@                                        5
            4096 |                                         1
            8192 |@@@@@@                                   61
           16384 |@@@@@@@@@@@@                             110
           32768 |                                         2
           65536 |                                         2
          131072 |                                         0
          262144 |                                         1
          524288 |                                         0

  recv
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@@@@@@@@@@@@                             17
            1024 |@@@@                                     6
            2048 |@@@@@@@@@@@@@                            19
            4096 |@@@@                                     6
            8192 |                                         0
           16384 |                                         0
           32768 |                                         0
           65536 |                                         0
          131072 |@@                                       3
          262144 |@@@@                                     5
          524288 |                                         0
         1048576 |                                         0
         2097152 |                                         0
         4194304 |                                         0
         8388608 |                                         0
        16777216 |@                                        1
        33554432 |                                         0

  nanosleep
           value  ------------- Distribution ------------- count
         4194304 |                                         0
         8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 201
        16777216 |                                         0
        33554432 |                                         0
        67108864 |                                         0
       134217728 |                                         0
       268435456 |                                         0
       536870912 |                                         2
      1073741824 |                                         0

  ioctl
           value  ------------- Distribution ------------- count
             128 |                                         0
             256 |@                                        50
             512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   2157
            1024 |                                         17
            2048 |                                         8
            4096 |                                         10
            8192 |                                         13
           16384 |                                         6
           32768 |                                         3
           65536 |                                         7
          131072 |                                         0
          262144 |                                         0
          524288 |                                         0
         1048576 |                                         0
         2097152 |                                         0
         4194304 |                                         0
         8388608 |                                         2
        16777216 |                                         0
        33554432 |                                         0
        67108864 |                                         6
       134217728 |                                         0
       268435456 |                                         1
       536870912 |                                         4
      1073741824 |                                         0

  lwp_cond_wait
           value  ------------- Distribution ------------- count
        16777216 |                                         0
        33554432 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@          46
        67108864 |@@@@                                     6
       134217728 |                                         0
       268435456 |@                                        2
       536870912 |@@@@                                     6
      1073741824 |                                         0

  pollsys
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@                                        2
            2048 |                                         1
            4096 |                                         1
            8192 |                                         1
           16384 |                                         0
           32768 |                                         0
           65536 |@                                        2
          131072 |                                         0
          262144 |@@                                       6
          524288 |@                                        2
         1048576 |@@                                       5
         2097152 |@                                        2
         4194304 |                                         0
         8388608 |@@@                                      8
        16777216 |                                         0
        33554432 |                                         1
        67108864 |@@@@@@@@@@@@@@@@@@                       56
       134217728 |@@@@@@@@@                                28
       268435456 |                                         0
       536870912 |@@@                                      8
      1073741824 |                                         1
      2147483648 |                                         0

  lwp_park
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |                                         6
            4096 |@                                        21
            8192 |@                                        20
           16384 |@@@@@@@@@                                134
           32768 |@@@@@@@@@@                               145
           65536 |@@@@@@@@@@                               153
          131072 |@                                        11
          262144 |                                         3
          524288 |                                         0
         1048576 |                                         0
         2097152 |                                         0
         4194304 |                                         0
         8388608 |@@@@@@                                   89
        16777216 |                                         0
        33554432 |                                         0
        67108864 |                                         0
       134217728 |                                         2
       268435456 |                                         4
       536870912 |@                                        18
      1073741824 |                                         2
      2147483648 |                                         0

  portfs
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |                                         4
            1024 |@@@                                      41
            2048 |@@@@                                     44
            4096 |@                                        14
            8192 |                                         2
           16384 |                                         1
           32768 |                                         2
           65536 |                                         1
          131072 |                                         3
          262144 |@                                        10
          524288 |                                         3
         1048576 |                                         6
         2097152 |                                         3
         4194304 |                                         0
         8388608 |@@@@@@@@@@@@@@@@@@@@@@@                  272
        16777216 |                                         1
        33554432 |                                         1
        67108864 |                                         4
       134217728 |                                         2
       268435456 |                                         5
       536870912 |@@@@@                                    58
      1073741824 |                                         3
      2147483648 |                                         1
      4294967296 |                                         0

For those keeping score, that would be 482 lines of output — and that was for just a couple of seconds. Brendan’s observation was that it would be great to tip these aggregations on their side (so their bars point up-and-down, not left-to-right) — with the output for each key appearing on one line. This is clearly a great idea, and “-x aggpack” was born:

# dtrace -n syscall:::entry'{self->ts = vtimestamp}' \
    -n syscall:::return'/self->ts/{@[probefunc] = \
    quantize(vtimestamp - self->ts); self->ts = 0}' -x aggpack
dtrace: description 'syscall:::entry' matched 233 probes
dtrace: description 'syscall:::return' matched 233 probes
^C

              key  min .------------------. max     | count
       sigpending    8 :     X            : 1048576 | 1
     lwp_continue    8 :      X           : 1048576 | 1
           uucopy    8 :      X           : 1048576 | 1
           getuid    8 :  x   x           : 1048576 | 2
         lwp_kill    8 :       X          : 1048576 | 1
        sigaction    8 :   xx x           : 1048576 | 4
           llseek    8 :     x x          : 1048576 | 2
          fstat64    8 :     xx           : 1048576 | 4
       setcontext    8 :      xx          : 1048576 | 2
      lwp_sigmask    8 :   xx _           : 1048576 | 10
       systeminfo    8 :     xx           : 1048576 | 4
        sysconfig    8 :   ____x          : 1048576 | 6
           accept    8 :       xx         : 1048576 | 2
             bind    8 :         X        : 1048576 | 2
            fstat    8 :     x    x       : 1048576 | 2
         recvfrom    8 :        X         : 1048576 | 5
           doorfs    8 :         xx       : 1048576 | 2
              brk    8 :     ___xx        : 1048576 | 8
       lwp_create    8 :           X      : 1048576 | 1
         schedctl    8 :       x   x      : 1048576 | 2
         p_online    8 :   X_  _          : 1048576 | 256
           getpid    8 :      xx_ _       : 1048576 | 28
          recvmsg    8 :       xx_        : 1048576 | 18
             open    8 :         xx x     : 1048576 | 4
            lseek    8 :       xx _ _     : 1048576 | 9
       getsockopt    8 :      _xx         : 1048576 | 43
             stat    8 :        x_x _     : 1048576 | 7
             mmap    8 :             X    : 1048576 | 1
           putmsg    8 :             X    : 1048576 | 1
             recv    8 :     _xxx__       : 1048576 | 65
            gtime    8 :   X_____         : 1048576 | 899
            fcntl    8 :   ___xx          : 1048576 | 208
       setsockopt    8 :      __x__       : 1048576 | 55
          sendmsg    8 :           xxx    : 1048576 | 9
  lwp_cond_signal    8 :       _x__x      : 1048576 | 33
            close    8 :       __xx_      : 1048576 | 65
    lwp_cond_wait    8 :        _xx_      : 1048576 | 69
           munmap    8 :                X : 1048576 | 1
             read    8 :    ___x_x_ _ _   : 1048576 | 137
           stat64    8 :        ___X      : 1048576 | 49
            yield    8 : _    X___        : 1048576 | 1314
        so_socket    8 :        ___x_     : 1048576 | 60
        nanosleep    8 :         _x__     : 1048576 | 77
             send    8 :      ____xx__    : 1048576 | 66
          pollsys    8 :       _ _xx_     : 1048576 | 86
            ioctl    8 :    X_________    : 1048576 | 3259
          connect    8 :         _ _xx_   : 1048576 | 57
           mmap64    8 :        __x _   x : 1048576 | 14
            write    8 :     __ __x_____  : 1048576 | 115
           portfs    8 :     ______x_     : 1048576 | 619
         lwp_park    8 :        _xx_x_    : 1048576 | 654

This communicates essentially the same amount of information in just a fraction of the output (55 lines versus 482) — and makes it (much) easier to quickly compare distributions across aggregation keys. That said, one of the challenges here is that ASCII can be very limiting when trying to come with characters of clearly different height. When I demonstrated a prototype of this at the illumos BOF at Surge, a couple of folks volunteered that I should look into using the Unicode Block Elements for this output. Here’s the same enabling, but rendered using these elements:

# dtrace -n syscall:::entry'{self->ts = vtimestamp}' \
    -n syscall:::return'/self->ts/{@[probefunc] = \
    quantize(vtimestamp - self->ts); self->ts = 0}' -x aggpack
dtrace: description 'syscall:::entry' matched 233 probes
dtrace: description 'syscall:::return' matched 233 probes
^C


              key  min .-------------------. max     | count
         lwp_self   32 :   █               : 8388608 | 1
        sysconfig   32 : ▃▃▃               : 8388608 | 3
       sigpending   32 :    █              : 8388608 | 1
             pset   32 :  ▆ ▃              : 8388608 | 3
      getsockname   32 :     █             : 8388608 | 1
       systeminfo   32 :   ▅▄              : 8388608 | 5
            fstat   32 :      █            : 8388608 | 1
           llseek   32 :    ▆▃             : 8388608 | 3
          memcntl   32 :      █            : 8388608 | 1
      resolvepath   32 :      █            : 8388608 | 1
           semsys   32 :      █            : 8388608 | 1
       setcontext   32 :     █             : 8388608 | 2
          setpgrp   32 :      █            : 8388608 | 1
          fstat64   32 :   ▃▃▃             : 8388608 | 6
        sigaction   32 : ▃▃▂▃              : 8388608 | 17
           accept   32 :       █           : 8388608 | 1
           access   32 :       █           : 8388608 | 1
           munmap   32 :       █           : 8388608 | 1
        setitimer   32 :    ▅▃▃            : 8388608 | 4
      lwp_sigmask   32 : ▄▃▃▂              : 8388608 | 26
             pipe   32 :        █          : 8388608 | 1
          waitsys   32 :   ▅    ▅          : 8388608 | 2
             stat   32 :     ▃ ▆           : 8388608 | 3
             bind   32 :      ▅▄           : 8388608 | 5
          mmapobj   32 :         █         : 8388608 | 1
           open64   32 :         █         : 8388608 | 1
         p_online   32 : █▁ ▁              : 8388608 | 256
           getpid   32 :   ▁▆▂             : 8388608 | 45
         schedctl   32 :         █         : 8388608 | 2
       getsockopt   32 :    ▃▅▂            : 8388608 | 32
       setsockopt   32 :   ▁▁▃▆            : 8388608 | 31
            fcntl   32 : ▂▁▃▃▂             : 8388608 | 114
          recvmsg   32 :    ▁▄▃▂▁▁         : 8388608 | 17
           putmsg   32 :           █       : 8388608 | 1
             mmap   32 :       ▅   ▅       : 8388608 | 2
           writev   32 :         ▆ ▃       : 8388608 | 3
            lseek   32 :   ▁▃▃▄▁▁          : 8388608 | 76
              brk   32 :  ▃▂▃▃▂▁▁ ▁        : 8388608 | 124
            gtime   32 : ▇▁▁▁▁▁ ▁          : 8388608 | 1405
          sendmsg   32 :        ▂▅▄        : 8388608 | 10
             recv   32 :   ▂▃▃▂▂▁          : 8388608 | 159
            yield   32 :    █▁▁▁           : 8388608 | 409
             open   32 :      ▃▂▄▁▂        : 8388608 | 30
            close   32 :    ▂▃▂▃▂▁         : 8388608 | 60
        so_socket   32 :       ▁▃▆         : 8388608 | 29
  lwp_cond_signal   32 :    ▁▃▂▂▁▃▁        : 8388608 | 59
        nanosleep   32 :       ▂▆▂         : 8388608 | 74
    lwp_cond_wait   32 :      ▂▃▄▂         : 8388608 | 120
          connect   32 :         ▂▅▃       : 8388608 | 24
           stat64   32 :       ▁▂▇▁        : 8388608 | 77
          pollsys   32 :   ▁▁▁ ▁▅▄         : 8388608 | 148
             send   32 :    ▁▂▂▂▂▃▂▁       : 8388608 | 137
             read   32 :   ▁▂▃▂▃▂▁▁▁▁      : 8388608 | 283
            ioctl   32 :  ▇▁▁▁▁▁▁▁▁▁▁      : 8388608 | 3697
            write   32 :   ▁▁▁▂▂▃▂▁▁ ▁▁    : 8388608 | 207
          forksys   32 :                 █ : 8388608 | 1
           portfs   32 :   ▁▂▂▁▁▂▄▁ ▁      : 8388608 | 807
         lwp_park   32 :  ▁ ▁▁▁▃▃▂▃▁       : 8388608 | 919

Delicious! (Assuming, of course, that these look right for you — which they may or may not, depending on how your monospaced font renders the Unicode Block Elements.) After one look at the Unicode Block Elements, it clearly had to be the default behavior — but if your terminal is rendered in a font that can’t display the UTF-8 encodings of these characters (less common) or if they render in a way that is not monospaced despite being in a putatively monospaced font (more common), I also added a “-x encoding” option that can be set to “ascii” to force the ASCII output.

Returning to our example, if the above is too much dead space for you, you can combine it with aggzoom:

# dtrace -n syscall:::entry'{self->ts = vtimestamp}' \
    -n syscall:::return'/self->ts/{@[probefunc] = \
    quantize(vtimestamp - self->ts); self->ts = 0}' -x aggpack -x aggzoom
dtrace: description 'syscall:::entry' matched 233 probes
dtrace: description 'syscall:::return' matched 233 probes
^C


              key  min .----------------. max     | count
     lwp_continue   32 :    █           : 1048576 | 1
       sigpending   32 :    █           : 1048576 | 1
           uucopy   32 :    █           : 1048576 | 1
         lwp_kill   32 :     █          : 1048576 | 1
        sigaction   32 : ▄▄ █           : 1048576 | 4
             pset   32 :  █  ▄          : 1048576 | 3
        sysconfig   32 : ███ █          : 1048576 | 4
       setcontext   32 :    ██          : 1048576 | 2
            fstat   32 :      █         : 1048576 | 1
         recvfrom   32 :      █         : 1048576 | 1
       systeminfo   32 :   ▅█           : 1048576 | 5
      lwp_sigmask   32 : ██▂▅           : 1048576 | 14
           accept   32 :     █ █        : 1048576 | 2
          recvmsg   32 :     █ █        : 1048576 | 2
             stat   32 :        █       : 1048576 | 2
         p_online   32 : █▁ ▁           : 1048576 | 256
         schedctl   32 :      █  █      : 1048576 | 2
              brk   32 :    ▄███▄       : 1048576 | 8
       getsockopt   32 :    ▅██         : 1048576 | 21
           getpid   32 :    █▇          : 1048576 | 39
       setsockopt   32 :     ▃█▂        : 1048576 | 16
       lwp_create   32 :          █     : 1048576 | 1
          sendmsg   32 :          █     : 1048576 | 1
            fcntl   32 : ▃▄▃▆█▁         : 1048576 | 60
           writev   32 :           █    : 1048576 | 1
            lseek   32 :    ▆▇█▂        : 1048576 | 65
             recv   32 :  ▁▆▃█▆▅        : 1048576 | 62
           putmsg   32 :           █    : 1048576 | 2
             open   32 :      █ ▅▂▃     : 1048576 | 16
            gtime   32 : █▁▁▁▁  ▁       : 1048576 | 1365
            close   32 :    ▂█▂█▄▃      : 1048576 | 36
  lwp_cond_signal   32 :     ▂▂█▅▅▂     : 1048576 | 18
        so_socket   32 :      ▁▂▁█      : 1048576 | 19
             mmap   32 :     ▆▃ █▄ ▆    : 1048576 | 13
        nanosleep   32 :       ▃█▃      : 1048576 | 34
             read   32 :   ▁▂▅▄█▅▂      : 1048576 | 144
    lwp_cond_wait   32 :       ▃█▂▁     : 1048576 | 74
            yield   32 :    █▁▁▁ ▁      : 1048576 | 1187
             send   32 :     ▁▂▅█▅▄▂    : 1048576 | 50
          connect   32 :      ▂▂ ▅██▃   : 1048576 | 20
           stat64   32 :     ▁▁▁▃█▁     : 1048576 | 80
          pollsys   32 :     ▁▁▁█▆      : 1048576 | 136
            write   32 :  ▂▄ ▃▂▄█▆▃▂ ▂  : 1048576 | 77
            ioctl   32 :  █▂▁▁▁▁▁▁ ▁    : 1048576 | 4587
           mmap64   32 :      ▂▄▄▂▅ ▂ █ : 1048576 | 20
           portfs   32 :  ▁▁▂▂▁▂▂█▂     : 1048576 | 601
         lwp_park   32 :    ▁▁▂▆▇▃█▁▁   : 1048576 | 787

Here’s another fun one:

# dtrace -n BEGIN'{start = timestamp}' \
    -n sched:::on-cpu'{@[execname] = \
    lquantize((timestamp - start) / 1000000000, 0, 30, 1)}' \
    -x aggpack -n tick-1sec'/++i >= 30/{exit(0)}' -q
              key     min .--------------------------------. max      | count
             sshd     < 0 : █                              : >= 30    | 1
            zpool     < 0 : █                              : >= 30    | 8
              zfs     < 0 : █                              : >= 30    | 19
          zoneadm     < 0 : █                              : >= 30    | 19
            utmpd     < 0 :     █                          : >= 30    | 1
            intrd     < 0 :                             █  : >= 30    | 2
             epmd     < 0 :   ▂    ▂    ▂    ▂    ▂    ▂   : >= 30    | 6
            mdnsd     < 0 :   ▂    ▂    ▂    ▂    ▂    ▂   : >= 30    | 6
         sendmail     < 0 :   ▂    ▂    ▂    ▂    ▂    ▂   : >= 30    | 6
         ur-agent     < 0 :   ▂▂         ▂         ▂   ▃▂  : >= 30    | 14
           vmadmd     < 0 :     ▃    ▂    ▂    ▂    ▂    ▃ : >= 30    | 22
         devfsadm     < 0 : ▁ ▁ ▁ ▁ ▁ ▁ ▁ ▁ ▁ ▁ ▁ ▁ ▁ ▁ ▁  : >= 30    | 30
          bridged     < 0 : ▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 30
          fsflush     < 0 : ▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 32
              fmd     < 0 :        ▁▁        ▁▇        ▁▁  : >= 30    | 41
            ipmon     < 0 : ▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 51
          ipmgmtd     < 0 :         ▃         ▃         ▃  : >= 30    | 66
            lldpd     < 0 : ▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 90
           dtrace     < 0 : ▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 111
          haproxy     < 0 : ▂▁▁▁▁▁▁▂▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂▁▁ : >= 30    | 113
      svc.configd     < 0 :         ▂▁        ▄▁        ▂▁ : >= 30    | 126
       svc.startd     < 0 :         ▃▁        ▃▁        ▃▁ : >= 30    | 150
         beam.smp     < 0 : ▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 209
             nscd     < 0 : ▁       ▃▂        ▃▂        ▃▂ : >= 30    | 192
         postgres     < 0 : ▁▁▁▁▁▁▁▂▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 598
     redis-server     < 0 : ▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 598
      zpool-zones     < 0 :     ▂  ▁ ▂    ▃  ▁ ▂    ▂  ▁ ▃ : >= 30    | 623
             java     < 0 : ▁▁▁▁▁▂▁▁▁▁▁▁▁▁▁▁▁▁▂▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 1211
             tail     < 0 : ▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 1178
             node     < 0 : ▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂▁ : >= 30    | 11195
            sched     < 0 : ▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁ : >= 30    | 22101

This (quickly) shows you the second offset for CPU scheduling events from the start of the D script for various applications, and points to some obvious conclusions: there are clearly a bunch of programs running once every ten seconds, a couple more running once every five seconds, and so on.

encoding

Seeing this, why should aggpack hog all that Unicode hawtness? While only aggpack will use the UTF-8 encodings by default, I also extended the encoding option to allow a “utf8” setting that forces the UTF-8 encoding of the Unicode Block Elements to be used for all aggregation display. For example, to return to our earlier agghist example:

# dtrace -n syscall:::entry'{@[execname] = count()}' \
    -x agghist -x aggzoom -x encoding=utf8
dtrace: description 'syscall:::entry' matched 233 probes
dtrace: description 'syscall:::entry' matched 233 probes
^C

              key  ------------- Distribution ------------- count
            utmpd |                                         2
             sshd |                                         10
           pickup |                                         14
              fmd |                                         20
         ur-agent |                                         21
             epmd |                                         22
           vmadmd |                                         31
      jsontool.js |                                         33
            mdnsd |                                         33
           master |                                         41
            intrd |                                         45
         devfsadm |                                         54
          ipmgmtd |                                         55
          bridged |                                         81
            mkdir |                                         83
              cat |                                         96
         sendmail |                                         101
            ipmon |                                         108
          dirname |                                         115
       svc.startd |                                         129
            ksh93 |                                         164
               ls |                                         182
          svcprop |▏                                        258
             bash |▏                                        290
            zpool |▎                                        436
             date |▎                                        448
             cron |▎                                        470
            lldpd |▍                                        595
 dump-minutely-sd |▍                                        609
          haproxy |▍                                        654
      svc.configd |▌                                        907
         zoneadmd |█                                        1554
              zfs |█▎                                       1979
          zoneadm |█▋                                       2414
             nscd |█▋                                       2522
             java |██▏                                      3205
             tail |██▌                                      3775
         postgres |████▏                                    6083
     redis-server |██████████████▋                          21710
           dtrace |███████████████████▎                     28509
             node |█████████████████████████▍               37427
         beam.smp |██████████████████████████████████████   55948

To paraphrase Kent Brockman, I for one welcome our new Unicode Block Element overlords — and I look forward to toiling in their underground sugar caves!

Availability

All of these new options have been integrated into SmartOS (and we aim to get them up into illumos). If you’re a Joyent public cloud customer, you already all have these improvements or they will be coming to you when your platform is next upgraded (depending on the compute node that you have landed on). And if you’re a DTrace user and like Brendan and have some new way that you’d like to see data visualized (or have any other DTrace feature request), don’t hesitate to speak up — DTrace only improves when those of us who depend on it every day envision a way that it could be even better!

Recent Posts

November 26, 2023
November 18, 2023
November 27, 2022
October 11, 2020
July 31, 2019
December 16, 2018
September 18, 2018
December 21, 2016
September 30, 2016
September 26, 2016
September 13, 2016
July 29, 2016
December 17, 2015
September 16, 2015
January 6, 2015
November 10, 2013
September 3, 2013
June 7, 2012
September 15, 2011
August 15, 2011
March 9, 2011
September 24, 2010
August 11, 2010
July 30, 2010
July 25, 2010
March 10, 2010
November 26, 2009
February 19, 2009
February 2, 2009
November 10, 2008
November 3, 2008
September 3, 2008
July 18, 2008
June 30, 2008
May 31, 2008
March 16, 2008
December 18, 2007
December 5, 2007
November 11, 2007
November 8, 2007
September 6, 2007
August 21, 2007
August 2, 2007
July 11, 2007
May 20, 2007
March 19, 2007
October 12, 2006
August 17, 2006
August 7, 2006
May 1, 2006
December 13, 2005
November 16, 2005
September 13, 2005
September 9, 2005
August 21, 2005
August 16, 2005

Archives