Nick

Reporter

Description

•

5 years ago

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;

})();

Nick

Reporter

Comment 1

•

5 years ago

Attached file shell-test.js — Details

Nick

Reporter

Comment 2

•

5 years ago

Attached file browser-test.js — Details

Liviu Seplecan

Comment 3

•

5 years ago

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

Component: Untriaged → JavaScript Engine

Flags: needinfo?(nickdev44)

Product: Firefox → Core

Nick

Reporter

Comment 4

•

5 years ago

For browser script

Preparations

Open two windows. WINDOW_1 and WINDOW_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.

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.

Flags: needinfo?(nickdev44)

Nick

Reporter

Comment 5

•

5 years ago

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.

Nick

Reporter

Comment 6

•

5 years ago

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.

Liviu Seplecan

Comment 7

•

5 years ago

Attached image bug 1585536 - about memory measure.png — Details

Liviu Seplecan

Comment 8

•

5 years ago

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

Status: UNCONFIRMED → NEW

status-firefox69: --- → affected

status-firefox70: --- → affected

status-firefox71: --- → affected

Component: JavaScript Engine → about:memory

Ever confirmed: true

OS: Unspecified → All

Product: Core → Toolkit

Hardware: Unspecified → Desktop

BugBot [:suhaib / :marco/ :calixte]

Comment 9

•

5 years ago

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

For more information, please visit auto_nag documentation.

Flags: needinfo?(n.nethercote)

Nicholas Nethercote [inactive]

Comment 10

•

5 years ago

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

Component: about:memory → JavaScript Engine

Flags: needinfo?(n.nethercote) → needinfo?(jdemooij)

Product: Toolkit → Core

Jan de Mooij [:jandem]

Comment 11

•

5 years ago

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

Flags: needinfo?(jdemooij) → needinfo?(andrebargull)

Jan de Mooij [:jandem]

Updated

•

5 years ago

Component: JavaScript Engine → JavaScript: Internationalization API

André Bargull [:anba]

Assignee

Comment 12

•

5 years ago

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.

Flags: needinfo?(andrebargull)

André Bargull [:anba]

Assignee

Comment 13

•

5 years ago

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. :-/

Flags: needinfo?(jcoppeard)

André Bargull [:anba]

Assignee

Comment 14

•

5 years ago

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.

Jon Coppeard (:jonco)

Comment 15

•

5 years ago

(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.

Flags: needinfo?(jcoppeard)

André Bargull [:anba]

Assignee

Comment 16

•

5 years ago

(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. :-)

André Bargull [:anba]

Assignee

Updated

•

5 years ago

Depends on: 1591711

André Bargull [:anba]

Assignee

Comment 17

•

5 years ago

Attached file IcuMemoryUsage.java — Details

Assignee: nobody → andrebargull

Status: NEW → ASSIGNED

André Bargull [:anba]

Assignee

Comment 18

•

5 years ago

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.

André Bargull [:anba]

Assignee

Comment 19

•

5 years ago

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.

André Bargull [:anba]

Assignee

Comment 20

•

5 years ago

Attached file Bug 1585536: Track estimated malloc memory use for ICU objects. r=jonco! — Details

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

André Bargull [:anba]

Assignee

Comment 21

•

5 years ago

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

Pulsebot

Comment 22

•

5 years ago

Pushed by opoprus@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6a9b59646d09
Track estimated malloc memory use for ICU objects. r=jonco

Oana Pop-Rus

Comment 23

•

5 years ago

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

Flags: needinfo?(andrebargull)

André Bargull [:anba]

Assignee

Comment 24

•

5 years ago

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

Flags: needinfo?(andrebargull)

Pulsebot

Comment 25

•

5 years ago

Pushed by csabou@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2c09452b6063
Track estimated malloc memory use for ICU objects. r=jonco

Stefan Hindli [:stefan_hindli]

Comment 26

•

5 years ago

bugherder

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

Status: ASSIGNED → RESOLVED

Closed: 5 years ago

status-firefox72: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → mozilla72

Ryan VanderMeulen [:RyanVM]

Updated

•

5 years ago

status-firefox69: affected → wontfix

status-firefox70: affected → wontfix

status-firefox71: affected → wontfix

shell-test.js 5 years ago Nick 492 bytes, application/x-javascript		Details
browser-test.js 5 years ago Nick 944 bytes, application/x-javascript		Details
bug 1585536 - about memory measure.png 5 years ago Liviu Seplecan 65.80 KB, image/png		Details
IcuMemoryUsage.java 5 years ago André Bargull [:anba] 8.35 KB, text/plain		Details
Bug 1585536: Track estimated malloc memory use for ICU objects. r=jonco! 5 years ago André Bargull [:anba] 47 bytes, text/x-phabricator-request		Details \| Review

toLocaleTimeString with locale memory usage

For browser script

Preparations

Run test

DURING RUN

Developer Tools Memory

Measurements

Updating about:memory from Web Console

Sample of result

At start

At 1 minute

At 3 minutes

At 4 minutes – First and only GC done

After 7 minutes

After 30 - 40 minutes