Subfont never finishes

[AcrylicShrimp]

Hello! Suddenly the subfont is stuck at populate.

> subfont --root ./dist --canonical-root https://blog.ashrimp.dev/ --output ./dist-opt --inline-css --no-fallbacks --debug ./dist/**/*.html

 ✔ 0.005 secs: logEvents
 ✔ 0.541 secs: loadAssets
 ⚠ WARN: dist\posts\meteorknight-engine-devlog-1\vid\demo.mp4 - spawn file ENOENT
         Including assets:
             dist\posts\meteorknight-engine-devlog-1\index.html

 ✔ 0.256 secs: populate
 ✔ 0.012 secs: checkIncompatibleTypes
 ✔ 0.007 secs: applySourceMaps
 ⚠ WARN: dist\posts\meteorknight-engine-devlog-1\vid\demo.mp4 - spawn file ENOENT
         Including assets:
             dist\posts\meteorknight-engine-devlog-1\index.html

 ✔ 0.017 secs: populate

And it never finishes without any additional output. What things should I check? Thank you!

EDIT

After long waiting, below is printed.

<--- Last few GCs --->

[17268:0000016D46B30090]  1848042 ms: Mark-sweep (reduce) 327.1 (413.1) -> 326.7 (357.2) MB, 262.8 / 0.0 ms  (average mu = 0.182, current mu = 0.088) last resort GC in old space requested[17268:0000016D46B30090]  1848352 ms: Mark-sweep (reduce) 326.7 (357.2) -> 326.7 (347.7) MB, 310.0 / 0.0 ms  (average mu = 0.092, current mu = 0.000) last resort GC in old space requested

<--- JS stacktrace --->

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: 00007FF7E492DF0F v8::internal::CodeObjectRegistry::~CodeObjectRegistry+113567
 2: 00007FF7E48BD736 v8::internal::MicrotaskQueue::GetMicrotasksScopeDepth+67398
 3: 00007FF7E48BE5ED node::OnFatalError+301
 4: 00007FF7E52B0CAE v8::Isolate::ReportExternalAllocationLimitReached+94
 5: 00007FF7E529B2FD v8::Isolate::Exit+653
 6: 00007FF7E513EC5C v8::internal::Heap::EphemeronKeyWriteBarrierFromCode+1468
 7: 00007FF7E5139BCE v8::internal::Heap::AllocateExternalBackingStore+2174
 8: 00007FF7E5156ADA v8::internal::Factory::CodeBuilder::AllocateCode+106
 9: 00007FF7E51570A4 v8::internal::Factory::CodeBuilder::BuildInternal+580
10: 00007FF7E5156D46 v8::internal::Factory::CodeBuilder::Build+22
11: 00007FF7E4C194B3 v8::internal::RegExpMacroAssemblerX64::GetCode+4259
12: 00007FF7E4EBD4E1 v8::internal::RegExpErrorString+8993
13: 00007FF7E4EA769E v8::PropertyDescriptor::value+5294
14: 00007FF7E4EA7ACE v8::internal::RegExp::CompileForTesting+526
15: 00007FF7E4EA80C8 v8::internal::RegExp::DotPrintForTesting+248
16: 00007FF7E4EA8FFB v8::internal::RegExp::ExperimentalOneshotExec+2491
17: 00007FF7E4EA8B1E v8::internal::RegExp::ExperimentalOneshotExec+1246
18: 00007FF7E4EA8587 v8::internal::RegExp::Exec+199
19: 00007FF7E4E838FC v8::internal::DeclarationScope::was_lazily_parsed+21260
20: 00007FF7E5343281 v8::internal::SetupIsolateDelegate::SetupHeap+513585
21: 00007FF7E53A0AA6 v8::internal::SetupIsolateDelegate::SetupHeap+896598
22: 0000016D503CB7C9

[papandreou]

Hard to know exactly what's going on without a copy of your dist directory, but it could look like subfont is trying to slurp a bunch of big video files into memory as part of the population.

[AcrylicShrimp]

@papandreou Thanks! But I'm wonder: why subfont tries to load video files? Does it needed?

[AcrylicShrimp]

And here's the dist directory. Check it if you need some tests.

https://www.dropbox.com/s/pfmo2e3af5t2qpg/dist.zip?dl=0

[papandreou]

Thanks. No, it doesn’t need the video files, so we’re in bug territory :)

[AcrylicShrimp]

I removed whole pages that contains video and same again. It still stuck.

[papandreou]

Hmm, it works for me (with node.js 12.16.1) with your command and dist directory.

I noticed that you have some quite heavy fonts:

15395184 NotoSansMonoCJKkr-Bold.woff
12114352 NotoSansMonoCJKkr-Bold.woff2
14928504 NotoSansMonoCJKkr-Regular.woff
11416896 NotoSansMonoCJKkr-Regular.woff2

All of those will be loaded into memory, so you have to make sure that you have enough and that node.js is allowed to use it.

[AcrylicShrimp]

All of those will be loaded into memory, so you have to make sure that you have enough and that node.js is allowed to use it.

You mean I have to make sure that nodejs takes enough memory? My machine has 32GiB memory, I think it's ok. Is there way to specify memory related options in subfont?

[AcrylicShrimp]

Hmm, it works for me (with node.js 12.16.1) with your command and dist directory.

I noticed that you have some quite heavy fonts:

15395184 NotoSansMonoCJKkr-Bold.woff
12114352 NotoSansMonoCJKkr-Bold.woff2
14928504 NotoSansMonoCJKkr-Regular.woff
11416896 NotoSansMonoCJKkr-Regular.woff2

All of those will be loaded into memory, so you have to make sure that you have enough and that node.js is allowed to use it.

Wait, I removed whole fonts and it still stucks. Hmm.

[papandreou]

Wrt. allowing it to use the memory I meant something like node --max-old-space-size=30000 path/to/subfont ...

[papandreou]

From the GC message it could look like your node thinks it's only allowed to use 512 MB.

[AcrylicShrimp]

@papandreou How long does it take to complete when you tested? And yes, it seems it's memory problem.

[papandreou]

real    1m30,825s
user    1m44,569s
sys 0m3,159s

[AcrylicShrimp]

real  1m30,825s
user  1m44,569s
sys   0m3,159s

1 minute and 30 seconds? That's weird. It's still running on my machine for a long time.

[papandreou]

Does --max-old-space-size=... help?

[AcrylicShrimp]

Does --max-old-space-size=... help?

With below command, it stuck too.

node --max-old-space-size=30000 ./node_modules/subfont/lib/cli.js --root ./dist --canonical-root https://blog.ashrimp.dev/ --output ./dist-opt --inline-css --no-fallbacks --debug ./dist/**/*.html

[papandreou]

Okay, weird that we're getting different results. Which version of node are you on?

[AcrylicShrimp]

I tried both v17.1.0 and v16.13.0. subfont version is 6.4.0. And I also in Windows 10.

[papandreou]

Looks like it also works for me with node.js 16.13.0, although it takes longer:

real    2m26,533s
user    2m34,528s
sys 0m2,580s

[AcrylicShrimp]

Thanks for testing :) But still I don't get it... Hmmmmm.

[papandreou]

Are you also trying with the exact contents of dist that you put into dropbox?

[AcrylicShrimp]

Yes.

[AcrylicShrimp]

I can reproduce this problem in even macOS. Hmm.

[AcrylicShrimp]

Ok, I got it. I tested it a lot on my macOS machine and found that the subfont won't work when the dist/index.html is included. Below command,

node --max-old-space-size=30000 ./node_modules/subfont/lib/cli.js --root ./dist --canonical-root https://blog.ashrimp.dev/ --output ./dist-opt --inline-css --no-fallbacks ./dist/**/*.html

doesn't include the dist/index.html(I think its bug or something). But the fun fact is when I remove the input, the subfont is going to defaults it with below message.

No input files specified, defaulting to file:///Users/ashrimp/Devel/Projects/devlog/devlog-ssg/dist/**/*.html

In this case, the subfont tries to process dist/index.html even though the explicit input ./dist/**/*.html does not.

Anyway, the subfont won't work when the dist/index.html is included. Hmmmmmmm. I'll try more.

[AcrylicShrimp]

After some printf-debugging, I found that its not stuck but it takes toooooooo long to call fontTracer. I don't know why.

What do you think? I'm going to analyze the font-tracer.

[AcrylicShrimp]

After many, many tries, I finally profiled the subfont, and got some critical informations.

Look at this:

   ticks parent  name
  11890   69.1%  C:\Program Files\nodejs\node.exe
   9765   82.1%    C:\Program Files\nodejs\node.exe
   5957   61.0%      LazyCompile: *DOMException D:\Devel\Projects\devlog\devlog-ssg\node_modules\domexception\lib\DOMException.js:86:18
   5957  100.0%        LazyCompile: ~emit D:\Devel\Projects\devlog\devlog-ssg\node_modules\nwsapi\src\nwsapi.js:559:13
   5957  100.0%          Function: ^compileSelector D:\Devel\Projects\devlog\devlog-ssg\node_modules\nwsapi\src\nwsapi.js:775:13
   5957  100.0%            LazyCompile: *compile D:\Devel\Projects\devlog\devlog-ssg\node_modules\nwsapi\src\nwsapi.js:724:13
   1977   20.2%      LazyCompile: ~emit D:\Devel\Projects\devlog\devlog-ssg\node_modules\nwsapi\src\nwsapi.js:559:13
   1977  100.0%        Function: ^compileSelector D:\Devel\Projects\devlog\devlog-ssg\node_modules\nwsapi\src\nwsapi.js:775:13
   1971   99.7%          LazyCompile: *compile D:\Devel\Projects\devlog\devlog-ssg\node_modules\nwsapi\src\nwsapi.js:724:13
   1971  100.0%            LazyCompile: *_matches D:\Devel\Projects\devlog\devlog-ssg\node_modules\nwsapi\src\nwsapi.js:1364:22
    582    6.0%      C:\Program Files\nodejs\node.exe
    276   47.4%        LazyCompile: *traceProp D:\Devel\Projects\devlog\devlog-ssg\node_modules\font-tracer\lib\fontTracer.js:217:25
    177   64.1%          LazyCompile: *memoizeSync.argumentsStringifier D:\Devel\Projects\devlog\devlog-ssg\node_modules\font-tracer\lib\fontTracer.js:160:5
    177  100.0%            Function: ^memoizer D:\Devel\Projects\devlog\devlog-ssg\node_modules\memoizesync\lib\memoizeSync.js:47:26
     99   35.9%          Function: ^memoizeSync.argumentsStringifier D:\Devel\Projects\devlog\devlog-ssg\node_modules\font-tracer\lib\fontTracer.js:160:5
     99  100.0%            Function: ^memoizer D:\Devel\Projects\devlog\devlog-ssg\node_modules\memoizesync\lib\memoizeSync.js:47:26
    100   17.2%        LazyCompile: *_matches D:\Devel\Projects\devlog\devlog-ssg\node_modules\nwsapi\src\nwsapi.js:1364:22
     99   99.0%          LazyCompile: *ElementImpl.matches D:\Devel\Projects\devlog\devlog-ssg\node_modules\jsdom\lib\jsdom\living\nodes\Element-impl.js:568:42
     98   99.0%            LazyCompile: *traceProp D:\Devel\Projects\devlog\devlog-ssg\node_modules\font-tracer\lib\fontTracer.js:217:25
      1    1.0%            LazyCompile: *safeMatchesSelector D:\Devel\Projects\devlog\devlog-ssg\node_modules\font-tracer\lib\fontTracer.js:21:29
      1    1.0%          Function: ^ElementImpl.matches D:\Devel\Projects\devlog\devlog-ssg\node_modules\jsdom\lib\jsdom\living\nodes\Element-impl.js:568:42
      1  100.0%            LazyCompile: *safeMatchesSelector D:\Devel\Projects\devlog\devlog-ssg\node_modules\font-tracer\lib\fontTracer.js:21:29
...

The DOMException takes most of the time. So I added some debug logs to know what's going on.

    class DOMException {
      constructor() {
        const args = [];
        {
          let curArg = arguments[0];
          if (curArg !== undefined) {
            curArg = conversions["DOMString"](curArg, { context: "Failed to construct 'DOMException': parameter 1" });
          } else {
            curArg = "";
          }
          args.push(curArg);
        }
        {
          let curArg = arguments[1];
          if (curArg !== undefined) {
            curArg = conversions["DOMString"](curArg, { context: "Failed to construct 'DOMException': parameter 2" });
          } else {
            curArg = "Error";
          }
          args.push(curArg);
        }
        console.log(`DOMException constructor args: ${args}`);``
        return iface.setup(Object.create(new.target.prototype), globalObject, args);
      }

And here's the output:

DOMException constructor args: unknown pseudo-class selector ':translate-x-8',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-x-7',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-x-6',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-x-5',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-x-4',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-x-3',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-x-2',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-x-1',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-x-0',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-full',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-3\/4',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-2\/4',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-1\/4',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-2\/3',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-1\/3',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-1\/2',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-y-full',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-y-3\/4',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-y-2\/4',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-y-1\/4',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-y-2\/3',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-y-1\/3',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':translate-y-1\/2',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-3\.5',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-2\.5',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-1\.5',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-0\.5',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-px',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-96',SyntaxError
DOMException constructor args: unknown pseudo-class selector ':-translate-y-80',SyntaxError

What is it? It tries to select pseudo-class :-translate and similar. And yes, they came from the tailwindCSS. The tailwindCSS uses special character : for class names by escaping it with \. So the cause is so obvious now. The logic for extracting all used CSS selector does not handle escapes correctly. I'm not sure what part is wrong for now, but I'll comment here when it's done.

[papandreou]

Ah, wow, nice work!

[AcrylicShrimp]

Ok, I ended this with enabling purge option in the tailwindCSS... It dramatically reduces css classes so it's working. But it's good to handle escapes correctly(not easy though).

[papandreou]

I'm sure we can figure that out together!

[AcrylicShrimp]

I found that I don't need to handle backslash escapes for now. There's no class names includes : after purging unused classes. So, let's close this issue. I'll re-open it when the problem arises again.

Thanks for your hark work @papandreou.

[papandreou]

You're welcome, happy that you found a way to avoid it. If you feel that there's a bug in font-tracer, please give me a hint 😇