cddl/contrib/dtracetoolkit/Examples/cputimes_example.txt

   1 The following demonstrates running the cputimes program on an idle system.
   2 We use an interval of 1 second and a count of 3,
   3
   4    # ./cputimes 1 3
   5    2005 Apr 27 23:37:58,
   6             THREADS        TIME (ns)
   7              KERNEL         10795499
   8             PROCESS         20941091
   9                IDLE        970707443
  10    2005 Apr 27 23:37:59,
  11             THREADS        TIME (ns)
  12              KERNEL          8919418
  13             PROCESS         77446789
  14                IDLE        910555040
  15    2005 Apr 27 23:38:00,
  16             THREADS        TIME (ns)
  17              KERNEL          8615123
  18             PROCESS         78314246
  19                IDLE        810100417
  20
  21 In the above output, we can see a breakdown of CPU time into the catagories
  22 KERNEL, PROCESS and IDLE. The time is measured in nanoseconds. Most of the
  23 time is in the IDLE category, as the system is idle. Very little time
  24 was spent serving the kernel.
  25
  26
  27
  28
  29 In the following example, several programs are run to hog the CPUs,
  30
  31    # ./cputimes 1 3
  32    2005 Apr 27 23:40:58,
  33             THREADS        TIME (ns)
  34              KERNEL         11398807
  35             PROCESS        992254664
  36    2005 Apr 27 23:40:59,
  37             THREADS        TIME (ns)
  38              KERNEL          9205260
  39             PROCESS        987561182
  40    2005 Apr 27 23:41:00,
  41             THREADS        TIME (ns)
  42              KERNEL          9196669
  43             PROCESS        877850474
  44
  45 Now there is no IDLE category, as the system is 100% utilised.
  46 The programs were the following,
  47
  48         while :; do :; done &
  49
  50 which keeps the CPU busy.
  51
  52
  53
  54
  55 In the following example a different style of program is run to hog the CPUs,
  56
  57         while :; do date; done
  58
  59 This causes many processes to be created and destroyed in a hurry, and can
  60 be difficult to troubleshoot (tools like prstat cannot sample quick enough
  61 to easily identify what is going on). The following is the cputimes output,
  62
  63    # ./cputimes 1 3
  64    2005 Apr 27 23:45:30,
  65             THREADS        TIME (ns)
  66              KERNEL        192647392
  67             PROCESS        835397568
  68    2005 Apr 27 23:45:31,
  69             THREADS        TIME (ns)
  70              KERNEL        168773713
  71             PROCESS        810825730
  72    2005 Apr 27 23:45:32,
  73             THREADS        TIME (ns)
  74              KERNEL        151676122
  75             PROCESS        728477272
  76
  77 Now the kernel is doing a substantial amount of work to create and destroy
  78 these processes.
  79
  80
  81
  82
  83 In the following example, a large amount of network activity occurs while
  84 cputimes is running,
  85
  86    # ./cputimes 1 6
  87    2005 Apr 27 23:49:29,
  88             THREADS        TIME (ns)
  89              KERNEL         10596399
  90             PROCESS         21793920
  91                IDLE        974395713
  92    2005 Apr 27 23:49:30,
  93             THREADS        TIME (ns)
  94              KERNEL        251465759
  95                IDLE        357436576
  96             PROCESS        508986422
  97    2005 Apr 27 23:49:31,
  98             THREADS        TIME (ns)
  99                IDLE          9758227
 100              KERNEL        367645318
 101             PROCESS        385427847
 102    2005 Apr 27 23:49:32,
 103             THREADS        TIME (ns)
 104                IDLE         28351679
 105              KERNEL        436022725
 106             PROCESS        451304688
 107    2005 Apr 27 23:49:33,
 108             THREADS        TIME (ns)
 109              KERNEL        262586158
 110             PROCESS        325238896
 111                IDLE        358243503
 112    2005 Apr 27 23:49:34,
 113             THREADS        TIME (ns)
 114              KERNEL         10075578
 115             PROCESS        238170506
 116                IDLE        647956998
 117
 118 Initially the system is idle. A command is run to cause heavy network
 119 activity, which peaks during the fourth sample - during which the kernel
 120 is using around 40% of the CPU. The Solaris 10 command "intrstat" can
 121 help to analyse this activity further.
 122
 123
 124
 125
 126 Longer samples are possible. The following is a 60 second sample,
 127
 128    # ./cputimes 60 1
 129    2005 Apr 27 23:53:02,
 130             THREADS        TIME (ns)
 131              KERNEL        689808449
 132             PROCESS       8529562214
 133                IDLE      50406951876
 134    #
 135
 136
 137
 138
 139 cputimes has a "-a" option to print all processes. The following is a
 140 single 1 second sample with -a,
 141
 142    # ./cputimes -a 1 1
 143    2005 Apr 28 00:00:32,
 144             THREADS        TIME (ns)
 145          svc.startd            51042
 146            nautilus           130645
 147           in.routed           131823
 148                 fmd           152822
 149                nscd           307042
 150                dsdm           415799
 151       mixer_applet2           551066
 152       gnome-smproxy           587234
 153        xscreensaver           672270
 154             fsflush          1060196
 155             java_vm          1552988
 156         wnck-applet          2060870
 157              dtrace          2398658
 158            acroread          2614687
 159         soffice.bin          2825117
 160         mozilla-bin          5497488
 161              KERNEL         13541120
 162            metacity         28924204
 163      gnome-terminal         74304348
 164                Xorg        289631407
 165                IDLE        465054209
 166
 167 The times are in nanoseconds, and multiple processes with the same name
 168 have their times aggregated. The above output is at an amazing resolution -
 169 svc.startd ran for 51 microseconds, and soffice.bin ran for 28 milliseconds.
 170
 171
 172
 173
 174 The following is a 10 second sample on an idle desktop,
 175
 176    # ./cputimes -a 10 1
 177    2005 Apr 28 00:03:57,
 178             THREADS        TIME (ns)
 179               snmpd           127859
 180                 fmd           171897
 181               inetd           177134
 182         svc.configd           185006
 183      mapping-daemon           197674
 184         miniserv.pl           305603
 185            gconfd-2           330511
 186        xscreensaver           443207
 187            sendmail           473434
 188            nautilus           506799
 189    gnome-vfs-daemon           549037
 190         gnome-panel           770631
 191                nscd           885353
 192          svc.startd          1181286
 193    gnome-netstatus-          4329671
 194       mixer_applet2          4833519
 195              dtrace          6244366
 196           in.routed          6556075
 197             fsflush          9553155
 198         soffice.bin         13954327
 199             java_vm         16285243
 200            acroread         32126193
 201      gnome-terminal         34891991
 202                Xorg         35553412
 203         mozilla-bin         67855629
 204              KERNEL         94834997
 205                IDLE       9540941846
 206
 207 Wow, maybe not as idle as I thought!
 208
 209
 210