Rework of -profile=gc calculations #2607

RazvanN7 · 2019-05-15T13:09:49Z

This is a revamp of #1846 . I'm having a hard time understanding the results of the test cases added in the original PR. Any help would be appreciated.

cc @leandro-lucarella-sociomantic

Edit: It looks like there is a missing call to resetThreadStats that causes the tests to fail. Can anyone help?

dlang-bot · 2019-05-15T13:09:52Z

Thanks for your pull request and interest in making D better, @RazvanN7! We are looking forward to reviewing it, and you should be hearing from a maintainer soon.
Please verify that your PR follows this checklist:

My PR is fully covered with tests (you can see the annotated coverage diff directly on GitHub with CodeCov's browser extension
My PR is as minimal as possible (smaller, focused PRs are easier to review than big ones)
I have provided a detailed rationale explaining my changes
New or modified functions have Ddoc comments (with Params: and Returns:)

Please see CONTRIBUTING.md for more information.

If you have addressed all reviews or aren't sure how to proceed, don't hesitate to ping us with a simple comment.

Bugzilla references

Your PR doesn't reference any Bugzilla issue.

If your PR contains non-trivial changes, please reference a Bugzilla issue or create a manual changelog.

Testing this PR locally

If you don't have a local development environment setup, you can use Digger to test this PR:

dub fetch digger
dub run digger -- build "master + druntime#2607"

src/gc/impl/conservative/gc.d

thewilsonator · 2019-05-15T18:22:00Z

src/rt/profilegc.d

@@ -41,24 +42,26 @@ __gshared

 extern (C) void profilegc_setlogfilename(string name)
 {
-    logfilename = name;
+    logfilename = name ~ "\0";


Because they are passed to C functions.

namely fopen

src/rt/profilegc.d

rainers · 2019-05-15T22:25:34Z

As noted in the original PR, I'm not a fan of this command line switch. Here's an example how to implement proper and extended tracing with a proxy GC: https://github.com/rainers/visuald/blob/dmdserver/tools/tracegc.d#L231

rainers · 2019-05-15T22:27:20Z

src/core/memory.d

+     * Resets runtime stats for currently active GC implementation of current thread
+     * See `core.memory.GC.Stats` for list of available metrics.
+     */
+    static void resetThreadLocalStats() nothrow


A reset function is never a good idea with independent clients checking the same value. Just use difference to a previous value.

The problem with this is detecting overflows of the counter for long lived processes. But it might be acceptable anyway. I have the feeling there were other reasons for the reset, but I can't remember right now.

The counter will overflow just the same as the difference between two consecutive calls.

One advantage for applications is they can reset the counter and then just look at it later. If they can't reset, they need to save the old value then subtract it from the current value.

It's still a bad API especially with multiple clients. Do you also reset the system clock if you are doing benchmarks?

@rainers has a point. The overflowing is still passing quite some complexity to the client but it's true there are workarounds to detect it and deal with it.

rainers · 2019-05-15T22:29:35Z

src/gc/impl/conservative/gc.d

@@ -395,6 +398,8 @@ class ConservativeGC : GC
            alloc_size = size;
        }
        gcx.leakDetector.log_malloc(p, size);
+        bytesAllocated += alloc_size;


Thread locals can be slow. Versioning this under a compile time condition might be acceptable.

Compile time is not a good option IMHO, because then you can't use this feature with a normal compiler. Two solutions come in mind. One is doing the proxy trick and providing some sort of flag to pick the GC you want to use, the tracing GC being one of the options. I don't remember if that mechanism is already in place and if currently any other GC is provided by the official distribution. Another option would be to do a simple runtime if (tracing) bytesAllocated += alloc_size;, that should be fast enough for all users.

The cost is there but should be evaluated relative to the surrounding time. I recall I measured a while ago and an allocation took several thousand cycles even in the best case. The additional overhead would be difficult to measure.

I did a short measurement with the vdparser benchmark, adding the TLS counter costs about 1% for Win64 (which probably has one of the faster implementation of TLS), though that measurement was done on a mobile processor with disabled speedstepping. Thats probably also consistent with the full allocation taking about 1000 cycles, given the additional instructions generated.

leandro-lucarella-sociomantic · 2019-05-17T15:02:05Z

I'm having a hard time understanding the results of the test cases added in the original PR. Any help would be appreciated.

The test is just allocating some memory and then verified the profiler got the right places and the amount of memory allocated is reported correctly. If you have more details on what needs clarification, please let me know.

Also ping @mihails-strasuns just in case you have some time.

leandro-lucarella-sociomantic · 2019-05-17T15:03:17Z

As noted in the original PR, I'm not a fan of this command line switch. Here's an example how to implement proper and extended tracing with a proxy GC: https://github.com/rainers/visuald/blob/dmdserver/tools/tracegc.d#L231

Interesting.

leandro-lucarella-sociomantic · 2019-05-17T15:07:43Z

Thanks @RazvanN7 for picking this up!

RazvanN7 · 2019-05-21T08:29:51Z

Thanks for the reply @leandro-lucarella-sociomantic . What I don't understand regarding the tests is the amount that is reported to be allocated. For example, the first line for linux 64 in the expected results file says:

288	              1	immutable(char)[][int] D main src/profilegc.d:23

Looking at line 23, we have:

string[int] aa = [1:"one", 2:"two", 3:"three"];

This implementation reports 464 bytes allocated instead 288 for this particular line. I have no idea why this difference occurs; I don't even know why it should report 288; as far as I can tell, it might be possible that the number represents the sum of previous allocations + the current one; it is very likely that a reset should have occurred but it didn't, however I do not know what can/should cause resets. Any information on this is welcome.

cc @mihails-strasuns

mihails-strasuns · 2019-05-21T08:33:34Z

@RazvanN7 naturally this test case is extremely fragile - it has to check for allocation size which is implementation defined and thus test needs to be updated each time implementation changes. It may also differ between platforms even at a single point of time (thus separate expected outputs per platform).

In case of AA - most likely it used to allocate exactly 288 bytes at the point of implementing original PR, all these numbers are taken from actual GC reports and not calculated manually. It is easily possible that something has changed in druntime/compiler since than and now the expected amount is different.

RazvanN7 · 2019-05-21T08:35:44Z

So, simply tweaking the test is an acceptable option?

mihails-strasuns · 2019-05-21T08:42:04Z

Sure, it must match what GC actually does.

RazvanN7 · 2019-05-21T09:33:03Z

This seems to be green now, so it will probably be merged soon.

@leandro-lucarella-sociomantic what other stats are you interested in? After this is merged, can we hop on implementing other stats or should we try to come up with a generic design that would potentially expose anything that the GC has to offer?

RazvanN7 · 2019-05-21T11:48:08Z

Windows failure is unrelated.

codecov · 2019-05-21T14:38:44Z

Codecov Report

Merging #2607 into master will increase coverage by 0.14%.
The diff coverage is 17.77%.

@@            Coverage Diff             @@
##           master    #2607      +/-   ##
==========================================
+ Coverage   73.82%   73.96%   +0.14%     
==========================================
  Files         145      145              
  Lines       16840    16815      -25     
==========================================
+ Hits        12432    12438       +6     
+ Misses       4408     4377      -31

Impacted Files	Coverage Δ
src/core/gc/gcinterface.d	`0% <ø> (ø)`	⬆️
src/gc/impl/proto/gc.d	`13.46% <ø> (ø)`	⬆️
src/gc/impl/manual/gc.d	`1.58% <ø> (ø)`	⬆️
src/rt/tracegc.d	`0% <0%> (ø)`	⬆️
src/gc/proxy.d	`50% <0%> (-0.69%)`	⬇️
src/core/memory.d	`95.63% <0%> (-0.47%)`	⬇️
src/rt/profilegc.d	`14.75% <20%> (+1.29%)`	⬆️
src/gc/impl/conservative/gc.d	`78.99% <83.33%> (+0.07%)`	⬆️
src/rt/aaA.d	`88.01% <0%> (-0.28%)`	⬇️
src/rt/lifetime.d	`84.48% <0%> (-0.11%)`	⬇️
... and 2 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 3906c3a...cc0349d. Read the comment docs.

andralex

LGTM, thanks

andralex · 2019-05-21T14:39:04Z

src/gc/impl/conservative/gc.d

@@ -395,6 +398,8 @@ class ConservativeGC : GC
            alloc_size = size;
        }
        gcx.leakDetector.log_malloc(p, size);
+        bytesAllocated += alloc_size;


The cost is there but should be evaluated relative to the surrounding time. I recall I measured a while ago and an allocation took several thousand cycles even in the best case. The additional overhead would be difficult to measure.

andralex · 2019-05-21T14:41:02Z

src/rt/profilegc.d

@@ -41,24 +42,26 @@ __gshared

 extern (C) void profilegc_setlogfilename(string name)
 {
-    logfilename = name;
+    logfilename = name ~ "\0";


namely fopen

leandro-lucarella-sociomantic · 2019-05-21T16:01:57Z

@leandro-lucarella-sociomantic what other stats are you interested in? After this is merged, can we hop on implementing other stats or should we try to come up with a generic design that would potentially expose anything that the GC has to offer?

Thanks a lot @RazvanN7 !

I recently notice dmd 2.085 already have some improvements on that front! https://dlang.org/phobos/core_memory.html#.GC.ProfileStats

Probably the most important stats for us are numCollections and totalPauseTime. I just created an issue in ocean so we can make use of it: sociomantic-tsunami/ocean#711.

As I mentioned in #1846 (comment), more info could be provided (allocation info) but at this point this is not a blocker for us, just a nice to have.

The other pending issue we have is about GC.stats being O(n) instead of O(1) (like in D1): #2164

The trade off for this is introducing bugs in the calculation if much easier if calculations are kept up to date all the time (but I think that also happens with the profiling info, so I'm not sure now.

rainers · 2019-05-21T20:36:28Z

Here's an example how to implement proper and extended tracing with a proxy GC: https://github.com/rainers/visuald/blob/dmdserver/tools/tracegc.d#L231

For reference, here is a skeleton that works for hooking the conservative GC with a tracing proxy: https://gist.githubusercontent.com/rainers/6cdf73b48837defb9f88/raw/7e776acd806f44668e5d615a17bdac20047fec64/tracegc.d
One downside of that approach is that you have to analyze the callstack to find the allocating call. That needs to be done anyway for all calls in phobos/druntime that have not been compiled with -profile=gc.

leandro-lucarella-sociomantic · 2019-06-04T10:16:40Z

I see this was finally merged, thanks again for picking it up and pushing for it.

About the reset, I agree with @rainers that, even when convenient for most use cases, having a reset is a bad API design and we should consider removing it before a first release.

wilzbach · 2019-06-04T10:19:09Z

we should consider removing it before a first release.

The next release is on 1.7 - with the first beta appearing on 15.6.

leandro-lucarella-sociomantic · 2019-06-04T10:40:59Z

#2629

Rework of -profile=gc calculations (revamp)

2fe8661

RazvanN7 requested review from andralex, DmitryOlshansky, MartinNowak, rainers and wilzbach as code owners May 15, 2019 13:09

RazvanN7 force-pushed the op_profile branch from 678bd01 to 2c0dabd Compare May 15, 2019 13:13

thewilsonator reviewed May 15, 2019

View reviewed changes

rainers reviewed May 15, 2019

View reviewed changes

RazvanN7 force-pushed the op_profile branch from 2c0dabd to c5a6a16 Compare May 21, 2019 08:51

RazvanN7 force-pushed the op_profile branch from c5a6a16 to 244fe43 Compare May 21, 2019 09:35

RazvanN7 force-pushed the op_profile branch 2 times, most recently from 8f65d6d to cc0349d Compare May 21, 2019 14:38

andralex approved these changes May 21, 2019

View reviewed changes

RazvanN7 force-pushed the op_profile branch 3 times, most recently from 9a20357 to 4aca77c Compare May 21, 2019 15:02

Rework of -profile=gc calculations

4246800

RazvanN7 force-pushed the op_profile branch from 4aca77c to 4246800 Compare May 21, 2019 15:06

andralex added the auto-merge label May 28, 2019

dlang-bot merged commit 5d2e7f0 into dlang:master May 28, 2019

leandro-lucarella-sociomantic mentioned this pull request Jun 4, 2019

gc: Remove resetThreadLocalStats() #2629

Merged

rainers mentioned this pull request Jun 6, 2019

Translate _d_arrayappend{T,cTX} to templates #2632

Merged

RazvanN7 mentioned this pull request Nov 2, 2021

Rework of -profile=gc calculations #1846

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Rework of -profile=gc calculations #2607

Rework of -profile=gc calculations #2607

RazvanN7 commented May 15, 2019 •

edited

Loading

dlang-bot commented May 15, 2019

thewilsonator May 15, 2019

leandro-lucarella-sociomantic May 17, 2019

andralex May 21, 2019

rainers commented May 15, 2019

rainers May 15, 2019

leandro-lucarella-sociomantic May 17, 2019

rainers May 21, 2019

andralex May 28, 2019

rainers May 28, 2019

leandro-lucarella-sociomantic Jun 4, 2019

rainers May 15, 2019

leandro-lucarella-sociomantic May 17, 2019

andralex May 21, 2019

rainers May 21, 2019

leandro-lucarella-sociomantic commented May 17, 2019

leandro-lucarella-sociomantic commented May 17, 2019

leandro-lucarella-sociomantic commented May 17, 2019

RazvanN7 commented May 21, 2019 •

edited

Loading

mihails-strasuns commented May 21, 2019

RazvanN7 commented May 21, 2019

mihails-strasuns commented May 21, 2019

RazvanN7 commented May 21, 2019 •

edited

Loading

RazvanN7 commented May 21, 2019

codecov bot commented May 21, 2019 •

edited

Loading

andralex left a comment

andralex May 21, 2019

andralex May 21, 2019

leandro-lucarella-sociomantic commented May 21, 2019

rainers commented May 21, 2019

leandro-lucarella-sociomantic commented Jun 4, 2019

wilzbach commented Jun 4, 2019

leandro-lucarella-sociomantic commented Jun 4, 2019

Rework of -profile=gc calculations #2607

Rework of -profile=gc calculations #2607

Conversation

RazvanN7 commented May 15, 2019 • edited Loading

dlang-bot commented May 15, 2019

Bugzilla references

Testing this PR locally

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rainers commented May 15, 2019

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

Choose a reason for hiding this comment

leandro-lucarella-sociomantic commented May 17, 2019

leandro-lucarella-sociomantic commented May 17, 2019

leandro-lucarella-sociomantic commented May 17, 2019

RazvanN7 commented May 21, 2019 • edited Loading

mihails-strasuns commented May 21, 2019

RazvanN7 commented May 21, 2019

mihails-strasuns commented May 21, 2019

RazvanN7 commented May 21, 2019 • edited Loading

RazvanN7 commented May 21, 2019

codecov bot commented May 21, 2019 • edited Loading

Codecov Report

andralex left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

leandro-lucarella-sociomantic commented May 21, 2019

rainers commented May 21, 2019

leandro-lucarella-sociomantic commented Jun 4, 2019

wilzbach commented Jun 4, 2019

leandro-lucarella-sociomantic commented Jun 4, 2019

RazvanN7 commented May 15, 2019 •

edited

Loading

RazvanN7 commented May 21, 2019 •

edited

Loading

RazvanN7 commented May 21, 2019 •

edited

Loading

codecov bot commented May 21, 2019 •

edited

Loading