1404666 - file:// directory listing is very slow

Status: RESOLVED FIXED

(Core :: Internationalization, defect, P2)

Description

[jomo]

After updating to Firefox 57, directory listing using the file:// protocol has become noticeably slower in directories with many files.

On my machine, loading takes about ~0.7s per 100 entries.

Comment 1

[--]

I can't spot any slow-down on 58 on Linux, but I haven't tried to measure.

56 on my mac seems snappy. Are you seeing the difference between 56 and 57 or have you done any closer bisecting?

Comment 2

[jomo]

When I reported this bug, after updating to FirefoxDeveloperEdition 57 (I assume 57.0b4 64-bit), directory listing was awkwardly slow.
Now testing again with FirefoxDeveloperEdition 57.0b9 (64-bit), speed is back to normal.

I created a directory with 10.000 (empty) files and tested the load times (waiting until the tab spinner stops) with the Firefox versions listed below on macOS Sierra.

After all, I wasn't able to reproduce this again with a clean profile, nor with my current profile in version 57.0b9. Loading has become very slightly slower, but it didn't take anywhere near 0.7s per 100 entries for those 10k files. I'll blame it on cosmic rays or an extension I had installed.

Firefox 53 (64-bit) ~5 seconds
Firefox 56 (64-bit) ~5 seconds
Firefox 57.0b3 (64-bit) ~7 seconds
Firefox 57.0b4 (64-bit) ~7 seconds
Firefox 57.0b5 (64-bit) ~7 seconds
Firefox 57.0b6 (64-bit) ~7 seconds
Firefox 57.0b7 (64-bit) ~7 seconds
Firefox 57.0b8 (64-bit) ~7 seconds
Firefox 57.0b9 (64-bit) ~7 seconds
FirefoxDeveloperEdition 57.0b3 (64-bit) ~7 seconds
FirefoxDeveloperEdition 57.0b4 (64-bit) ~8 seconds
FirefoxDeveloperEdition 57.0b7 (64-bit) ~8 seconds
FirefoxDeveloperEdition 57.0b8 (64-bit) ~8 seconds
FirefoxDeveloperEdition 57.0b9 (64-bit) ~8 seconds

Comment 3

[jomo]

Reopening this bug because it seems to appear randomly. I have managed to capture a slow directory listing with Gecko Profiler. 
The result can be accessed here: https://perf-html.io/public/9f0374bd28c8d25a79ff7de2d1ab0e73d2db646c/

Hopefully someone can figure out why it's taking ~52 seconds to display 10k files :)

Comment 4

[Valentin Gosu [:valentin] {{ PTO 2 - 12 April }}]

I reproduced the bug via the following steps:
I ran the following commands to create the files:

cd /tmp
mkdir lots
cd lots
python -c '
for i in range(10000):
  f = open("file"+str(i), "w+")
  f.close()
'

Then I navigated to file:///tmp/lots

I used the geckoProfiler, and it turns out at least half of the time is spent in mozilla::DateTimeFormat::FormatPRTime, called from nsIndexedToHTML::OnIndexAvailable.

icu_63::NumberFormat::createInstance(icu_63::Locale const&, UErrorCode&)
icu_63::SimpleDateFormat::initialize(icu_63::Locale const&, UErrorCode&)
icu_63::SimpleDateFormat::construct(icu_63::DateFormat::EStyle, icu_63::DateFormat::EStyle, icu_63::Locale const&, UErrorCode&)
icu_63::SimpleDateFormat::SimpleDateFormat(icu_63::DateFormat::EStyle, icu_63::DateFormat::EStyle, icu_63::Locale const&, UErrorCode&)
icu_63::DateFormat::create(icu_63::DateFormat::EStyle, icu_63::DateFormat::EStyle, icu_63::Locale const&)
icu_63::DateTimePatternGenerator::addICUPatterns(icu_63::Locale const&, UErrorCode&)
icu_63::DateTimePatternGenerator::initData(icu_63::Locale const&, UErrorCode&)
icu_63::DateTimePatternGenerator::createInstance(icu_63::Locale const&, UErrorCode&)
udatpg_open_63
mozilla::intl::OSPreferences::GetPatternForSkeleton(nsTSubstring<char16_t> const&, nsTSubstring<char> const&, nsTSubstring<char16_t>&)
mozilla::intl::OSPreferences::ReadDateTimePattern(mozilla::intl::OSPreferences::DateTimeFormatStyle, mozilla::intl::OSPreferences::DateTimeFormatStyle, nsTSubstring<char> const&, nsTSubstring<char16_t>&)
mozilla::intl::OSPreferences::GetDateTimePattern(int, int, nsTSubstring<char> const&, nsTSubstring<char16_t>&)
mozilla::DateTimeFormat::FormatUDateTime(mozilla::nsDateFormatSelector, mozilla::nsTimeFormatSelector, double, PRTimeParameters const*, nsTSubstring<char16_t>&)
nsIndexedToHTML::OnIndexAvailable(nsIRequest*, nsISupports*, nsIDirIndex*)
nsDirIndexParser::ProcessData(nsIRequest*, nsISupports*)

It seems in GetPatternForSkeleton that we instantiate a new UDateTimePatternGenerator on every call, then close it.
I think we should try to cache the object between calls.

Comment 5

[Zibi Braniecki [:zbraniecki][:gandalf]]

Thank you for reporting!

I'll take a look at it soon.

Comment 6

[Zibi Braniecki [:zbraniecki][:gandalf]]

Jonathan - do you have any thought on how we could cache it?

Comment 7

[Jonathan Kew [:jfkthame]]

I think we should do a couple of things here. First, add a small cache in intl::OSPreferences to cache the pattern that's found for a specific combination of locale and styles, so that we don't do all the work of re-creating the pattern every time GetDateTimePattern is called.

In my local testing (listing a directory of about 1500 items), this cuts the total time spent under mozilla::DateTimeFormat::FormatUDateTime by around 50%, from 475ms with current trunk code to 285ms. Better, but not good enough.

The second thing to do is to add a cache of UDateFormat instances in intl::DateTimeFormat. Most use-cases will likely use the same few formats repeatedly to format lots of pieces of data, so we can save a lot of time by caching these instead of re-creating them for every formatting operation.

With this cache added, the total time under FormatUDateTime in my testcase drops to about 10ms.

Patches coming, after I run them through try to check for breakage...

Comment 8

[Jonathan Kew [:jfkthame]]

Attachment: patch 1 - Accelerate OSPreferences::GetDateTimePattern by caching patterns found for particular style/locale combinations

Comment 9

[Jonathan Kew [:jfkthame]]

Attachment: patch 2 - Accelerate DateTimeFormat::FormatUDateTime by caching ICU UDateFormat objects instead of creating them afresh every time

Comment 10

[Jonathan Kew [:jfkthame]]

These patches just cache a few items in a hashtable in each case, keyed by the requested format options & locale. I figure it's unlikely that a huge number of different combinations of options/locale will be needed by any real-world use case. To prevent a malicious page that deliberately tries to blow up these caches, they just get wiped out if too many items accumulate; we could do smarter things such as tracking access and discarding the least-recently-used items, but I don't think it's worth the added complexity here.

BTW, note that the specific example here of listing a large file:/// directory would be fixed by patch 2 alone, as this is at a higher level than patch 1, and caching here means we'd avoid repeatedly calling GetDateTimePattern. Still, I think it's worth doing patch 1 as well, as it's pretty simple and means that other callers of GetDateTimePattern (e.g. from JS) can also benefit.

Comment 11

[Zibi Braniecki [:zbraniecki][:gandalf]]

Thanks Jonathan! The patches look good.

The only concern I have is the arbitrary max=15. I have no idea if it's a high or low number and am a bit worried that we'll keep it forever as the count grows until someone catches it in profiling.
Do you know how many formatters we create now when opening a browser and navigating to Preferences for example?
Could we add a DEBUG level warning when the cache overflows? Would it make sense to invalidate it on `intl:app-locales-changed`?

Also,
I'd like to see us diving a bit further into this and adding a FIFO nsDataHashtable with a set limit of items. We could then extend it to handle invalidation from observer.

Would you agree that something like that would benefit this code in the longer run? If so, can you file a bug and reference it from this patch as a comment?

Comment 12

[Jonathan Kew [:jfkthame]]

The max is indeed rather arbitrary. In practice, though, I'm having a hard time finding a use case that ends up creating more than 3-4 instances of UDateFormat once these patches are in place, so the limit doesn't come into play at all. We *could* hit it but it seems like that'd require a script that explicitly wants to iterate over all possible locales and/or formatting styles, which isn't a likely real-world case. Any given page is unlikely to be using more than a handful of formatting styles (e.g. the file:/// directory listing uses two; opening Page Info creates one).

(Without the patches, a directory listing may -- depending on number of items -- create and destroy thousands of UDateFormats. Opening Page Info still just creates one, though viewing a certificate in the Security panel creates about 7 more.)

So my current assessment is that it's simply not worth doing anything more elaborate here. The limit was intended to be large enough that no normal use-case will be affected by it, yet it prevents a malicious page deliberately filling up memory by creating every possible permutation and ensures the memory usage stays insignificant.

I'll add an NS_WARNING when we flush the cache, but I suspect that aside from pathological test-cases, it'll never be hit.

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/eb0bf2e711af
patch 1 - Accelerate OSPreferences::GetDateTimePattern by caching patterns found for particular style/locale combinations. r=gandalf
https://hg.mozilla.org/integration/mozilla-inbound/rev/e5910e320457
patch 2 - Accelerate DateTimeFormat::FormatUDateTime by caching ICU UDateFormat objects instead of creating them afresh every time. r=gandalf

Comment 14

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/eb0bf2e711af
https://hg.mozilla.org/mozilla-central/rev/e5910e320457

Comment 15

[Jorg K (CEST = GMT+2)]

https://hg.mozilla.org/releases/mozilla-esr60/rev/64bba4f9928e6b0f0cded35016f671a32b812519
https://hg.mozilla.org/releases/mozilla-esr60/rev/aafc47a21cd3190e7d22521e409aa3cbaceb9861
on THUNDERBIRD_60_VERBRANCH