Add logger highlighting inefficient allocation and copy patterns #1035

upsj · 2022-04-27T16:08:41Z

Above a certain size threshold, we log

Repeated allocations/deallocations of the same size
Repeated cross-executor copies from/to the same data

We count how often these events take place and output messages at counts equal to powers of 10.

Closes #804

upsj · 2022-04-27T16:10:37Z

format-rebase!

ginkgo-bot · 2022-04-27T16:12:11Z

Formatting rebase introduced changes, see Artifacts here to review them

include/ginkgo/core/log/performance_hint.hpp

yhmtsai · 2022-04-28T09:32:39Z

include/ginkgo/core/log/stream.hpp

-    std::ostream& os_;
+    std::ostream* os_;


is any consideration here?

yes, reference members are a bad idea in general, because every assignment to the object gets passed through to the member, since the reference can't be reassigned.

pratikvn

A minor comment on having the type of executor info displayed as well. Otherwise looks really good!

pratikvn · 2022-04-28T09:37:29Z

core/log/performance_hint.cpp

+        const auto count1 = ++copy_src_histogram_[location_from];
+        const auto count2 = ++copy_dst_histogram_[location_to];
+        if (should_log_count(count1)) {
+            print_copy_from_message(log(), location_from, count1);


I think it might be useful to also print the executor type ? Might be a bit ugly to do dynamic casts to all the concrete executor types, but I think that might be useful information.

This might also be a time to add a get executor string method to the base Executor class and have the concrete classes store and return the names.

name_demangling should work there :)

actually it doesn't work too well, since I don't keep the information which allocator a pointer is associated with, and this doesn't work with print_status. Storing the executor would work for copies, but not for allocations.

But you do have the from and to executors available in the function, that you can propagate to the print functions ?

they are no longer available in the print_status function though, which is the only issue here

include/ginkgo/core/log/performance_hint.hpp

include/ginkgo/core/log/stream.hpp

sonarqubecloud · 2022-04-28T16:38:01Z

Kudos, SonarCloud Quality Gate passed!

0 Bugs
0 Vulnerabilities
0 Security Hotspots
8 Code Smells

91.7% Coverage
4.0% Duplication

codecov · 2022-04-28T16:43:57Z

Codecov Report

Merging #1035 (8555622) into develop (6873586) will increase coverage by 0.57%.
The diff coverage is 92.11%.

❗ Current head 8555622 differs from pull request most recent head 75b2557. Consider uploading reports for the commit 75b2557 to get more accurate results

@@             Coverage Diff             @@
##           develop    #1035      +/-   ##
===========================================
+ Coverage    91.66%   92.24%   +0.57%     
===========================================
  Files          499      498       -1     
  Lines        43010    41891    -1119     
===========================================
- Hits         39426    38641     -785     
+ Misses        3584     3250     -334

Impacted Files	Coverage Δ
include/ginkgo/core/log/logger.hpp	`85.10% <ø> (-10.64%)`	⬇️
include/ginkgo/core/base/executor.hpp	`73.07% <80.00%> (-0.06%)`	⬇️
core/log/stream.cpp	`88.88% <84.82%> (ø)`
core/log/performance_hint.cpp	`95.58% <95.58%> (ø)`
core/test/log/performance_hint.cpp	`100.00% <100.00%> (ø)`
include/ginkgo/core/log/performance_hint.hpp	`100.00% <100.00%> (ø)`
include/ginkgo/core/log/stream.hpp	`100.00% <100.00%> (+50.00%)`	⬆️
common/unified/matrix/csr_kernels.cpp	`32.55% <0.00%> (-19.75%)`	⬇️
include/ginkgo/core/base/abstract_factory.hpp	`87.09% <0.00%> (-12.91%)`	⬇️
... and 91 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 6873586...75b2557. Read the comment docs.

fritzgoebel

LGTM

include/ginkgo/core/log/logger.hpp

yhmtsai

LGTM in general. With record logger, we should be able to notice where to give the message.
one nit: the count based on size may be from different sources, but I have no idea how to deal with it by the current interface. It may be good enough in the current case thuogh.

core/log/performance_hint.cpp

yhmtsai · 2022-06-20T11:37:46Z

core/log/performance_hint.cpp

+void print_copy_to_message(std::ostream& stream, gko::uintptr ptr, int count)
+{
+    stream << "Observed " << count << " cross-executor copies to "
+           << location_name(ptr)
+           << " that may point to unnecessary data transfers.\n";
+}


do we only record copy_from? the copy_to(A, B) call copy_from(B, A);

we record both, since the logger is likely only attached to one of the two executors involved

yhmtsai · 2022-06-20T11:43:57Z

core/log/performance_hint.cpp

+                                        const uintptr& location_to,
+                                        const size_type& num_bytes) const
+{
+    if (num_bytes > copy_size_limit_ && from != to) {


Suggested change

if (num_bytes > copy_size_limit_ && from != to) {

if (num_bytes > copy_size_limit_ && !from->memory_accessible(to)) {

but need to add memory_acceible(const Executor*) interface

if memory is accessible between the two executors, there should be no copy at all, shouldn't it? So warning about it still seems like the right thing to do.

yhmtsai · 2022-06-20T11:55:41Z

core/test/log/performance_hint.cpp

+    // by now we have forgotten the first allocation.
+    while (!data.empty()) {
+        data.pop_back();
+    }


what's the meaning here?
I thought pop_back also destroys the element

yes, that is intended behavior: We first create 10 entries, and then destroy them in the reverse order, meaning the first element to be created (last to be destroyed) will no longer be part of the logger's allocation_sizes_ history.

include/ginkgo/core/log/performance_hint.hpp

yhmtsai · 2022-06-20T13:45:42Z

core/log/performance_hint.cpp

+    if (it != allocation_sizes_.end()) {
+        const auto size = it->second;
+        allocation_sizes_.erase(it);
+        const auto count = ++allocation_histogram_[size];


size count may be from different sources.

yes, that is the best we can do with the available information, unless we start inspecting backtraces (for which there is no portable API yet)

pratikvn

Should be very useful! Thanks for adding this. LGTM!

pratikvn · 2022-06-24T09:12:04Z

core/log/performance_hint.cpp

+        const auto count1 = ++copy_src_histogram_[location_from];
+        const auto count2 = ++copy_dst_histogram_[location_to];
+        if (should_log_count(count1)) {
+            print_copy_from_message(log(), location_from, count1);


But you do have the from and to executors available in the function, that you can propagate to the print functions ?

pratikvn · 2022-06-24T09:18:54Z

core/log/performance_hint.cpp

+        }
+    }
+    for (auto entry : copy_src_histogram_) {
+        if (entry.second >= 10) {


Maybe it makes sense to print only for the largest count, instead of printing for every count that we track ?

that may hide some issues, with people having to discover them step by step, instead of seeing all of them in a single spot?

Right now, lets say the count is 110, and the limit set is 120, then it would print:

[PERFORMANCE] >>> Observed 10 allocate-free pairs of size x that may point to unnecessary allocations. [PERFORMANCE] >>> Observed 100 allocate-free pairs of size x that may point to unnecessary allocations.

I feel this is a bit more confusing, than if it was just

[PERFORMANCE] >>> Observed 100 allocate-free pairs of size x that may point to unnecessary allocations.

which is what I think the user would expect, when they set the limit to 120

I don't follow. The histogram contains only a single count for each size, so the output of print_status() would be

[PERFORMANCE] >>> Observed 110 allocate-free pairs of size x that may point to unnecessary allocations.

Okay, maybe I misunderstood something. What I mean is something like here

That is independent of print_status(): The output you're seeing is immediate after the allocation took place, thus if the application has its own status output, the interspersed logger messages will allow users to see where this unnecessary allocation took place. print_status() is meant more as a tool to print a summary at the end.

* Repeated allocations/deallocations of the same size * Repeated cross-executor copies from/to the same data

ginkgo-bot · 2022-06-24T16:15:55Z

Note: This PR changes the Ginkgo ABI:

Functions changes summary: 4 Removed, 4 Changed (32 filtered out), 451 Added functions
Variables changes summary: 0 Removed, 0 Changed, 1 Added variable

For details check the full ABI diff under Artifacts here

sonarqubecloud · 2022-06-24T20:11:13Z

Kudos, SonarCloud Quality Gate passed!

0 Bugs
0 Vulnerabilities
0 Security Hotspots
6 Code Smells

91.7% Coverage
4.1% Duplication

Advertise release 1.5.0 and last changes + Add changelog, + Update third party libraries + A small fix to a CMake file See PR: #1195 The Ginkgo team is proud to announce the new Ginkgo minor release 1.5.0. This release brings many important new features such as: - MPI-based multi-node support for all matrix formats and most solvers; - full DPC++/SYCL support, - functionality and interface for GPU-resident sparse direct solvers, - an interface for wrapping solvers with scaling and reordering applied, - a new algebraic Multigrid solver/preconditioner, - improved mixed-precision support, - support for device matrix assembly, and much more. If you face an issue, please first check our [known issues page](https://github.com/ginkgo-project/ginkgo/wiki/Known-Issues) and the [open issues list](https://github.com/ginkgo-project/ginkgo/issues) and if you do not find a solution, feel free to [open a new issue](https://github.com/ginkgo-project/ginkgo/issues/new/choose) or ask a question using the [github discussions](https://github.com/ginkgo-project/ginkgo/discussions). Supported systems and requirements: + For all platforms, CMake 3.13+ + C++14 compliant compiler + Linux and macOS + GCC: 5.5+ + clang: 3.9+ + Intel compiler: 2018+ + Apple LLVM: 8.0+ + NVHPC: 22.7+ + Cray Compiler: 14.0.1+ + CUDA module: CUDA 9.2+ or NVHPC 22.7+ + HIP module: ROCm 4.0+ + DPC++ module: Intel OneAPI 2021.3 with oneMKL and oneDPL. Set the CXX compiler to `dpcpp`. + Windows + MinGW and Cygwin: GCC 5.5+ + Microsoft Visual Studio: VS 2019 + CUDA module: CUDA 9.2+, Microsoft Visual Studio + OpenMP module: MinGW or Cygwin. Algorithm and important feature additions: + Add MPI-based multi-node for all matrix formats and solvers (except GMRES and IDR). ([#676](#676), [#908](#908), [#909](#909), [#932](#932), [#951](#951), [#961](#961), [#971](#971), [#976](#976), [#985](#985), [#1007](#1007), [#1030](#1030), [#1054](#1054), [#1100](#1100), [#1148](#1148)) + Porting the remaining algorithms (preconditioners like ISAI, Jacobi, Multigrid, ParILU(T) and ParIC(T)) to DPC++/SYCL, update to SYCL 2020, and improve support and performance ([#896](#896), [#924](#924), [#928](#928), [#929](#929), [#933](#933), [#943](#943), [#960](#960), [#1057](#1057), [#1110](#1110), [#1142](#1142)) + Add a Sparse Direct interface supporting GPU-resident numerical LU factorization, symbolic Cholesky factorization, improved triangular solvers, and more ([#957](#957), [#1058](#1058), [#1072](#1072), [#1082](#1082)) + Add a ScaleReordered interface that can wrap solvers and automatically apply reorderings and scalings ([#1059](#1059)) + Add a Multigrid solver and improve the aggregation based PGM coarsening scheme ([#542](#542), [#913](#913), [#980](#980), [#982](#982), [#986](#986)) + Add infrastructure for unified, lambda-based, backend agnostic, kernels and utilize it for some simple kernels ([#833](#833), [#910](#910), [#926](#926)) + Merge different CUDA, HIP, DPC++ and OpenMP tests under a common interface ([#904](#904), [#973](#973), [#1044](#1044), [#1117](#1117)) + Add a device_matrix_data type for device-side matrix assembly ([#886](#886), [#963](#963), [#965](#965)) + Add support for mixed real/complex BLAS operations ([#864](#864)) + Add a FFT LinOp for all but DPC++/SYCL ([#701](#701)) + Add FBCSR support for NVIDIA and AMD GPUs and CPUs with OpenMP ([#775](#775)) + Add CSR scaling ([#848](#848)) + Add array::const_view and equivalent to create constant matrices from non-const data ([#890](#890)) + Add a RowGatherer LinOp supporting mixed precision to gather dense matrix rows ([#901](#901)) + Add mixed precision SparsityCsr SpMV support ([#970](#970)) + Allow creating CSR submatrix including from (possibly discontinuous) index sets ([#885](#885), [#964](#964)) + Add a scaled identity addition (M <- aI + bM) feature interface and impls for Csr and Dense ([#942](#942)) Deprecations and important changes: + Deprecate AmgxPgm in favor of the new Pgm name. ([#1149](#1149)). + Deprecate specialized residual norm classes in favor of a common `ResidualNorm` class ([#1101](#1101)) + Deprecate CamelCase non-polymorphic types in favor of snake_case versions (like array, machine_topology, uninitialized_array, index_set) ([#1031](#1031), [#1052](#1052)) + Bug fix: restrict gko::share to rvalue references (*possible interface break*) ([#1020](#1020)) + Bug fix: when using cuSPARSE's triangular solvers, specifying the factory parameter `num_rhs` is now required when solving for more than one right-hand side, otherwise an exception is thrown ([#1184](#1184)). + Drop official support for old CUDA < 9.2 ([#887](#887)) Improved performance additions: + Reuse tmp storage in reductions in solvers and add a mutable workspace to all solvers ([#1013](#1013), [#1028](#1028)) + Add HIP unsafe atomic option for AMD ([#1091](#1091)) + Prefer vendor implementations for Dense dot, conj_dot and norm2 when available ([#967](#967)). + Tuned OpenMP SellP, COO, and ELL SpMV kernels for a small number of RHS ([#809](#809)) Fixes: + Fix various compilation warnings ([#1076](#1076), [#1183](#1183), [#1189](#1189)) + Fix issues with hwloc-related tests ([#1074](#1074)) + Fix include headers for GCC 12 ([#1071](#1071)) + Fix for simple-solver-logging example ([#1066](#1066)) + Fix for potential memory leak in Logger ([#1056](#1056)) + Fix logging of mixin classes ([#1037](#1037)) + Improve value semantics for LinOp types, like moved-from state in cross-executor copy/clones ([#753](#753)) + Fix some matrix SpMV and conversion corner cases ([#905](#905), [#978](#978)) + Fix uninitialized data ([#958](#958)) + Fix CUDA version requirement for cusparseSpSM ([#953](#953)) + Fix several issues within bash-script ([#1016](#1016)) + Fixes for `NVHPC` compiler support ([#1194](#1194)) Other additions: + Simplify and properly name GMRES kernels ([#861](#861)) + Improve pkg-config support for non-CMake libraries ([#923](#923), [#1109](#1109)) + Improve gdb pretty printer ([#987](#987), [#1114](#1114)) + Add a logger highlighting inefficient allocation and copy patterns ([#1035](#1035)) + Improved and optimized test random matrix generation ([#954](#954), [#1032](#1032)) + Better CSR strategy defaults ([#969](#969)) + Add `move_from` to `PolymorphicObject` ([#997](#997)) + Remove unnecessary device_guard usage ([#956](#956)) + Improvements to the generic accessor for mixed-precision ([#727](#727)) + Add a naive lower triangular solver implementation for CUDA ([#764](#764)) + Add support for int64 indices from CUDA 11 onward with SpMV and SpGEMM ([#897](#897)) + Add a L1 norm implementation ([#900](#900)) + Add reduce_add for arrays ([#831](#831)) + Add utility to simplify Dense View creation from an existing Dense vector ([#1136](#1136)). + Add a custom transpose implementation for Fbcsr and Csr transpose for unsupported vendor types ([#1123](#1123)) + Make IDR random initilization deterministic ([#1116](#1116)) + Move the algorithm choice for triangular solvers from Csr::strategy_type to a factory parameter ([#1088](#1088)) + Update CUDA archCoresPerSM ([#1175](#1116)) + Add kernels for Csr sparsity pattern lookup ([#994](#994)) + Differentiate between structural and numerical zeros in Ell/Sellp ([#1027](#1027)) + Add a binary IO format for matrix data ([#984](#984)) + Add a tuple zip_iterator implementation ([#966](#966)) + Simplify kernel stubs and declarations ([#888](#888)) + Simplify GKO_REGISTER_OPERATION with lambdas ([#859](#859)) + Simplify copy to device in tests and examples ([#863](#863)) + More verbose output to array assertions ([#858](#858)) + Allow parallel compilation for Jacobi kernels ([#871](#871)) + Change clang-format pointer alignment to left ([#872](#872)) + Various improvements and fixes to the benchmarking framework ([#750](#750), [#759](#759), [#870](#870), [#911](#911), [#1033](#1033), [#1137](#1137)) + Various documentation improvements ([#892](#892), [#921](#921), [#950](#950), [#977](#977), [#1021](#1021), [#1068](#1068), [#1069](#1069), [#1080](#1080), [#1081](#1081), [#1108](#1108), [#1153](#1153), [#1154](#1154)) + Various CI improvements ([#868](#868), [#874](#874), [#884](#884), [#889](#889), [#899](#899), [#903](#903), [#922](#922), [#925](#925), [#930](#930), [#936](#936), [#937](#937), [#958](#958), [#882](#882), [#1011](#1011), [#1015](#1015), [#989](#989), [#1039](#1039), [#1042](#1042), [#1067](#1067), [#1073](#1073), [#1075](#1075), [#1083](#1083), [#1084](#1084), [#1085](#1085), [#1139](#1139), [#1178](#1178), [#1187](#1187))

upsj added the 1:ST:ready-for-review This PR is ready for review label Apr 27, 2022

upsj added this to the Ginkgo 1.5.0 milestone Apr 27, 2022

upsj requested a review from a team April 27, 2022 16:08

upsj self-assigned this Apr 27, 2022

ginkgo-bot added mod:core This is related to the core module. reg:build This is related to the build system. reg:testing This is related to testing. labels Apr 27, 2022

upsj requested a review from pratikvn April 27, 2022 16:09

ginkgo-bot force-pushed the performance_hint_logger branch from 618a165 to ca47038 Compare April 27, 2022 16:12

upsj force-pushed the performance_hint_logger branch 2 times, most recently from 74d6d73 to 8555622 Compare April 28, 2022 08:17

MarcelKoch reviewed Apr 28, 2022

View reviewed changes

include/ginkgo/core/log/performance_hint.hpp Show resolved Hide resolved

yhmtsai reviewed Apr 28, 2022

View reviewed changes

pratikvn reviewed Apr 28, 2022

View reviewed changes

upsj requested a review from fritzgoebel May 9, 2022 09:29

fritzgoebel approved these changes May 24, 2022

View reviewed changes

include/ginkgo/core/log/logger.hpp Outdated Show resolved Hide resolved

MarcelKoch self-requested a review June 2, 2022 12:01

yhmtsai approved these changes Jun 20, 2022

View reviewed changes

upsj force-pushed the performance_hint_logger branch from 8555622 to de2d4b7 Compare June 24, 2022 07:16

upsj added 1:ST:ready-to-merge This PR is ready to merge. and removed 1:ST:ready-for-review This PR is ready for review labels Jun 24, 2022

pratikvn approved these changes Jun 24, 2022

View reviewed changes

add logger highlighting inefficient patterns

75b2557

* Repeated allocations/deallocations of the same size * Repeated cross-executor copies from/to the same data

upsj force-pushed the performance_hint_logger branch from de2d4b7 to 75b2557 Compare June 24, 2022 16:01

upsj merged commit f78b474 into develop Jun 28, 2022

upsj deleted the performance_hint_logger branch June 28, 2022 08:30

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add logger highlighting inefficient allocation and copy patterns #1035

Add logger highlighting inefficient allocation and copy patterns #1035

upsj commented Apr 27, 2022

upsj commented Apr 27, 2022

ginkgo-bot commented Apr 27, 2022

yhmtsai Apr 28, 2022

upsj Apr 28, 2022

pratikvn left a comment

pratikvn Apr 28, 2022

upsj Jun 23, 2022

upsj Jun 23, 2022

pratikvn Jun 24, 2022

upsj Jun 24, 2022

sonarqubecloud bot commented Apr 28, 2022

codecov bot commented Apr 28, 2022 •

edited

Loading

fritzgoebel left a comment

yhmtsai left a comment

yhmtsai Jun 20, 2022

upsj Jun 22, 2022

yhmtsai Jun 20, 2022

upsj Jun 22, 2022

yhmtsai Jun 20, 2022

upsj Jun 22, 2022

yhmtsai Jun 20, 2022

upsj Jun 22, 2022

pratikvn left a comment

pratikvn Jun 24, 2022

pratikvn Jun 24, 2022

upsj Jun 24, 2022

pratikvn Jun 24, 2022

upsj Jun 24, 2022

pratikvn Jun 24, 2022

upsj Jun 24, 2022

ginkgo-bot commented Jun 24, 2022

sonarqubecloud bot commented Jun 24, 2022

	if (num_bytes > copy_size_limit_ && from != to) {
	if (num_bytes > copy_size_limit_ && !from->memory_accessible(to)) {

Add logger highlighting inefficient allocation and copy patterns #1035

Add logger highlighting inefficient allocation and copy patterns #1035

Conversation

upsj commented Apr 27, 2022

upsj commented Apr 27, 2022

ginkgo-bot commented Apr 27, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pratikvn left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sonarqubecloud bot commented Apr 28, 2022

codecov bot commented Apr 28, 2022 • edited Loading

Codecov Report

fritzgoebel left a comment

Choose a reason for hiding this comment

yhmtsai left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pratikvn left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ginkgo-bot commented Jun 24, 2022

sonarqubecloud bot commented Jun 24, 2022

codecov bot commented Apr 28, 2022 •

edited

Loading