Home | History | Annotate | Line # | Download | only in Examples
      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 
    211