1058178 - DMD: Add heap scanning mode

Status: RESOLVED FIXED

(Core :: DMD, defect)

Description

[Andrew McCreight [:mccr8]]

Using information DMD stores about the set of live heap blocks, we can conservatively scan the set of live blocks to see how they may point to other live blocks, and log this to a file.  This, in combination with the allocation stacks DMD already records for live blocks, may be an easier way to investigate difficult leaks than refcount logging.

Spinning this off from bug 1014346, which isn't quite the same thing.

Comment 1

[Andrew McCreight [:mccr8]]

I had a little fast path set up for the conservative scanner, which computes the largest and smallest address of any allocated block, so we can avoid a splay tree lookup.  It does fairly well, with about a 92% hit rate on a simple open-and-close browser session, but there was no measurable improvement to the speed, so I think I will omit it.  Something to keep in mind for the future.

Comment 2

[Andrew McCreight [:mccr8]]

Attachment: part 1 - Add the ability to record the set of heap blocks.

Comment 3

[Andrew McCreight [:mccr8]]

Attachment: part 2 - De-const PrintRecords so we can mutate in it later.

Comment 4

[Andrew McCreight [:mccr8]]

Attachment: part 3 - Conservative heap graph logger. WIP

Comment 5

[Andrew McCreight [:mccr8]]

I implemented a new script:
  https://github.com/amccreight/heapgraph/blob/master/dmd/clamp_to_block.py

This takes two files: a DMD log of live blocks and a random text file.  It looks in the text file for anything that looks like an address, then checks to see if the address is part of any of the live blocks.  If it is, it replaces the address with the address of the block.

The idea here is that a cycle collector log contains a bunch of pointers, but they are pointers into the middle of an object, due to vtables etc., so it is hard to relate DMD addresses to CC addresses.  The idea is that once you run the clamp script on the CC log, this can be done easily.  I haven't tried it in practice yet.

Comment 6

[Andrew McCreight [:mccr8]]

I've used the tools here in bug 1060526 to narrow down the problem.

bz points out in IRC that debugging information like pahole should be able to map offsets to field names, which would make the output more useful.

Comment 7

[Andrew McCreight [:mccr8]]

My current thought is to just dump memory out a word at a time, and then do the conservative analysis in a post-processing script (I already have such a script written).  That's what trace malloc does.  That will make the logs bigger, but it will simplify the C++ DMD code, as most of the current complexity is building the splay tree of address ranges.

Comment 8

[Andrew McCreight [:mccr8]]

Attachment: part 1 - Add the ability to record the set of heap blocks. WIP.

Comment 9

[Andrew McCreight [:mccr8]]

Attachment: part 2 - De-const PrintRecords so we can mutate in it later.

Comment 10

[Andrew McCreight [:mccr8]]

Attachment: part 3 - Conservative heap graph logger. WIP

Comment 11

[Andrew McCreight [:mccr8]]

For some things, like nsGlobalWindow, the conservative heap scan and the CC log are matching up nicely, but I'm having trouble with XPCWrappedJS.  I'll have to investigate this, but I suspect I'm not doing the clamping-to-blocks correctly somehow.

Comment 12

[Andrew McCreight [:mccr8]]

Attachment: Implement conservative DMD heap scanning. WIP

This is very simple now.  When the scanning is set, it adds a new property "addr" to each object that is the address of the object.  It also adds a property "contents" that is a list of the word-aligned values in each object.  That's not the most compact representation in the world, but it is easy to deal with, and in my local experiments it is small enough for developer use.

The actual smarts about clamping the random values to particular addresses is done in a script:
  https://github.com/amccreight/heapgraph/blob/master/dmd/clamp_to_block.py

There's another script that tells you what other blocks point at a particular block:
  https://github.com/amccreight/heapgraph/blob/master/dmd/analyzer.py

I need to add a DMD option to enable scanning.

Comment 13

[Andrew McCreight [:mccr8]]

Attachment: Add a hacky way to do shutdown DMD scans. Not for landing.

This is how I've been triggering it for shutdown leaks, though it isn't anywhere near landable yet.

Comment 14

[Nicholas Nethercote [inactive]]

> This is very simple now.

Wow, it really is. Nice.

Comment 15

[Andrew McCreight [:mccr8]]

Attachment: Implement conservative DMD heap scanning.

I should probably write a test or something.  Or maybe just run it with scanning one time, until I get a script landed.

Comment 16

[Andrew McCreight [:mccr8]]

Attachment: Add a hacky way to do shutdown DMD scans. Not for landing.

Comment 17

[Andrew McCreight [:mccr8]]

Thanks to erahm for pointing out that the shouldScan flag is more of an option for the log invocation, not the DMD invocation.

Comment 18

[Nicholas Nethercote [inactive]]

Yes please on the test front. memory/replace/dmd/test/test_dmd.js is where you should look.

But note that waiting until bug 1076446 re-lands will make things easier and avoid conflicts. It should happen on Monday. (Sorry for the delay; to summarize, the current incredible slowness of the Mac test machines is being an *enormous* pain w.r.t. that bug.)

Comment 19

[Andrew McCreight [:mccr8]]

There's no particular hurry.  Now that the patch is small, it is easy to rebase.

Comment 20

[Andrew McCreight [:mccr8]]

Attachment: Add a hacky way to do shutdown DMD scans. Not for landing.

Slightly less hacky now. It uses environment variables to control where to log the file, and to control which kind of processes get logged.

Also, it now runs after bloat logging is shutdown, which removes a lot of noisiness from BloatView entries.

Comment 21

[Andrew McCreight [:mccr8]]

Attachment: Implement conservative DMD heap scanning.

I changed the selection of scanning over to being a DMD mode. Maybe that doesn't entirely make sense, but it feels a little more consistent with what we're doing. Maybe that's wrong. It does at least avoid passing around a boolean everywhere. This patch also updates dmd.py to at least make mode=contents behave like mode=live, but does not change the output otherwise. I did update my two DMD heap scan scripts, the one that analyzes who points to a block, and the one that clamps the addresses in a log, in my github repo.

Comment 22

[Andrew McCreight [:mccr8]]

Nick, do you have a preference about having a new DMD mode or having a new flag that you pass in when generating the report?  The mode avoids adding an extra thing to tweak somehow, but doing a heap scan only affects the report, not the actual gathering of data before that, so it isn't entirely consistent.

Comment 23

[Nicholas Nethercote [inactive]]

I prefer a new mode. It's less flexible but keeps things simpler -- you choose the mode once at start-up, and then you don't have to make any further choices when dumping the data to file or when post-processing the data.

(We discussed this back when I first suggested adding modes, though that was a while ago.)

Comment 24

[Andrew McCreight [:mccr8]]

Attachment: Implement conservative DMD heap scanning.

This is a new version of the patch, on top of the changes in bug 1171647. As you can see, there is now very little boilerplate to add a new mode.

Comment 25

[Andrew McCreight [:mccr8]]

Attachment: Implement conservative DMD heap scanning.

I still need to add some testing.

Comment 26

[Andrew McCreight [:mccr8]]

Attachment: (not for landing) Add DMDScanHeap().

Comment 27

[Andrew McCreight [:mccr8]]

Attachment: Implement conservative DMD heap scanning.

New version for the simpler variant of bug 1171647.

Comment 28

[Andrew McCreight [:mccr8]]

Attachment: part 1 - Implement conservative DMD heap scanning.

I added some tests. It checks that the actual values in memory that are read out are correct. I also renamed it to scan mode, as that is less weird.

Comment 29

[Andrew McCreight [:mccr8]]

Attachment: part 2 - Add address clamping to DMD.

I changed my mind and added the address clamping to the default dmd.py script. I think it makes sense to have it there because it is akin to the stack fixing script, where you run it once per log. It is hideously slow on my machine (taking over a minute) mostly due to the JSON dumping call, so I left it off by default. I added a test that the clamping works correctly.

Comment 30

[Andrew McCreight [:mccr8]]

Attachment: part 1 - Implement DMD heap scanning mode.

This implements a new "scan" mode for DMD that records the address
and contents of every live unsampled block in the DMD log. This
enables the low-level analysis of references from one block to
another, which can help leak investigations.

try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=3c66f4735055

try with an older version: https://treeherder.mozilla.org/#/jobs?repo=try&revision=90371bf36d2d

I still need to make sure my latest version works on Windows but I think it should be okay.

This does not do the basic DMD tests on the scan log. The problem is that the test writes out a number of pointer sized values, so the actual size of the block varies from 32-bit to 64-bit. I could write out different values depending on the platform, but then the contents would vary. scan mode only adds a couple of fields, so I think it is okay to not test it.

Comment 31

[Andrew McCreight [:mccr8]]

Attachment: part 2 - Implement address clamping analysis for DMD scan logs.

This adds a new option --clamp-contents to dmd.py. This replaces every value
contained in the memory contents in the log with a pointer to the start of a live
block, if the value is a pointer into the middle of that block. All other values
are replaced with 0. This conservative analysis makes it easier to determine
which blocks point to other blocks.

Comment 32

[Nicholas Nethercote [inactive]]

Comment on attachment 8621292 [details] [diff] [review]
part 1 - Implement DMD heap scanning mode.

Review of attachment 8621292 [details] [diff] [review]:
-----------------------------------------------------------------

This all looks fine except for the testing stuff which is awful :)  Is there a problem with having non-deterministic addresses in the output? Or is the problem the fact that you are using a different script for the post-processing? If it's the latter, then that's a strong argument for merging that script with this one.

::: memory/replace/dmd/DMD.cpp
@@ +1780,5 @@
> +{
> +public:
> +  const char* ToPtrString(const void* aPtr)
> +  {
> +    snprintf(kPtrBuf, sizeof kPtrBuf - 1, "%" PRIxPTR, (uintptr_t)aPtr);

Please put parentheses around |kPtrBuf| to make the precedence clearer.

@@ +1786,5 @@
> +  }
> +
> +private:
> +  static const size_t kPtrBufLen = 32;
> +  char kPtrBuf[kPtrBufLen];

kPtrBufLen has a single use. Using 32 directly is fine.

@@ +1792,5 @@
> +
> +static void
> +WriteBlockContents(JSONWriter& aWriter, const LiveBlock& aBlock)
> +{
> +  MOZ_ASSERT(!aBlock.IsSampled(), "Sampled blocks do not have accurate sizes");

You should also have a check in Init() for if --mode=scan is used without --sample-below=1, so the user gets an immediate and more helpful error message.

::: memory/replace/dmd/DMD.h
@@ +198,5 @@
> +//       // recorded. Additionally, any such block that is at least one word
> +//       // long will contain an array "contents" of the values contained in
> +//       // the block, read out one word at a time, including only full words.
> +//       "addr": "4e4e4e4e",
> +//       "contents": ["0", "6", "7f7f7f7f", "0"]

The other field comments follow a particular form. Can you do something more like this, which is consistent with that form:

For "addr": "The address of the block. This is mandatory in "scan" mode, but omitted otherwise."

For "contents": "The contents of the block, read one word at a time. This is mandatory in "scan" mode if the block's length is at least one word, but omitted otherwise."

Comment 33

[Nicholas Nethercote [inactive]]

Comment on attachment 8621294 [details] [diff] [review]
part 2 - Implement address clamping analysis for DMD scan logs.

Review of attachment 8621294 [details] [diff] [review]:
-----------------------------------------------------------------

::: memory/replace/dmd/dmd.py
@@ +717,5 @@
> +# Code for clamping addresses using conservative pointer analysis.
> +##################################################################
> +
> +# Start is the address of the first byte of the block, while end is
> +# the first byte past the end of the block.

"end" is unclear... in SpiderMonkey "limit" is often used for "one past the end".

@@ +854,5 @@
> +    tmpFile = tempfile.NamedTemporaryFile(delete=False)
> +    tmpFilename = tmpFile.name
> +    if isZipped:
> +        tmpFile = gzip.GzipFile(filename='', fileobj=tmpFile)
> +    json.dump(j, tmpFile, sort_keys=True)

As you've noticed elsewhere, using Python's JSON dumping will completely change the whitespace layout of the file, and this will potentially screw up stack-fixing, because stack-fixing relies on the stack traces having a particular form. (The stack-fixing scripts don't care that the input is JSON, and just look directly for stack trace info that they rewrite in-place.)

Bleh, this is all so hacky but I'm having trouble thinking of a better way to do it :(

Comment 34

[Andrew McCreight [:mccr8]]

(In reply to Nicholas Nethercote [:njn] from comment #32)
> This all looks fine except for the testing stuff which is awful :)  Is there
> a problem with having non-deterministic addresses in the output? Or is the
> problem the fact that you are using a different script for the
> post-processing? If it's the latter, then that's a strong argument for
> merging that script with this one.

The only script I have is one that takes a block address as an argument and prints out information about each block that points to that block, if any, including the size, the offset of the pointers within that block, and allocation stack. That is not ideal from a testing perspective, because it only gives very weak information about what is actually in the log, particularly since the DMD testing regime is to elide the stack. The size and offsets will also be different depending on the platform. So you'd need some kind of testing mode that doesn't require you pass in an address (or dig around in the raw JSON for the address), and then doesn't print out the address, and somehow massages the output so that the output is in words instead of bytes or something.

> You should also have a check in Init() for if --mode=scan is used without
> --sample-below=1, so the user gets an immediate and more helpful error
> message.
The call to WriteBlockContents() is guarded on b.IsSampled(), so users should never hit this assert. The assert is there because at various points in the development I forgot about this restriction, and it produces really weird output, because you are reading far past the end of the actual memory block.

That said, the actual processing script throws immediately when given a scan log where sampling is disabled, so I should handle this better. The easiest thing to do, now that I think about it, is just to manually set mSampleBelowSize to 1 at the end of the Options ctor if scan mode is set. You always want to disable sampling when doing scanning. How does that sound?

> The other field comments follow a particular form. Can you do something more
> like this, which is consistent with that form:
Oh, sorry. I forgot about that, and I find the style really weird. ;) I've updated it mostly to follow your suggestion, thanks.

I've address the rest of the comments.

Comment 35

[Andrew McCreight [:mccr8]]

Attachment: part 1 - Implement DMD heap scanning mode.

Comment 36

[Andrew McCreight [:mccr8]]

(In reply to Nicholas Nethercote [:njn] from comment #33)
> "end" is unclear... in SpiderMonkey "limit" is often used for "one past the
> end".
I'll update the comment to be more precise about what I mean.

> As you've noticed elsewhere, using Python's JSON dumping will completely
> change the whitespace layout of the file, and this will potentially screw up
> stack-fixing, because stack-fixing relies on the stack traces having a
> particular form. (The stack-fixing scripts don't care that the input is
> JSON, and just look directly for stack trace info that they rewrite
> in-place.)

Yeah, it isn't a big deal, because we can just do stack fixing first, and you are only going to do stack fixing and clamping once. The main drawback is that it renders it so that you can't really open the resulting file in Emacs because it puts everything on a single line. The python JSON thing does have some pretty printing options, but I played around with it a tiny bit and the results were not great.

One alternative would be to write a custom parser (maybe one that uses a JSON parser to read each individual block line), that would let us preserve the white space better, but of course that would make it slightly more fragile. I'll take a crack at that I guess.

> Bleh, this is all so hacky but I'm having trouble thinking of a better way
> to do it :(

Yeah...

Comment 37

[Andrew McCreight [:mccr8]]

Removing trailing zeros from objects seems to be pretty effective. It reduces the uncompressed size of this log file I have from 48MB to 33MB, which also reduces the processing time from about a minute to 44 seconds.

Comment 38

[Andrew McCreight [:mccr8]]

By "trailing zeros", I mean all entries at the end of the list that make up "contents" that are "0".

Comment 39

[Andrew McCreight [:mccr8]]

Attachment: part 1 - Implement DMD heap scanning mode.

Minor change to the test to make more of a difference when dropping trailing nulls.

Comment 40

[Andrew McCreight [:mccr8]]

Attachment: part 2 - Implement address clamping analysis for DMD scan logs.

In this version, I implemented a pretty printer for DMD JSON output. This means that the output will look more or less like the original output, so you can open the file without Emacs freezing, and Linux stack fixing should hopefully still work on the output.

I also trimmed trailing nulls, which shrinks the file and speeds up the clamping process. We only care about pointers from one block to another in a clamped file, so this should be okay. I suspect a lot of the size savings from this are giant blocks of memory used for graphics stuff.

It also fixes a bug in the previous version that meant I wasn't actually testing clamped mode. Oops!

Comment 41

[Nicholas Nethercote [inactive]]

In theory DMD's output format is JSON, which is great because it's so ubiquitous and easy to manipulate. But in practice that's a lie, and it's actually this weird JSON dialect that requires particular whitespace layout so that stack fixing can work. Which is pretty sucky. With effort it would probably be possible to tweak the fix-stacks script so that you can call into them to transform individual stack traces rather than running them wholesale across the input. Then the whitespace wouldn't matter.

> I implemented a pretty printer for DMD JSON output.

Oof. Sorry you had to do that. But Python putting lots of JSON on a single line is pretty daft.

> The size and offsets will also be different depending on the platform.

Would running that test only on 64-bit be an option? I don't know if that's a good idea or not. But having strict 64-bit only tests may be better than weak all-platform tests.

Comment 42

[Andrew McCreight [:mccr8]]

It sounds like I should check that my patch actually is compatible with stack fixing, if it is that fragile.

(In reply to Nicholas Nethercote [:njn] from comment #41)
> Oof. Sorry you had to do that. But Python putting lots of JSON on a single
> line is pretty daft.
Yeah, like I said there's some kind of pretty printing options for Json.dump, but I didn't like the output. I think the problem is that it puts the leaves each on their own line, whereas I'd prefer they are all on the same line, because there aren't that many.

The pretty printer was quite simple to do, and it should be reusable for any other JSON-level transformations we might come up with in the future.

> Would running that test only on 64-bit be an option? I don't know if that's
> a good idea or not. But having strict 64-bit only tests may be better than
> weak all-platform tests.

That sounds like a reasonable idea. I'll see if I can figure out how to do that.

Comment 43

[Andrew McCreight [:mccr8]]

Attachment: part 1 - Implement DMD heap scanning mode.

This version detects whether it is 32- or 64-bit, which then lets it specify which test file to use. Hopefully that will work.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=dcefc8cbf35b

Comment 44

[Andrew McCreight [:mccr8]]

Attachment: part 2 - Implement address clamping analysis for DMD scan logs.

Comment 45

[Andrew McCreight [:mccr8]]

Attachment: part 1 - Implement DMD heap scanning mode.

Forgot to address a few minor comments.

Comment 46

[Andrew McCreight [:mccr8]]

Attachment: part 2 - Implement address clamping analysis for DMD scan logs.

Comment 47

[Andrew McCreight [:mccr8]]

Green on Linux and Windows:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=bfd021e2088f

Comment 48

[Nicholas Nethercote [inactive]]

The reason you need basicScanTesting in dmd.py is that dmd.py does not produce output with any scan-specific data for scan mode. And if it did, it would contain pointer data that varies between runs, which makes it hard to match against expected output.

What about just getting rid of basicScanTesting and --basic-scan-testing? It would leave a hole in the test coverage, but the coupling between TestScan in SmokeDMD.cpp and basicScanTesting is so tight that it's hardly meaningful at the moment anyway.

Comment 49

[Nicholas Nethercote [inactive]]

Alternatively, --filter-stack-for-testing could be modified (and renamed) to filter addresses as well?

Comment 50

[Andrew McCreight [:mccr8]]

Attachment: part 1 - Implement DMD heap scanning mode.

Update to the latest version. I think the main problem was a bug in basic-scan-32-expected.txt.

Comment 51

[Andrew McCreight [:mccr8]]

Attachment: part 2 - Implement address clamping analysis for DMD scan logs.

Comment 52

[Andrew McCreight [:mccr8]]

(In reply to Nicholas Nethercote [:njn] from comment #48)
> The reason you need basicScanTesting in dmd.py is that dmd.py does not
> produce output with any scan-specific data for scan mode. And if it did, it
> would contain pointer data that varies between runs, which makes it hard to
> match against expected output.

Yes, that is part of the problem. The larger reason for it is to make sure that the scan is producing the correct results. I don't have any particular idea of how that would be actually useful to a developer, but I think it is still important to check that we're producing the correct results.

> What about just getting rid of basicScanTesting and --basic-scan-testing? It
> would leave a hole in the test coverage, but the coupling between TestScan
> in SmokeDMD.cpp and basicScanTesting is so tight that it's hardly meaningful
> at the moment anyway.

The goal of basicScanTesting is twofold:
1. Does the C++ code in DMD.cpp produce the right output?
2. Does the address clamping code work (and not totally mangle the JSON)?

Aside from the address clamping, it doesn't really have anything to do with the usual job of dmd.py. I could split it out into a separate script if you prefer. I mostly just shoved the JSON checking in there out of convenience.

Comment 53

[Nicholas Nethercote [inactive]]

A separate script sounds good. Thank you.

Comment 54

[Andrew McCreight [:mccr8]]

Attachment: part 1 - Implement DMD heap scanning mode.

I split the testing code into a new file. I'm waiting for try results before I put it up for review.

Comment 55

[Andrew McCreight [:mccr8]]

Attachment: part 2 - Implement address clamping analysis for DMD scan logs.

Comment 56

[Andrew McCreight [:mccr8]]

Comment on attachment 8627388 [details] [diff] [review]
part 1 - Implement DMD heap scanning mode.

L32 and L64 are green at least: https://treeherder.mozilla.org/#/jobs?repo=try&revision=efe447f9fe8b

Comment 57

[Nicholas Nethercote [inactive]]

Comment on attachment 8627388 [details] [diff] [review]
part 1 - Implement DMD heap scanning mode.

Review of attachment 8627388 [details] [diff] [review]:
-----------------------------------------------------------------

::: memory/replace/dmd/test/scan-test.py
@@ +24,5 @@
> +'''
> +    p = argparse.ArgumentParser(description=description)
> +
> +    p.add_argument('input_file',
> +                   help='a file produced by DMD')

Nit: odd line break?

Comment 58

[Nicholas Nethercote [inactive]]

Thank you for your patience :)

Comment 59

[Andrew McCreight [:mccr8]]

(In reply to Nicholas Nethercote [:njn] from comment #57)
> Nit: odd line break?

I just copied this from dmd.py. I think it looks weird when there aren't a ton of other options. I'll just leave it as is...

(In reply to Nicholas Nethercote [:njn] from comment #58)
> Thank you for your patience :)

Thanks for all of your feedback!

Comment 60

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/3f27e434f853
https://hg.mozilla.org/integration/mozilla-inbound/rev/8b29f027c12b

Comment 61

[Andrew McCreight [:mccr8]]

I should document this on the DMD page.

Comment 62

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/3f27e434f853
https://hg.mozilla.org/mozilla-central/rev/8b29f027c12b

Comment 63

[Andrew McCreight [:mccr8]]

I added some basic documentation of heap scan mode and --clamp-contents to https://developer.mozilla.org/en-US/docs/Mozilla/Performance/DMD