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.
14 Python version 3.6.x or higher
16 python3-gnuplot 1.8 or higher
17 (Most of the distributions have these required packages. They may be called
18 gnuplot-py, python-gnuplot or python3-gnuplot, gnuplot-nox, ... )
20 HWP (Hardware P-States are disabled)
21 Kernel config for Linux trace is enabled
23 see print_help(): for Usage and Output details
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, trace_file
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
75 def print_help(driver_name):
76 print('%s_tracer.py:'%driver_name)
78 print(' If the trace file is available, then to simply parse and plot, use (sudo not required):')
79 print(' ./%s_tracer.py [-c cpus] -t <trace_file> -n <test_name>'%driver_name)
81 print(' ./%s_tracer.py [--cpu cpus] ---trace_file <trace_file> --name <test_name>'%driver_name)
82 print(' To generate trace file, parse and plot, use (sudo required):')
83 print(' sudo ./%s_tracer.py [-c cpus] -i <interval> -n <test_name> -m <kbytes>'%driver_name)
85 print(' sudo ./%s_tracer.py [--cpu cpus] --interval <interval> --name <test_name> --memory <kbytes>'%driver_name)
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 # autoscale this one, no set y1 range
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 # autoscale this one, no set y1 range
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 # autoscale this one, no set y range
148 g_plot('set title "{} : durations : CPU {:0>3} : {:%F %H:%M}"'.format(testname, cpu_index, datetime.now()))
149 g_plot('set ylabel "Timer Duration (MilliSeconds)"')
151 g_plot('set key off')
152 set_4_plot_linestyles(g_plot)
153 g_plot('plot "' + file_name + '" using {:d}:{:d} with linespoints linestyle 1 axis x1y1'.format(C_ELAPSED, C_DURATION))
155 def plot_loads(cpu_index):
156 """ Plot per cpu loads """
158 file_name = 'cpu{:0>3}.csv'.format(cpu_index)
159 if os.path.exists(file_name):
160 output_png = "cpu%03d_loads.png" % cpu_index
161 g_plot = common_all_gnuplot_settings(output_png)
162 g_plot('set yrange [0:100]')
163 g_plot('set ytics 0, 10')
164 g_plot('set title "{} : loads : CPU {:0>3} : {:%F %H:%M}"'.format(testname, cpu_index, datetime.now()))
165 g_plot('set ylabel "CPU load (percent)"')
167 g_plot('set key off')
168 set_4_plot_linestyles(g_plot)
169 g_plot('plot "' + file_name + '" using {:d}:{:d} with linespoints linestyle 1 axis x1y1'.format(C_ELAPSED, C_LOAD))
171 def plot_pstate_cpu_with_sample():
172 """ Plot all cpu information """
174 if os.path.exists('cpu.csv'):
175 output_png = 'all_cpu_pstates_vs_samples.png'
176 g_plot = common_all_gnuplot_settings(output_png)
177 # autoscale this one, no set y range
179 g_plot('set xlabel "Samples"')
180 g_plot('set ylabel "P-State"')
181 g_plot('set title "{} : cpu pstate vs. sample : {:%F %H:%M}"'.format(testname, datetime.now()))
182 title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).decode('utf-8').replace('\n', ' ')
183 plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_SAMPLE, C_TO)
184 g_plot('title_list = "{}"'.format(title_list))
187 def plot_pstate_cpu():
188 """ Plot all cpu information from csv files """
190 output_png = 'all_cpu_pstates.png'
191 g_plot = common_all_gnuplot_settings(output_png)
192 # autoscale this one, no set y range
193 g_plot('set ylabel "P-State"')
194 g_plot('set title "{} : cpu pstates : {:%F %H:%M}"'.format(testname, datetime.now()))
196 # the following command is really cool, but doesn't work with the CPU masking option because it aborts on the first missing file.
197 # 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'
199 title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).decode('utf-8').replace('\n', ' ')
200 plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_TO)
201 g_plot('title_list = "{}"'.format(title_list))
205 """ Plot all cpu loads """
207 output_png = 'all_cpu_loads.png'
208 g_plot = common_all_gnuplot_settings(output_png)
209 g_plot('set yrange [0:100]')
210 g_plot('set ylabel "CPU load (percent)"')
211 g_plot('set title "{} : cpu loads : {:%F %H:%M}"'.format(testname, datetime.now()))
213 title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).decode('utf-8').replace('\n', ' ')
214 plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_LOAD)
215 g_plot('title_list = "{}"'.format(title_list))
218 def plot_frequency_cpu():
219 """ Plot all cpu frequencies """
221 output_png = 'all_cpu_frequencies.png'
222 g_plot = common_all_gnuplot_settings(output_png)
223 # autoscale this one, no set y range
224 g_plot('set ylabel "CPU Frequency (GHz)"')
225 g_plot('set title "{} : cpu frequencies : {:%F %H:%M}"'.format(testname, datetime.now()))
227 title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).decode('utf-8').replace('\n', ' ')
228 plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_FREQ)
229 g_plot('title_list = "{}"'.format(title_list))
232 def plot_duration_cpu():
233 """ Plot all cpu durations """
235 output_png = 'all_cpu_durations.png'
236 g_plot = common_all_gnuplot_settings(output_png)
237 # autoscale this one, no set y range
238 g_plot('set ylabel "Timer Duration (MilliSeconds)"')
239 g_plot('set title "{} : cpu durations : {:%F %H:%M}"'.format(testname, datetime.now()))
241 title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).decode('utf-8').replace('\n', ' ')
242 plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_DURATION)
243 g_plot('title_list = "{}"'.format(title_list))
246 def plot_scaled_cpu():
247 """ Plot all cpu scaled busy """
249 output_png = 'all_cpu_scaled.png'
250 g_plot = common_all_gnuplot_settings(output_png)
251 # autoscale this one, no set y range
252 g_plot('set ylabel "Scaled Busy (Unitless)"')
253 g_plot('set title "{} : cpu scaled busy : {:%F %H:%M}"'.format(testname, datetime.now()))
255 title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).decode('utf-8').replace('\n', ' ')
256 plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_SCALED)
257 g_plot('title_list = "{}"'.format(title_list))
260 def plot_boost_cpu():
261 """ Plot all cpu IO Boosts """
263 output_png = 'all_cpu_boost.png'
264 g_plot = common_all_gnuplot_settings(output_png)
265 g_plot('set yrange [0:100]')
266 g_plot('set ylabel "CPU IO Boost (percent)"')
267 g_plot('set title "{} : cpu io boost : {:%F %H:%M}"'.format(testname, datetime.now()))
269 title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).decode('utf-8').replace('\n', ' ')
270 plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_BOOST)
271 g_plot('title_list = "{}"'.format(title_list))
275 """ Plot all cpu tsc ghz """
277 output_png = 'all_cpu_ghz.png'
278 g_plot = common_all_gnuplot_settings(output_png)
279 # autoscale this one, no set y range
280 g_plot('set ylabel "TSC Frequency (GHz)"')
281 g_plot('set title "{} : cpu TSC Frequencies (Sanity check calculation) : {:%F %H:%M}"'.format(testname, datetime.now()))
283 title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).decode('utf-8').replace('\n', ' ')
284 plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_GHZ)
285 g_plot('title_list = "{}"'.format(title_list))
288 def common_all_gnuplot_settings(output_png):
289 """ common gnuplot settings for multiple CPUs one one graph. """
291 g_plot = common_gnuplot_settings()
292 g_plot('set output "' + output_png + '"')
295 def common_gnuplot_settings():
296 """ common gnuplot settings. """
298 g_plot = Gnuplot.Gnuplot(persist=1)
299 # The following line is for rigor only. It seems to be assumed for .csv files
300 g_plot('set datafile separator \",\"')
301 g_plot('set ytics nomirror')
302 g_plot('set xtics nomirror')
303 g_plot('set xtics font ", 10"')
304 g_plot('set ytics font ", 10"')
305 g_plot('set tics out scale 1.0')
307 g_plot('set key out horiz')
308 g_plot('set key bot center')
309 g_plot('set key samplen 2 spacing .8 font ", 9"')
310 g_plot('set term png size 1200, 600')
311 g_plot('set title font ", 11"')
312 g_plot('set ylabel font ", 10"')
313 g_plot('set xlabel font ", 10"')
314 g_plot('set xlabel offset 0, 0.5')
315 g_plot('set xlabel "Elapsed Time (Seconds)"')
318 def set_4_plot_linestyles(g_plot):
319 """ set the linestyles used for 4 plots in 1 graphs. """
321 g_plot('set style line 1 linetype 1 linecolor rgb "green" pointtype -1')
322 g_plot('set style line 2 linetype 1 linecolor rgb "red" pointtype -1')
323 g_plot('set style line 3 linetype 1 linecolor rgb "purple" pointtype -1')
324 g_plot('set style line 4 linetype 1 linecolor rgb "blue" pointtype -1')
326 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, cpu_mask):
327 """ Store master csv file information """
329 global graph_data_present
331 if cpu_mask[cpu_int] == 0:
335 f_handle = open('cpu.csv', 'a')
336 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)
337 f_handle.write(string_buffer);
340 print('IO error cpu.csv')
343 graph_data_present = True;
345 def split_csv(current_max_cpu, cpu_mask):
346 """ seperate the all csv file into per CPU csv files. """
348 if os.path.exists('cpu.csv'):
349 for index in range(0, current_max_cpu + 1):
350 if cpu_mask[int(index)] != 0:
351 os.system('grep -m 1 common_cpu cpu.csv > cpu{:0>3}.csv'.format(index))
352 os.system('grep CPU_{:0>3} cpu.csv >> cpu{:0>3}.csv'.format(index, index))
354 def fix_ownership(path):
355 """Change the owner of the file to SUDO_UID, if required"""
357 uid = os.environ.get('SUDO_UID')
358 gid = os.environ.get('SUDO_GID')
360 os.chown(path, int(uid), int(gid))
362 def cleanup_data_files():
363 """ clean up existing data files """
365 if os.path.exists('cpu.csv'):
367 f_handle = open('cpu.csv', 'a')
368 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')
372 def clear_trace_file():
373 """ Clear trace file """
376 f_handle = open('/sys/kernel/tracing/trace', 'w')
379 print('IO error clearing trace file ')
382 def enable_trace(trace_file):
386 open(trace_file,'w').write("1")
388 print('IO error enabling trace ')
391 def disable_trace(trace_file):
392 """ Disable trace """
395 open(trace_file, 'w').write("0")
397 print('IO error disabling trace ')
400 def set_trace_buffer_size(memory):
401 """ Set trace buffer size """
404 with open('/sys/kernel/tracing/buffer_size_kb', 'w') as fp:
407 print('IO error setting trace buffer size ')
410 def free_trace_buffer():
411 """ Free the trace buffer memory """
414 open('/sys/kernel/tracing/buffer_size_kb'
417 print('IO error freeing trace buffer ')
420 def read_trace_data(filename, cpu_mask):
421 """ Read and parse trace data """
423 global current_max_cpu
424 global sample_num, last_sec_cpu, last_usec_cpu, start_time
427 data = open(filename, 'r').read()
429 print('Error opening ', filename)
432 for line in data.splitlines():
434 re.search(r'(^(.*?)\[)((\d+)[^\]])(.*?)(\d+)([.])(\d+)(.*?core_busy=)(\d+)(.*?scaled=)(\d+)(.*?from=)(\d+)(.*?to=)(\d+)(.*?mperf=)(\d+)(.*?aperf=)(\d+)(.*?tsc=)(\d+)(.*?freq=)(\d+)'
438 cpu = search_obj.group(3)
442 time_pre_dec = search_obj.group(6)
443 time_post_dec = search_obj.group(8)
444 core_busy = search_obj.group(10)
445 scaled = search_obj.group(12)
446 _from = search_obj.group(14)
447 _to = search_obj.group(16)
448 mperf = search_obj.group(18)
449 aperf = search_obj.group(20)
450 tsc = search_obj.group(22)
451 freq = search_obj.group(24)
452 common_comm = search_obj.group(2).replace(' ', '')
454 # Not all kernel versions have io_boost field
456 search_obj = re.search(r'.*?io_boost=(\d+)', line)
458 io_boost = search_obj.group(1)
461 start_time = Decimal(time_pre_dec) + Decimal(time_post_dec) / Decimal(1000000)
464 if last_sec_cpu[cpu_int] == 0 :
465 last_sec_cpu[cpu_int] = time_pre_dec
466 last_usec_cpu[cpu_int] = time_post_dec
468 duration_us = (int(time_pre_dec) - int(last_sec_cpu[cpu_int])) * 1000000 + (int(time_post_dec) - int(last_usec_cpu[cpu_int]))
469 duration_ms = Decimal(duration_us) / Decimal(1000)
470 last_sec_cpu[cpu_int] = time_pre_dec
471 last_usec_cpu[cpu_int] = time_post_dec
472 elapsed_time = Decimal(time_pre_dec) + Decimal(time_post_dec) / Decimal(1000000) - start_time
473 load = Decimal(int(mperf)*100)/ Decimal(tsc)
474 freq_ghz = Decimal(freq)/Decimal(1000000)
475 # Sanity check calculation, typically anomalies indicate missed samples
476 # However, check for 0 (should never occur)
478 if duration_ms != Decimal(0) :
479 tsc_ghz = Decimal(tsc)/duration_ms/Decimal(1000000)
480 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, cpu_mask)
482 if cpu_int > current_max_cpu:
483 current_max_cpu = cpu_int
484 # End of for each trace line loop
485 # Now seperate the main overall csv file into per CPU csv files.
486 split_csv(current_max_cpu, cpu_mask)
488 def signal_handler(signal, frame):
489 print(' SIGINT: Forcing cleanup before exit.')
491 disable_trace(trace_file)
497 if __name__ == "__main__":
498 trace_file = "/sys/kernel/tracing/events/power/pstate_sample/enable"
499 signal.signal(signal.SIGINT, signal_handler)
506 graph_data_present = False;
511 cpu_mask = zeros((MAX_CPUS,), dtype=int)
514 opts, args = getopt.getopt(sys.argv[1:],"ht:i:c:n:m:",["help","trace_file=","interval=","cpu=","name=","memory="])
515 except getopt.GetoptError:
516 print_help('intel_pstate')
518 for opt, arg in opts:
520 print_help('intel_pstate')
522 elif opt in ("-t", "--trace_file"):
524 location = os.path.realpath(os.path.join(os.getcwd(), os.path.dirname(__file__)))
525 filename = os.path.join(location, arg)
526 elif opt in ("-i", "--interval"):
529 elif opt in ("-c", "--cpu"):
531 elif opt in ("-n", "--name"):
534 elif opt in ("-m", "--memory"):
537 if not (valid1 and valid2):
538 print_help('intel_pstate')
542 for p in re.split("[,]", cpu_list):
543 if int(p) < MAX_CPUS :
546 for i in range (0, MAX_CPUS):
549 if not os.path.exists('results'):
551 # The regular user needs to own the directory, not root.
552 fix_ownership('results')
555 if os.path.exists(testname):
556 print('The test name directory already exists. Please provide a unique test name. Test re-run not supported, yet.')
559 # The regular user needs to own the directory, not root.
560 fix_ownership(testname)
563 # Temporary (or perhaps not)
564 cur_version = sys.version_info
565 print('python version (should be >= 3.6):')
568 # Left as "cleanup" for potential future re-run ability.
572 filename = "/sys/kernel/tracing/trace"
574 set_trace_buffer_size(memory)
575 enable_trace(trace_file)
576 print('Sleeping for ', interval, 'seconds')
577 time.sleep(int(interval))
578 disable_trace(trace_file)
582 read_trace_data(filename, cpu_mask)
589 if graph_data_present == False:
590 print('No valid data to plot')
593 for cpu_no in range(0, current_max_cpu + 1):
594 plot_perf_busy_with_sample(cpu_no)
595 plot_perf_busy(cpu_no)
596 plot_durations(cpu_no)
599 plot_pstate_cpu_with_sample()
608 # It is preferrable, but not necessary, that the regular user owns the files, not root.
609 for root, dirs, files in os.walk('.'):