Using xperfinfoxperf

1
Usingxperfinfo/xperf

• Cristian Levcovici
• Windows Client Performance

2
Outline

• Introduction
• Overview of xperf
• Overview of xperfinfo
• Extensibility
• References

3
Introduction

• What is xperfinfo/xperf?
• What is ETW?

4
xperfinfo/xperf
Introduction

• Extensible performance analysis toolset
• Based on ETW instrumentation
• Performs high-level decoding
• Cross-platform (XPSP1, W2K3, LH)
• Cross-architecture (x86, x64, ia64)
• Capture-anywhere process-anywhere

5
Main strength
Introduction

• High level control and decoding of a large number
  of ETW events built into the NT kernel

• process lifetime
• thread lifetime
• image lifetime
• sample profile
• context switch
• DPC (Deferred Procedure Call)
• ISR (Interrupt Service Routine)
• driver delay

• disk I/O
• file I/O
• registry
• hardfault
• pagefault
• virtual allocation
• heap
• TCP/UDP

and many others
Stackwalking support (LH only)
6
What is ETW?
Introduction

• Event Tracing for Windows
• High performance, low overhead, highly scalable
  tracing facility provided by the Windows OS
  (Win2K)
• Extensively used by the NT kernel for
  self-instrumentation
• On a typical server setup, TraceEvent() takes
  1,500 to 2,000 cycles
• lt2 CPU overhead for a sustained rate of 20,000
  events/sec on a 2GHz processor
• Uses an efficient buffering and logging mechanism
• Non-blocking and uses per-processor buffers that
  are written to disk by a separate writer thread

7
What is ETW? (contd.)
Introduction

• Event Tracing for Windows
• Fast, reliable, and versatile set of features for
  logging events raised by user-mode applications
  and kernel-mode drivers
• Turn tracing on/off dynamically without requiring
  reboots or application restarts
• The disk log is a binary file
• Event format is encoded by GUID type version
• Trace must be post processed
• events must be correlated with context events and
  domain specific knowledge for high-level decoding

8
What is ETW used for?
Introduction

• Debug application bugs including hangs, crashes,
  or unexpected behavior
• Diagnose performance problems
• Track computing resource consumption at
  application transaction level for capacity
  planning

9
ETW Architecture
Introduction

• Provider
• Provides event traces. Can be user-mode app,
  kernel-mode driver, or the kernel itself
• Providers are instrumented with ETW APIs to
  register with the ETW framework to send event
  traces from various points in the code.
• When enabled dynamically by the trace controller
  application, the provider sends event traces to a
  specific trace session designated by the
  controller.
• Controller
• Assists in starting, stopping or updating trace
  sessions in the kernel as well as enabling or
  disabling providers
• Used to set trace session properties such as
  sequential or circular file logging or direct
  delivery to consumers
• Consumer
• Application that reads trace files or listens to
  active trace sessions and processes logged events
• Not aware of the Providers
• Only receive event traces from the trace sessions
  or log files
• Event Trace Session infrastructure
• Brokers the event traces from the provider to
  consumer and in the process adds valuable data to
  each event such as TimeStamp, Thread, Process, CPU

10
Overview of xperf

• Detailed interactive analysis of ETW traces
• Emphasis on kernel events
• Support for 3rd party events, primarily in
  conjunction with kernel events

11
Timeline
Overview of xperf
12
Timeline
Overview of xperf
13
Timeline
Overview of xperf
14
CPU Usage Summary Table
Overview of xperf
15
Timeline
Overview of xperf
16
Timeline
Overview of xperf
17
Timeline
Overview of xperf
18
Timeline
Overview of xperf
19
Timeline
Overview of xperf
20
Timeline
Overview of xperf
21
Timeline
Overview of xperf
22
Disk I/O Summary Table
Overview of xperf
23
Disk I/O Summary Table
Overview of xperf
24
Disk I/O Summary Table
Overview of xperf
25
Timeline
Overview of xperf
26
Timeline
Overview of xperf
27
Timeline
Overview of xperf
28
Disk Detail
Overview of xperf
29
Disk Detail
Overview of xperf
30
Disk Detail
Overview of xperf
31
Disk Detail Summary Table
Overview of xperf
32
Timeline
Overview of xperf
33
Timeline
Overview of xperf
34
Timeline
Overview of xperf
35
CPU Summary Table
Overview of xperf
36
CPU Summary Table
Overview of xperf
37
Timeline
Overview of xperf
38
Timeline
Overview of xperf
39
Timeline
Overview of xperf
40
Timeline
Overview of xperf
41
Timeline
Overview of xperf
42
CPU Summary Table Symbol Decoding Enabled
Overview of xperf
43
CPU Summary Table Symbol Decoding Enabled
Overview of xperf
44
CPU Summary Table Symbol Decoding Enabled
Overview of xperf
45
Available Graphs
Overview of xperf

• xperf provides many graphs and summary tables

• Sample Profile
• CPU Availability
• CPU Scheduling
• Disk Counts
• Disk Utilization
• Disk Detail
• Process Lifetime
• DPC (Deferred Procedure Call)
• ISR (Interrupt Service Routine)

• Registry counts
• Driver Delay
• Hardfault
• Pagefault
• Services
• Plug n Play
• Marks
• Generic

46
Overview of xperfinfo

• High level control and decoding
• Dumping of ETW traces
• Command line analysis of ETW traces
• emphasis on kernel events
• support for 3rd party events

47
Taking a kernel trace
Overview of xperfinfo

• Start kernel trace
• Run scenario
• Stop and merge kernel trace

C\analysisgt xperfinfo on basecswitch
C\analysisgt MyTestApp.exe
C\analysisgt xperfinfo d trace.etl Merged Etl
trace.etl
48
Taking a user trace
Overview of xperfinfo

• Start user trace
• Run scenario
• Stop user trace

C\analysisgt xperfinfo start MySession on
KerberosMRxSmb f kerberos.etl
C\analysisgt MyTestApp.exe
C\analysisgt xperfinfo stop MySession
49
Taking a kerneluser trace
Overview of xperfinfo

• Start kernel and user traces
• Run scenario
• Stop user trace

C\analysisgt xperfinfo on basecswitch C\analysi
sgt xperfinfo start MySession on KerberosMRxSmb
f kerberos.etl
C\analysisgt MyTestApp.exe
C\analysisgt xperfinfo stop MySession stop d
trace.etl Merged Etl trace.etl
50
Retrieving Trace Header
Overview of xperfinfo
C\analysisgt xperfinfo -i trace.etl -a
tracestats Number of Processors 4 CPU Speed
2372 MHz OS Version
05.01.01.00 OS Build Number 2600 Clock
type PerfCounter Boot time
2005/10/13160514.5000000 Native Pointer Size
4 (32bit) Start time
2005/10/14040314.3388906 End time
2005/10/14040323.8073376 (
0000009.4684470) Total Lost Buffers
0 Total Lost Events 0 Number of Traces
1 Trace name trace.etl Log file mode
Relogged Pointer size 4
(32bit) Start time
2005/10/14040314.3388906 End time
2005/10/14040323.8073376 (
0000009.4684470) Lost Buffers 0
Lost Events 0
51
Retrieving Trace Summary
Overview of xperfinfo
C\analysisgt xperfinfo -i trace.etl -a tracestats
-detail Classic EventGuid TotalCount
TotalSize Name

66838
1703946 ltAllgt 01853a65-418f-4f36-aefc-dc0f1d2f
d235 58
39376 SysConfig Type Level Version
Count TotalSize Name ---- -----
------- ---------- ---------------
--------------------------- 0x0a 0x00 0x0001
1 952 SysConfig CPUs
0x0b 0x00 0x0001 2 1224
SysConfig Physical Disks 0x0c 0x00 0x0001
4 448 SysConfig Logical
Disks 0x0d 0x00 0x0001 1
744 SysConfig Network Cards 0x0e 0x00
0x0001 2 5168 SysConfig
Video Adapters 0x0f 0x00 0x0001
47 30832 SysConfig Services 0x10
0x00 0x0001 1 8
SysConfig Power Management ...
52
Retrieving Action Help
Overview of xperfinfo
C\analysisgt xperfinfo -i trace.etl -a tracestats
/? Action invocation xperfinfo -i
lttrace filegt ... -o ltoutputgt -a tracestats
... Action help tracestats
-timespan actual -detail -timespan
actual Show information about session and
traces. default Without
parameters, -timespan requires inspection of
trace headers only no pass
is performed through the traces in
the session. When
the parameter "actual" is specified, the actual
times of the first event and
the last event in the session
are added to the report. In this case, a pass
through the traces in the
session is required. -detail Show
detailed information about providers, ids,
tasks, opcodes, versions,
channels and levels of events in the
session along with provider and opcode
friendly names. Requires a
full pass through the traces in the session.
53
Dumping a Trace
Overview of xperfinfo
C\analysisgt xperfinfo -i trace.etl o
trace.txt 1/2 100.0 2/2
100.0 C\analysisgt notepad trace.txt
54
Dumping a Trace with Symbol Decoding
Overview of xperfinfo
C\analysisgt set _NT_SYMBOL_PATHsrvC\symbols\\
symbols\symbols C\analysisgt xperfinfo -i
trace.etl o trace_symbols.txt -symbols 1/2
100.0 2/2 100.0 C\analysisgt notepad
trace_symbols.txt
55
Available Actions
Overview of xperfinfo

• xperfinfo provides many actions

• dumper
• tracestats
• sysconfig
• marks
• process
• perfctrs
• profile
• cswitch
• dpcisr
• registry

• diskio
• filename
• hardfault
• pagefault
• drvdelay
• reference_set
• boot
• suspend
• shutdown

and many others
56
Online Help
Overview of xperfinfo

• Your best friend is the online help

C\analysisgt xperfinfo -help Usage
xperfinfo options ... xperfinfo -help
start for logger start options
xperfinfo -help providers for known
tracing flags xperfinfo -help stop
for logger stop options xperfinfo
-help merge for merge multiple trace
files xperfinfo -help processing
for trace processing options xperfinfo
-help symbols for symbol decoding
configuration xperfinfo -help query
for query options xperfinfo -help
mark for mark and mark-flush
xperfinfo -help format for time and
timespan formats on
the command line xperfinfo
-help advanced for advanced options
(things you
don't need to know -))
57
Extensibility

• xperfinfo and xperf are built on top of an
  extensible core, xperfcore, that supports 3rd
  party binary addins providing custom
• Event dumpers
• Infosources
• Event name databases
• Graphs summary tables
• Application drivers
• xperfinfo Actions
• For details, please see the Extending xperfcore
  presentation

58
References

• Homepage
• http//toolbox/sites/xperf
• Tools distribution point
• \\ntperformance\tools\xperf\x86\latest
• \\ntperformance\tools\xperf\amd64\latest
• \\ntperformance\tools\xperf\ia64\latest
• README.TXT
• \\ntperformance\tools\xperf\x86\latest\README.TXT

59
Context Slides