899848 - Ensure minimal disk io caused by background thumbnailing

Status: RESOLVED WORKSFORME

(Firefox :: General, defect)

Description

[Mark Hammond [:markh] [:mhammond]]

From IRC:

10:48:08 AM - taras: actually i have one q
10:48:16 AM - taras: do we disable disk cache in plugin container
10:48:21 AM - taras: or does it get wiped on exit?
10:48:37 AM - markh: I believe all of that remains in the parent
10:48:50 AM - markh: all networking does.  The data gets "piped" to the child IIUC
10:49:01 AM - markh: but note we are using PB mode
10:49:20 AM - markh: and I'm not clear on what the practical implications of that are WRT cache etc
10:52:02 AM - markh: (I *hope* it will read from cache, but not write)
10:52:30 AM - taras: you should profile that
10:53:22 AM - markh: your concern there is simply that we want to avoid that diskio while capturing?
10:53:23 AM - taras: osx got some fs activity script
10:53:27 AM - taras: yes
10:53:56 AM - taras: fs activity dtrace script

Comment 1

[Drew Willcoxon :adw]

I used iosnoop to watch file I/O while capturing some sites (CNN, NY Times, Facebook, Google, Twitter, some others), and the results look good.  Not much I/O occurs during capture in either the chrome or content process.

In the chrome process, these are the only two files that showed up:

>  UID   PID D    BLOCK   SIZE       COMM PATHNAME
>  501 70864 W 183981496   4096 firefox-bin ??/zyw5pxiv.tmp/_CACHE_CLEAN_
>  501 72322 W 86545648  69632 firefox-bin ??/pnfx5tjo.tmp/permissions.sqlite-journal

twitter.com is the only site I tested where permissions.sqlite-journal appeared.  _CACHE_CLEAN_ appeared with pretty much every capture, sometimes a few times per capture.  That file is written here: http://mxr.mozilla.org/mozilla-central/source/netwerk/cache/nsDiskCacheMap.cpp

In the content process, these files showed up at various times:

>  501 70855 W 183998624   4096 plugin-containe ??/Preferences/com.apple.ATS.plist.D0bCiMl
>  501 71699 R 185532120   4096 plugin-containe ??/components/PeerConnection.js
>  501 71699 R 159089536  36864 plugin-containe ??/media/PeerConnection.js
>  501 71699 R 132956320   8192 plugin-containe ??/sidebar/nsSidebar.js
>  501 72188 R 133072688   8192 plugin-containe ??/layout/htmlparser.properties
>  501 71699 R 21751872  65536 plugin-containe ??/Fonts/Helvetica.dfont/..namedfork/rsrc
> (many other font files)

All of these appeared inconsistently, and for most captures, none of them appeared.  I don't know what triggered them.

Reassuringly, if I comment out the cache-inhibiting load flags for the content process, I can see cache files being written in the chrome process during captures, e.g.:

>  501 72322 W 67675232  49152 firefox-bin ??/1F/38BECd01

This analysis misses any in-memory data generated during captures that would otherwise not be present that is written out at a later time as part of some larger data structure.

Comment 2

[Drew Willcoxon :adw]

I got some stack traces with dtruss.

dtruss shows a stack per system call, and there are a few calls for permissions.sqlite-journal: open, unlink, access, stat64.  I guess the "W" in iosnoop's permissions.sqlite-journal entry indicates the unlink.  Here's the open stack:

>   libsystem_kernel.dylib`__open+0xa
>   libnss3.dylib`robust_open+0x71
>   libnss3.dylib`unixOpen+0x9bc
>   XUL`(anonymous namespace)::xOpen(sqlite3_vfs*, char const*, sqlite3_file*, int, int*)+0x3f4
>   libnss3.dylib`sqlite3OsOpen+0x52
>   libnss3.dylib`pager_open_journal+0x23a
>   libnss3.dylib`pager_write+0x1b6
>   libnss3.dylib`sqlite3PagerWrite+0x643
>   libnss3.dylib`sqlite3BtreeInsert+0x669
>   libnss3.dylib`sqlite3VdbeExec+0xbf9a
>   libnss3.dylib`sqlite3Step+0x2ec
>   libnss3.dylib`sqlite3_step+0x86
>   XUL`mozilla::storage::Connection::stepStatement(sqlite3_stmt*)+0xb9
>   XUL`mozilla::storage::AsyncExecuteStatements::executeStatement(sqlite3_stmt*)+0x87
>   XUL`mozilla::storage::AsyncExecuteStatements::executeAndProcessStatement(sqlite3_stmt*, bool)+0x35
>   XUL`mozilla::storage::AsyncExecuteStatements::bindExecuteAndProcessStatement(mozilla::storage::StatementData&, bool)+0x209
>   XUL`mozilla::storage::AsyncExecuteStatements::Run()+0x32e
>   XUL`nsThread::ProcessNextEvent(bool, bool*)+0x6c3
>   XUL`NS_ProcessNextEvent(nsIThread*, bool)+0xa9
>   XUL`nsThread::ThreadFunc(void*)+0x127

The XUL sections of the other call stacks are the same.  This is just SQLite maintaining its journal under the hood, so I don't think there's anything we can do about this file access -- or should do.

The font file open calls have this stack:

>   libsystem_kernel.dylib`__open+0xa
>   libFontParser.dylib`TFileDataReference::TFileDataReference(char const*)+0x3f
>   libFontParser.dylib`TFileDataSurrogate::TFileDataSurrogate(char const*, bool)+0x85
>   libFontParser.dylib`TFont::CreateFontEntitiesForFile(char const*, bool, TSimpleArray<TFont*>&, bool, short, char const*)+0x92d
>   libFontParser.dylib`FPFontCreateFontsWithPath+0xad
>   libCGXType.A.dylib`create_private_data_with_path+0x16
>   CoreGraphics`CGFontCreateFontsWithPath+0x24
>   CoreGraphics`CGFontCreateFontsWithURL+0x1af
>   CoreGraphics`CGFontFinderCreateFontWithName+0x26
>   CoreGraphics`CGFontCreateWithFontName+0x2e
>   XUL`MacOSFontEntry::GetFontRef()+0x4a
>   XUL`MacOSFontEntry::GetFontTable(unsigned int)+0x1c
>   XUL`gfxFontEntry::AutoTable::AutoTable(gfxFontEntry*, unsigned int)+0x2d
>   XUL`gfxFontEntry::AutoTable::AutoTable(gfxFontEntry*, unsigned int)+0x23
>   XUL`gfxFontFamily::ReadFaceNames(gfxPlatformFontList*, bool)+0x117
>   XUL`gfxPlatformFontList::RunLoader()+0x201
>   XUL`gfxFontInfoLoader::LoaderTimerFire()+0x65
>   XUL`gfxFontInfoLoader::LoaderTimerCallback(nsITimer*, void*)+0x21
>   XUL`nsTimerImpl::Fire()+0x3d5
>   XUL`nsTimerEvent::Run()+0xd1

It looks like this timer is created when finding or listing fonts, which doesn't seem unusual.

open("nsSidebar.js") looks like maybe someone accessing window.sidebar:

>   libsystem_kernel.dylib`__open+0xa
>   libnss3.dylib`PR_Open+0x21
>   XUL`nsLocalFile::OpenNSPRFileDesc(int, int, PRFileDesc**)+0x3b
>   XUL`mozJSComponentLoader::ObjectForLocation(nsIFile*, nsIURI*, JSObject**, char**, bool, JS::MutableHandle<JS::Value>)+0x911
>   XUL`mozJSComponentLoader::LoadModule(mozilla::FileLocation&)+0x31f
>   XUL`nsComponentManagerImpl::KnownModule::Load()+0x86
>   XUL`nsFactoryEntry::GetFactory()+0x84
>   XUL`nsComponentManagerImpl::CreateInstance(nsID const&, nsISupports*, nsID const&, void**)+0x9c
>   XUL`CallCreateInstance(nsID const&, nsISupports*, nsID const&, void**)+0x9b
>   XUL`nsCreateInstanceByCID::operator()(nsID const&, void**) const+0x34
>   XUL`nsCOMPtr_base::assign_from_helper(nsCOMPtr_helper const&, nsID const&)+0x41
>   XUL`nsCOMPtr<nsISupports>::nsCOMPtr(nsCOMPtr_helper const&)+0x44
>   XUL`nsCOMPtr<nsISupports>::nsCOMPtr(nsCOMPtr_helper const&)+0x1d
>   XUL`nsWindowSH::GlobalResolve(nsGlobalWindow*, JSContext*, JS::Handle<JSObject*>, JS::Handle<jsid>, bool*)+0x1aa9
>   XUL`nsWindowSH::NewResolve(nsIXPConnectWrappedNative*, JSContext*, JSObject*, jsid, unsigned int, JSObject**, bool*)+0x1124
>   XUL`non-virtual thunk to nsWindowSH::NewResolve(nsIXPConnectWrappedNative*, JSContext*, JSObject*, jsid, unsigned int, JSObject**, bool*)+0x7a
>   XUL`_ZL24XPC_WN_Helper_NewResolveP9JSContextN2JS6HandleIP8JSObjectEENS2_I4jsidEEjNS1_13MutableHandleIS4_EE+0x364
>   XUL`_ZL13CallResolveOpP9JSContextN2JS6HandleIP8JSObjectEENS2_I4jsidEEjNS1_13MutableHandleIS4_EENS8_IPN2js5ShapeEEEPb+0x1ff
>   XUL`_ZL32LookupOwnPropertyWithFlagsInlineILN2js7AllowGCE1EEbPNS0_16ExclusiveContextENS0_11MaybeRootedIP8JSObjectXT_EE10HandleTypeENS4_I4jsidXT_EE10HandleTypeEjNS7_17MutableHandleTypeENS4_IPNS0_5ShapeEXT_EE17MutableHandleTypeEPb+0x261
>   XUL`_ZL29LookupPropertyWithFlagsInlineILN2js7AllowGCE1EEbPNS0_16ExclusiveContextENS0_11MaybeRootedIP8JSObjectXT_EE10HandleTypeENS4_I4jsidXT_EE10HandleTypeEjNS7_17MutableHandleTypeENS4_IPNS0_5ShapeEXT_EE17MutableHandleTypeE+0xd7

I also tried using the new disk cache by setting the browser.cache.use_new_backend pref to 1 (bug 913807).  This caused some new writes per page load that are not present with the old cache, like this:

>  501  2844 W 159884120   4096 firefox-bin ??/entries/59DBA353725251AC2CE8683BFFC504B5BCF93953

The entries subdirectory is under a new cache2 subdirectory in Firefox's top-level cache directory.  So it looks like the new cache is either not properly respecting nsIRequest.INHIBIT_CACHING or these files aren't covered by that flag.  INHIBIT_CACHING is checked in a couple of places in bug 913807's patch, though...

I think we can resolve this bug, since the I/O that occurs seems normal and expected, and there's not that much of it.  I can look into those cache2 files, but that's a separate problem, at least while cache2 is preffed off.

Does anyone disagree?

Comment 3

[:Gavin Sharp [email: [e-mail]]]

(In reply to Drew Willcoxon :adw from comment #2)
> I also tried using the new disk cache by setting the
> browser.cache.use_new_backend pref to 1 (bug 913807).  This caused some new
> writes per page load that are not present with the old cache, like this:
> 
> >  501  2844 W 159884120   4096 firefox-bin ??/entries/59DBA353725251AC2CE8683BFFC504B5BCF93953
> 
> The entries subdirectory is under a new cache2 subdirectory in Firefox's
> top-level cache directory.  So it looks like the new cache is either not
> properly respecting nsIRequest.INHIBIT_CACHING or these files aren't covered
> by that flag.  INHIBIT_CACHING is checked in a couple of places in bug
> 913807's patch, though...

Honza, does any of this surprise you? Should we file a bug on this?

Comment 4

[Honza Bambas (:mayhemer)]

INHIBIT_CACHING is fully handled in http channel which doesn't know about the cache backend used at all, so if your testing says we respect it for cache1, then it should work with cache2 as well.  There however, can of course be a bug - e.g. that we cache with cache1 too, but the content is expired immediately so we bypass write at all (cache2 has gaps here, bugs filed) or, we simply store to block files through our memory buffers, so you might not see the write.  In general take also into account that cache1 uses block files, cache2 stores each entry to its own file, so there MUST be more writes with cache2.

At [1] we check for the INHIBIT_CACHING flag, set mCacheEntryIsReadOnly flag and at [2] prevent write to the entry.

[1] http://hg.mozilla.org/mozilla-central/annotate/4e7d1e2c93a6/netwerk/protocol/http/nsHttpChannel.cpp#l2530
[2] http://hg.mozilla.org/mozilla-central/annotate/4e7d1e2c93a6/netwerk/protocol/http/nsHttpChannel.cpp#l3623

Note: in PB mode, we don't read the existing cache.  That is the whole purpose of PB mode.

Comment 5

[Drew Willcoxon :adw]

I'm going to close this now, per comment 2.  The cache2 discussion is potentially useful but since it's not turned on, it's a bit of a tangent for this bug.