diff options
Diffstat (limited to 'tools')
| -rwxr-xr-x | tools/power/x86/intel_pstate_tracer/intel_pstate_tracer.py | 569 |
1 files changed, 569 insertions, 0 deletions
diff --git a/tools/power/x86/intel_pstate_tracer/intel_pstate_tracer.py b/tools/power/x86/intel_pstate_tracer/intel_pstate_tracer.py new file mode 100755 index 0000000..fd706ac --- /dev/null +++ b/tools/power/x86/intel_pstate_tracer/intel_pstate_tracer.py @@ -0,0 +1,569 @@ +#!/usr/bin/python +# -*- coding: utf-8 -*- +# +""" This utility can be used to debug and tune the performance of the +intel_pstate driver. This utility can be used in two ways: +- If there is Linux trace file with pstate_sample events enabled, then +this utility can parse the trace file and generate performance plots. +- If user has not specified a trace file as input via command line parameters, +then this utility enables and collects trace data for a user specified interval +and generates performance plots. + +Prerequisites: + Python version 2.7.x + gnuplot 5.0 or higher + gnuplot-py 1.8 + (Most of the distributions have these required packages. They may be called + gnuplot-py, phython-gnuplot. ) + + HWP (Hardware P-States are disabled) + Kernel config for Linux trace is enabled + + see print_help(): for Usage and Output details + +""" +from __future__ import print_function +from datetime import datetime +import subprocess +import os +import time +import re +import sys +import getopt +import Gnuplot +from numpy import * +from decimal import * + +__author__ = "Srinivas Pandruvada" +__copyright__ = " Copyright (c) 2017, Intel Corporation. " +__license__ = "GPL version 2" + + +MAX_CPUS = 256 + +# Define the csv file columns +C_COMM = 18 +C_GHZ = 17 +C_ELAPSED = 16 +C_SAMPLE = 15 +C_DURATION = 14 +C_LOAD = 13 +C_BOOST = 12 +C_FREQ = 11 +C_TSC = 10 +C_APERF = 9 +C_MPERF = 8 +C_TO = 7 +C_FROM = 6 +C_SCALED = 5 +C_CORE = 4 +C_USEC = 3 +C_SEC = 2 +C_CPU = 1 + +global sample_num, last_sec_cpu, last_usec_cpu, start_time, testname + +# 11 digits covers uptime to 115 days +getcontext().prec = 11 + +sample_num =0 +last_sec_cpu = [0] * MAX_CPUS +last_usec_cpu = [0] * MAX_CPUS + +def print_help(): + print('intel_pstate_tracer.py:') + print(' Usage:') + print(' If the trace file is available, then to simply parse and plot, use (sudo not required):') + print(' ./intel_pstate_tracer.py [-c cpus] -t <trace_file> -n <test_name>') + print(' Or') + print(' ./intel_pstate_tracer.py [--cpu cpus] ---trace_file <trace_file> --name <test_name>') + print(' To generate trace file, parse and plot, use (sudo required):') + print(' sudo ./intel_pstate_tracer.py [-c cpus] -i <interval> -n <test_name>') + print(' Or') + print(' sudo ./intel_pstate_tracer.py [--cpu cpus] --interval <interval> --name <test_name>') + print(' Optional argument:') + print(' cpus: comma separated list of CPUs') + print(' Output:') + print(' If not already present, creates a "results/test_name" folder in the current working directory with:') + print(' cpu.csv - comma seperated values file with trace contents and some additional calculations.') + print(' cpu???.csv - comma seperated values file for CPU number ???.') + print(' *.png - a variety of PNG format plot files created from the trace contents and the additional calculations.') + print(' Notes:') + print(' Avoid the use of _ (underscore) in test names, because in gnuplot it is a subscript directive.') + print(' Maximum number of CPUs is {0:d}. If there are more the script will abort with an error.'.format(MAX_CPUS)) + 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.') + print(' Empty y range warnings for autoscaled plots can occur and can be ignored.') + +def plot_perf_busy_with_sample(cpu_index): + """ Plot method to per cpu information """ + + file_name = 'cpu{:0>3}.csv'.format(cpu_index) + if os.path.exists(file_name): + output_png = "cpu%03d_perf_busy_vs_samples.png" % cpu_index + g_plot = common_all_gnuplot_settings(output_png) + g_plot('set yrange [0:40]') + g_plot('set y2range [0:200]') + g_plot('set y2tics 0, 10') + g_plot('set title "{} : cpu perf busy vs. sample : CPU {:0>3} : {:%F %H:%M}"'.format(testname, cpu_index, datetime.now())) +# Override common + g_plot('set xlabel "Samples"') + g_plot('set ylabel "P-State"') + g_plot('set y2label "Scaled Busy/performance/io-busy(%)"') + set_4_plot_linestyles(g_plot) + g_plot('plot "' + file_name + '" using {:d}:{:d} with linespoints linestyle 1 axis x1y2 title "performance",\\'.format(C_SAMPLE, C_CORE)) + g_plot('"' + file_name + '" using {:d}:{:d} with linespoints linestyle 2 axis x1y2 title "scaled-busy",\\'.format(C_SAMPLE, C_SCALED)) + g_plot('"' + file_name + '" using {:d}:{:d} with linespoints linestyle 3 axis x1y2 title "io-boost",\\'.format(C_SAMPLE, C_BOOST)) + g_plot('"' + file_name + '" using {:d}:{:d} with linespoints linestyle 4 axis x1y1 title "P-State"'.format(C_SAMPLE, C_TO)) + +def plot_perf_busy(cpu_index): + """ Plot some per cpu information """ + + file_name = 'cpu{:0>3}.csv'.format(cpu_index) + if os.path.exists(file_name): + output_png = "cpu%03d_perf_busy.png" % cpu_index + g_plot = common_all_gnuplot_settings(output_png) + g_plot('set yrange [0:40]') + g_plot('set y2range [0:200]') + g_plot('set y2tics 0, 10') + g_plot('set title "{} : perf busy : CPU {:0>3} : {:%F %H:%M}"'.format(testname, cpu_index, datetime.now())) + g_plot('set ylabel "P-State"') + g_plot('set y2label "Scaled Busy/performance/io-busy(%)"') + set_4_plot_linestyles(g_plot) + g_plot('plot "' + file_name + '" using {:d}:{:d} with linespoints linestyle 1 axis x1y2 title "performance",\\'.format(C_ELAPSED, C_CORE)) + g_plot('"' + file_name + '" using {:d}:{:d} with linespoints linestyle 2 axis x1y2 title "scaled-busy",\\'.format(C_ELAPSED, C_SCALED)) + g_plot('"' + file_name + '" using {:d}:{:d} with linespoints linestyle 3 axis x1y2 title "io-boost",\\'.format(C_ELAPSED, C_BOOST)) + g_plot('"' + file_name + '" using {:d}:{:d} with linespoints linestyle 4 axis x1y1 title "P-State"'.format(C_ELAPSED, C_TO)) + +def plot_durations(cpu_index): + """ Plot per cpu durations """ + + file_name = 'cpu{:0>3}.csv'.format(cpu_index) + if os.path.exists(file_name): + output_png = "cpu%03d_durations.png" % cpu_index + g_plot = common_all_gnuplot_settings(output_png) +# Should autoscale be used here? Should seconds be used here? + g_plot('set yrange [0:5000]') + g_plot('set ytics 0, 500') + g_plot('set title "{} : durations : CPU {:0>3} : {:%F %H:%M}"'.format(testname, cpu_index, datetime.now())) + g_plot('set ylabel "Timer Duration (MilliSeconds)"') +# override common + g_plot('set key off') + set_4_plot_linestyles(g_plot) + g_plot('plot "' + file_name + '" using {:d}:{:d} with linespoints linestyle 1 axis x1y1'.format(C_ELAPSED, C_DURATION)) + +def plot_loads(cpu_index): + """ Plot per cpu loads """ + + file_name = 'cpu{:0>3}.csv'.format(cpu_index) + if os.path.exists(file_name): + output_png = "cpu%03d_loads.png" % cpu_index + g_plot = common_all_gnuplot_settings(output_png) + g_plot('set yrange [0:100]') + g_plot('set ytics 0, 10') + g_plot('set title "{} : loads : CPU {:0>3} : {:%F %H:%M}"'.format(testname, cpu_index, datetime.now())) + g_plot('set ylabel "CPU load (percent)"') +# override common + g_plot('set key off') + set_4_plot_linestyles(g_plot) + g_plot('plot "' + file_name + '" using {:d}:{:d} with linespoints linestyle 1 axis x1y1'.format(C_ELAPSED, C_LOAD)) + +def plot_pstate_cpu_with_sample(): + """ Plot all cpu information """ + + if os.path.exists('cpu.csv'): + output_png = 'all_cpu_pstates_vs_samples.png' + g_plot = common_all_gnuplot_settings(output_png) + g_plot('set yrange [0:40]') +# override common + g_plot('set xlabel "Samples"') + g_plot('set ylabel "P-State"') + g_plot('set title "{} : cpu pstate vs. sample : {:%F %H:%M}"'.format(testname, datetime.now())) + title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).replace('\n', ' ') + plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_SAMPLE, C_TO) + g_plot('title_list = "{}"'.format(title_list)) + g_plot(plot_str) + +def plot_pstate_cpu(): + """ Plot all cpu information from csv files """ + + output_png = 'all_cpu_pstates.png' + g_plot = common_all_gnuplot_settings(output_png) + g_plot('set yrange [0:40]') + g_plot('set ylabel "P-State"') + g_plot('set title "{} : cpu pstates : {:%F %H:%M}"'.format(testname, datetime.now())) + +# the following command is really cool, but doesn't work with the CPU masking option because it aborts on the first missing file. +# 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' +# + title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).replace('\n', ' ') + plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_TO) + g_plot('title_list = "{}"'.format(title_list)) + g_plot(plot_str) + +def plot_load_cpu(): + """ Plot all cpu loads """ + + output_png = 'all_cpu_loads.png' + g_plot = common_all_gnuplot_settings(output_png) + g_plot('set yrange [0:100]') + g_plot('set ylabel "CPU load (percent)"') + g_plot('set title "{} : cpu loads : {:%F %H:%M}"'.format(testname, datetime.now())) + + title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).replace('\n', ' ') + plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_LOAD) + g_plot('title_list = "{}"'.format(title_list)) + g_plot(plot_str) + +def plot_frequency_cpu(): + """ Plot all cpu frequencies """ + + output_png = 'all_cpu_frequencies.png' + g_plot = common_all_gnuplot_settings(output_png) + g_plot('set yrange [0:4]') + g_plot('set ylabel "CPU Frequency (GHz)"') + g_plot('set title "{} : cpu frequencies : {:%F %H:%M}"'.format(testname, datetime.now())) + + title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).replace('\n', ' ') + plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_FREQ) + g_plot('title_list = "{}"'.format(title_list)) + g_plot(plot_str) + +def plot_duration_cpu(): + """ Plot all cpu durations """ + + output_png = 'all_cpu_durations.png' + g_plot = common_all_gnuplot_settings(output_png) + g_plot('set yrange [0:5000]') + g_plot('set ytics 0, 500') + g_plot('set ylabel "Timer Duration (MilliSeconds)"') + g_plot('set title "{} : cpu durations : {:%F %H:%M}"'.format(testname, datetime.now())) + + title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).replace('\n', ' ') + plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_DURATION) + g_plot('title_list = "{}"'.format(title_list)) + g_plot(plot_str) + +def plot_scaled_cpu(): + """ Plot all cpu scaled busy """ + + output_png = 'all_cpu_scaled.png' + g_plot = common_all_gnuplot_settings(output_png) +# autoscale this one, no set y range + g_plot('set ylabel "Scaled Busy (Unitless)"') + g_plot('set title "{} : cpu scaled busy : {:%F %H:%M}"'.format(testname, datetime.now())) + + title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).replace('\n', ' ') + plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_SCALED) + g_plot('title_list = "{}"'.format(title_list)) + g_plot(plot_str) + +def plot_boost_cpu(): + """ Plot all cpu IO Boosts """ + + output_png = 'all_cpu_boost.png' + g_plot = common_all_gnuplot_settings(output_png) + g_plot('set yrange [0:100]') + g_plot('set ylabel "CPU IO Boost (percent)"') + g_plot('set title "{} : cpu io boost : {:%F %H:%M}"'.format(testname, datetime.now())) + + title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).replace('\n', ' ') + plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_BOOST) + g_plot('title_list = "{}"'.format(title_list)) + g_plot(plot_str) + +def plot_ghz_cpu(): + """ Plot all cpu tsc ghz """ + + output_png = 'all_cpu_ghz.png' + g_plot = common_all_gnuplot_settings(output_png) +# autoscale this one, no set y range + g_plot('set ylabel "TSC Frequency (GHz)"') + g_plot('set title "{} : cpu TSC Frequencies (Sanity check calculation) : {:%F %H:%M}"'.format(testname, datetime.now())) + + title_list = subprocess.check_output('ls cpu???.csv | sed -e \'s/.csv//\'',shell=True).replace('\n', ' ') + plot_str = "plot for [i in title_list] i.'.csv' using {:d}:{:d} pt 7 ps 1 title i".format(C_ELAPSED, C_GHZ) + g_plot('title_list = "{}"'.format(title_list)) + g_plot(plot_str) + +def common_all_gnuplot_settings(output_png): + """ common gnuplot settings for multiple CPUs one one graph. """ + + g_plot = common_gnuplot_settings() + g_plot('set output "' + output_png + '"') + return(g_plot) + +def common_gnuplot_settings(): + """ common gnuplot settings. """ + + g_plot = Gnuplot.Gnuplot(persist=1) +# The following line is for rigor only. It seems to be assumed for .csv files + g_plot('set datafile separator \",\"') + g_plot('set ytics nomirror') + g_plot('set xtics nomirror') + g_plot('set xtics font ", 10"') + g_plot('set ytics font ", 10"') + g_plot('set tics out scale 1.0') + g_plot('set grid') + g_plot('set key out horiz') + g_plot('set key bot center') + g_plot('set key samplen 2 spacing .8 font ", 9"') + g_plot('set term png size 1200, 600') + g_plot('set title font ", 11"') + g_plot('set ylabel font ", 10"') + g_plot('set xlabel font ", 10"') + g_plot('set xlabel offset 0, 0.5') + g_plot('set xlabel "Elapsed Time (Seconds)"') + return(g_plot) + +def set_4_plot_linestyles(g_plot): + """ set the linestyles used for 4 plots in 1 graphs. """ + + g_plot('set style line 1 linetype 1 linecolor rgb "green" pointtype -1') + g_plot('set style line 2 linetype 1 linecolor rgb "red" pointtype -1') + g_plot('set style line 3 linetype 1 linecolor rgb "purple" pointtype -1') + g_plot('set style line 4 linetype 1 linecolor rgb "blue" pointtype -1') + +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): + """ Store master csv file information """ + + global graph_data_present + + if cpu_mask[cpu_int] == 0: + return + + try: + f_handle = open('cpu.csv', 'a') + 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) + f_handle.write(string_buffer); + f_handle.close() + except: + print('IO error cpu.csv') + return + + graph_data_present = True; + +def split_csv(): + """ seperate the all csv file into per CPU csv files. """ + + global current_max_cpu + + if os.path.exists('cpu.csv'): + for index in range(0, current_max_cpu + 1): + if cpu_mask[int(index)] != 0: + os.system('grep -m 1 common_cpu cpu.csv > cpu{:0>3}.csv'.format(index)) + os.system('grep CPU_{:0>3} cpu.csv >> cpu{:0>3}.csv'.format(index, index)) + +def cleanup_data_files(): + """ clean up existing data files """ + + if os.path.exists('cpu.csv'): + os.remove('cpu.csv') + f_handle = open('cpu.csv', 'a') + 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') + f_handle.write('\n') + f_handle.close() + +def clear_trace_file(): + """ Clear trace file """ + + try: + f_handle = open('/sys/kernel/debug/tracing/trace', 'w') + f_handle.close() + except: + print('IO error clearing trace file ') + quit() + +def enable_trace(): + """ Enable trace """ + + try: + open('/sys/kernel/debug/tracing/events/power/pstate_sample/enable' + , 'w').write("1") + except: + print('IO error enabling trace ') + quit() + +def disable_trace(): + """ Disable trace """ + + try: + open('/sys/kernel/debug/tracing/events/power/pstate_sample/enable' + , 'w').write("0") + except: + print('IO error disabling trace ') + quit() + +def set_trace_buffer_size(): + """ Set trace buffer size """ + + try: + open('/sys/kernel/debug/tracing/buffer_size_kb' + , 'w').write("10240") + except: + print('IO error setting trace buffer size ') + quit() + +def read_trace_data(filename): + """ Read and parse trace data """ + + global current_max_cpu + global sample_num, last_sec_cpu, last_usec_cpu, start_time + + try: + data = open(filename, 'r').read() + except: + print('Error opening ', filename) + quit() + + for line in data.splitlines(): + search_obj = \ + re.search(r'(^(.*?)\[)((\d+)[^\]])(.*?)(\d+)([.])(\d+)(.*?core_busy=)(\d+)(.*?scaled=)(\d+)(.*?from=)(\d+)(.*?to=)(\d+)(.*?mperf=)(\d+)(.*?aperf=)(\d+)(.*?tsc=)(\d+)(.*?freq=)(\d+)' + , line) + + if search_obj: + cpu = search_obj.group(3) + cpu_int = int(cpu) + cpu = str(cpu_int) + + time_pre_dec = search_obj.group(6) + time_post_dec = search_obj.group(8) + core_busy = search_obj.group(10) + scaled = search_obj.group(12) + _from = search_obj.group(14) + _to = search_obj.group(16) + mperf = search_obj.group(18) + aperf = search_obj.group(20) + tsc = search_obj.group(22) + freq = search_obj.group(24) + common_comm = search_obj.group(2).replace(' ', '') + + # Not all kernel versions have io_boost field + io_boost = '0' + search_obj = re.search(r'.*?io_boost=(\d+)', line) + if search_obj: + io_boost = search_obj.group(1) + + if sample_num == 0 : + start_time = Decimal(time_pre_dec) + Decimal(time_post_dec) / Decimal(1000000) + sample_num += 1 + + if last_sec_cpu[cpu_int] == 0 : + last_sec_cpu[cpu_int] = time_pre_dec + last_usec_cpu[cpu_int] = time_post_dec + else : + duration_us = (int(time_pre_dec) - int(last_sec_cpu[cpu_int])) * 1000000 + (int(time_post_dec) - int(last_usec_cpu[cpu_int])) + duration_ms = Decimal(duration_us) / Decimal(1000) + last_sec_cpu[cpu_int] = time_pre_dec + last_usec_cpu[cpu_int] = time_post_dec + elapsed_time = Decimal(time_pre_dec) + Decimal(time_post_dec) / Decimal(1000000) - start_time + load = Decimal(int(mperf)*100)/ Decimal(tsc) + freq_ghz = Decimal(freq)/Decimal(1000000) +# Sanity check calculation, typically anomalies indicate missed samples +# However, check for 0 (should never occur) + tsc_ghz = Decimal(0) + if duration_ms != Decimal(0) : + tsc_ghz = Decimal(tsc)/duration_ms/Decimal(1000000) + 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) + + if cpu_int > current_max_cpu: + current_max_cpu = cpu_int +# End of for each trace line loop +# Now seperate the main overall csv file into per CPU csv files. + split_csv() + +interval = "" +filename = "" +cpu_list = "" +testname = "" +graph_data_present = False; + +valid1 = False +valid2 = False + +cpu_mask = zeros((MAX_CPUS,), dtype=int) + +try: + opts, args = getopt.getopt(sys.argv[1:],"ht:i:c:n:",["help","trace_file=","interval=","cpu=","name="]) +except getopt.GetoptError: + print_help() + sys.exit(2) +for opt, arg in opts: + if opt == '-h': + print() + sys.exit() + elif opt in ("-t", "--trace_file"): + valid1 = True + location = os.path.realpath(os.path.join(os.getcwd(), os.path.dirname(__file__))) + filename = os.path.join(location, arg) + elif opt in ("-i", "--interval"): + valid1 = True + interval = arg + elif opt in ("-c", "--cpu"): + cpu_list = arg + elif opt in ("-n", "--name"): + valid2 = True + testname = arg + +if not (valid1 and valid2): + print_help() + sys.exit() + +if cpu_list: + for p in re.split("[,]", cpu_list): + if int(p) < MAX_CPUS : + cpu_mask[int(p)] = 1 +else: + for i in range (0, MAX_CPUS): + cpu_mask[i] = 1 + +if not os.path.exists('results'): + os.mkdir('results') + +os.chdir('results') +if os.path.exists(testname): + print('The test name directory already exists. Please provide a unique test name. Test re-run not supported, yet.') + sys.exit() +os.mkdir(testname) +os.chdir(testname) + +# Temporary (or perhaps not) +cur_version = sys.version_info +print('python version (should be >= 2.7):') +print(cur_version) + +# Left as "cleanup" for potential future re-run ability. +cleanup_data_files() + +if interval: + filename = "/sys/kernel/debug/tracing/trace" + clear_trace_file() + set_trace_buffer_size() + enable_trace() + print('Sleeping for ', interval, 'seconds') + time.sleep(int(interval)) + disable_trace() + +current_max_cpu = 0 + +read_trace_data(filename) + +if graph_data_present == False: + print('No valid data to plot') + sys.exit(2) + +for cpu_no in range(0, current_max_cpu + 1): + plot_perf_busy_with_sample(cpu_no) + plot_perf_busy(cpu_no) + plot_durations(cpu_no) + plot_loads(cpu_no) + +plot_pstate_cpu_with_sample() +plot_pstate_cpu() +plot_load_cpu() +plot_frequency_cpu() +plot_duration_cpu() +plot_scaled_cpu() +plot_boost_cpu() +plot_ghz_cpu() + +os.chdir('../../') |
