2 # SPDX-License-Identifier: GPL-2.0-only
3 # -*- coding: utf-8 -*-
5 """ This utility can be used to debug and tune the performance of the
6 intel_pstate driver. This utility can be used in two ways:
7 - If there is Linux trace file with pstate_sample events enabled, then
8 this utility can parse the trace file and generate performance plots.
9 - If user has not specified a trace file as input via command line parameters,
10 then this utility enables and collects trace data for a user specified interval
11 and generates performance plots.
17 (Most of the distributions have these required packages. They may be called
18 gnuplot-py, phython-gnuplot. )
20 HWP (Hardware P-States are disabled)
21 Kernel config for Linux trace is enabled
23 see print_help(): for Usage and Output details
26 from __future__
import print_function
27 from datetime
import datetime
39 __author__
= "Srinivas Pandruvada"
40 __copyright__
= " Copyright (c) 2017, Intel Corporation. "
41 __license__
= "GPL version 2"
46 # Define the csv file columns
66 global sample_num
, last_sec_cpu
, last_usec_cpu
, start_time
, testname
68 # 11 digits covers uptime to 115 days
69 getcontext().prec
= 11
72 last_sec_cpu
= [0] * MAX_CPUS
73 last_usec_cpu
= [0] * MAX_CPUS
76 print('intel_pstate_tracer.py:')
78 print(' If the trace file is available, then to simply parse and plot, use (sudo not required):')
79 print(' ./intel_pstate_tracer.py [-c cpus] -t <trace_file> -n <test_name>')
81 print(' ./intel_pstate_tracer.py [--cpu cpus] ---trace_file <trace_file> --name <test_name>')
82 print(' To generate trace file, parse and plot, use (sudo required):')
83 print(' sudo ./intel_pstate_tracer.py [-c cpus] -i <interval> -n <test_name> -m <kbytes>')
85 print(' sudo ./intel_pstate_tracer.py [--cpu cpus] --interval <interval> --name <test_name> --memory <kbytes>')
86 print(' Optional argument:')
87 print(' cpus: comma separated list of CPUs')
88 print(' kbytes: Kilo bytes of memory per CPU to allocate to the trace buffer. Default: 10240')
90 print(' If not already present, creates a "results/test_name" folder in the current working directory with:')
91 print(' cpu.csv - comma seperated values file with trace contents and some additional calculations.')
92 print(' cpu???.csv - comma seperated values file for CPU number ???.')
93 print(' *.png - a variety of PNG format plot files created from the trace contents and the additional calculations.')
95 print(' Avoid the use of _ (underscore) in test names, because in gnuplot it is a subscript directive.')
96 print(' Maximum number of CPUs is {0:d}. If there are more the script will abort with an error.'.format(MAX_CPUS
))
97 print(' Off-line CPUs cause the script to list some warnings, and create some empty files. Use the CPU mask feature for a clean run.')
98 print(' Empty y range warnings for autoscaled plots can occur and can be ignored.')
100 def plot_perf_busy_with_sample(cpu_index
):
101 """ Plot method to per cpu information """
103 file_name
= 'cpu{:0>3}.csv'.format(cpu_index
)
104 if os
.path
.exists(file_name
):
105 output_png
= "cpu%03d_perf_busy_vs_samples.png" % cpu_index
106 g_plot
= common_all_gnuplot_settings(output_png
)
107 g_plot('set yrange [0:40]')
108 g_plot('set y2range [0:200]')
109 g_plot('set y2tics 0, 10')
110 g_plot('set title "{} : cpu perf busy vs. sample : CPU {:0>3} : {:%F %H:%M}"'.format(testname
, cpu_index
, datetime
.now()))
112 g_plot('set xlabel "Samples"')
113 g_plot('set ylabel "P-State"')
114 g_plot('set y2label "Scaled Busy/performance/io-busy(%)"')
115 set_4_plot_linestyles(g_plot
)
116 g_plot('plot "' + file_name
+ '" using {:d}:{:d} with linespoints linestyle 1 axis x1y2 title "performance",\\'.format(C_SAMPLE
, C_CORE
))
117 g_plot('"' + file_name
+ '" using {:d}:{:d} with linespoints linestyle 2 axis x1y2 title "scaled-busy",\\'.format(C_SAMPLE
, C_SCALED
))
118 g_plot('"' + file_name
+ '" using {:d}:{:d} with linespoints linestyle 3 axis x1y2 title "io-boost",\\'.format(C_SAMPLE
, C_BOOST
))
119 g_plot('"' + file_name
+ '" using {:d}:{:d} with linespoints linestyle 4 axis x1y1 title "P-State"'.format(C_SAMPLE
, C_TO
))
121 def plot_perf_busy(cpu_index
):
122 """ Plot some per cpu information """
124 file_name
= 'cpu{:0>3}.csv'.format(cpu_index
)
125 if os
.path
.exists(file_name
):
126 output_png
= "cpu%03d_perf_busy.png" % cpu_index
127 g_plot
= common_all_gnuplot_settings(output_png
)
128 g_plot('set yrange [0:40]')
129 g_plot('set y2range [0:200]')
130 g_plot('set y2tics 0, 10')
131 g_plot('set title "{} : perf busy : CPU {:0>3} : {:%F %H:%M}"'.format(testname
, cpu_index
, datetime
.now()))
132 g_plot('set ylabel "P-State"')
133 g_plot('set y2label "Scaled Busy/performance/io-busy(%)"')
134 set_4_plot_linestyles(g_plot
)
135 g_plot('plot "' + file_name
+ '" using {:d}:{:d} with linespoints linestyle 1 axis x1y2 title "performance",\\'.format(C_ELAPSED
, C_CORE
))
136 g_plot('"' + file_name
+ '" using {:d}:{:d} with linespoints linestyle 2 axis x1y2 title "scaled-busy",\\'.format(C_ELAPSED
, C_SCALED
))
137 g_plot('"' + file_name
+ '" using {:d}:{:d} with linespoints linestyle 3 axis x1y2 title "io-boost",\\'.format(C_ELAPSED
, C_BOOST
))
138 g_plot('"' + file_name
+ '" using {:d}:{:d} with linespoints linestyle 4 axis x1y1 title "P-State"'.format(C_ELAPSED
, C_TO
))
140 def plot_durations(cpu_index
):
141 """ Plot per cpu durations """
143 file_name
= 'cpu{:0>3}.csv'.format(cpu_index
)
144 if os
.path
.exists(file_name
):
145 output_png
= "cpu%03d_durations.png" % cpu_index
146 g_plot
= common_all_gnuplot_settings(output_png
)
147 # Should autoscale be used here? Should seconds be used here?
148 g_plot('set yrange [0:5000]')
149 g_plot('set ytics 0, 500')
150 g_plot('set title "{} : durations : CPU {:0>3} : {:%F %H:%M}"'.format(testname
, cpu_index
, datetime
.now()))
151 g_plot('set ylabel "Timer Duration (MilliSeconds)"')
153 g_plot('set key off')
154 set_4_plot_linestyles(g_plot
)
155 g_plot('plot "' + file_name
+ '" using {:d}:{:d} with linespoints linestyle 1 axis x1y1'.format(C_ELAPSED
, C_DURATION
))
157 def plot_loads(cpu_index
):
158 """ Plot per cpu loads """
160 file_name
= 'cpu{:0>3}.csv'.format(cpu_index
)
161 if os
.path
.exists(file_name
):
162 output_png
= "cpu%03d_loads.png" % cpu_index
163 g_plot
= common_all_gnuplot_settings(output_png
)
164 g_plot('set yrange [0:100]')
165 g_plot('set ytics 0, 10')
166 g_plot('set title "{} : loads : CPU {:0>3} : {:%F %H:%M}"'.format(testname
, cpu_index
, datetime
.now()))
167 g_plot('set ylabel "CPU load (percent)"')
169 g_plot('set key off')
170 set_4_plot_linestyles(g_plot
)
171 g_plot('plot "' + file_name
+ '" using {:d}:{:d} with linespoints linestyle 1 axis x1y1'.format(C_ELAPSED
, C_LOAD
))
173 def plot_pstate_cpu_with_sample():
174 """ Plot all cpu information """
176 if os
.path
.exists('cpu.csv'):
177 output_png
= 'all_cpu_pstates_vs_samples.png'
178 g_plot
= common_all_gnuplot_settings(output_png
)
179 g_plot('set yrange [0:40]')
181 g_plot('set xlabel "Samples"')
182 g_plot('set ylabel "P-State"')
183 g_plot('set title "{} : cpu pstate vs. sample : {:%F %H:%M}"'.format(testname
, datetime
.now()))
184 title_list
= subprocess
.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell
=True).replace('\n', ' ')
185 plot_str
= "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_SAMPLE
, C_TO
)
186 g_plot('title_list = "{}"'.format(title_list
))
189 def plot_pstate_cpu():
190 """ Plot all cpu information from csv files """
192 output_png
= 'all_cpu_pstates.png'
193 g_plot
= common_all_gnuplot_settings(output_png
)
194 g_plot('set yrange [0:40]')
195 g_plot('set ylabel "P-State"')
196 g_plot('set title "{} : cpu pstates : {:%F %H:%M}"'.format(testname
, datetime
.now()))
198 # the following command is really cool, but doesn't work with the CPU masking option because it aborts on the first missing file.
199 # plot_str = 'plot for [i=0:*] file=sprintf("cpu%03d.csv",i) title_s=sprintf("cpu%03d",i) file using 16:7 pt 7 ps 1 title title_s'
201 title_list
= subprocess
.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell
=True).replace('\n', ' ')
202 plot_str
= "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED
, C_TO
)
203 g_plot('title_list = "{}"'.format(title_list
))
207 """ Plot all cpu loads """
209 output_png
= 'all_cpu_loads.png'
210 g_plot
= common_all_gnuplot_settings(output_png
)
211 g_plot('set yrange [0:100]')
212 g_plot('set ylabel "CPU load (percent)"')
213 g_plot('set title "{} : cpu loads : {:%F %H:%M}"'.format(testname
, datetime
.now()))
215 title_list
= subprocess
.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell
=True).replace('\n', ' ')
216 plot_str
= "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED
, C_LOAD
)
217 g_plot('title_list = "{}"'.format(title_list
))
220 def plot_frequency_cpu():
221 """ Plot all cpu frequencies """
223 output_png
= 'all_cpu_frequencies.png'
224 g_plot
= common_all_gnuplot_settings(output_png
)
225 g_plot('set yrange [0:4]')
226 g_plot('set ylabel "CPU Frequency (GHz)"')
227 g_plot('set title "{} : cpu frequencies : {:%F %H:%M}"'.format(testname
, datetime
.now()))
229 title_list
= subprocess
.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell
=True).replace('\n', ' ')
230 plot_str
= "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED
, C_FREQ
)
231 g_plot('title_list = "{}"'.format(title_list
))
234 def plot_duration_cpu():
235 """ Plot all cpu durations """
237 output_png
= 'all_cpu_durations.png'
238 g_plot
= common_all_gnuplot_settings(output_png
)
239 g_plot('set yrange [0:5000]')
240 g_plot('set ytics 0, 500')
241 g_plot('set ylabel "Timer Duration (MilliSeconds)"')
242 g_plot('set title "{} : cpu durations : {:%F %H:%M}"'.format(testname
, datetime
.now()))
244 title_list
= subprocess
.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell
=True).replace('\n', ' ')
245 plot_str
= "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED
, C_DURATION
)
246 g_plot('title_list = "{}"'.format(title_list
))
249 def plot_scaled_cpu():
250 """ Plot all cpu scaled busy """
252 output_png
= 'all_cpu_scaled.png'
253 g_plot
= common_all_gnuplot_settings(output_png
)
254 # autoscale this one, no set y range
255 g_plot('set ylabel "Scaled Busy (Unitless)"')
256 g_plot('set title "{} : cpu scaled busy : {:%F %H:%M}"'.format(testname
, datetime
.now()))
258 title_list
= subprocess
.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell
=True).replace('\n', ' ')
259 plot_str
= "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED
, C_SCALED
)
260 g_plot('title_list = "{}"'.format(title_list
))
263 def plot_boost_cpu():
264 """ Plot all cpu IO Boosts """
266 output_png
= 'all_cpu_boost.png'
267 g_plot
= common_all_gnuplot_settings(output_png
)
268 g_plot('set yrange [0:100]')
269 g_plot('set ylabel "CPU IO Boost (percent)"')
270 g_plot('set title "{} : cpu io boost : {:%F %H:%M}"'.format(testname
, datetime
.now()))
272 title_list
= subprocess
.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell
=True).replace('\n', ' ')
273 plot_str
= "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED
, C_BOOST
)
274 g_plot('title_list = "{}"'.format(title_list
))
278 """ Plot all cpu tsc ghz """
280 output_png
= 'all_cpu_ghz.png'
281 g_plot
= common_all_gnuplot_settings(output_png
)
282 # autoscale this one, no set y range
283 g_plot('set ylabel "TSC Frequency (GHz)"')
284 g_plot('set title "{} : cpu TSC Frequencies (Sanity check calculation) : {:%F %H:%M}"'.format(testname
, datetime
.now()))
286 title_list
= subprocess
.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell
=True).replace('\n', ' ')
287 plot_str
= "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED
, C_GHZ
)
288 g_plot('title_list = "{}"'.format(title_list
))
291 def common_all_gnuplot_settings(output_png
):
292 """ common gnuplot settings for multiple CPUs one one graph. """
294 g_plot
= common_gnuplot_settings()
295 g_plot('set output "' + output_png
+ '"')
298 def common_gnuplot_settings():
299 """ common gnuplot settings. """
301 g_plot
= Gnuplot
.Gnuplot(persist
=1)
302 # The following line is for rigor only. It seems to be assumed for .csv files
303 g_plot('set datafile separator \",\"')
304 g_plot('set ytics nomirror')
305 g_plot('set xtics nomirror')
306 g_plot('set xtics font ", 10"')
307 g_plot('set ytics font ", 10"')
308 g_plot('set tics out scale 1.0')
310 g_plot('set key out horiz')
311 g_plot('set key bot center')
312 g_plot('set key samplen 2 spacing .8 font ", 9"')
313 g_plot('set term png size 1200, 600')
314 g_plot('set title font ", 11"')
315 g_plot('set ylabel font ", 10"')
316 g_plot('set xlabel font ", 10"')
317 g_plot('set xlabel offset 0, 0.5')
318 g_plot('set xlabel "Elapsed Time (Seconds)"')
321 def set_4_plot_linestyles(g_plot
):
322 """ set the linestyles used for 4 plots in 1 graphs. """
324 g_plot('set style line 1 linetype 1 linecolor rgb "green" pointtype -1')
325 g_plot('set style line 2 linetype 1 linecolor rgb "red" pointtype -1')
326 g_plot('set style line 3 linetype 1 linecolor rgb "purple" pointtype -1')
327 g_plot('set style line 4 linetype 1 linecolor rgb "blue" pointtype -1')
329 def store_csv(cpu_int
, time_pre_dec
, time_post_dec
, core_busy
, scaled
, _from
, _to
, mperf
, aperf
, tsc
, freq_ghz
, io_boost
, common_comm
, load
, duration_ms
, sample_num
, elapsed_time
, tsc_ghz
):
330 """ Store master csv file information """
332 global graph_data_present
334 if cpu_mask
[cpu_int
] == 0:
338 f_handle
= open('cpu.csv', 'a')
339 string_buffer
= "CPU_%03u, %05u, %06u, %u, %u, %u, %u, %u, %u, %u, %.4f, %u, %.2f, %.3f, %u, %.3f, %.3f, %s\n" % (cpu_int
, int(time_pre_dec
), int(time_post_dec
), int(core_busy
), int(scaled
), int(_from
), int(_to
), int(mperf
), int(aperf
), int(tsc
), freq_ghz
, int(io_boost
), load
, duration_ms
, sample_num
, elapsed_time
, tsc_ghz
, common_comm
)
340 f_handle
.write(string_buffer
);
343 print('IO error cpu.csv')
346 graph_data_present
= True;
349 """ seperate the all csv file into per CPU csv files. """
351 global current_max_cpu
353 if os
.path
.exists('cpu.csv'):
354 for index
in range(0, current_max_cpu
+ 1):
355 if cpu_mask
[int(index
)] != 0:
356 os
.system('grep -m 1 common_cpu cpu.csv > cpu{:0>3}.csv'.format(index
))
357 os
.system('grep CPU_{:0>3} cpu.csv >> cpu{:0>3}.csv'.format(index
, index
))
359 def fix_ownership(path
):
360 """Change the owner of the file to SUDO_UID, if required"""
362 uid
= os
.environ
.get('SUDO_UID')
363 gid
= os
.environ
.get('SUDO_GID')
365 os
.chown(path
, int(uid
), int(gid
))
367 def cleanup_data_files():
368 """ clean up existing data files """
370 if os
.path
.exists('cpu.csv'):
372 f_handle
= open('cpu.csv', 'a')
373 f_handle
.write('common_cpu, common_secs, common_usecs, core_busy, scaled_busy, from, to, mperf, aperf, tsc, freq, boost, load, duration_ms, sample_num, elapsed_time, tsc_ghz, common_comm')
377 def clear_trace_file():
378 """ Clear trace file """
381 f_handle
= open('/sys/kernel/debug/tracing/trace', 'w')
384 print('IO error clearing trace file ')
391 open('/sys/kernel/debug/tracing/events/power/pstate_sample/enable'
394 print('IO error enabling trace ')
398 """ Disable trace """
401 open('/sys/kernel/debug/tracing/events/power/pstate_sample/enable'
404 print('IO error disabling trace ')
407 def set_trace_buffer_size():
408 """ Set trace buffer size """
411 with
open('/sys/kernel/debug/tracing/buffer_size_kb', 'w') as fp
:
414 print('IO error setting trace buffer size ')
417 def free_trace_buffer():
418 """ Free the trace buffer memory """
421 open('/sys/kernel/debug/tracing/buffer_size_kb'
424 print('IO error freeing trace buffer ')
427 def read_trace_data(filename
):
428 """ Read and parse trace data """
430 global current_max_cpu
431 global sample_num
, last_sec_cpu
, last_usec_cpu
, start_time
434 data
= open(filename
, 'r').read()
436 print('Error opening ', filename
)
439 for line
in data
.splitlines():
441 re
.search(r
'(^(.*?)\[)((\d+)[^\]])(.*?)(\d+)([.])(\d+)(.*?core_busy=)(\d+)(.*?scaled=)(\d+)(.*?from=)(\d+)(.*?to=)(\d+)(.*?mperf=)(\d+)(.*?aperf=)(\d+)(.*?tsc=)(\d+)(.*?freq=)(\d+)'
445 cpu
= search_obj
.group(3)
449 time_pre_dec
= search_obj
.group(6)
450 time_post_dec
= search_obj
.group(8)
451 core_busy
= search_obj
.group(10)
452 scaled
= search_obj
.group(12)
453 _from
= search_obj
.group(14)
454 _to
= search_obj
.group(16)
455 mperf
= search_obj
.group(18)
456 aperf
= search_obj
.group(20)
457 tsc
= search_obj
.group(22)
458 freq
= search_obj
.group(24)
459 common_comm
= search_obj
.group(2).replace(' ', '')
461 # Not all kernel versions have io_boost field
463 search_obj
= re
.search(r
'.*?io_boost=(\d+)', line
)
465 io_boost
= search_obj
.group(1)
468 start_time
= Decimal(time_pre_dec
) + Decimal(time_post_dec
) / Decimal(1000000)
471 if last_sec_cpu
[cpu_int
] == 0 :
472 last_sec_cpu
[cpu_int
] = time_pre_dec
473 last_usec_cpu
[cpu_int
] = time_post_dec
475 duration_us
= (int(time_pre_dec
) - int(last_sec_cpu
[cpu_int
])) * 1000000 + (int(time_post_dec
) - int(last_usec_cpu
[cpu_int
]))
476 duration_ms
= Decimal(duration_us
) / Decimal(1000)
477 last_sec_cpu
[cpu_int
] = time_pre_dec
478 last_usec_cpu
[cpu_int
] = time_post_dec
479 elapsed_time
= Decimal(time_pre_dec
) + Decimal(time_post_dec
) / Decimal(1000000) - start_time
480 load
= Decimal(int(mperf
)*100)/ Decimal(tsc
)
481 freq_ghz
= Decimal(freq
)/Decimal(1000000)
482 # Sanity check calculation, typically anomalies indicate missed samples
483 # However, check for 0 (should never occur)
485 if duration_ms
!= Decimal(0) :
486 tsc_ghz
= Decimal(tsc
)/duration_ms
/Decimal(1000000)
487 store_csv(cpu_int
, time_pre_dec
, time_post_dec
, core_busy
, scaled
, _from
, _to
, mperf
, aperf
, tsc
, freq_ghz
, io_boost
, common_comm
, load
, duration_ms
, sample_num
, elapsed_time
, tsc_ghz
)
489 if cpu_int
> current_max_cpu
:
490 current_max_cpu
= cpu_int
491 # End of for each trace line loop
492 # Now seperate the main overall csv file into per CPU csv files.
495 def signal_handler(signal
, frame
):
496 print(' SIGINT: Forcing cleanup before exit.')
504 signal
.signal(signal
.SIGINT
, signal_handler
)
511 graph_data_present
= False;
516 cpu_mask
= zeros((MAX_CPUS
,), dtype
=int)
519 opts
, args
= getopt
.getopt(sys
.argv
[1:],"ht:i:c:n:m:",["help","trace_file=","interval=","cpu=","name=","memory="])
520 except getopt
.GetoptError
:
523 for opt
, arg
in opts
:
527 elif opt
in ("-t", "--trace_file"):
529 location
= os
.path
.realpath(os
.path
.join(os
.getcwd(), os
.path
.dirname(__file__
)))
530 filename
= os
.path
.join(location
, arg
)
531 elif opt
in ("-i", "--interval"):
534 elif opt
in ("-c", "--cpu"):
536 elif opt
in ("-n", "--name"):
539 elif opt
in ("-m", "--memory"):
542 if not (valid1
and valid2
):
547 for p
in re
.split("[,]", cpu_list
):
548 if int(p
) < MAX_CPUS
:
551 for i
in range (0, MAX_CPUS
):
554 if not os
.path
.exists('results'):
556 # The regular user needs to own the directory, not root.
557 fix_ownership('results')
560 if os
.path
.exists(testname
):
561 print('The test name directory already exists. Please provide a unique test name. Test re-run not supported, yet.')
564 # The regular user needs to own the directory, not root.
565 fix_ownership(testname
)
568 # Temporary (or perhaps not)
569 cur_version
= sys
.version_info
570 print('python version (should be >= 2.7):')
573 # Left as "cleanup" for potential future re-run ability.
577 filename
= "/sys/kernel/debug/tracing/trace"
579 set_trace_buffer_size()
581 print('Sleeping for ', interval
, 'seconds')
582 time
.sleep(int(interval
))
587 read_trace_data(filename
)
594 if graph_data_present
== False:
595 print('No valid data to plot')
598 for cpu_no
in range(0, current_max_cpu
+ 1):
599 plot_perf_busy_with_sample(cpu_no
)
600 plot_perf_busy(cpu_no
)
601 plot_durations(cpu_no
)
604 plot_pstate_cpu_with_sample()
613 # It is preferrable, but not necessary, that the regular user owns the files, not root.
614 for root
, dirs
, files
in os
.walk('.'):