1403010 - Intermittent toolkit/components/aboutmemory/tests/test_memoryReporters.xul | application crashed [@ arena_salloc]

Status: RESOLVED FIXED

(Core :: Networking: Cache, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: wkocher [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=133147714&repo=autoland

https://queue.taskcluster.net/v1/task/OwXi9KAaSq25Zr-Qo_R90A/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Nicholas Nethercote [inactive]]

I looked at this a bit. The problem is this line in CacheFileMetadata::SizeOfExcludingThis():

> n += mallocSizeOf(mWriteBuf);

That calls through to malloc_usable_size(), which calls isalloc_validate(), which determines that the pointer isn't null or near-null, and isn't at the start of a chunk. It then calls salloc(), which fails here:

> MOZ_DIAGNOSTIC_ASSERT((mapbits & CHUNK_MAP_ALLOCATED) != 0);

That suggests that mWriteBuf is a freed block. There are two places in netwerk/cache2/CacheFileMetadata.cpp that free mWriteBuf (using CacheFileUtils::FreeBuffer()) but they both immediately set mWriteBuf to nullptr afterwards, so I can't see how we could end up with this assertion failure... unless this code is running off the main thread and we got very unlucky and the mallocSizeof() call occurred after the `CacheFileUtils::FreeBuffer(mWriteBuf)` but before the `mWriteBuf = nullptr;`. Is that possible?

Semi-relatedly, I did notice that mWriteBuf is not freed within ~CacheFileMetadata(). Should it be?

Michal, are you able to answer the two questions above? Thank you.

Comment 2

[Nicholas Nethercote [inactive]]

BTW, I don't think this should necessarily block the stylo-intermittent-test-failures bug; it doesn't appear to have anything to do with Stylo.

Comment 3

[Michal Novotny [:michal]]

(In reply to Nicholas Nethercote [:njn] from comment #1)
> I looked at this a bit. The problem is this line in
> CacheFileMetadata::SizeOfExcludingThis():
> 
> > n += mallocSizeOf(mWriteBuf);
> 
> That calls through to malloc_usable_size(), which calls isalloc_validate(),
> which determines that the pointer isn't null or near-null, and isn't at the
> start of a chunk. It then calls salloc(), which fails here:
> 
> > MOZ_DIAGNOSTIC_ASSERT((mapbits & CHUNK_MAP_ALLOCATED) != 0);
> 
> That suggests that mWriteBuf is a freed block. There are two places in
> netwerk/cache2/CacheFileMetadata.cpp that free mWriteBuf (using
> CacheFileUtils::FreeBuffer()) but they both immediately set mWriteBuf to
> nullptr afterwards, so I can't see how we could end up with this assertion
> failure... unless this code is running off the main thread and we got very
> unlucky and the mallocSizeof() call occurred after the
> `CacheFileUtils::FreeBuffer(mWriteBuf)` but before the `mWriteBuf =
> nullptr;`. Is that possible?

Yes, this is usually called on the background thread.

> Semi-relatedly, I did notice that mWriteBuf is not freed within
> ~CacheFileMetadata(). Should it be?

No. The buffer is allocated in CacheFileMetadata::WriteMetadata and released in CacheFileMetadata::OnDataWritten or in CacheFileMetadata::WriteMetadata when something fails and CacheFileMetadata::OnDataWritten wouldn't be called. I can add MOZ_ASSERT(!mWriteBuf) to ~CacheFileMetadata().

Comment 4

[Michal Novotny [:michal]]

It looks like the same problem can happen with CacheFileMetadata::mBuf because it can be reallocated or freed on the background thread outside CacheFile's lock. Everything around CacheFile is protected by CacheFile::mLock, but the problem is that CacheFileMetadata doesn't have a reference to the CacheFile so it cannot grab the lock itself. Protected are only methods called from CacheFile which is not this case.

I'd like to avoid adding lock just for memory reporting. What's a difference between mallocSizeOf(mWriteBuf) and the number passed to malloc()? We could use this number instead of calling mallocSizeOf().

Comment 5

[Nicholas Nethercote [inactive]]

> I'd like to avoid adding lock just for memory reporting. What's a difference between mallocSizeOf(mWriteBuf)
> and the number passed to malloc()? We could use this number instead of calling mallocSizeOf().

The heap allocator rounds up many size requests, so that will underreport. Also, that doesn't give us DMD integration.

There are some ways around this that I can use, but I'd like to clarify something...

(In reply to Michal Novotny (:michal) from comment #4)
> It looks like the same problem can happen with CacheFileMetadata::mBuf
> because it can be reallocated or freed on the background thread outside
> CacheFile's lock. Everything around CacheFile is protected by
> CacheFile::mLock, but the problem is that CacheFileMetadata doesn't have a
> reference to the CacheFile so it cannot grab the lock itself. Protected are
> only methods called from CacheFile which is not this case.

Can you describe exactly how the threads and locking work here? It sounds like this code is racy even if we ignore the memory reporting, though I may be misunderstanding. Thanks.

Comment 6

[Michal Novotny [:michal]]

(In reply to Nicholas Nethercote [:njn] from comment #5)
> Can you describe exactly how the threads and locking work here? It sounds
> like this code is racy even if we ignore the memory reporting, though I may
> be misunderstanding. Thanks.

AFAICS, racy is only memory reporting. Normally, all methods are called from CacheFile and this is protected with CacheFile's lock. There are just 2 exceptions:

1) When reading metadata from the disk. CacheFileMetadata::ReadMetadata() is called (under the lock) and it calls CacheFileIOManager::Read(). When data are read from the disk, CacheFileIOManager calls CacheFileMetadata::OnDataRead() which tries to parse the metadata and then calls CacheFile::OnMetadataRead() which grabs the CacheFile's lock.

Everything related to parsing metadata (which can cause reallocating buffer and reading more data from the disk, or freeing the buffer and failing with completely empty metadata) is executed outside the lock. But until the metadata is loaded and CacheFile::OnMetadataRead() is called, the CacheFile is not ready and is not used, so no method which could access the buffer is called from CacheFile. The only exception is memory reporting, which is called even if the metadata is being read.

2) Similar is writing of metadata. CacheFileMetadata::WriteMetadata() creates mWriteBuf (again under the CacheFile's lock) which is passed to CacheFileIOManager::Write(). It is freed in CacheFileMetadata::OnDataWritten(). The difference when comapred with (1) is that mWriteBuf is used only inside CacheFileMetadata so there is no problem to call CacheFileMetadata's methods when the metadata is being written. The exception is memory reporting again.


The solution for (2) might be to not include mWriteBuf in memory reporting because this buffer exists for a short time only. To solve (1) we could exclude CacheFileMetadata which is being read from the disk from memory reporting. Nicholas, does this sound like a good solution?

Comment 7

[Intermittent Failures Robot]

1 failures in 885 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows7-32-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403010&startday=2017-09-25&endday=2017-10-01&tree=all

Comment 8

[Nicholas Nethercote [inactive]]

> The solution for (2) might be to not include mWriteBuf in memory reporting
> because this buffer exists for a short time only. To solve (1) we could
> exclude CacheFileMetadata which is being read from the disk from memory
> reporting.

How would we exclude it in that case?

> Nicholas, does this sound like a good solution?

I think so. I didn't entirely follow your description. Excluding mWriteBuf is certainly safe :)

Comment 9

[Michal Novotny [:michal]]

Attachment: fix

Comment 10

[Michal Novotny [:michal]]

(In reply to Nicholas Nethercote [:njn] from comment #8)
> > The solution for (2) might be to not include mWriteBuf in memory reporting
> > because this buffer exists for a short time only. To solve (1) we could
> > exclude CacheFileMetadata which is being read from the disk from memory
> > reporting.
> 
> How would we exclude it in that case?

CacheFile::mReady is false until metadata is either read or created.

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/9c847604792e
Crash due to race condition in CacheFileMetadata::SizeOfExcludingThis when reading or writing metadata, r=valentin

Comment 12

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

https://hg.mozilla.org/mozilla-central/rev/9c847604792e

Comment 13

[Ryan VanderMeulen [:RyanVM]]

This code goes back as far as Gecko 30 AFAICT, but since there are no crash reports with this signature and OF only shows the one failure this bug was initially filed for, I'm marking older versions as wontfix. Feel free to set 57 back to affected and nominate for Beta uplift if you feel it's warranted, though.

Comment 14

[Nicholas Nethercote [inactive]]

Thank you for the fix, Michal. I think uplifting is reasonable, because it's a very simple fix.