High system time on Windows running in a VM

Posted in: Technical Track

Recently I’ve seen an issue with CPU usage on a server running Windows 2003 Server in a VMware. This is a small Virtual Machine with just 2 cores allocated (which are possibly mapped to “threads” on a host level but I don’t know the details). For some reason very high System CPU time was reported in a Statspack report.

Here is how it looks like in a 1 hour Statspack report:

Host CPU  (CPUs: 2  Cores: 2  Sockets: 0)
~~~~~~~~              Load Average
                      Begin     End      User  System    Idle     WIO     WCPU
                    ——- ——-   ——- ——- ——- ——- ——–
                                         3.04    8.77   88.19

Note that the System CPU time is more than twice the User CPU time on average (remember the averages could be misleading sometimes). This caught my attention as usual. Although the average CPU used is not really high, this server is somewhat sluggish even for a one hop RDP connection over the VPN.
I have tried to find out some details about what is going on. Since I’m not a Windows guy, I did not know what kind of tools could be used to track places in the OS kernel that take too much time. On Linux this is relatively easy starting with strace/pstack/perf utilities and other command line tools. Windows is different.

I’ve started to search for the options available, and the first thing to find is of course Perfmon, which allows to track and visualize different OS related metrics (counters in Perfmon terminology) on a system, CPU, or process levels. I’ve used it to capture a few key metrics such as User Time, System Time (which is apparently called Privileged Time on Windows), Queue length and Context Switches per second. From a graph of the CPU usage the issue is visible:

Here the white line is representing Privileged (or System) CPU, and yellow line is Total CPU. It’s clear that almost all used CPU is accounted to the Privileged part.
By the way it is actually very easy to see a similar picture in a standard Performance tab of Task Manager, you just need to select View then Show Kernel Times and Privileged part of the used CPU will be displayed in red.

After that I have searched for details of where to find why Privileged CPU time is so high. A good article that I have found is here. Although it is relatively old, it fits my case as the OS is a 32 bit Windows 2003 Server. The article points to a tool called KernRates. This is a command line tool with a very easy interface: you run it, wait for some time and stop it with Ctrl-C. After that the tool prints the profile of system calls by module. Here is what I’ve seen:

C:\Program Files\KrView\Kernrates>Kernrate_i386_Win2000.exe
 /==============================\
<         KERNRATE LOG           >
 \==============================/
Date: 2014/09/03   Time: 12:39:21
Machine Name: ***
Number of Processors: 2
PROCESSOR_ARCHITECTURE: x86
PROCESSOR_LEVEL: 6
PROCESSOR_REVISION: 1706
Physical Memory: 3072 MB
Pagefile Total: 6996 MB
Virtual Total: 2047 MB
PageFile1: \??\C:\pagefile.sys, 4080MB
OS Version: 5.2 Build 3790 Service-Pack: 2.0
WinDir: C:\WINDOWS
Kernrate User-Specified Command Line:
Kernrate_i386_Win2000.exe
Kernel Profile (PID = 0): Source= Time,
Using Kernrate Default Rate of 25000 events/hit
Starting to collect profile data
***> Press ctrl-c to finish collecting profile data
===> Finished Collecting Data, Starting to Process Results
————Overall Summary:————–
P0     K 0:00:03.703 ( 8.7%)  U 0:00:00.734 ( 1.7%)  I 0:00:38.046 (89.6%)  DPC 0:00:00.031 ( 0.1%)  Interrupt 0:00:00.406 ( 1.0%)
       Interrupts= 22840, Interrupt Rate= 538/sec.
P1     K 0:00:02.343 ( 5.5%)  U 0:00:00.656 ( 1.5%)  I 0:00:39.484 (92.9%)  DPC 0:00:00.000 ( 0.0%)  Interrupt 0:00:00.281 ( 0.7%)
       Interrupts= 20017, Interrupt Rate= 471/sec.
TOTAL  K 0:00:06.046 ( 7.1%)  U 0:00:01.390 ( 1.6%)  I 0:01:17.531 (91.2%)  DPC 0:00:00.031 ( 0.0%)  Interrupt 0:00:00.687 ( 0.8%)
       Total Interrupts= 42857, Total Interrupt Rate= 1009/sec.
Total Profile Time = 42484 msec
                                       BytesStart          BytesStop         BytesDiff.
    Available Physical Memory   ,       372678656,       363945984,        -8732672
    Available Pagefile(s)       ,      3285475328,      3281805312,        -3670016
    Available Virtual           ,      2131267584,      2130219008,        -1048576
    Available Extended Virtual  ,               0,               0,               0
                                  Total      Avg. Rate
    Context Switches     ,        61247,         1442/sec.
    System Calls         ,       305201,         7184/sec.
    Page Faults          ,        58440,         1376/sec.
    I/O Read Operations  ,         3496,         82/sec.
    I/O Write Operations ,         2637,         62/sec.
    I/O Other Operations ,        29567,         696/sec.
    I/O Read Bytes       ,     59649045,         17062/ I/O
    I/O Write Bytes      ,      2653894,         1006/ I/O
    I/O Other Bytes      ,    624604436,         21125/ I/O
—————————–
Results for Kernel Mode:
—————————–
OutputResults: KernelModuleCount = 109
Percentage in the following table is based on the Total Hits for the Kernel
Time   33235 hits, 25000 events per hit ——–
 Module                                Hits   msec  %Total  Events/Sec
intelppm                              30310      42486    91 %    17835286
ntkrnlpa                               2337      42486     7 %     1375158
hal                                     271      42486     0 %      159464
mfehidk01                                74      42486     0 %       43543
Ntfs                                     58      42486     0 %       34128
mfehidk                                  52      42486     0 %       30598
mfeapfk                                  47      42486     0 %       27656
mfeavfk01                                17      42486     0 %       10003
tcpip                                    13      42486     0 %        7649
win32k                                   12      42486     0 %        7061
mfeavfk                                  10      42486     0 %        5884
fltmgr                                    6      42486     0 %        3530
CLASSPNP                                  3      42486     0 %        1765
SCSIPORT                                  3      42486     0 %        1765
RDPDD                                     2      42486     0 %        1176
afd                                       2      42486     0 %        1176
Npfs                                      2      42486     0 %        1176
NDIS                                      2      42486     0 %        1176
symmpi                                    2      42486     0 %        1176
TDTCP                                     1      42486     0 %         588
rdbss                                     1      42486     0 %         588
netbt                                     1      42486     0 %         588
mfetdi2k                                  1      42486     0 %         588
ipsec                                     1      42486     0 %         588
termdd                                    1      42486     0 %         588
TDI                                       1      42486     0 %         588
vmxnet                                    1      42486     0 %         588
KSecDD                                    1      42486     0 %         588
atapi                                     1      42486     0 %         588
volsnap                                   1      42486     0 %         588
ftdisk                                    1      42486     0 %         588
================================= END OF RUN ==================================
============================== NORMAL END OF RUN ==============================

The default output contains some basic information about the system, CPU usage, memory and context switching. The kernel modules profile is the most interesting part here. It lists some modules with internal names and the profile data: number of times the module was running during a sample; this is the most important information. So in mycase intelppm was the top running kernel module.
I’ve searched again, now for intelppm, and found a few posts describing similar symptoms. Apparently intelppm is a CPU driver. Sometimes it causes issues such as BSOD or high CPU usage, especially if it is a cloned VM and CPU architecture changes in between. It was not clear if this something which can be disabled, but there were posts suggesting that stopping this service (which is not listed in Services) helped a few people. So I have recommended the client to try to disable this driver with the following commands:

sc config intelppm start=disabled
sc stop intelppm

Theoretically this should disable Intel CPU driver and Windows should try to use another if it is available. When we tried to run it, the 2nd command (to stop the driver) failed with the following message:

[SC] ControlService FAILED 1052:
The requested control is not valid for this service.

So it is not possible to stop the driver online, and Windows restart is necessary.
We did a restart of the VM. After that, the situation was a bit different: the CPU time was somewhat reduced; but the privileged part was still quite high with hal (Hardware Abstraction Layer) on top instead of intelppm:

Time   95865 hits, 25000 events per hit ——–
 Module                                Hits   msec  %Total  Events/Sec
hal                                   82669     125183    86 %    16509629
ntkrnlpa                              11788     125183    12 %     2354153
mfehidk                                 474     125183     0 %       94661
mfeapfk                                 224     125183     0 %       44734
Ntfs                                    207     125183     0 %       41339
vmmemctl                                155     125183     0 %       30954
mfeavfk                                  92     125183     0 %       18373
tcpip                                    85     125183     0 %       16975
win32k                                   54     125183     0 %       10784
fltmgr                                   14     125183     0 %        2795
mfetdi2k                                 11     125183     0 %        2196
TDI                                      10     125183     0 %        1997
RDPWD                                     9     125183     0 %        1797
PartMgr                                   9     125183     0 %        1797
KSecDD                                    7     125183     0 %        1397
SCSIPORT                                  7     125183     0 %        1397
afd                                       6     125183     0 %        1198
symmpi                                    6     125183     0 %        1198
RDPDD                                     5     125183     0 %         998
ipsec                                     5     125183     0 %         998
NDIS                                      5     125183     0 %         998
CLASSPNP                                  5     125183     0 %         998
mfebopk                                   4     125183     0 %         798
Npfs                                      3     125183     0 %         599
termdd                                    3     125183     0 %         599
vmxnet                                    2     125183     0 %         399
volsnap                                   2     125183     0 %         399
ndisuio                                   1     125183     0 %         199
mrxsmb                                    1     125183     0 %         199
rdbss                                     1     125183     0 %         199
atapi                                     1     125183     0 %         199

But in terms of Oracle performance everything changed: everything now run much faster, including simple queries in the SQL*Plus. A particular query started to run 3 times faster on average:

— stats before
SQL> @sqlstats cp9jr3hp1jupk
                  Elapsed     Ela/exec                            User IO     Rows per   Versi           Share  Avg hard
       Execs            s            s      CPU, s    Gets/exec         s         exec     ons   Loads Mem, MB parse, ms PX Exec
———— ———— ———— ———– ———— ——— ———— ——- ——- ——- ——— ——-
         135      170.093        1.260      155.31          835      4.29            1       1       1     .02    350.99       0
— stats after
SQL> @sqlstats cp9jr3hp1jupk
                  Elapsed     Ela/exec                            User IO     Rows per   Versi           Share  Avg hard
       Execs            s            s      CPU, s    Gets/exec         s         exec     ons   Loads Mem, MB parse, ms PX Exec
———— ———— ———— ———– ———— ——— ———— ——- ——- ——- ——— ——-
         604      212.151         .351      154.75        1,013     31.79            1       1       1     .02      8.34       0

It looks like the change helped, but there is no sign that it helped on the OS level. This makes me think that such an improvement in performance may be attributed to something else, such as OS, hypervisor or combination of them and Oracle. In any case, high system time is not good and it usually indicates that something is wrong.

email

Interested in working with Timur? Schedule a tech call.

4 Comments. Leave new

Michael Zhilin
October 23, 2014 12:39 am

intelppm is enemy of all VMs. 2 years ago I’ve faced similar issue with VirtualBox & JMeter, and after turning off intelppm throughput increased 4-5 times.

Reply
Timur Akhmadeev
October 23, 2014 2:05 am

Thanks Michael

Reply

What you did is disabling the ‘idle time’code in the intelppm, and replaced it by the idle loop in the HAL.
(you can verify the module by zooming into the driver with -z hal or -z intelppm and it will tell you in which module the time was spend, but first setup the symbols correctly using the msft symbol server)
If your Oracle query sped up, it’s very likely that your server and or VM spend time sleeping while it should have been running your query. Disabeling powersafe options in VMWare, your OS and/or hardware will prevent this.

Reply
Timur Akhmadeev
October 27, 2014 8:49 am

Thanks Mario, this is very helpful.

Reply

Leave a Reply

Your email address will not be published. Required fields are marked *