Training courses

Kernel and Embedded Linux

Bootlin training courses

Embedded Linux, kernel,
Yocto Project, Buildroot, real-time,
graphics, boot time, debugging...

Bootlin logo

Elixir Cross Referencer

The following demonstrates running the cputimes program on an idle system.
We use an interval of 1 second and a count of 3,

   # ./cputimes 1 3
   2005 Apr 27 23:37:58,
            THREADS        TIME (ns)
             KERNEL         10795499
            PROCESS         20941091
               IDLE        970707443
   2005 Apr 27 23:37:59,
            THREADS        TIME (ns)
             KERNEL          8919418
            PROCESS         77446789
               IDLE        910555040
   2005 Apr 27 23:38:00,
            THREADS        TIME (ns)
             KERNEL          8615123
            PROCESS         78314246
               IDLE        810100417

In the above output, we can see a breakdown of CPU time into the catagories
KERNEL, PROCESS and IDLE. The time is measured in nanoseconds. Most of the
time is in the IDLE category, as the system is idle. Very little time
was spent serving the kernel.




In the following example, several programs are run to hog the CPUs,

   # ./cputimes 1 3
   2005 Apr 27 23:40:58,
            THREADS        TIME (ns)
             KERNEL         11398807
            PROCESS        992254664
   2005 Apr 27 23:40:59,
            THREADS        TIME (ns)
             KERNEL          9205260
            PROCESS        987561182
   2005 Apr 27 23:41:00,
            THREADS        TIME (ns)
             KERNEL          9196669
            PROCESS        877850474

Now there is no IDLE category, as the system is 100% utilised. 
The programs were the following,

	while :; do :; done &

which keeps the CPU busy.




In the following example a different style of program is run to hog the CPUs,

	while :; do date; done 

This causes many processes to be created and destroyed in a hurry, and can 
be difficult to troubleshoot (tools like prstat cannot sample quick enough
to easily identify what is going on). The following is the cputimes output,

   # ./cputimes 1 3
   2005 Apr 27 23:45:30,
            THREADS        TIME (ns)
             KERNEL        192647392
            PROCESS        835397568
   2005 Apr 27 23:45:31,
            THREADS        TIME (ns)
             KERNEL        168773713
            PROCESS        810825730
   2005 Apr 27 23:45:32,
            THREADS        TIME (ns)
             KERNEL        151676122
            PROCESS        728477272

Now the kernel is doing a substantial amount of work to create and destroy
these processes.




In the following example, a large amount of network activity occurs while
cputimes is running,

   # ./cputimes 1 6
   2005 Apr 27 23:49:29,
            THREADS        TIME (ns)
             KERNEL         10596399
            PROCESS         21793920
               IDLE        974395713
   2005 Apr 27 23:49:30,
            THREADS        TIME (ns)
             KERNEL        251465759
               IDLE        357436576
            PROCESS        508986422
   2005 Apr 27 23:49:31,
            THREADS        TIME (ns)
               IDLE          9758227
             KERNEL        367645318
            PROCESS        385427847
   2005 Apr 27 23:49:32,
            THREADS        TIME (ns)
               IDLE         28351679
             KERNEL        436022725
            PROCESS        451304688
   2005 Apr 27 23:49:33,
            THREADS        TIME (ns)
             KERNEL        262586158
            PROCESS        325238896
               IDLE        358243503
   2005 Apr 27 23:49:34,
            THREADS        TIME (ns)
             KERNEL         10075578
            PROCESS        238170506
               IDLE        647956998

Initially the system is idle. A command is run to cause heavy network
activity, which peaks during the fourth sample - during which the kernel
is using around 40% of the CPU. The Solaris 10 command "intrstat" can
help to analyse this activity further.




Longer samples are possible. The following is a 60 second sample,

   # ./cputimes 60 1
   2005 Apr 27 23:53:02,
            THREADS        TIME (ns)
             KERNEL        689808449
            PROCESS       8529562214
               IDLE      50406951876
   #




cputimes has a "-a" option to print all processes. The following is a 
single 1 second sample with -a,

   # ./cputimes -a 1 1
   2005 Apr 28 00:00:32,
            THREADS        TIME (ns)
         svc.startd            51042
           nautilus           130645
          in.routed           131823
                fmd           152822
               nscd           307042
               dsdm           415799
      mixer_applet2           551066
      gnome-smproxy           587234
       xscreensaver           672270
            fsflush          1060196
            java_vm          1552988
        wnck-applet          2060870
             dtrace          2398658
           acroread          2614687
        soffice.bin          2825117
        mozilla-bin          5497488
             KERNEL         13541120
           metacity         28924204
     gnome-terminal         74304348
               Xorg        289631407
               IDLE        465054209

The times are in nanoseconds, and multiple processes with the same name
have their times aggregated. The above output is at an amazing resolution - 
svc.startd ran for 51 microseconds, and soffice.bin ran for 28 milliseconds.




The following is a 10 second sample on an idle desktop,

   # ./cputimes -a 10 1
   2005 Apr 28 00:03:57,
            THREADS        TIME (ns)
              snmpd           127859
                fmd           171897
              inetd           177134
        svc.configd           185006
     mapping-daemon           197674
        miniserv.pl           305603
           gconfd-2           330511
       xscreensaver           443207
           sendmail           473434
           nautilus           506799
   gnome-vfs-daemon           549037
        gnome-panel           770631
               nscd           885353
         svc.startd          1181286
   gnome-netstatus-          4329671
      mixer_applet2          4833519
             dtrace          6244366
          in.routed          6556075
            fsflush          9553155
        soffice.bin         13954327
            java_vm         16285243
           acroread         32126193
     gnome-terminal         34891991
               Xorg         35553412
        mozilla-bin         67855629
             KERNEL         94834997
               IDLE       9540941846

Wow, maybe not as idle as I thought!