check-playback: add check for FW performance #959
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change | ||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| @@ -0,0 +1,11 @@ | ||||||||||||||
| [ | ||||||||||||||
| { | ||||||||||||||
| "test-key": "tgl-sof-tgl-nocodec.tplg-ipc4-zephyr-check-playback-hw:0,0" , | ||||||||||||||
| "ll-timer-avg": 2589 | ||||||||||||||
|
There was a problem hiding this comment.
Suggested change
Suggested change
Suggested change
You get the idea. |
||||||||||||||
| }, | ||||||||||||||
| { | ||||||||||||||
| "test-key": "tgl-sof-tgl-nocodec.tplg-ipc4-zephyr-check-playback-hw:0,1" , | ||||||||||||||
| "ll-timer-avg": 2589 | ||||||||||||||
| } | ||||||||||||||
| ] | ||||||||||||||
|
|
||||||||||||||
| Original file line number | Diff line number | Diff line change | ||||
|---|---|---|---|---|---|---|
| @@ -0,0 +1,59 @@ | ||||||
| #!/usr/bin/env python3 | ||||||
|
There was a problem hiding this comment. Most of what this script does is parsing a log file but there's neither "parsing" nor "log" in the name. This is a test code so I don't think this is an "implementation detail" that should be hidden. |
||||||
|
|
||||||
| '''Script to analyze performance data in SOF FW log output''' | ||||||
|
There was a problem hiding this comment. |
||||||
|
|
||||||
| import sys | ||||||
| import re | ||||||
| import json | ||||||
| from statistics import median | ||||||
|
|
||||||
| # allowed error margin before error is raised for | ||||||
| # lower observed performance (1.05 -> 5% difference | ||||||
| # required to raise error) | ||||||
| AVG_ERROR_MARGIN = 1.05 | ||||||
|
There was a problem hiding this comment. This feels overkill / YAGNI... why not just bump the thresholds 5%? There are only two of them. There was a problem hiding this comment. @marc-hb I added this on purpose. Basicly anyone setting baseline values is going to run a test and copy values over to the database. Probably we add a option to the test script it self that if you pass "--reference-capture", script will run the test, measure performance, but instead of comparing against expected value, just write the measured values out in jsof/init format, so they can be incorporated in the database (after of course reviewed that values are a sane new baseline). So to make above possible, it's better the margin is stored elsewhere. |
||||||
|
|
||||||
| max_vals = [] | ||||||
| avg_vals = [] | ||||||
| overruns = 0 | ||||||
|
|
||||||
| f = open(sys.argv[1]) | ||||||
|
|
||||||
| for line in f: | ||||||
| m = re.search('.*ll timer avg ([0-9]*), max ([0-9]*), overruns ([0-9]*)', line) | ||||||
| if m: | ||||||
| avg_vals.append(int(m.group(1))) | ||||||
| max_vals.append(int(m.group(2))) | ||||||
| overruns += int(m.group(3)) | ||||||
|
|
||||||
| median_avg_vals = median(avg_vals) | ||||||
| print("Measurements:\t\t%d" % len(avg_vals)) | ||||||
| print("Median avg reported:\t%d" % median_avg_vals) | ||||||
| print("Median max reported:\t%d" % median(max_vals)) | ||||||
| print("Highest max reported:\t%d" % max(max_vals)) | ||||||
|
There was a problem hiding this comment. import logging
# Can be invoked only once and only before any actual logging
logging.basicConfig(level=logging.DEBUG)
...
logging.info(""Measurements:\t\t%d" % len(avg_vals)")and that's it, nothing else needed. Fancy stuff can be more easily added later if/when needed. https://docs.python.org/3/howto/logging.html |
||||||
|
|
||||||
| if overruns: | ||||||
| print("ERROR: %s overruns detected" % overruns, file=sys.stderr) | ||||||
| sys.exit(-1) | ||||||
|
There was a problem hiding this comment.
Suggested change
prints the message on |
||||||
|
|
||||||
| if len(sys.argv) < 4: | ||||||
| print("No reference data for key '%s', unable to check performance against reference") | ||||||
| sys.exit(0) | ||||||
|
|
||||||
| median_avg_ref = None | ||||||
| dbfile = open(sys.argv[3]) | ||||||
| ref_key = sys.argv[2] | ||||||
|
There was a problem hiding this comment.
|
||||||
| ref_data_all = json.load(dbfile) | ||||||
|
There was a problem hiding this comment. Have you considered a It's less powerful and less flexible but more user-friendly and more programmer friendly. Long story short: do you expect a hierarchy of values? There was a problem hiding this comment. That should be considered, yeah. I frankly don't yet know whether even whole concept is pragmatic/feasible, so I just wanted to get some minimum-working-set and json was good for this. |
||||||
|
|
||||||
| for ref in ref_data_all: | ||||||
| if ref["test-key"] == ref_key: | ||||||
| median_avg_ref = ref["ll-timer-avg"] | ||||||
| break | ||||||
|
|
||||||
| if not median_avg_ref: | ||||||
| print("No reference data for key '%s', unable to check performance against reference" % ref_key) | ||||||
|
There was a problem hiding this comment. You would probably need that code with a simpler .ini file, it would likely just fail with a meaning full stack trace and error message. |
||||||
| sys.exit(0) | ||||||
|
|
||||||
| median_avg_ref_w_margin = median_avg_ref * AVG_ERROR_MARGIN | ||||||
| if median_avg_vals > median_avg_ref_w_margin: | ||||||
| print("ERROR: ll-timer-avg median %d over threshold %d (%d without margin)" % (median_avg_vals, median_avg_ref_w_margin, median_avg_ref), file=sys.stderr) | ||||||
| sys.exit(-1) | ||||||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
AFAIK this new test is merely scanning logs so it should be hardcoded to neither IPC4 nor Zephyr nor mtrace.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@marc-hb Well that's complicated. The log output structure is specific to Zephyr (it uses formatting of the Zephyr logging subsystem). IPC4 should not be a dependency, but we do need separate code to handle sof-logger output.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
One big TODO that needs to be addresses is limiting the analysis to also cover logs that happened during the test run. Here full mtrace.txt is analyzed, but it is not guaranteed the DSP went to D3 between the test iterations. So some kind of capture of the timestamp of last line of log line before test starts, and pruning the log to only cover the new entries added during test execution, is needed.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Seems complicated...
It's possible 3 may not work, as it may still present the same challenges.