Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Subfont never finishes #154

Closed
AcrylicShrimp opened this issue Dec 5, 2021 · 30 comments
Closed

Subfont never finishes #154

AcrylicShrimp opened this issue Dec 5, 2021 · 30 comments

Comments

@AcrylicShrimp
Copy link

AcrylicShrimp commented Dec 5, 2021

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
Copy link
Collaborator

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
Copy link
Author

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

@AcrylicShrimp
Copy link
Author

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

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

@papandreou
Copy link
Collaborator

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

@AcrylicShrimp
Copy link
Author

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

@papandreou
Copy link
Collaborator

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
Copy link
Author

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
Copy link
Author

AcrylicShrimp commented Dec 5, 2021

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
Copy link
Collaborator

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

@papandreou
Copy link
Collaborator

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

@AcrylicShrimp
Copy link
Author

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

@papandreou
Copy link
Collaborator

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

@AcrylicShrimp
Copy link
Author

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
Copy link
Collaborator

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

@AcrylicShrimp
Copy link
Author

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
Copy link
Collaborator

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

@AcrylicShrimp
Copy link
Author

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

@papandreou
Copy link
Collaborator

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
Copy link
Author

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

@papandreou
Copy link
Collaborator

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

@AcrylicShrimp
Copy link
Author

Yes.

@AcrylicShrimp
Copy link
Author

I can reproduce this problem in even macOS. Hmm.

@AcrylicShrimp
Copy link
Author

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
Copy link
Author

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

스크린샷 2021-12-07 오후 3 57 13

스크린샷 2021-12-07 오후 3 59 32

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

@AcrylicShrimp
Copy link
Author

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
Copy link
Collaborator

Ah, wow, nice work!

@AcrylicShrimp
Copy link
Author

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
Copy link
Collaborator

I'm sure we can figure that out together!

@AcrylicShrimp
Copy link
Author

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
Copy link
Collaborator

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 😇

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants