1239253 - Intermittent test_dmd.js | test - [test : 113] full-unsampled1-live - false == true

Status: RESOLVED WORKSFORME

(Core :: DMD, defect)

Description

[Nigel Babu [:nigelb]]

https://treeherder.mozilla.org/logviewer.html#?job_id=19719183&repo=mozilla-inbound


 20:05:33     INFO -  TEST-PASS | netwerk/test/unit/test_altsvc.js | took 4763ms
 20:05:33     INFO -  TEST-START | netwerk/test/unit/test_offlinecache_custom-directory.js
 20:05:34     INFO -  TEST-PASS | netwerk/test/unit/test_offlinecache_custom-directory.js | took 867ms
 20:05:34     INFO -  TEST-START | netwerk/test/unit/test_bug767025.js
 20:05:35     INFO -  TEST-PASS | netwerk/test/unit/test_bug767025.js | took 1093ms
 20:05:35     INFO -  Retrying tests that failed when run in parallel.
 20:05:35     INFO -  TEST-START | dom/push/test/xpcshell/test_quota_exceeded.js
 20:05:41     INFO -  TEST-PASS | dom/push/test/xpcshell/test_quota_exceeded.js | took 6082ms
 20:05:41     INFO -  TEST-START | memory/replace/dmd/test/test_dmd.js
 20:05:42  WARNING -  TEST-UNEXPECTED-FAIL | memory/replace/dmd/test/test_dmd.js | xpcshell return code: 0
 20:05:42     INFO -  TEST-INFO took 1110ms
 20:05:42     INFO -  >>>>>>>
 20:05:42     INFO -  PROCESS | 1950 | [1950] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/slave/m-in-l64-d-0000000000000000000/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2339
 20:05:42     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] $DMD is undefined
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] Dump 1 {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the heap block list...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack trace table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack frame table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] Dump 2 {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the heap block list...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack trace table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack frame table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] Dump 3 {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the heap block list...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack trace table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack frame table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] Dump 4 {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the heap block list...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack trace table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack frame table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Execution measurements {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Data structures that persist after Dump() ends {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used stack traces:         2,496 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Unused stack traces:       2,080 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Stack trace table:       262,224 bytes (16,384 entries, 22 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Live block table:         24,656 bytes (512 entries, 30 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Dead block table:            400 bytes (8 entries, 0 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Data structures that are destroyed after Dump() ends {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service:         202,992 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used stack traces set:     16,384 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used PCs set:              16,384 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Pointer ID map:            24,576 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Counts {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service:            21 requests
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service cache:   0.0% hit rate, 0.5% occupancy at end
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] Dump 5 {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the heap block list...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack trace table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack frame table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Execution measurements {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Data structures that persist after Dump() ends {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used stack traces:         6,448 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Unused stack traces:       6,240 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Stack trace table:       262,224 bytes (16,384 entries, 61 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Live block table:          4,176 bytes (64 entries, 30 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Dead block table:            400 bytes (8 entries, 0 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Data structures that are destroyed after Dump() ends {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service:         202,992 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used stack traces set:     16,384 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used PCs set:              16,384 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Pointer ID map:            24,576 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Counts {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service:            39 requests
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service cache:   0.0% hit rate, 1.0% occupancy at end
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] Dump 6 {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the heap block list...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack trace table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack frame table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Execution measurements {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Data structures that persist after Dump() ends {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used stack traces:         3,536 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Unused stack traces:      18,720 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Stack trace table:       262,224 bytes (16,384 entries, 107 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Live block table:          4,176 bytes (64 entries, 27 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Dead block table:            400 bytes (8 entries, 0 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Data structures that are destroyed after Dump() ends {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service:         202,960 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used stack traces set:     16,384 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used PCs set:              16,384 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Pointer ID map:            24,576 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Counts {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service:            26 requests
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service cache:   0.0% hit rate, 0.6% occupancy at end
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] Dump 7 {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the heap block list...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack trace table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack frame table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Execution measurements {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Data structures that persist after Dump() ends {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used stack traces:         3,536 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Unused stack traces:      22,672 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Stack trace table:       262,224 bytes (16,384 entries, 126 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Live block table:          4,176 bytes (64 entries, 27 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Dead block table:          1,104 bytes (16 entries, 9 used)
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Data structures that are destroyed after Dump() ends {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service:         202,992 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used stack traces set:     16,384 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Used PCs set:              16,384 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Pointer ID map:            24,576 bytes
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     Counts {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service:            26 requests
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]       Location service cache:   0.0% hit rate, 0.6% occupancy at end
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]     }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] Dump 8 {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the heap block list...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack trace table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack frame table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] }
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] Dump 9 {
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the heap block list...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack trace table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974]   Constructing the stack frame table...
 20:05:42     INFO -  PROCESS | 1950 | DMD[1974] }
 20:05:42     INFO -  TEST-PASS | memory/replace/dmd/test/test_dmd.js | test - [test : 113] full-empty-live - true == true
 20:05:42     INFO -  TEST-PASS | memory/replace/dmd/test/test_dmd.js | test - [test : 113] full-empty-dark-matter - true == true

Comment 1

[Nicholas Nethercote [inactive]]

Here's a more relevant part of the output

> 20:05:42     INFO -  PROCESS | 1950 | @@ -53,7 +75,13 @@
> 20:05:42     INFO -  PROCESS | 1950 |    Individual block sizes: 128; 112; 96; 80; 64; 48
> 20:05:42     INFO -  PROCESS | 1950 |    4.37% of the heap (93.32% cumulative)
> 20:05:42     INFO -  PROCESS | 1950 |    Allocated at {
> 20:05:42     INFO -  PROCESS | 1950 | -    #01: ... DMD.cpp ...
> 20:05:42     INFO -  PROCESS | 1950 | +    #01: libdmd.so + 0x887e
> 20:05:42     INFO -  PROCESS | 1950 | +    #02: SmokeDMD + 0x55a4
> 20:05:42     INFO -  PROCESS | 1950 | +    #03: SmokeDMD + 0x5991
> 20:05:42     INFO -  PROCESS | 1950 | +    #04: SmokeDMD + 0x5f3a
> 20:05:42     INFO -  PROCESS | 1950 | +    #05: SmokeDMD + 0x5fbe
> 20:05:42     INFO -  PROCESS | 1950 | +    #06: libc.so.6 + 0x2176d
> 20:05:42     INFO -  PROCESS | 1950 | +    #07: SmokeDMD + 0x4f35
> 20:05:42     INFO -  PROCESS | 1950 |    }
> 20:05:42     INFO -  PROCESS | 1950 |  }

There are other, similar differences.

dmd.py is run with --filter-stacks-for-testing in the test. If a stack trace contains "DMD.cpp" or "dmd.cpp" anywhere then the entire stack trace will be replaced with to "#01: ... DMD.cpp ...". This filtering is done to counter the non-determinism in the stack entries on different platforms.

What happened here is that the stack trace didn't contain any such entries so the replacement didn't happen. I don't know why this would happen. It suggests that debug info was stripped, or something like that. I don't know why this would happen in a once-off fashion.

Comment 2

[Mike Hommey [:glandium]]

The subject says it's intermittent, but is it permanent for a given build? That is, does it always fail if you retrigger an orange and does it always succeed if you retrigger a green? If so, then it could be caused by some race condition at build time.

Comment 3

[Andrew McCreight [:mccr8]]

It looks like somebody was trying to figure out that very question:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=linux%20x64%20debug%20x1&tochange=ed0c58e53473&fromchange=26a221678726

It is almost permanent on this build, but not happening at all on previous builds.

Comment 4

[Andrew McCreight [:mccr8]]

There was also another failure a day later:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=3c473ad89a25&filter-searchStr=x1

Comment 5

[Intermittent Failures Robot]

10 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 9
* mozilla-central: 1

Platform breakdown:
* linux64: 10

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1239253&startday=2016-01-11&endday=2016-01-17&tree=all

Comment 6

[Intermittent Failures Robot]

24 automation job failures were associated with this bug yesterday.

Repository breakdown:
* mozilla-inbound: 19
* fx-team: 3
* mozilla-central: 2

Platform breakdown:
* windows8-64: 24

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1239253&startday=2016-03-25&endday=2016-03-25&tree=all

Comment 7

[Nicholas Nethercote [inactive]]

(In reply to OrangeFactor Robot from comment #6)
> 24 automation job failures were associated with this bug yesterday.

These were because of bug 1181142, which changed the minimum size of a heap allocation on Windows, which broke test_dmd.js, and was eventually backed out. The failures are different to the original failures in this bug, though they were on the same sub-test so they look similar.

Anyway, it looks like the original (intermittent and never fully diagnosed) problem has gone, and yesterday's (persistent and understood) problem was fixed by the backout. This bug can be closed.

Comment 8

[Intermittent Failures Robot]

37 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 20
* fx-team: 12
* mozilla-central: 3
* try: 2

Platform breakdown:
* windows8-64: 37

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1239253&startday=2016-03-21&endday=2016-03-27&tree=all

Comment 9

[Intermittent Failures Robot]

27 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 27

Platform breakdown:
* windows8-64: 27

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1239253&startday=2016-05-10&endday=2016-05-16&tree=all

Comment 10

[Nicholas Nethercote [inactive]]

(In reply to OrangeFactor Robot from comment #9)
> 27 automation job failures were associated with this bug in the last 7 days.
> 
> Repository breakdown:
> * mozilla-beta: 27
> 
> Platform breakdown:
> * windows8-64: 27

These are all because the patch from bug 1181142 that changed jemalloc's minimum size was landed on Beta, but the corresponding patch that adjusts test_dmd.js was not.

Comment 11

[Nicholas Nethercote [inactive]]

> These are all because the patch from bug 1181142 that changed jemalloc's
> minimum size was landed on Beta, but the corresponding patch that adjusts
> test_dmd.js was not.

I just looked at backporting the test_dmd.js patch from that bug, but it's a pain because DMD recently underwent a big change that is not on Beta. I'm content to live with the failures from Beta for the rest of this cycle. Things are ok on Aurora.