diff --git a/.clang-format b/.clang-format index 39b753e7a..8178613b6 100644 --- a/.clang-format +++ b/.clang-format @@ -63,6 +63,8 @@ ForEachMacros: SortIncludes: true IncludeBlocks: Regroup IncludeCategories: + - Regex: '"V3Pch.*\.h"' + Priority: -2 # Precompiled headers - Regex: '"(config_build|verilated_config|verilatedos)\.h"' Priority: -1 # Sepecials before main header - Regex: '(<|")verilated.*' @@ -112,6 +114,9 @@ SpacesBeforeTrailingComments: 2 SpacesInAngles: false SpacesInContainerLiterals: true SpacesInCStyleCastParentheses: false +SpacesInLineCommentPrefix: + Minimum: 0 + Maximum: -1 SpacesInParentheses: false SpacesInSquareBrackets: false Standard: Cpp11 diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 704917c53..ca68a4957 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -23,6 +23,10 @@ defaults: shell: bash working-directory: repo +concurrency: + group: ${{ github.workflow }}-${{ github.event_name == 'pull_request' && github.ref || github.run_id }} + cancel-in-progress: true + jobs: build: @@ -33,7 +37,8 @@ jobs: compiler: - { cc: clang, cxx: clang++ } - { cc: gcc, cxx: g++ } - m32: [0, 1] + # m32 1 is deprecated, not here to speed up regressions + m32: [0] exclude: # Build pull requests only with ubuntu-22.04 and without m32 # - os: ${{ github.event_name == 'pull_request' && 'ubuntu-18.04' || 'do-not-exclude' }} @@ -58,7 +63,7 @@ jobs: CC: ${{ matrix.compiler.cc }} CXX: ${{ matrix.compiler.cxx }} CACHE_BASE_KEY: build-${{ matrix.os }}-${{ matrix.compiler.cc }}-m32=${{ matrix.m32 }} - CCACHE_MAXSIZE: 250M # Per build matrix entry (2000M in total) + CCACHE_MAXSIZE: 1000M # Per build matrix entry (* 5 = 5000M in total) VERILATOR_ARCHIVE: verilator-${{ github.sha }}-${{ matrix.os }}-${{ matrix.compiler.cc }}${{ matrix.m32 && '-m32' || '' }}.tar.gz steps: @@ -103,7 +108,7 @@ jobs: compiler: - { cc: clang, cxx: clang++ } - { cc: gcc, cxx: g++ } - m32: [0, 1] + m32: [0] suite: [dist-vlt-0, dist-vlt-1, dist-vlt-2, vltmt-0, vltmt-1] exclude: # Build pull requests only with ubuntu-22.04 and without m32 @@ -131,7 +136,7 @@ jobs: CC: ${{ matrix.compiler.cc }} CXX: ${{ matrix.compiler.cxx }} CACHE_BASE_KEY: test-${{ matrix.os }}-${{ matrix.compiler.cc }}-m32=${{ matrix.m32 }}-${{ matrix.suite }} - CCACHE_MAXSIZE: 64M # Per build matrix entry (2160M in total) + CCACHE_MAXSIZE: 100M # Per build per suite (* 5 * 5 = 2500M in total) VERILATOR_ARCHIVE: verilator-${{ github.sha }}-${{ matrix.os }}-${{ matrix.compiler.cc }}${{ matrix.m32 && '-m32' || '' }}.tar.gz steps: diff --git a/.github/workflows/lint.yaml b/.github/workflows/lint.yaml new file mode 100644 index 000000000..cb64707f4 --- /dev/null +++ b/.github/workflows/lint.yaml @@ -0,0 +1,53 @@ +# DESCRIPTION: Github actions config +# SPDX-License-Identifier: LGPL-3.0-only OR Artistic-2.0 + +name: lint + +on: + push: + pull_request: + workflow_dispatch: + schedule: + - cron: '0 0 * * 0' # weekly + +env: + CI_OS_NAME: linux + CI_COMMIT: ${{ github.sha }} + +defaults: + run: + shell: bash + working-directory: repo + +concurrency: + group: ${{ github.workflow }}-${{ github.event_name == 'pull_request' && github.ref || github.run_id }} + cancel-in-progress: true + +jobs: + + lint-py: + runs-on: ubuntu-22.04 + name: Lint Python + env: + CI_BUILD_STAGE_NAME: build + CI_RUNS_ON: ubuntu-22.04 + CI_M32: 0 + steps: + - name: Checkout + uses: actions/checkout@v3 + with: + path: repo + + - name: Install packages for build + run: ./ci/ci-install.bash + + # We use specific version numbers, otherwise a Python package + # update may add a warning and break our build + - name: Install packages for lint + run: sudo pip3 install pylint==3.0.2 ruff==0.1.3 clang sphinx sphinx_rtd_theme sphinxcontrib-spelling breathe ruff + + - name: Configure + run: autoconf && ./configure --enable-longtests --enable-ccwarn + + - name: Lint + run: make -k lint-py diff --git a/.github/workflows/msbuild.yml b/.github/workflows/msbuild.yml index dd25c2669..fe148ad6e 100644 --- a/.github/workflows/msbuild.yml +++ b/.github/workflows/msbuild.yml @@ -22,6 +22,10 @@ defaults: run: working-directory: repo +concurrency: + group: ${{ github.workflow }}-${{ github.event_name == 'pull_request' && github.ref || github.run_id }} + cancel-in-progress: true + jobs: windows: diff --git a/.gitignore b/.gitignore index e7e3d788a..c04dcedeb 100644 --- a/.gitignore +++ b/.gitignore @@ -43,3 +43,4 @@ verilator-config-version.cmake /.vscode/ /.idea/ /cmake-build-*/ +/test_regress/snapshot/ diff --git a/CMakeLists.txt b/CMakeLists.txt index 4c600a850..63510641a 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -15,7 +15,7 @@ cmake_minimum_required(VERSION 3.15) cmake_policy(SET CMP0091 NEW) # Use MSVC_RUNTIME_LIBRARY to select the runtime project(Verilator - VERSION 5.016 + VERSION 5.018 HOMEPAGE_URL https://verilator.org LANGUAGES CXX ) diff --git a/Changes b/Changes index 2a6f93e02..ee1167e6f 100644 --- a/Changes +++ b/Changes @@ -8,6 +8,82 @@ The changes in each Verilator version are described below. The contributors that suggested a given feature are shown in []. Thanks! +Verilator 5.018 2023-10-30 +========================== + +**Major:** + +* Support compilation with precompiled headers with Make and GCC or CLang. +* Change include of systemc instead of systemc.h (#4622) (#4623). [Chih-Mao Chen] + This may require that SystemC programs add 'using namespace sc_core', 'using namespace sc_dt'. + +**Minor:** + +* Add SIDEEFFECT warning on mishandled side effect cases. +* Add trace() API even when Verilated without --trace (#4462). [phelter] +* Add warning on interface instantiation without parens (#4094). [Gökçe Aydos] +* Add sv_vpi_user.h from IEEE 1800-2017 Annex M (#4606). [Marlon James] +* Support 'disable fork' (#4125) (#4569). [Aleksander Kiryk, Antmicro Ltd.] +* Support 'wait fork' (#4586). [Aleksander Kiryk, Antmicro Ltd.] +* Support 'randc' (#4349). +* Support assigning events (#4403). [Krzysztof Boroński] +* Support resizing function call inout arguments (#4467). +* Support NBAs in non-inlined functions/tasks (#4496) (#4572). [Krzysztof Bieganski, Antmicro Ltd.] +* Support converting parameters inside modules to localparams (#4511). [Anthony Donlon] +* Support concatenation of unpacked arrays (#4558). [Yutetsu TAKATSUKASA] +* Support Clang 16 (#4592). [Mariusz Glebocki] +* Support VPI variables of real and string data types (#4594). [Marlon James] +* Support making VL_LOCK_SPINS configurable (#4599). [Geza Lore] +* Change code --stats output (#4597). [Geza Lore] +* Change --prof-exec infrastructure and report (#4602). [Geza Lore] +* Change lint_off to not propagate upwards to files including where the lint_off is. +* Optimize empty expression statements (#4544). +* Optimize trace internals (#4610) (#4612). [Geza Lore] +* Optimize internal performance issues (#4638). [Geza Lore] +* Fix conversion of impure logical expressions to bit expressions (#487 partial) (#4437). [Ryszard Rozak, Antmicro Ltd.] +* Fix enum functions in localparams (#3999). [Andrew Nolte] +* Fix passing arguments by reference (#3385 partial) (#4489). [Ryszard Rozak, Antmicro Ltd.] +* Fix multithreading handling to separate by code units that use/never use it (#4228). [Mariusz Glebocki, Antmicro Ltd.] +* Fix usage of annotation options (#4486) (#4504). [Michal Czyz] +* Fix detecting local vars in nested forks (#4493) (#4506). [Kamil Rakoczy] +* Fix handling input file path separator (#4515) (#4516). [Anthony Donlon] +* Fix mis-support for parameterized UDPs (#4518). [Anthony Donlon] +* Fix constant conversion of $realtobits, $bitstoreal (#4522). [Andrew Nolte] +* Fix conversion of integers in $display '%e' (#4528). [muzafferkal] +* Fix non-inlined interface tracing (#3984) (#4530). [Todd Strader] +* Fix stream operations with operands of struct type (#4531) (#4532). [Ryszard Rozak, Antmicro Ltd.] +* Fix 'this' in a constructor (#4533). [Ryszard Rozak, Antmicro Ltd.] +* Fix stream shift operator of 32 bits (#4536). [Julien Faucher] +* Fix object destruction after a copy constructor (#4540) (#4541). [Ryszard Rozak, Antmicro Ltd.] +* Fix inlining of real functions miscasting (#4543). [Andrew Nolte] +* Fix broken link error for enum references (#4551). [Anthony Donlon] +* Fix logical expressions with class objects - caching in v3Const (#4552). [Ryszard Rozak, Antmicro Ltd.] +* Fix using functions/tasks following class definition inside module (#4553). [Anthony Donlon] +* Fix large constant buffer overflow (#4556). [Varun Koyyalagunta] +* Fix instance arrays connecting to array of structs (#4557). [raphmaster] +* Fix error message for invalid parameter overrides (#4559). [Anthony Donlon] +* Fix shift to remove operation side effects (#4563). +* Fix compile warning on unused member function variable (#4567). +* Fix method narrowing conversion compiler error (#4568). +* Fix interface comparison (#4570). [Krzysztof Bieganski, Antmicro Ltd.] +* Fix dynamic triggers for named events (#4571). [Krzysztof Bieganski, Antmicro Ltd.] +* Fix dictionaries with keys of class types (#4576). [Ryszard Rozak, Antmicro Ltd.] +* Fix to not remap local assign intervals in forks (#4583). [Krzysztof Bieganski, Antmicro Ltd.] +* Fix display optimization ignoring side effects (#4585). +* Fix PLI/DPI user defined system task/function grammar (#4587) (#4588). [Quentin Corradi] +* Fix fault on empty clocking block (#4593). [Alex Mykyta] +* Fix creating implicit nets for inputs of gate primitives (#4603). [Geza Lore] +* Fix try_put method of unbounded mailbox (#4608). [Ryszard Rozak, Antmicro Ltd.] +* Fix stable name generation in V3Fork (#4615) (#4624). [Krzysztof Boroński] +* Fix virtual methods (#4616). [Ryszard Rozak, Antmicro Ltd.] +* Fix insertion at queue end (#4619). [Krzysztof Boroński] +* Fix rand fields of reference types (#4627). [Ryszard Rozak, Antmicro Ltd.] +* Fix dynamic casts of null values (#4631). [Ryszard Rozak, Antmicro Ltd.] +* Fix signals read via virtual interfaces being misoptimized (#4645). [Krzysztof Bieganski, Antmicro Ltd.] +* Fix handling of static keyword in methods (#4649). [Ryszard Rozak, Antmicro Ltd.] +* Fix preprocessor to show `line 2 on resumed file. + + Verilator 5.016 2023-09-16 ========================== diff --git a/Makefile.in b/Makefile.in index 358823411..8eb581f1e 100644 --- a/Makefile.in +++ b/Makefile.in @@ -173,6 +173,10 @@ smoke-test: all_nomsg test_regress: all_nomsg $(MAKE) -C test_regress +.PHONY: test-snap test-diff +test-snap test-diff: + $(MAKE) -C test_regress $@ + examples: all_nomsg for p in $(EXAMPLES) ; do \ $(MAKE) -C $$p VERILATOR_ROOT=`pwd` || exit 10; \ @@ -430,9 +434,15 @@ PYLINT_FLAGS = --score=n --disable=R0801 RUFF = ruff RUFF_FLAGS = check --ignore=E402,E501,E701 +# "make -k" so can see all tool result errors lint-py: - -$(PYLINT) $(PYLINT_FLAGS) $(PY_PROGRAMS) - -$(RUFF) $(RUFF_FLAGS) $(PY_PROGRAMS) + $(MAKE) -k lint-py-pylint lint-py-ruff + +lint-py-pylint: + $(PYLINT) $(PYLINT_FLAGS) $(PY_PROGRAMS) + +lint-py-ruff: + $(RUFF) $(RUFF_FLAGS) $(PY_PROGRAMS) format-pl-exec: -chmod a+x test_regress/t/*.pl diff --git a/README.rst b/README.rst index 2c3d98961..d6fed5975 100644 --- a/README.rst +++ b/README.rst @@ -150,7 +150,7 @@ the terms of either the GNU Lesser General Public License Version 3 or the Perl Artistic License Version 2.0. See the documentation for more details. .. _CHIPS Alliance: https://chipsalliance.org -.. _Icarus Verilog: http://iverilog.icarus.com +.. _Icarus Verilog: https://steveicarus.github.io/iverilog .. _Linux Foundation: https://www.linuxfoundation.org .. |Logo| image:: https://www.veripool.org/img/verilator_256_200_min.png .. |verilator multithreaded performance| image:: https://www.veripool.org/img/verilator_multithreaded_performance_bg-min.png diff --git a/bin/verilator_gantt b/bin/verilator_gantt index 0015cb57f..60814b209 100755 --- a/bin/verilator_gantt +++ b/bin/verilator_gantt @@ -1,33 +1,32 @@ #!/usr/bin/env python3 -# pylint: disable=C0103,C0114,C0116,C0209,C0301,R0914,R0912,R0915,W0511,eval-used +# pylint: disable=C0103,C0114,C0116,C0209,C0301,R0914,R0912,R0915,W0511,W0603,eval-used ###################################################################### import argparse +import bisect import collections import math import re import statistics # from pprint import pprint -Threads = collections.defaultdict(lambda: collections.defaultdict(lambda: {})) -Mtasks = collections.defaultdict(lambda: {}) -Evals = collections.defaultdict(lambda: {}) -EvalLoops = collections.defaultdict(lambda: {}) +Sections = [] +LongestVcdStrValueLength = 0 +Threads = collections.defaultdict(lambda: []) # List of records per thread id +Mtasks = collections.defaultdict(lambda: {'elapsed': 0, 'end': 0}) +Cpus = collections.defaultdict(lambda: {'mtask_time': 0}) Global = { 'args': {}, 'cpuinfo': collections.defaultdict(lambda: {}), - 'rdtsc_cycle_time': 0, 'stats': {} } +ElapsedTime = None # total elapsed time +ExecGraphTime = 0 # total elapsed time excuting an exec graph +ExecGraphIntervals = [] # list of (start, end) pairs ###################################################################### -def process(filename): - read_data(filename) - report() - - def read_data(filename): with open(filename, "r", encoding="utf8") as fh: re_thread = re.compile(r'^VLPROFTHREAD (\d+)$') @@ -39,14 +38,17 @@ def read_data(filename): re_arg1 = re.compile(r'VLPROF arg\s+(\S+)\+([0-9.]*)\s*') re_arg2 = re.compile(r'VLPROF arg\s+(\S+)\s+([0-9.]*)\s*$') re_stat = re.compile(r'VLPROF stat\s+(\S+)\s+([0-9.]+)') - re_time = re.compile(r'rdtsc time = (\d+) ticks') re_proc_cpu = re.compile(r'VLPROFPROC processor\s*:\s*(\d+)\s*$') re_proc_dat = re.compile(r'VLPROFPROC ([a-z_ ]+)\s*:\s*(.*)$') cpu = None thread = None + execGraphStart = None - lastEvalBeginTick = None - lastEvalLoopBeginTick = None + global LongestVcdStrValueLength + global ExecGraphTime + + SectionStack = [] + mTaskThread = {} for line in fh: recordMatch = re_record.match(line) @@ -54,29 +56,31 @@ def read_data(filename): kind, tick, payload = recordMatch.groups() tick = int(tick) payload = payload.strip() - if kind == "EVAL_BEGIN": - Evals[tick]['start'] = tick - lastEvalBeginTick = tick - elif kind == "EVAL_END": - Evals[lastEvalBeginTick]['end'] = tick - lastEvalBeginTick = None - elif kind == "EVAL_LOOP_BEGIN": - EvalLoops[tick]['start'] = tick - lastEvalLoopBeginTick = tick - elif kind == "EVAL_LOOP_END": - EvalLoops[lastEvalLoopBeginTick]['end'] = tick - lastEvalLoopBeginTick = None + if kind == "SECTION_PUSH": + LongestVcdStrValueLength = max(LongestVcdStrValueLength, + len(payload)) + SectionStack.append(payload) + Sections.append((tick, tuple(SectionStack))) + elif kind == "SECTION_POP": + assert SectionStack, "SECTION_POP without SECTION_PUSH" + SectionStack.pop() + Sections.append((tick, tuple(SectionStack))) elif kind == "MTASK_BEGIN": mtask, predict_start, ecpu = re_payload_mtaskBegin.match( payload).groups() mtask = int(mtask) predict_start = int(predict_start) ecpu = int(ecpu) - Threads[thread][tick]['mtask'] = mtask - Threads[thread][tick]['predict_start'] = predict_start - Threads[thread][tick]['cpu'] = ecpu - if 'elapsed' not in Mtasks[mtask]: - Mtasks[mtask] = {'end': 0, 'elapsed': 0} + mTaskThread[mtask] = thread + records = Threads[thread] + assert not records or records[-1]['start'] <= records[-1][ + 'end'] <= tick + records.append({ + 'start': tick, + 'mtask': mtask, + 'predict_start': predict_start, + 'cpu': ecpu + }) Mtasks[mtask]['begin'] = tick Mtasks[mtask]['thread'] = thread Mtasks[mtask]['predict_start'] = predict_start @@ -86,11 +90,18 @@ def read_data(filename): mtask = int(mtask) predict_cost = int(predict_cost) begin = Mtasks[mtask]['begin'] - Threads[thread][begin]['end'] = tick - Threads[thread][begin]['predict_cost'] = predict_cost + record = Threads[mTaskThread[mtask]][-1] + record['end'] = tick + record['predict_cost'] = predict_cost Mtasks[mtask]['elapsed'] += tick - begin Mtasks[mtask]['predict_cost'] = predict_cost Mtasks[mtask]['end'] = max(Mtasks[mtask]['end'], tick) + elif kind == "EXEC_GRAPH_BEGIN": + execGraphStart = tick + elif kind == "EXEC_GRAPH_END": + ExecGraphTime += tick - execGraphStart + ExecGraphIntervals.append((execGraphStart, tick)) + execGraphStart = None elif Args.debug: print("-Unknown execution trace record: %s" % line) elif re_thread.match(line): @@ -109,7 +120,7 @@ def read_data(filename): elif re_proc_cpu.match(line): match = re_proc_cpu.match(line) cpu = int(match.group(1)) - elif cpu and re_proc_dat.match(line): + elif cpu is not None and re_proc_dat.match(line): match = re_proc_dat.match(line) term = match.group(1) value = match.group(2) @@ -121,11 +132,6 @@ def read_data(filename): pass elif Args.debug: print("-Unk: %s" % line) - # TODO -- this is parsing text printed by a client. - # Really, verilator proper should generate this - # if it's useful... - if re_time.match(line): - Global['rdtsc_cycle_time'] = re_time.group(1) def re_match_result(regexp, line, result_to): @@ -144,125 +150,33 @@ def report(): plus = "+" if re.match(r'^\+', arg) else " " print(" %s%s%s" % (arg, plus, Global['args'][arg])) + for records in Threads.values(): + for record in records: + cpu = record['cpu'] + elapsed = record['end'] - record['start'] + Cpus[cpu]['mtask_time'] += elapsed + + global ElapsedTime + ElapsedTime = int(Global['stats']['ticks']) nthreads = int(Global['stats']['threads']) - Global['cpus'] = {} - for thread in Threads: - # Make potentially multiple characters per column - for start in Threads[thread]: - if not Threads[thread][start]: - continue - cpu = Threads[thread][start]['cpu'] - elapsed = Threads[thread][start]['end'] - start - if cpu not in Global['cpus']: - Global['cpus'][cpu] = {'cpu_time': 0} - Global['cpus'][cpu]['cpu_time'] += elapsed + ncpus = max(len(Cpus), 1) - measured_mt_mtask_time = 0 - predict_mt_mtask_time = 0 - long_mtask_time = 0 - measured_last_end = 0 - predict_last_end = 0 - for mtask in Mtasks: - measured_mt_mtask_time += Mtasks[mtask]['elapsed'] - predict_mt_mtask_time += Mtasks[mtask]['predict_cost'] - measured_last_end = max(measured_last_end, Mtasks[mtask]['end']) - predict_last_end = max( - predict_last_end, - Mtasks[mtask]['predict_start'] + Mtasks[mtask]['predict_cost']) - long_mtask_time = max(long_mtask_time, Mtasks[mtask]['elapsed']) - Global['measured_last_end'] = measured_last_end - Global['predict_last_end'] = predict_last_end - - # If we know cycle time in the same (rdtsc) units, - # this will give us an actual utilization number, - # (how effectively we keep the cores busy.) - # - # It also gives us a number we can compare against - # serial mode, to estimate the overhead of data sharing, - # which will show up in the total elapsed time. (Overhead - # of synchronization and scheduling should not.) - print("\nAnalysis:") - print(" Total threads = %d" % nthreads) - print(" Total mtasks = %d" % len(Mtasks)) - ncpus = max(len(Global['cpus']), 1) - print(" Total cpus used = %d" % ncpus) - print(" Total yields = %d" % - int(Global['stats'].get('yields', 0))) - print(" Total evals = %d" % len(Evals)) - print(" Total eval loops = %d" % len(EvalLoops)) - if Mtasks: - print(" Total eval time = %d rdtsc ticks" % - Global['measured_last_end']) - print(" Longest mtask time = %d rdtsc ticks" % long_mtask_time) - print(" All-thread mtask time = %d rdtsc ticks" % - measured_mt_mtask_time) - long_efficiency = long_mtask_time / (Global.get( - 'measured_last_end', 1) or 1) - print(" Longest-thread efficiency = %0.1f%%" % - (long_efficiency * 100.0)) - mt_efficiency = measured_mt_mtask_time / ( - Global.get('measured_last_end', 1) * nthreads or 1) - print(" All-thread efficiency = %0.1f%%" % - (mt_efficiency * 100.0)) - print(" All-thread speedup = %0.1f" % - (mt_efficiency * nthreads)) - if Global['rdtsc_cycle_time'] > 0: - ut = measured_mt_mtask_time / Global['rdtsc_cycle_time'] - print("tot_mtask_cpu=" + measured_mt_mtask_time + " cyc=" + - Global['rdtsc_cycle_time'] + " ut=" + ut) - - predict_mt_efficiency = predict_mt_mtask_time / ( - Global.get('predict_last_end', 1) * nthreads or 1) - print("\nPrediction (what Verilator used for scheduling):") - print(" All-thread efficiency = %0.1f%%" % - (predict_mt_efficiency * 100.0)) - print(" All-thread speedup = %0.1f" % - (predict_mt_efficiency * nthreads)) - - p2e_ratios = [] - min_p2e = 1000000 - min_mtask = None - max_p2e = -1000000 - max_mtask = None - - for mtask in sorted(Mtasks.keys()): - if Mtasks[mtask]['elapsed'] > 0: - if Mtasks[mtask]['predict_cost'] == 0: - Mtasks[mtask]['predict_cost'] = 1 # don't log(0) below - p2e_ratio = math.log(Mtasks[mtask]['predict_cost'] / - Mtasks[mtask]['elapsed']) - p2e_ratios.append(p2e_ratio) - - if p2e_ratio > max_p2e: - max_p2e = p2e_ratio - max_mtask = mtask - if p2e_ratio < min_p2e: - min_p2e = p2e_ratio - min_mtask = mtask - - print("\nMTask statistics:") - print(" min log(p2e) = %0.3f" % min_p2e, end="") - print(" from mtask %d (predict %d," % - (min_mtask, Mtasks[min_mtask]['predict_cost']), - end="") - print(" elapsed %d)" % Mtasks[min_mtask]['elapsed']) - print(" max log(p2e) = %0.3f" % max_p2e, end="") - print(" from mtask %d (predict %d," % - (max_mtask, Mtasks[max_mtask]['predict_cost']), - end="") - print(" elapsed %d)" % Mtasks[max_mtask]['elapsed']) - - stddev = statistics.pstdev(p2e_ratios) - mean = statistics.mean(p2e_ratios) - print(" mean = %0.3f" % mean) - print(" stddev = %0.3f" % stddev) - print(" e ^ stddev = %0.3f" % math.exp(stddev)) + print("\nSummary:") + print(" Total elapsed time = {} rdtsc ticks".format(ElapsedTime)) + print(" Parallelized code = {:.2%} of elapsed time".format( + ExecGraphTime / ElapsedTime)) + print(" Total threads = %d" % nthreads) + print(" Total CPUs used = %d" % ncpus) + print(" Total mtasks = %d" % len(Mtasks)) + print(" Total yields = %d" % int(Global['stats'].get('yields', 0))) + report_mtasks() report_cpus() + report_sections() if nthreads > ncpus: print() - print("%%Warning: There were fewer CPUs (%d) then threads (%d)." % + print("%%Warning: There were fewer CPUs (%d) than threads (%d)." % (ncpus, nthreads)) print(" : See docs on use of numactl.") else: @@ -279,32 +193,130 @@ def report(): print() +def report_mtasks(): + if not Mtasks: + return + + nthreads = int(Global['stats']['threads']) + + # If we know cycle time in the same (rdtsc) units, + # this will give us an actual utilization number, + # (how effectively we keep the cores busy.) + # + # It also gives us a number we can compare against + # serial mode, to estimate the overhead of data sharing, + # which will show up in the total elapsed time. (Overhead + # of synchronization and scheduling should not.) + total_mtask_time = 0 + thread_mtask_time = collections.defaultdict(lambda: 0) + long_mtask_time = 0 + long_mtask = None + predict_mtask_time = 0 + predict_elapsed = 0 + for mtaskId in Mtasks: + record = Mtasks[mtaskId] + predict_mtask_time += record['predict_cost'] + total_mtask_time += record['elapsed'] + thread_mtask_time[record['thread']] += record['elapsed'] + predict_end = record['predict_start'] + record['predict_cost'] + predict_elapsed = max(predict_elapsed, predict_end) + if record['elapsed'] > long_mtask_time: + long_mtask_time = record['elapsed'] + long_mtask = mtaskId + Global['predict_last_end'] = predict_elapsed + + serialTime = ElapsedTime - ExecGraphTime + + def subReport(elapsed, work): + print(" Thread utilization = {:7.2%}".format(work / + (elapsed * nthreads))) + print(" Speedup = {:6.3}x".format(work / elapsed)) + + print("\nParallelized code, measured:") + subReport(ExecGraphTime, total_mtask_time) + + print("\nParallelized code, predicted during static scheduling:") + subReport(predict_elapsed, predict_mtask_time) + + print("\nAll code, measured:") + subReport(ElapsedTime, serialTime + total_mtask_time) + + print("\nAll code, measured, scaled by predicted speedup:") + expectedParallelSpeedup = predict_mtask_time / predict_elapsed + scaledElapsed = serialTime + total_mtask_time / expectedParallelSpeedup + subReport(scaledElapsed, serialTime + total_mtask_time) + + p2e_ratios = [] + min_p2e = 1000000 + min_mtask = None + max_p2e = -1000000 + max_mtask = None + + for mtask in sorted(Mtasks.keys()): + if Mtasks[mtask]['elapsed'] > 0: + if Mtasks[mtask]['predict_cost'] == 0: + Mtasks[mtask]['predict_cost'] = 1 # don't log(0) below + p2e_ratio = math.log(Mtasks[mtask]['predict_cost'] / + Mtasks[mtask]['elapsed']) + p2e_ratios.append(p2e_ratio) + + if p2e_ratio > max_p2e: + max_p2e = p2e_ratio + max_mtask = mtask + if p2e_ratio < min_p2e: + min_p2e = p2e_ratio + min_mtask = mtask + + print("\nMTask statistics:") + print(" Longest mtask id = {}".format(long_mtask)) + print(" Longest mtask time = {:.2%} of time elapsed in parallelized code". + format(long_mtask_time / ExecGraphTime)) + print(" min log(p2e) = %0.3f" % min_p2e, end="") + + print(" from mtask %d (predict %d," % + (min_mtask, Mtasks[min_mtask]['predict_cost']), + end="") + print(" elapsed %d)" % Mtasks[min_mtask]['elapsed']) + print(" max log(p2e) = %0.3f" % max_p2e, end="") + print(" from mtask %d (predict %d," % + (max_mtask, Mtasks[max_mtask]['predict_cost']), + end="") + print(" elapsed %d)" % Mtasks[max_mtask]['elapsed']) + + stddev = statistics.pstdev(p2e_ratios) + mean = statistics.mean(p2e_ratios) + print(" mean = %0.3f" % mean) + print(" stddev = %0.3f" % stddev) + print(" e ^ stddev = %0.3f" % math.exp(stddev)) + + def report_cpus(): - print("\nCPUs:") + print("\nCPU info:") Global['cpu_sockets'] = collections.defaultdict(lambda: 0) Global['cpu_socket_cores'] = collections.defaultdict(lambda: 0) - for cpu in sorted(Global['cpus'].keys()): - print(" cpu %d: " % cpu, end='') - print("cpu_time=%d" % Global['cpus'][cpu]['cpu_time'], end='') - - socket = None + print(" Id | Time spent executing MTask | Socket | Core | Model") + print(" | % of elapsed ticks / ticks | | |") + print(" ====|============================|========|======|======") + for cpu in sorted(Cpus): + socket = "" + core = "" + model = "" if cpu in Global['cpuinfo']: cpuinfo = Global['cpuinfo'][cpu] if 'physical_id' in cpuinfo and 'core_id' in cpuinfo: - socket = int(cpuinfo['physical_id']) + socket = cpuinfo['physical_id'] Global['cpu_sockets'][socket] += 1 - print(" socket=%d" % socket, end='') - - core = int(cpuinfo['core_id']) - Global['cpu_socket_cores'][str(socket) + "__" + str(core)] += 1 - print(" core=%d" % core, end='') + core = cpuinfo['core_id'] + Global['cpu_socket_cores'][socket + "__" + core] += 1 if 'model_name' in cpuinfo: model = cpuinfo['model_name'] - print(" %s" % model, end='') - print() + + print(" {:3d} | {:7.2%} / {:16d} | {:>6s} | {:>4s} | {}".format( + cpu, Cpus[cpu]['mtask_time'] / ElapsedTime, + Cpus[cpu]['mtask_time'], socket, core, model)) if len(Global['cpu_sockets']) > 1: Global['cpu_sockets_warning'] = True @@ -313,25 +325,68 @@ def report_cpus(): Global['cpu_socket_cores_warning'] = True +def report_sections(): + if not Sections: + return + print("\nSection profile:") + + totalTime = collections.defaultdict(lambda: 0) + selfTime = collections.defaultdict(lambda: 0) + + sectionTree = [0, {}, 1] # [selfTime, childTrees, numberOfTimesEntered] + prevTime = 0 + prevStack = () + for time, stack in Sections: + if len(stack) > len(prevStack): + scope = sectionTree + for item in stack: + scope = scope[1].setdefault(item, [0, {}, 0]) + scope[2] += 1 + dt = time - prevTime + scope = sectionTree + for item in prevStack: + scope = scope[1].setdefault(item, [0, {}, 0]) + scope[0] += dt + + if prevStack: + for name in prevStack: + totalTime[name] += dt + selfTime[prevStack[-1]] += dt + prevTime = time + prevStack = stack + + def treeSum(tree): + n = tree[0] + for subTree in tree[1].values(): + n += treeSum(subTree) + return n + + # Make sure the tree sums to the elapsed time + sectionTree[0] += ElapsedTime - treeSum(sectionTree) + + def printTree(prefix, name, entries, tree): + print(" {:7.2%} | {:7.2%} | {:8} | {:10.2f} | {}".format( + treeSum(tree) / ElapsedTime, tree[0] / ElapsedTime, tree[2], + tree[2] / entries, prefix + name)) + for k in sorted(tree[1], key=lambda _: -treeSum(tree[1][_])): + printTree(prefix + " ", k, tree[2], tree[1][k]) + + print(" Total | Self | Total | Relative | Section") + print(" time | time | entries | entries | name ") + print("==========|=========|==========|============|========") + printTree("", "*TOTAL*", 1, sectionTree) + + ###################################################################### def write_vcd(filename): print("Writing %s" % filename) with open(filename, "w", encoding="utf8") as fh: - vcd = { - 'values': - collections.defaultdict(lambda: {}), # {