Konstantin Chebotarev and
Dmitry Vostokov, 25th June 2009
http://support.citrix.com
Once we were discussing various ways to save memory dumps during high CPU consumption and both of us independently had an idea about writing such a small tool which allows to model different types of CPU load with different number of threads and different priorities. Because this tool can help people to understand CPU spike issues and play with different scenarios we decided to write an article for this magazine issue.
Cpuload tool was created usign MFC framework. Almost all our tools are created with the help of MFC instead of raw Win32 API to save developing time. First, we briefly discuss the code we added to MFC skeleton. Most of error handling is omitted for clarity there. Then we show the tool in action, and finally, show it internals from the debugger point of view (WinDbg).
The tool dialog resource is very simple. It consists from a slider to dynamically adjust CPU load and a static field to show CPU load percentage as a number:
The dialog initialization code sets realtime priority level for the current thread to boost GUI response. Because it is relative to the thread priority class (normal by default) this doesn’t freeze the system even on a uniprocessor machine. We need a good timer to model CPU balance so we are goimg to use the multimedia timer and set its resolution to 1 millisecond. Then we query the number of processors and call a function to create a CPU spiking thread for each processor.
BOOL CcpuloadDlg::OnInitDialog()
{
CDialog::OnInitDialog();
// …
SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_TIME_CRITICAL);
MMRESULT res=timeBeginPeriod(1);
SYSTEM_INFO SystemInfo;
GetSystemInfo(&SystemInfo);
CPU_Num = SystemInfo.dwNumberOfProcessors;
for(int i=0; i < CPU_Num; ++i)
{
CreateCPUSpiking(i);
}
return TRUE;
}
The following MFC code handles slider events and should be self-explanatory for MFC developers. If you don’t use MFC then after any slider move cpuval variable (int) is set to the value between 0 and 100:
CcpuloadDlg::CcpuloadDlg(CWnd* pParent /*=NULL*/)
: CDialog(CcpuloadDlg::IDD, pParent) , m_CPU_val(0)
{
m_hIcon = AfxGetApp()->LoadIcon(IDR_MAINFRAME);
}
void CcpuloadDlg::DoDataExchange(CDataExchange* pDX)
{
CDialog::DoDataExchange(pDX);
DDX_Control(pDX, IDC_CPULOAD_SLIDER, mSlider);
DDX_Text(pDX, IDC_CPU_PERCENT, m_CPU_val);
}
BEGIN_MESSAGE_MAP(CcpuloadDlg, CDialog)
ON_WM_SYSCOMMAND()
ON_WM_PAINT()
ON_WM_QUERYDRAGICON()
//}}AFX_MSG_MAP
ON_WM_HSCROLL()
END_MESSAGE_MAP()
void CcpuloadDlg::OnHScroll(UINT nSBCode, UINT nPos, CScrollBar* pScrollBar)
{
if(nSBCode==TB_THUMBTRACK)
{
m_CPU_val=cpuval=nPos;
UpdateData(FALSE);
CDialog::OnHScroll(nSBCode, nPos, pScrollBar);
}
}
The function that creates spiking threads also sets their thread affinity (assigns a unique processor for each thread):
void CreateCPUSpiking(int CPU_idx)
{
DWORD ThreadID;
HANDLE hThread;
hThread=::CreateThread(NULL,0,SpikingThread, NULL,0,&ThreadID);
DWORD_PTR mask=1 << CPU_idx;
SetThreadAffinityMask(hThread,mask);
}
Thread routine that runs thread code sleeps appropriate amount of milliseconds necessary to model CPU load:
DWORD WINAPI SpikingThread(LPVOID lpParameter)
{
double a=1.1;
DWORD time1=timeGetTime();
DWORD time2;
DWORD dt=100; // time to loop in milliseconds
DWORD ts; // time to sleep in milliseconds
do
{
a=a+0.1; // some dummy code to make CPU busy
a=a-0.1; //
time2=timeGetTime();
if((time2-time1) > dt) // if time to loop
// finished calculate new times
{
dt=cpuval*10; ts=1000-dt;
Sleep(ts);
time1=timeGetTime();
}
}
while(true);
return 0;
}
This code models CPU load almost exactly and its value corresponds to one that we see in Task Manager (all pictures were taken from 2 processor PC running x64 Windows Server 2008):
However 100% is not attainable when Task Manager is running because it eats approximately 1% of CPU time:
Other processes can eat CPU too, for example, this screenshot was taken while Windows Media Player was playing a CD (wmplayer.exe) with graphical animation turned on that ate csrss.exe time too:
In order to see what’s inside cpuload process we set CPU load to 100% and noninvasively attached WinDbg to it:
0:000> ~*k . 0 Id: 710.ec4 Suspend: 1 Teb: 7efdd000 Unfrozen ChildEBP RetAddr 0017fba0 778a67f0 USER32!NtUserGetMessage+0x15 0017fbbc 00510211 USER32!GetMessageW+0x33 WARNING: Stack unwind information not available. Following frames may be wrong. 0017fbe8 0051173c cpuload+0x110211 0017fbf4 0051031f cpuload+0x11173c 0017fc00 00535ea5 cpuload+0x11031f 0017fc28 00515561 cpuload+0x135ea5 0017fc94 004f814d cpuload+0x115561 0017fe84 006a43b2 cpuload+0xf814d 0017fea8 006a42a8 cpuload+0x2a43b2 0017fec0 00626d0f cpuload+0x2a42a8 0017ff80 00626a4d cpuload+0x226d0f 0017ff88 775de4a5 cpuload+0x226a4d 0017ff94 77eecfed kernel32!BaseThreadInitThunk+0xe 0017ffd4 77eed1ff ntdll!__RtlUserThreadStart+0x23 0017ffec 00000000 ntdll!_RtlUserThreadStart+0x1b 1 Id: 710.994 Suspend: 1 Teb: 7efda000 Unfrozen ChildEBP RetAddr 02e7ff88 775de4a5 WINMM!_alldiv+0x4d 02e7ff94 77eecfed kernel32!BaseThreadInitThunk+0xe 02e7ffd4 77eed1ff ntdll!__RtlUserThreadStart+0x23 02e7ffec 00000000 ntdll!_RtlUserThreadStart+0x1b 2 Id: 710.d20 Suspend: 1 Teb: 7efd7000 Unfrozen ChildEBP RetAddr WARNING: Stack unwind information not available. Following frames may be wrong. 02f7ff88 775de4a5 cpuload+0xf87cf 02f7ff94 77eecfed kernel32!BaseThreadInitThunk+0xe 02f7ffd4 77eed1ff ntdll!__RtlUserThreadStart+0x23 02f7ffec 00000000 ntdll!_RtlUserThreadStart+0x1b
We deliberately not applied symbol files for cpuload to show real life CPU spike scenario when symbol files are not available for 3rd-party software vendor modules. We see that threads 1 and 2 consumed plenty of CPU time in user mode relative to their life span:
0:000> !runaway f User Mode Time Thread Time 1:994 0 days 0:05:06.089 2:d20 0 days 0:04:45.076 0:ec4 0 days 0:00:00.156 Kernel Mode Time Thread Time 0:ec4 0 days 0:00:00.452 2:d20 0 days 0:00:00.062 1:994 0 days 0:00:00.015 Elapsed Time Thread Time 0:ec4 0 days 0:18:56.449 2:d20 0 days 0:18:56.143 1:994 0 days 0:18:56.143
So we have all information to diagnose Spiking Thread memory dump analysis pattern pointing to cpuload module[4]. Notice also that even noninvasive attach suspended threads and real CPU load becomes 0%. To resume the program we use ~m WinDbg command:
0:000> ~*m
Then we can randomly catch our thread stack traces:
0:000> ~*k . 0 Id: 710.ec4 Suspend: 0 Teb: 7efdd000 Unfrozen ChildEBP RetAddr 0017fba0 778a67f0 USER32!NtUserGetMessage+0x15 0017fbbc 00510211 USER32!GetMessageW+0x33 WARNING: Stack unwind information not available. Following frames may be wrong. 0017fbe8 0051173c cpuload+0x110211 0017fbf4 0051031f cpuload+0x11173c 0017fc00 00535ea5 cpuload+0x11031f 0017fc28 00515561 cpuload+0x135ea5 0017fc94 004f814d cpuload+0x115561 0017fe84 006a43b2 cpuload+0xf814d 0017fea8 006a42a8 cpuload+0x2a43b2 0017fec0 00626d0f cpuload+0x2a42a8 0017ff80 00626a4d cpuload+0x226d0f 0017ff88 775de4a5 cpuload+0x226a4d 0017ff94 77eecfed kernel32!BaseThreadInitThunk+0xe 0017ffd4 77eed1ff ntdll!__RtlUserThreadStart+0x23 0017ffec 00000000 ntdll!_RtlUserThreadStart+0x1b 1 Id: 710.994 Suspend: 0 Teb: 7efda000 Unfrozen ChildEBP RetAddr WARNING: Stack unwind information not available. Following frames may be wrong. 02e7ff88 775de4a5 cpuload+0xf87cf 02e7ff94 77eecfed kernel32!BaseThreadInitThunk+0xe 02e7ffd4 77eed1ff ntdll!__RtlUserThreadStart+0x23 02e7ffec 00000000 ntdll!_RtlUserThreadStart+0x1b 2 Id: 710.d20 Suspend: 0 Teb: 7efd7000 Unfrozen ChildEBP RetAddr WARNING: Stack unwind information not available. Following frames may be wrong. 02f7ff88 775de4a5 cpuload+0xf87cf 02f7ff94 77eecfed kernel32!BaseThreadInitThunk+0xe 02f7ffd4 77eed1ff ntdll!__RtlUserThreadStart+0x23 02f7ffec 00000000 ntdll!_RtlUserThreadStart+0x1b
If we apply symbols we get nicer stack traces:
0:000> ~*kL . 0 Id: 710.ec4 Suspend: 0 Teb: 7efdd000 Unfrozen ChildEBP RetAddr 0017fba0 778a67f0 USER32!NtUserGetMessage+0x15 0017fbbc 00510211 USER32!GetMessageW+0x33 0017fbe8 0051173c cpuload!AfxInternalPumpMessage+0x21 0017fbf4 0051031f cpuload!CWinThread::PumpMessage+0xc 0017fc00 00535ea5 cpuload!AfxPumpMessage+0x1f 0017fc28 00515561 cpuload!CWnd::RunModalLoop+0x1d5 0017fc94 004f814d cpuload!CDialog::DoModal+0x1e1 0017fe84 006a43b2 cpuload!CcpuloadApp::InitInstance+0xad 0017fea8 006a42a8 cpuload!AfxWinMain+0x82 0017fec0 00626d0f cpuload!wWinMain+0x18 0017ff80 00626a4d cpuload!__tmainCRTStartup+0x2af 0017ff88 775de4a5 cpuload!wWinMainCRTStartup+0xd 0017ff94 77eecfed kernel32!BaseThreadInitThunk+0xe 0017ffd4 77eed1ff ntdll!__RtlUserThreadStart+0x23 0017ffec 00000000 ntdll!_RtlUserThreadStart+0x1b 1 Id: 710.994 Suspend: 0 Teb: 7efda000 Unfrozen ChildEBP RetAddr 02e7fe74 004f87e7 WINMM!timeGetTime+0x14 02e7ff88 775de4a5 cpuload!SpikingThread+0x67 02e7ff94 77eecfed kernel32!BaseThreadInitThunk+0xe 02e7ffd4 77eed1ff ntdll!__RtlUserThreadStart+0x23 02e7ffec 00000000 ntdll!_RtlUserThreadStart+0x1b 2 Id: 710.d20 Suspend: 0 Teb: 7efd7000 Unfrozen ChildEBP RetAddr 02f7ff88 775de4a5 cpuload!SpikingThread+0x58 02f7ff94 77eecfed kernel32!BaseThreadInitThunk+0xe 02f7ffd4 77eed1ff ntdll!__RtlUserThreadStart+0x23 02f7ffec 00000000 ntdll!_RtlUserThreadStart+0x1b
We have highlighted in red the currently executing module and function.
The cpuload application and its symbols can be downloaded from:
http://www.dumpanalysis.org/Debugged/Jun09/download/cpuload.zip
[4] http://www.dumpanalysis.org/blog/index.php/2007/05/11/crash-dump-analysi...
