1701105 - Corruption in XPCOM_MEM_REFCNT_LOG when starting another XPCOM process

Status: NEW

(Core :: XPCOM, defect)

Description

[Ben Campbell]

(Disclaimer: This is in Thunderbird, not sure if it's a more general issue)

I've got a debug build (so refcnt tracing is on), but when I run with an XPCOM_MEM_REFCNT_LOG, a large chunk at the start of the logfile seems to get clobbered with zero bytes.

So, for example, when I do:

$ env XPCOM_MEM_LOG_CLASSES=nsMSgDBFolder XPCOM_MEM_REFCNT_LOG=/tmp/foo.log ./mach run

After the run, a hex dump of the log file looks like this:

$ hd /tmp/foo.log | head -n 10
00000000  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
005da250  00 00 00 00 00 00 00 00  00 0a 3c 6e 73 4d 73 67  |..........<nsMsg|
005da260  44 42 46 6f 6c 64 65 72  3e 20 30 78 37 66 33 64  |DBFolder> 0x7f3d|
005da270  66 35 64 65 39 34 30 30  20 33 20 41 64 64 52 65  |f5de9400 3 AddRe|
005da280  66 20 31 32 20 5b 74 68  72 65 61 64 20 30 78 37  |f 12 [thread 0x7|
005da290  66 33 65 33 30 38 32 30  32 38 30 5d 0a 20 20 20  |f3e30820280].   |
005da2a0  20 23 30 31 3a 20 3f 3f  3f 5b 2f 68 6f 6d 65 2f  | #01: ???[/home/|
005da2b0  62 65 6e 2f 74 62 2f 6d  6f 7a 69 6c 6c 61 2f 6f  |ben/tb/mozilla/o|
005da2c0  62 6a 2d 78 38 36 5f 36  34 2d 70 63 2d 6c 69 6e  |bj-x86_64-pc-lin|

So, about 6MB(!) of zeros at the beginning.

From some stepping through in the debugger and watching the contents or the logfile, I think it's overwriting entries - I see some entries appear which are later replaced by zero bytes.
This is supported by the fact that when I do more analysis of the logfile I find lots of Release() entries on objects that have no record of being AddRef()ed.
I haven't yet pinned down the point where the corruption occurs. It's around the time the main window appears.

In my stdout, I do see the following startup info appear twice:

### XPCOM_MEM_REFCNT_LOG defined -- logging refcounts to /tmp/fook.log
### XPCOM_MEM_LOG_CLASSES defined -- only logging these classes: nsMsgDBFolder

So, I'm rather leaning toward the idea of a second thread/process jumping in and screwing up the logfile. But I haven't managed to pinpoint this in the debugger yet.

I see the same issue using XPCOM_MEM_COMPTR_LOG.

Still investigating - will post any new findings here.

Comment 1

[Andrew McCreight [:mccr8]]

How do processes in Thunderbird work?

In Firefox, we have only one non-content process. XPCOM only includes the PID in the file name of content processes (which we should probably change...) A reason I've seen multiple processes writing into a single log in Firefox because a static constructor caused the logging to start up before the static variable for the process type got set up correctly, which meant that a content process was treated like a parent process.

Comment 2

[Ben Campbell]

(In reply to Andrew McCreight [:mccr8] from comment #1)

How do processes in Thunderbird work?

Good question. I was under the impression that moving over to proper multi-process separation hadn't yet occurred, but I don't know for sure (update: and as I wrote the rest of this comment, it became obvious to me that there is multiprocess stuff going on already!).

In Firefox, we have only one non-content process. XPCOM only includes the PID in the file name of content processes (which we should probably change...) A reason I've seen multiple processes writing into a single log in Firefox because a static constructor caused the logging to start up before the static variable for the process type got set up correctly, which meant that a content process was treated like a parent process.

When I comment out the parent-checking code in nsTraceRefCnt.cpp and force it to use the PID in the filename, it produces multiple separate log files (three, not two, as I reported above, but I was opening an extra window to trigger the leak I'm looking for).
And because the filehandle (in a static var) is clear each time, it's being called from separate processes, rather than just separate threads as I initially expected.
Only one of those log files actually logs any refcnt entries (at least, for the classes I've been filtering by so far), and split out like that they don't appear to have the corruption.
So a crappy workaround, but a workaround nonetheless.

So - the original corruption I saw fits this nicely:

1. the first log file is opened (by the "parent" process? Not too sure of the terminology)
2. a whole bunch of addref/release uses are logs (about 6MB of them, in my original case)
3. another process opens the same logfile, truncating it.
4. the first process continues logging addref/releases at the position it was at, and the file gets padded out with zero bytes until that point.

Given that the extra processes start up around the time the main window pops up (and the fact I saw an extra process during the run where I opened an extra window), I'd bet that the extra processes are content ones, but just aren't being set up properly by TB, so the logging gets borked.

I suspect it warrants another TB-specific bug to deal with starting up content processes properly, but I really have no idea on the details.
I suspect I'll need to learn those details sooner than anticipated now :-)

Comment 3

[Nika Layzell [:nika] (ni? for response)]

Looks like this might be more of an issue with multiple processes being started & using the same log file, meaning that they step on each-others toes at this point? Not sure there's much we can do about this on the XPCOM side. I suppose we could consider making the code to invoke external protocol handlers and stuff like that clear this flag so it doesn't propagate out to another XPCOM process being started?

Comment 4

[Andrew McCreight [:mccr8]]

We could put the pid in all log file names. That would at least help a bit.

Comment 5

[Nika Layzell [:nika] (ni? for response)]

(In reply to Andrew McCreight [:mccr8] from comment #4)

We could put the pid in all log file names. That would at least help a bit.

Yeah, I suppose that would be an option - might be nice to include the xpcom process type as well so it's easier to find the main process or similar as well?

Comment 6

[Andrew McCreight [:mccr8]]

Yeah, we do that for most processes. I'm not sure why a special case was added for the main process. My guess would be to minimize the amount of work needed for e10s. There might need to be test harness changes to accommodate it, but it shouldn't be much.