1585536 - toLocaleTimeString with locale memory usage

Status: RESOLVED FIXED

(Core :: JavaScript: Internationalization API, defect)

Description

[Nick]

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:69.0) Gecko/20100101 Firefox/69.0

Steps to reproduce:

Linux / Ubuntu 64-bit:
SpiderMonkey shell JavaScript-C71.0a1
Fire Fox 69.0.1 (64-bit)

Successive calls to toLocaleTimeString() result in a rapid memory build up when locale is specified.

Tested with two scripts (among others) - code below:
shell-test.js
browser-test.js

shell-test.js is typically executed as:
./js shell-test.js 0 10000 (To run 10,000 iterations without locale)
./js shell-test.js 1 10000 (To run 10,000 iterations with locale)

For my tests :
/usr/bin/time -v ./js shell-test.js 1 100000 2>&1 | sed -n '/Max|Run/p'

The browser-test.js can be pasted in browser-console and started with T() to test without locale, and T(1) to test with locale. Successive calls to T() start / stop the test.

The browser test was run by simultaneously checking about:memory -> Measure.

Actual results:

Results shell-test:

Without locale:
1000 iterations: Maximum resident set size: 22484 kb
2000 iterations: Maximum resident set size: 22144 kb
3000 iterations: Maximum resident set size: 22156 kb
4000 iterations: Maximum resident set size: 22164 kb
14000 iterations: Maximum resident set size: 22340 kb

With locale:
1000 iterations: Maximum resident set size: 90744 kb
2000 iterations: Maximum resident set size: 154988 kb
3000 iterations: Maximum resident set size: 221548 kb
4000 iterations: Maximum resident set size: 286376 kb
14000 iterations: Maximum resident set size: 940156 kb

For the browser test, I sometimes experience a GC / CC - but over time it build up and go as far as crashing the host system.

Expected results:

Understand there might be some extra memory used with look up for locale, but not that much; and the build up does not look good.

FILE shell-test.js:

(function (world) {
"use_strict";

let d = new Date();
let iter = 0;
let locale = parseInt(scriptArgs[0]);
let lim = parseInt(scriptArgs[1]) || 10000;

function t() {
    if (locale)
        d.toLocaleTimeString('en-US');
    else
        d.toLocaleTimeString();
    if (++iter === lim) {
        quit();
        throw "done";
    }
}

console.log(`Run ${lim} iterations with locale=${locale}`);
for (;;)
    t();

})();

FILE browser-test.js:

let T = (function () {
"use_strict";

const AF = requestAnimationFrame;

const timer = {
    date: null,
    running: 0,
    iter: 0,
    locale: 0,
    tick: function (ts) {
        if ((++timer.iter === 1000)) {
            console.log('1k iterations');
            timer.iter = 0;
        }
        if (timer.locale)
            timer.date.toLocaleTimeString('en-US');
        else
            timer.date.toLocaleTimeString();
        if (timer.running)
            AF(timer.tick);
    },
    toggle: function (l) {
        if ((timer.running ^= 1)) {
            timer.date = new Date();
            timer.locale = l;
            AF(timer.tick);
        }
        return timer.running ?
            'Started - Locale : ' + (l ? 'Yes' : 'No') :
            'Stopped'
        ;
    }
};
return timer.toggle;

})();

Comment 1

[Nick]

Attachment: shell-test.js

Comment 2

[Nick]

Attachment: browser-test.js

Comment 3

[Liviu Seplecan]

Hi @Nick, for now I will set a component for the issue, if isn't the right one please fell free to change it. Afterwards, cannot do much thing with the code provided. Should I simply loaded in browser? => doing that no action occurs. Terminal commands needs to be inserted? Please add accurate steps in order to test.
Regards,
Liviu

Comment 4

[Nick]

For browser script

Preparations

1. Open two windows. WINDOW_1 and WINDOW_2

2. In WINDOW_1:
   a ) Optionally go to a light weight web-page so it easier to locate later. https://ident.me/ is a good candidate.
   b ) Open Developer tools Web Console. Typically Ctrl+Shift+K or

   • Menu -> Web Developer -> Web Console

   c ) In the console paste the contents of browser-test.js

   • If one have not pasted in that browser earlier, one have to type allow pasting in the console first.
   • This can be reset by going to about:config and resetting devtools.selfxss.count + restart

The script is now loaded and ready. Nothing is running yet.

2. In WINDOW_2:
   a ) Enter about:memory in the address bar and press Enter
   b ) Where it say «Show memory reports» click on the button «Measure»
   c ) Click on the list of Processes on the right hand side to find WINDOW_1
   • If only two windows, this is usually the topmost. Search or look for the URL the page is on if any.

Remember the pid so it easy to locate in the side menu after new Measurements.

Optionally remember the link location. (Shown in the address bar). Typically #start1.

Run test

Go back to WINDOW_1 and in the console type: T(1) and press Enter. This will start the loop calling toLocaleTimeString().

• To stop: At any time type T() and press Enter in the console. Status running / stopped is printed.

The argument 1 to T() tell the function to specify locale when calling toLocaleTimeString(). Where the issue lies.
For comparison one can call T() with no argument or 0 to test without locale string. So to sum up:

T(0); // RUN without specifying locale string
T(1); // RUN with specifying locale string
Successive calls toggles running / stopped status.

DURING RUN

As the script is running, go back to WINDOW_2. (Where the about:memory page is open)

• Go to top of window
• Click on the button Measure.
• Locate WINDOW_1 in the process list, by clicking in the menu on right hand side, and check memory consumption.
• Repeat and notice changes

Developer Tools Memory

As a note: The snapshot tool under Developer Tools -> Memory does not reveal the memory usage.
When about:memory say the page is using for example 5,000 MB RAM, the snapshot tool still say 1-2MB

Measurements

Results from a test done in next comment.

Updating about:memory from Web Console

(Only adding this as a bonus - not relative)

As an alternative to Clicking the Measure button and navigating the page one could enter this in the Web Console for the about:memory tab:

doMeasure(); setTimeout(function () { gFilter = 'icu'; updateAboutMemoryFromCurrentData(); }, 1200);

This does a new Measure and filter on icu after 1.2 seconds. At least here that gives me the correct view.

Alternatively:

doMeasure();  setTimeout(function () { window.location = "about:memory#start1"; }, 1200);

where you change #start1 to what ever process you want to jump to.

Comment 5

[Nick]

Sample of result

Results from a test done now:

At start

47.18 MB (100.0%) -- explicit
├──16.65 MB (35.30%) ── heap-unclassified
├──15.55 MB (32.97%) ++ heap-overhead
├──10.40 MB (22.04%) ++ js-non-window
├───1.17 MB (02.49%) ++ window-objects/top(https://ident.me/, id=32212254721)
├───0.85 MB (01.81%) ── skia-font-cache
├───0.70 MB (01.48%) ++ gfx
├───0.65 MB (01.37%) ++ layout
├───0.64 MB (01.35%) ++ threads
└───0.56 MB (01.19%) ++ (18 tiny)

At 1 minute

305.90 MB (100.0%) -- explicit
├──250.49 MB (81.89%) ── icu
├───17.32 MB (05.66%) ++ js-non-window
├───16.84 MB (05.50%) ── heap-unclassified
├───13.55 MB (04.43%) ++ heap-overhead
├────4.31 MB (01.41%) ++ window-objects/top(https://ident.me/, id=32212254721)
└────3.39 MB (01.11%) ++ (21 tiny)

At 3 minutes

770.97 MB (100.0%) -- explicit
├──698.15 MB (90.55%) ── icu
├───23.72 MB (03.08%) ++ js-non-window
├───20.73 MB (02.69%) ++ heap-overhead
├───16.86 MB (02.19%) ── heap-unclassified
├────8.13 MB (01.05%) ++ window-objects/top(https://ident.me/, id=32212254721)
└────3.39 MB (00.44%) ++ (21 tiny)

At 4 minutes – First and only GC done

276.63 MB (100.0%) -- explicit
├──223.14 MB (80.66%) ── icu
├───16.76 MB (06.06%) ── heap-unclassified
├───15.27 MB (05.52%) ++ js-non-window
├───14.06 MB (05.08%) ++ heap-overhead
├────4.01 MB (01.45%) ++ window-objects/top(https://ident.me/, id=32212254721)
└────3.38 MB (01.22%) ++ (21 tiny)

After 7 minutes

1,023.92 MB (100.0%) -- explicit
├────946.02 MB (92.39%) ── icu
├─────25.20 MB (02.46%) ++ heap-overhead
├─────21.59 MB (02.11%) ++ js-non-window
├─────16.76 MB (01.64%) ── heap-unclassified
├─────10.97 MB (01.07%) ++ window-objects/top(https://ident.me/, id=32212254721)
└──────3.38 MB (00.33%) ++ (21 tiny)

After 30 - 40 minutes

5,083.36 MB (100.0%) -- explicit
├──4,908.68 MB (96.56%) ── icu
├─────89.44 MB (01.76%) ++ (24 tiny)
└─────85.25 MB (01.68%) ++ heap-overhead

So 5 G RAM with no end in sight.

This crashed the host system on an earlier run when memory got exhausted.

Comment 6

[Nick]

And yes. The original post has some bad formatting. There is no formatting hints on the «Enter A Bug» page, nor preview before post, and it was only possible to attach 1 file so I pasted the scripts in post. (In hindsight clearly a Bad Choice). If anyone has option to change original post - feel free to clean it up. Sorry for the mess.

Comment 7

[Liviu Seplecan]

Attachment: bug 1585536 - about memory measure.png

Comment 8

[Liviu Seplecan]

Hi @Nick, tks for the supplied info, re-test the issue and here are the results:
[Platforms affected]: Windows 10, Ubuntu 18.04, Mac OS X
[FF affected versions]: nightly 71.0a1, beta 70.0b13, release 69.0.2
=> on all versions & OS's the issue can be reproduced; in Window 1 when I type in console t(1) & the iterations started on Windows 2 in about:memory -> Measure / on different time intervals can be observed different memory allocated. Also, I will add couple of screenshots to see that.
Regards,
Liviu

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

The priority flag is not set for this bug.
:njn, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 10

[Nicholas Nethercote [inactive]]

Sounds like a Spidermonkey issue. Jan, can you take a look?

Comment 11

[Jan de Mooij [:jandem]]

André, any idea what's going on here? Feel free to send it back to me if you don't have time to investigate.

Comment 12

[André Bargull [:anba]]

It looks like we're just missing to inform the GC about ICU memory allocations, so we never collect the dead Intl.DateTimeFormat objects (resp. collecting them to late). For example when adding if (iter % 1000 === 0) gc(); to the test case from comment #0, the "Maximum resident set size" drops from 3.3 GB to 90 MB for me.

XPCOMInit.cpp calls JS_SetICUMemoryFunctions, but only uses the memory functions for reporting the overall memory used by ICU and doesn't interact with the GC in any way.

Also there are some open ICU bugs about performance/memory issues for date-time formatting, like https://unicode-org.atlassian.net/browse/ICU-20115 and https://unicode-org.atlassian.net/browse/ICU-20427.

Comment 13

[André Bargull [:anba]]

Hi Jon, is there a way to use the ICU memory hooks to inform the GC about malloc pressure? Unfortunately we can't pinpoint the exact memory usage for each Intl.DateTimeFormat object, but instead are restricted to the memory function interface supplied by ICU. That means for example we know the amount of memory requested by a malloc call in ICU, but in a subsequent free call, we only receive the pointer to be freed, but not the amount of memory to be freed. And as a further complication, ICU's u_setMemoryFunctions must be called early during start-up and can't be called repeatedly, so I don't see how to use something like ZoneAllocator which calls maybeMallocTriggerZoneGC() based on the malloc usage per zone, because we only get to set a single ICU memory hook for the complete process using ICU. :-/

Comment 14

[André Bargull [:anba]]

As an interim solution we could just measure the (average) malloc memory used by an Intl.DateTimeFormat object and then assigned it to the object via AddCellMemory.

Comment 15

[Jon Coppeard (:jonco)]

(In reply to André Bargull [:anba] from comment #13)

Hi Jon, is there a way to use the ICU memory hooks to inform the GC about malloc pressure?

It's difficult, for the reasons you mention.

It might be possible to use the hooks to record the sizes of all allocations make while one of these objects is being created, and store their sum for use when freeing. But that's not really a great solution.

As an interim solution we could just measure the (average) malloc memory used by an Intl.DateTimeFormat object and then assigned it to the object via AddCellMemory.

That's probably good enough to fix the excessive memory usage reported in this bug.

Looking at the way toLocaleString() is implemented, it seems there is a cache that's used when no locate is specified:

https://searchfox.org/mozilla-central/source/js/src/builtin/Date.js#159-161

I wonder if it's possible to cache these DateTimeFormat objects that are created when a locale is specified? Then we might stop creating so many.

Comment 16

[André Bargull [:anba]]

(In reply to Jon Coppeard (:jonco) from comment #15)

I wonder if it's possible to cache these DateTimeFormat objects that are created when a locale is specified? Then we might stop creating so many.

This is tracked under bug 1514851 (basically the same issue exists for NumberFormat). Caching the objects is a bit complicating, because we not only need to take the locale argument into account, but also the optional options argument (cf. bug 1517354). That means for Intl.NumberFormat, the cache-key consists of 16 different entries, and for Intl.DateTimeFormat maybe just three or four entries, but probably we need another cache for the skeleton-to-pattern computation, because that one is relatively slow, IIRC. And because we can't cache all possible locale x options combinations (there are simply too many possible combinations), we probably still want to track the memory usage somehow. :-)

Comment 17

[André Bargull [:anba]]

Attachment: IcuMemoryUsage.java

Comment 18

[André Bargull [:anba]]

Using the attached Java script file, I got the following memory report in an instrumented shell:

Name	max	min	avg	50p	75p	85p	95p	99p	mem
Collator	1128	272	1061	1128	1128	1128	1128	1128	527088
DateTimeFormat	91626	43936	45627	46416	46416	46416	46416	46416	5309645
ListFormat	24	24	24	24	24	24	24	24	546249
NumberFormat	750	744	744	744	744	744	744	744	764202
PluralRules	2976	336	864	712	832	1088	2216	2608	1505768
RelativeTimeFormat	278	272	272	272	272	272	272	272	13981282

The max/min/avg/Xp columns display the memory use in bytes for a single Intl object. The last column ("mem") shows the memory ICU is using for (internal) caches after instantiating Intl objects for many locales (*). The last column isn't terribly interesting for this issue, but I thought it's interesting to know how large certain ICU caches can grow.

The memory report shows that especially Intl.DateTimeFormat are quite heavyweight, with an average of 45KB per instance and up to 91KB. (91KB were used for the case when the calendar was set to the Japanese imperial calendar.)

(*) This situation won't occur in normal websites, because no website will display numbers or dates in hundreds of different locales.

Comment 19

[André Bargull [:anba]]

For completeness sake also the DateTimeFormat numbers when all locales and all calendar options are tried.

Name	max	min	avg	50p	75p	85p	95p	99p	mem
DateTimeFormat	91716	43936	48480	46289	46805	49261	89333	91626	9720261

The 99th percentile matches the maximum usage from comment #18, so I'd say when estimating the memory usage we can simply take the maximum numbers from comment #18 to account for most scenarios.

Comment 20

[André Bargull [:anba]]

Attachment: Bug 1585536: Track estimated malloc memory use for ICU objects. r=jonco!

The estimated memory is based on the maximum observed memory usage when running
the Java script attached to the bug report.

Comment 21

[André Bargull [:anba]]

With the patch applied, the max. RSS drops from 4.0 GB to 74 MB for me (at 60000 iterations).

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/6a9b59646d09
Track estimated malloc memory use for ICU objects. r=jonco

Comment 23

[Oana Pop-Rus]

Backed out changeset 6a9b59646d09 (bug 1585536) for Spidermonkey build bustages on Collator.cpp

Push that started the failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=273891202&resultStatus=pending%2Crunning%2Csuccess%2Csuperseded%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&searchStr=linux%2Cx64%2Cdebug%2Cspidermonkey%2Cbuilds%2Chazard-linux64-shell-haz%2Fdebug%2Csm%28h%29&revision=6a9b59646d094cb8d8561e15c1f81269651544e9

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=273891202&repo=autoland&lineNumber=8693

Backout: https://hg.mozilla.org/integration/autoland/rev/9a2e7d38cb07538761fdef5512550618cb00b3fa

Comment 24

[André Bargull [:anba]]

Sigh. I should have seen this coming... :-/

Comment 25

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2c09452b6063
Track estimated malloc memory use for ICU objects. r=jonco

Comment 26

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/2c09452b6063