Closed AcrylicShrimp closed 2 years ago
It reaches 38GiB and never finishes :(
Ok, I tested all of subfont versions and there's no difference. And the debug option --debug
does not print any debug information.
npx subfont --root ./dist --canonical-root https://blog.ashrimp.dev/ --output ./dist-opt --inline-css --no-fallbacks --debug --dry-run
No input files specified, defaulting to file:///Users/ashrimp/Devel/devlog/devlog-ssg/dist/**/*.html
✔ 0.002 secs: logEvents
✔ 0.333 secs: loadAssets
✔ 0.047 secs: populate
✔ 0.011 secs: checkIncompatibleTypes
✔ 0.004 secs: applySourceMaps
✔ 0.009 secs: populate
And here's the profiling report.
node --prof ./node_modules/subfont/lib/cli.js --root ./dist --canonical-root https://blog.ashrimp.dev/ --output ./dist-opt --inline-css --no-fallbacks
Statistical profiling result from isolate-0x150008000-3552-v8.log, (251330 ticks, 364 unaccounted, 0 excluded).
[Shared libraries]:
ticks total nonlib name
314 0.1% /usr/lib/system/libsystem_malloc.dylib
59 0.0% /usr/lib/system/libsystem_pthread.dylib
46 0.0% /usr/lib/system/libsystem_kernel.dylib
43 0.0% /usr/lib/system/libsystem_c.dylib
24 0.0% /usr/lib/libc++.1.dylib
8 0.0% /usr/lib/system/libdyld.dylib
7 0.0% /usr/lib/system/libsystem_platform.dylib
5 0.0% /usr/lib/libc++abi.dylib
[JavaScript]:
ticks total nonlib name
12897 5.1% 5.1% LazyCompile: *expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
8 0.0% 0.0% LazyCompile: *resolve node:path:1091:10
2 0.0% 0.0% RegExp: (?::(?:active|any|checked|default|empty|enabled|fullscreen|focus|hover|indeterminate|in-range|invalid|link|optional|out-of-range|read-only|read-write|scope|target|valid|visited))+
2 0.0% 0.0% LazyCompile: *_processToken /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/parse5/lib/parser/index.js:656:18
2 0.0% 0.0% Function: ^traceProp /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/fontTracer.js:260:25
2 0.0% 0.0% Function: ^tinf_inflate_block_data /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/tiny-inflate/index.js:246:33
2 0.0% 0.0% Function: ^expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
1 0.0% 0.0% RegExp: (^|\s)mathscr(\s|$)
1 0.0% 0.0% RegExp: (?:^| )preload(?:$| )
1 0.0% 0.0% LazyCompile: *traceProp /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/fontTracer.js:260:25
1 0.0% 0.0% LazyCompile: *queueMutationRecord /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/helpers/mutation-observers.js:33:29
1 0.0% 0.0% LazyCompile: *parse /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/sift/lib/index.js:476:15
1 0.0% 0.0% LazyCompile: *nestedValidator /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/sift/lib/index.js:412:25
1 0.0% 0.0% LazyCompile: *matches /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/generated/Element.js:613:12
1 0.0% 0.0% LazyCompile: *get childNodes /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/generated/Node.js:526:19
1 0.0% 0.0% LazyCompile: *format node:url:617:39
1 0.0% 0.0% LazyCompile: *findValues /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/sift/lib/index.js:439:20
1 0.0% 0.0% LazyCompile: *exports.is /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/generated/Node.js:15:14
1 0.0% 0.0% LazyCompile: *createDeclarationGenerator /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/fontTracer.js:160:37
1 0.0% 0.0% LazyCompile: *compare /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/sift/lib/index.js:557:17
1 0.0% 0.0% LazyCompile: *comparable /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/sift/lib/index.js:37:20
1 0.0% 0.0% LazyCompile: *_update /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/nodes/NodeList-impl.js:27:10
1 0.0% 0.0% LazyCompile: *<anonymous> /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/sift/lib/index.js:57:19
1 0.0% 0.0% Function: ^startTagInBody /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/parse5/lib/parser/index.js:1677:24
1 0.0% 0.0% Function: ^shadowIncludingInclusiveDescendantsIterator /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/helpers/shadow-dom.js:238:54
1 0.0% 0.0% Function: ^set readyState /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/nodes/Document-impl.js:272:17
1 0.0% 0.0% Function: ^resolve node:path:1091:10
1 0.0% 0.0% Function: ^realpathSync node:fs:2439:22
1 0.0% 0.0% Function: ^queueAttributeMutationRecord /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/helpers/mutation-observers.js:110:38
1 0.0% 0.0% Function: ^parse /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/sift/lib/index.js:476:15
1 0.0% 0.0% Function: ^makeWrapper /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/generated/DOMStringMap.js:26:21
1 0.0% 0.0% Function: ^isEncoding node:buffer:532:40
1 0.0% 0.0% Function: ^getPosition /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/postcss/lib/parser.js:404:14
1 0.0% 0.0% Function: ^get parentNode /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/nodes/Node-impl.js:148:17
1 0.0% 0.0% Function: ^get nodeName /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/nodes/Node-impl.js:156:15
1 0.0% 0.0% Function: ^get namespaceURI /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/nodes/Element-impl.js:126:19
1 0.0% 0.0% Function: ^get lastChild /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/nodes/Node-impl.js:197:16
1 0.0% 0.0% Function: ^get canonicalRoot /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/assetgraph/lib/AssetGraph.js:116:20
1 0.0% 0.0% Function: ^get /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/sift/lib/index.js:49:13
1 0.0% 0.0% Function: ^exports.create /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/generated/DOMStringMap.js:48:18
1 0.0% 0.0% Function: ^expandCustomProperties /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandCustomProperties.js:7:32
1 0.0% 0.0% Function: ^end /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/postcss/lib/parser.js:366:6
1 0.0% 0.0% Function: ^decl /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/postcss/lib/parser.js:179:7
1 0.0% 0.0% Function: ^childrenToArray /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/symbol-tree/lib/SymbolTree.js:265:24
1 0.0% 0.0% Function: ^_shouldProcessTokenInForeignContent /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/parse5/lib/parser/index.js:612:40
1 0.0% 0.0% Function: ^Resolver :3:38
1 0.0% 0.0% Function: ^Module._resolveLookupPaths node:internal/modules/cjs/loader:668:38
1 0.0% 0.0% Function: ^JSDOM /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/api.js:30:14
1 0.0% 0.0% Function: ^<anonymous> node:internal/validators:72:3
1 0.0% 0.0% Function: ^<anonymous> node:internal/fs/utils:669:38
1 0.0% 0.0% Function: ^<anonymous> node:internal/fs/utils:637:3
1 0.0% 0.0% Function: ^<anonymous> /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/parse5/lib/tokenizer/index.js:587:17
1 0.0% 0.0% Function: ^<anonymous> /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/generated/HTMLUListElement.js:90:25
1 0.0% 0.0% Function: ^<anonymous> /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/jsdom/lib/jsdom/living/generated/Element.js:1249:54
[C++]:
ticks total nonlib name
191019 76.0% 76.2% T node::fs::BindingData::MemoryInfo(node::MemoryTracker*) const
19590 7.8% 7.8% t __os_nospin_lock_unlock_slow
10151 4.0% 4.0% T ___bsdthread_terminate
9370 3.7% 3.7% T _task_restartable_ranges_register
2820 1.1% 1.1% T _semaphore_signal
1934 0.8% 0.8% T __kernelrpc_mach_port_get_refs
1569 0.6% 0.6% T _mach_port_insert_member
505 0.2% 0.2% T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
152 0.1% 0.1% t __os_once_gate_wait
102 0.0% 0.0% T _sigprocmask
50 0.0% 0.0% T _connect$NOCANCEL
36 0.0% 0.0% t __os_nospin_lock_lock_slow
33 0.0% 0.0% T __kernelrpc_mach_port_move_member_trap
30 0.0% 0.0% T ___libplatform_init
23 0.0% 0.0% T _mach_port_insert_right
19 0.0% 0.0% t ___pfz_setup
18 0.0% 0.0% T _mach_port_deallocate
11 0.0% 0.0% t std::__1::basic_ostream<char, std::__1::char_traits<char> >& std::__1::__put_character_sequence<char, std::__1::char_traits<char> >(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, char const*, unsigned long)
11 0.0% 0.0% T node::contextify::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
7 0.0% 0.0% T ___pthread_init
6 0.0% 0.0% t std::__1::ostreambuf_iterator<char, std::__1::char_traits<char> > std::__1::__pad_and_output<char, std::__1::char_traits<char> >(std::__1::ostreambuf_iterator<char, std::__1::char_traits<char> >, char const*, char const*, char const*, std::__1::ios_base&, char)
6 0.0% 0.0% T _posix_spawnattr_setflags
5 0.0% 0.0% T node::contextify::ContextifyContext::MakeContext(v8::FunctionCallbackInfo<v8::Value> const&)
5 0.0% 0.0% T _task_get_exception_ports
3 0.0% 0.0% T _pthread_mutex_trylock
3 0.0% 0.0% T _pthread_cond_signal
2 0.0% 0.0% t void node::Buffer::(anonymous namespace)::StringSlice<(node::encoding)1>(v8::FunctionCallbackInfo<v8::Value> const&)
2 0.0% 0.0% T node::fs::Close(v8::FunctionCallbackInfo<v8::Value> const&)
2 0.0% 0.0% T _os_unfair_recursive_lock_unlock
1 0.0% 0.0% t void std::__1::__tree_balance_after_insert<std::__1::__tree_node_base<void*>*>(std::__1::__tree_node_base<void*>*, std::__1::__tree_node_base<void*>*)
1 0.0% 0.0% t std::__1::deque<unsigned long, std::__1::allocator<unsigned long> >::__add_back_capacity()
1 0.0% 0.0% t std::__1::__shared_ptr_pointer<char*, std::__1::default_delete<char []>, std::__1::allocator<char> >::__on_zero_shared_weak()
1 0.0% 0.0% t node::EnvGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
1 0.0% 0.0% t node::Buffer::(anonymous namespace)::CreateFromString(v8::FunctionCallbackInfo<v8::Value> const&)
1 0.0% 0.0% t __pthread_mutex_droplock
1 0.0% 0.0% T _pthread_testcancel
1 0.0% 0.0% T _pthread_qos_max_parallelism
1 0.0% 0.0% T _pthread_override_qos_class_start_np
1 0.0% 0.0% T _pthread_mutexattr_settype
1 0.0% 0.0% T _pthread_atfork
1 0.0% 0.0% T _os_unfair_recursive_lock_lock_with_options
1 0.0% 0.0% T __platform_strncmp
1 0.0% 0.0% T __os_semaphore_dispose
[Summary]:
ticks total nonlib name
12962 5.2% 5.2% JavaScript
237498 94.5% 94.7% C++
209960 83.5% 83.7% GC
506 0.2% Shared libraries
364 0.1% Unaccounted
[C++ entry points]:
ticks cpp total name
27334 97.7% 10.9% T node::fs::BindingData::MemoryInfo(node::MemoryTracker*) const
505 1.8% 0.2% T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
35 0.1% 0.0% T _sigprocmask
29 0.1% 0.0% T __kernelrpc_mach_port_move_member_trap
18 0.1% 0.0% T _mach_port_deallocate
11 0.0% 0.0% T node::contextify::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
10 0.0% 0.0% t std::__1::basic_ostream<char, std::__1::char_traits<char> >& std::__1::__put_character_sequence<char, std::__1::char_traits<char> >(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, char const*, unsigned long)
9 0.0% 0.0% t __os_once_gate_wait
5 0.0% 0.0% T node::contextify::ContextifyContext::MakeContext(v8::FunctionCallbackInfo<v8::Value> const&)
5 0.0% 0.0% T _task_get_exception_ports
4 0.0% 0.0% t std::__1::ostreambuf_iterator<char, std::__1::char_traits<char> > std::__1::__pad_and_output<char, std::__1::char_traits<char> >(std::__1::ostreambuf_iterator<char, std::__1::char_traits<char> >, char const*, char const*, char const*, std::__1::ios_base&, char)
4 0.0% 0.0% t ___pfz_setup
3 0.0% 0.0% T _task_restartable_ranges_register
3 0.0% 0.0% T ___libplatform_init
2 0.0% 0.0% t void node::Buffer::(anonymous namespace)::StringSlice<(node::encoding)1>(v8::FunctionCallbackInfo<v8::Value> const&)
2 0.0% 0.0% t __os_nospin_lock_unlock_slow
2 0.0% 0.0% T node::fs::Close(v8::FunctionCallbackInfo<v8::Value> const&)
2 0.0% 0.0% T _mach_port_insert_member
2 0.0% 0.0% T __kernelrpc_mach_port_get_refs
1 0.0% 0.0% t void std::__1::__tree_balance_after_insert<std::__1::__tree_node_base<void*>*>(std::__1::__tree_node_base<void*>*, std::__1::__tree_node_base<void*>*)
1 0.0% 0.0% t node::EnvGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
1 0.0% 0.0% t node::Buffer::(anonymous namespace)::CreateFromString(v8::FunctionCallbackInfo<v8::Value> const&)
1 0.0% 0.0% T _os_unfair_recursive_lock_lock_with_options
[Bottom up (heavy) profile]:
Note: percentage shows a share of a particular caller in the total
amount of its parent calls.
Callers occupying less than 1.0% are not shown.
ticks parent name
191019 76.0% T node::fs::BindingData::MemoryInfo(node::MemoryTracker*) const
24695 12.9% LazyCompile: *expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
24672 99.9% T node::fs::BindingData::MemoryInfo(node::MemoryTracker*) const
24448 99.1% LazyCompile: *expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
24448 100.0% T node::fs::BindingData::MemoryInfo(node::MemoryTracker*) const
24134 98.7% LazyCompile: *expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
314 1.3% LazyCompile: ~<anonymous> /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/fontTracer.js:1015:56
19590 7.8% t __os_nospin_lock_unlock_slow
12897 5.1% LazyCompile: *expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
12456 96.6% T node::fs::BindingData::MemoryInfo(node::MemoryTracker*) const
12265 98.5% LazyCompile: *expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
12265 100.0% T node::fs::BindingData::MemoryInfo(node::MemoryTracker*) const
12098 98.6% LazyCompile: *expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
12098 100.0% T node::fs::BindingData::MemoryInfo(node::MemoryTracker*) const
167 1.4% LazyCompile: ~<anonymous> /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/fontTracer.js:1015:56
167 100.0% Function: ^arrayMap /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/lodash/lodash.js:647:20
191 1.5% LazyCompile: ~<anonymous> /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/fontTracer.js:1015:56
191 100.0% Function: ^arrayMap /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/lodash/lodash.js:647:20
191 100.0% LazyCompile: ~map /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/lodash/lodash.js:9620:17
191 100.0% LazyCompile: ~flatMap /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/lodash/lodash.js:9324:21
437 3.4% LazyCompile: *expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
437 100.0% T node::fs::BindingData::MemoryInfo(node::MemoryTracker*) const
433 99.1% LazyCompile: *expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
433 100.0% T node::fs::BindingData::MemoryInfo(node::MemoryTracker*) const
428 98.8% LazyCompile: *expandPermutations /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/expandPermutations.js:11:29
5 1.2% LazyCompile: ~<anonymous> /Users/ashrimp/Devel/devlog/devlog-ssg/node_modules/font-tracer/lib/fontTracer.js:1015:56
10151 4.0% T ___bsdthread_terminate
9370 3.7% T _task_restartable_ranges_register
2820 1.1% T _semaphore_signal
I traced source code, and I found that the fontTracer
is never finishes.
// subsetFonts.js L679
console.log('tracing font...');
const textByProps = fontTracer(htmlOrSvgAsset.parseTree, {
stylesheetsWithPredicates: gatherStylesheetsWithPredicates(
htmlOrSvgAsset.assetGraph,
htmlOrSvgAsset
),
getCssRulesByProperty: memoizedGetCssRulesByProperty,
asset: htmlOrSvgAsset,
});
console.log(`1) textByProps.length: ${textByProps.length}`);
It stucks printing below.
tracing font...
I traced some more. I found a function ...expandPermutations(props)
, which never finishes(and consumes infinite memories).
When I looked into the input object, it has 64 keys which has 35184372088832 of all possible permutations...
Is it intended? I'm not sure which side is wrong for input or it's logic.
Please let me know if you need more information.
Thank you.
I finally found a correct cause and a way to bypass it.
The actual cause of this problem is again, the tailwindcss
(is this an evil???). It emits a lot of css properties that starts with --tw-
. This enlarges the total permutations so common PCs cannot handle it.
So I added a small script to remove them(I'm sure they never contribute for font tracing).
(Before the below) https://github.com/assetgraph/font-tracer/blob/8b15e4735a5e837c94ce86b19d0bd8673c0bf9b5/lib/fontTracer.js#L1014
// Purge the custom css properties from the tailwindcss
for (const styledText of styledTexts) {
styledText.props =
Object.keys(styledText.props)
.filter(key => !key.startsWith("--tw-")).reduce((acc, key) => {
acc[key] = styledText.props[key];
return acc;
}, {});
}
And good, it works again! (and quite fast 🚀)
But I'm still wondering if this specific care can be generalized. What do you think? Can we add a configuration to ignore some css properties?
Thank you again!
Thank you for reporting this. I didn't know that a large number of CSS variables would cause an exponential effect on permutations in that way. I can think of no easy fix right now, but we'll definitely have to look into how to avoid that somehow.
Looking at https://play.tailwindcss.com/ it seems like tailwind applies all of its theme variables to EVERY element and pseudo-element with a *, *::before, *::after
selector. This seems like bad practice. Shouldn't those just be set once on a single top-level element like html
or body
?
I think it's going to be difficult to avoid diving into permutations, but maybe there's are optimizations that can be achieved by only creating permutations for variables known to affect font styles, or realizing that the selector is the same, and maybe using that information to reduce the number of permutations.
It's a long time since I looked at that code, so I am not entirely sure what can be done. Maybe @papandreou has more qualified insights here.
I don't think a CSS blacklist is the way to go. It could very easily end up resulting in wrong subsets with no good way of detecting that
I've also been thinking about this problem. I've been wondering if it's possible to collapse some of the hypothetical states together if we can prove that a bunch of predicates are all false or true together. I'm not sure it'll work, and it'll probably be a big effort, so no promises :)
@AcrylicShrimp, can you share a copy of your dist
directory?
@papandreou Here's what you want :)
Thanks, it's certainly reproducible :see_no_evil:
I applied a quick fix to not bother with custom properties that don't affect font styles, as @Munter suggested. That's enough to get the run time down to a few seconds. Released font-tracer 3.2.0 and subfont 6.6.0 with the fix.
The subfont trying to consume all of the memory.
(It reaches 28GiB now)
What's wrong with it?
I'm using subfont version
6.4.2
on M1 Macbook.