It looks like the site loading is done in parallel but the rendering is not: threads are spawned but only one seem used.
TODOs:
Site::render_section to ensure it uses as many threads as possible efficiently, might be a case of using https://docs.rs/rayon/1.0.2/rayon/iter/trait.IndexedParallelIterator.html#method.with_min_lenThere are some benches in site/benches but you will need to run the gen.py first to generate some. Given the current speed, the medium-blog and medium-kb are probably the best ones to run.
Heh. Spent a few minutes on this. Before:
Building site...
load sections 7.057634ms
load pages 7.569582ms
register_early_global_fns 47.949µs
28 pages
render pages 1.235751584s
5 sections
render sections 114.522µs
render_markdown 1.236066107s
populate_sections 4.705176ms
populate_taxonomies 990.847µs
register_tera_global_fns 3.33598ms
-> Creating 28 pages (0 orphan), 4 sections, and processing 0 images
Done in 1.4s.
After:
Building site...
load sections 6.787299ms
load pages 7.347483ms
register_early_global_fns 123.304µs
28 pages
render pages 172.197069ms
5 sections
render sections 505.971µs
render_markdown 172.937422ms
populate_sections 5.612221ms
populate_taxonomies 2.353669ms
register_tera_global_fns 4.012975ms
-> Creating 28 pages (0 orphan), 4 sections, and processing 0 images
Done in 312ms.
This call to par_mut_iter() seems problematic, since this is pretty much all I did:
diff --git components/site/src/lib.rs components/site/src/lib.rs
index 775d534..2ee3f93 100644
--- components/site/src/lib.rs
+++ components/site/src/lib.rs
@@ -271,13 +271,12 @@ impl Site {
pages_insert_anchors.insert(p.file.path.clone(), self.find_parent_section_insert_anchor(&p.file.parent.clone()));
}
- self.pages.par_iter_mut()
+ self.pages.iter_mut()
.map(|(_, page)| {
let insert_anchor = pages_insert_anchors[&page.file.path];
page.render_markdown(permalinks, tera, config, base_path, insert_anchor)
})
- .fold(|| Ok(()), Result::and)
- .reduce(|| Ok(()), Result::and)?;
+ .collect::<Result<()>>()?;
self.sections.par_iter_mut()
.map(|(_, section)| section.render_markdown(permalinks, tera, config, base_path))
That's interesting :o Just to be sure though: you are not running it in --release mode right? It might change things.
Can you push the branch with timings on? Looks like a good base to experiment on. From what I've seen with more pages (1000-10000), ~95% of the time is spent in https://github.com/Keats/gutenberg/blob/ae7a65b51f3dda4d6789483e930574437c6651e6/components/site/src/lib.rs#L850-L855 writing the pages to disk, which should be pretty fast in theory.
That is release mode, and it's generating my own site. gutenberg build on the blog and kb benchmarks are less impressive but still no worse.
(The actual cargo bench benchmarks seem of dubious value. I stopped the rendering one after the first test ate 2 hours of CPU time and was still going).
This is on a dual hex core Westmere Xeon, so default thread count is 24. A quick once-over of syscall activity suggests a _lot_ of contention and yielding with higher thread counts, but cutting it with RAYON_NUM_THREADS shows negative scaling after just two, and still provides less benefit than just serializing render_page.
I'll push a test branch in a bit, got soup to make and eat first :)
I think https://docs.rs/rayon/1.0.2/rayon/iter/trait.IndexedParallelIterator.html#method.with_min_len should help to avoid wasting time parallelizing small things. Rendering 10k pages from a single section however should be done concurrently.
I won't have time to look into that too much this week myself, hopefully next week.
medium-kb (1000 pages):
The scaling is just pants.
Something feels wrong, surely with n threads it should be faster than a single one since they don't do any locking... Maybe I'm using rayong wrongly
Tried a quick hack with crossbeam scope and channel and see basically the same thing, with scaling for rendering stopping around 4 and going negative soon after. So whatever the problem it doesn't seem rayon-specific.
Dear me.
components/site/src/lib.rs:165: 208.96µs - get_all_orphan_pages pages_in_sections
components/site/src/lib.rs:172: 692.05ms - get_all_orphan_pages for each page
-> Creating 1000 pages (0 orphan), 10 sections, and processing 0 images
components/site/src/lib.rs:588: 166.38ms - build clean
components/site/src/lib.rs:593: 349.64ms - build render_sections
components/site/src/lib.rs:165: 240.11µs - get_all_orphan_pages pages_in_sections
components/site/src/lib.rs:172: 707.50ms - get_all_orphan_pages for each page
components/site/src/lib.rs:596: 707.88ms - build render_orphan_pages
A build on medium-kb spends about half its time just checking orphans by repeatedly searching a vec. Twice. I dread to think how long it would take on a huge site :/
After replacing with a HashSet:
components/site/src/lib.rs:165: 1.48ms - get_all_orphan_pages pages_in_sections
components/site/src/lib.rs:172: 2.92ms - get_all_orphan_pages for each page
-> Creating 1000 pages (0 orphan), 10 sections, and processing 0 images
components/site/src/lib.rs:588: 169.72ms - build clean
components/site/src/lib.rs:593: 357.97ms - build render_sections
components/site/src/lib.rs:165: 1.51ms - get_all_orphan_pages pages_in_sections
components/site/src/lib.rs:172: 3.05ms - get_all_orphan_pages for each page
components/site/src/lib.rs:596: 4.69ms - build render_orphan_pages
The improvement increases with larger sites.
Heh, huge-kb goes from 150 seconds to 9 :)
Pull request in #424.
I guess this can be closed now :o
I should probably still set some min_len to avoid spinning up threads for nothing though.
Just saw https://github.com/Freaky/gutenberg/commit/986fda25e66a04a0b6751f305acee341bc0318c8do you want to do a PR with it as well?
Might be worth using dedicated thread pools for IO and rendering, rather than just throwing everything on the global rayon pool.
From what I've seen the IO-bound stuff scales fairly well (at least with SSD/from cache, HDD's might disagree), while rendering bottlenecks quite quickly, at least on my machine.
with_min_len is just going to band-aid specific cases: it'll leave available concurrency on the floor for small sites and will still end up using too much on larger ones. Similarly low-core-count systems could well benefit from having more threads than cores if they're spending much of their time waiting for reads.
PR #427 for the fold/reduce → collect tweak.
I did a few more tests and while huge-kb is now very fast to render, big-blog is still slow: 44s on my machine.
Loading the site (Site::load) is super fast even for big sites (1s maybe out of the 44s above) and the rest of the time is spent writing to disk.
43s for writing 1000 files to disk means something is definitely going wrong somewhere. Adding some measurements, it turns out that each pager page rendered by Site::render_paginated takes 800m-2s on my machine. par_iter does work here, it takes 100s otherwise. I couldn't find a particular reason for paginator.render_pager to be slow though, individual parts seem fast enough. That's going to be for another day!
I also had a look at replacing some clone() by using Cow in Sections but it wasn't conclusive. It doesn't seem to be a big bottleneck anyway, other than for rebuild of big sites
So, erm. huge-blog.
55788 freaky 25 52 0 19367M 19325M uwait 9 39:21 753.21% gutenberg
It's up and down like a yoyo, peaking at 24GB, dropping to 5GB, then peaking back at 24GB. Over and over. 44 seconds? I killed it after 6 minutes and nearly 2 hours of CPU burnt roughly equally between user and system.
What on earth.
-> Creating 10000 pages (0 orphan), 0 sections, and processing 0 images
render_paginated...
template_name in 6.36s
build_paginator_context in 12.12ms
render_remplate in 1.36s
paginator.render_pager in 8.05s
built in 8.05s
It takes over 6 seconds just to work out what name the template should have?
Right. So. This bit.
let template_name = match self.root {
PaginationRoot::Section(s) => {
context.insert("section", &s);
s.get_template_name()
}
from components/pagination/src/lib.rs. That context.insert("section", &s) bit, specifically. That serializes the current section using serde_json. The section with thousands and thousands of pages in it.
If I comment that one line out, huge-blog builds in 39 seconds and peaks at 3.9GB instead of 24.
I somehow missed that line yesterday :scream:
The section is only there for the metadata so we don't need to have the pages at all in it, i'll make Section::clone_without_page to handle that
After doing that (https://github.com/Keats/gutenberg/pull/398/commits/6903975202e0114a815e2266dce1bdd89a00866a), big-blog goes from 44s to 2.9s. huge-blog goes from crashing my computer to 43s. A good 10-15x improvement but the odd thing is that your computer with tons of cores is only barely faster than my 5 years old laptop with a dual core.
Looking at https://forestry.io/blog/hugo-vs-jekyll-benchmark/ it still seems Gutenberg is about 5-10x slower than Hugo but it is at least in the same ballpark now.
There's a lot of noise, but this flame graph looks... interesting.
A lot of time seems to be going into generating backtraces.
And indeed it's about 30% faster if I turn off RUST_BACKTRACE=1
Quick run on medium-blog without backtraces, and slightly tidier stack entries: https://hur.st/flame/gutenberg-demangled-medium-blog.svg
And with RAYON_NUM_THREADS=1, which is also faster: https://hur.st/flame/gutenberg-demangled-medium-blog-sequential.svg
I removed all the parallel iterators and the result is much tidier: https://hur.st/flame/gutenberg-huge-blog-no-threads-no-bt.svg
Try clicking on each section to drill down. Serde pops up a lot - serializing JSON in render_taxonomies accounts for 13% of samples all on its own.
Pages cloned in Site::populate_taxonomies(), and fed to taxonomies::find_taxonomies() where the pages are cloned again.
Might be worth investigating the use of Arc, and/or using a slotmap and keeping indexes to things instead of copying left and right.
Those SVGs flamegraph are so cool :o how do you generate them?
In your first one, highlighting::get_highlighter takes some time but should only be called if highlight_code is true in the settings, did you turn it on?
Pages cloned in Site::populate_taxonomies(), and fed to taxonomies::find_taxonomies() where the pages are cloned again.
That's also an issue in populate_sections where pages and sections are cloned a few times. The issue with keeping indices is that we want to serialize everything in order to have the pages in the template context.
I removed all the parallel iterators and the result is much tidier
That is surprising :o I had some speed regression when removing some par_iter although i didn't remove all of them.
I'll add RUST_BACKTRACE=1 to the travis/appveyor build, backtraces shouldn't be needed (ideally)
Those SVGs flamegraph are so cool :o how do you generate them?
More or less:
# dtrace -x stackframes=100 -n 'profile-197 /pid == $target/ { @[ustack()] = count(); }' -c "../../../../target/release/gutenberg build" -o out.stacks
# ~/bin/rustfilter <out.stacks >out.demangled
# perl stackcollapse.pl out.demangled | perl flamegraph.pl >out.svg
Perl scripts: https://github.com/brendangregg/FlameGraph via http://www.brendangregg.com/flamegraphs.html
rustfilter: https://gist.github.com/eddyb/3a233c4709018e92b866 - I modified it to use rustfilt instead of c++filt, and gsed instead of BSD sed.
That's also an issue in populate_sections where pages and sections are cloned a few times. The issue with keeping indices is that we want to serialize everything in order to have the pages in the template context.
Then you use the index to look it up and serialize it directly, rather than from a clone of a clone. Or use Arc to make a clone operation an atomic increment returning an immutable reference.
Might also be worth considering whether there's a better way of handling template lookups than throwing it at serde en-masse. Populate context on demand or something?
That is surprising ⭕️ I had some speed regression when removing some par_iter although i didn't remove all of them.
It didn't improve performance, it just made the stack traces tidier because they weren't full of rayon noise.
I'll add RUST_BACKTRACE=1 to the travis/appveyor build, it shouldn't be needed (ideally)
To be clear, adding that makes it slower, because error-chain then generates a lot of useless backtraces that never get used. I just have it enabled in my environment because I like wordier panics, but if it's going to kill performance... ugh.
Might also be worth considering whether there's a better way of handling template lookups than throwing it at serde en-masse. Populate context on demand or something?
I'm not sure it's possible, unless we analyze each template to see which variables are used
To be clear, adding that makes it slower, because error-chain then generates a lot of useless backtraces that never get used. I just have it enabled in my environment because I like wordier panics, but if it's going to kill performance... ugh.
Ah ok, I misunderstood.
Then you use the index to look it up and serialize it directly, rather than from a clone of a clone. Or use Arc to make a clone operation an atomic increment returning an immutable reference.
You don't have access to the context in the serde serialize method so you would need it to do it manually everywhere. I think Arc is the best bet and I'll have a look when I get some time unless someones wants to have a go
It feels very much like working against Rust because we wish it was something else. Wish it was OO, wish it had GC, wish it had weak rules on references and ownership—beat it into submission by making half a dozen copies of something, and trying to avoid that by wrapping them in two different management structures to avoid the compile-time checks.
I think a lot of it would melt away with the right refactorings. vague handwave.
To be honest, most of it are stupid mistakes from me. I just pushed a commit to the next branch that gives a ~50% speed increase because I was calculating reading analytics in the serialization instead of once when loading a page.
I think a lot of it would melt away with the right refactorings.
Any idea on that?
Sequential build on huge-blog went from 108s -> 82s, nice.
Looking at valgrind profiling, I noticed that there were quite a few calls to syntect, which shouldn't happen as the example sites don't have syntax highlighting enabled. Turns out the default for highlight_code in the Config was incorrectly true.
huge-blog is now built in 23s to have a more apple-to-apple comparison with the forestry article above
Ah yes, you mentioned that looking at the flame graphs too. 82s -> 69s \o/
Refactoring wise I think the biggest thing is sorting out who owns a Page and its relations to other things. At the moment each page seems to live in at least half a dozen different places. Maybe try to think more like a relational database than an OO programmer, because that's the sort of impedance mismatch we're looking at IMO.
Anyway, I've been playing about with this dtrace sampling stack dump and the results are quite interesting:
Most of the time is spent rendering stuff, which is hardly odd: but over half of total run-time is spent just in serde. Which given each rendered page means dumping object graphs through it several times is hardly surprising. Nearly 20% of run-time is spent just by serde chunking up Unicode:
Memory management and copying takes up a sizable chunk split up into various fragments:
I pushed a few more commits reducing cloning in the next branch.
but over half of total run-time is spent just in serde
I have opened https://github.com/Keats/tera/issues/340 which should alleviate that problem once implemented. That won't happen before a couple of months I think though, tons of stuff to do for a v1.
Updated flamegraph: https://hur.st/flame/gutenberg-huge-blog-f100d9.svg
Edit: and again with your last changes: https://hur.st/flame/gutenberg-huge-blog-69dce5.svg
Pushed another commit to speed up a bit the serialization of pages but it didn't seem to make a dent.
Looking at the last flamegraph and some valgrind, it seems the following are still pretty slow:
Site::render_paginated is a bit slower than it should beContext::insert which should be fixed by the issue mentioned above but not immediatelyWe probably can make it faster by removing the clones required for sort_pages/populate_sections/find_taxonomies but that seems like it would need a substantial refactoring and I don't think it will be a huge win vs the potential of changing the serialization in Tera.
I had a quick look and pulled the code from serde-json we would need in Tera; https://github.com/Keats/serde-tera minus all the utility methods but it seems smaller than I expected.
So, I added some logging to tera::Context::insert to see how many times stuff is being serialized. Just Context::insert: key={} bytes={} hash={:x}\n{}\n.
huge-blog, which is 24MB of content, produced this: 1071969578 Sep 21 16:59 context-add.log
80,000 entries were set. 46,000 of them were unique.
A unique string inserted on one page appeared in the output 12 times.
I'm guessing the page, its prev/next ones, n taxonomies, rss if enabled ( + n per enabled taxonomies) and a few more that I can't think of the top of my head.
I think that's the main advantage Hugo has, the template engine can use reflection so they don't need to serialize anything, they can directly call the methods from the template so they only compute what the user needs. I'm not entirely sure how to solve that and not even sure it matters that much: it's still taking less than 30s to generate 10k pages with taxonomies and pagination which is pretty fast.
Interestingly enough, after removing pagination huge-blog builds in 9.5s so there is definitely something fishy going on there that is worth a look. It shouldn't take 15s (25s - 9.5s) to render the 2k paginated pages.
where to find huge-blog
@tshepang Run gen.py in components/site/benches
Most of the time is spent creating the pagers variable in Paginator::build_paginator_context, about ~8s for the huge-blog.
In practice this field is completely useless as no one is going to list every page, they are just going to show prev/next and maybe first/last which are already present in the context. Now that Tera has string concatenations, we can just add the default pagination url to the context (without an index in it) and users can build their own pagination, although we need to add things like length and the base url mentioned before to the paginator context.
That is a breaking change though so for the next major release: https://github.com/Keats/gutenberg/issues/437
In the end I've decided to have the next version with the new name be a major version so I will do the breaking changes mentioned in this thread
I removed Paginator::pagers in the next branch and huge-blog is now built in ~10s on my machine.
It looks like #436 isn't really needed though, even with 10k pages it doesn't make a significant difference in my runs.
@Freaky how fast it is to run on your beefy machine?
There are still things to fix imo like cloning of sections/pages (Arc most of the things or a refactoring to use indices instead) but it seems fast enough for the first performance oriented release, thanks to you!
huge-blog vs RAYON_NUM_THREADS:
Still runs into diminishing returns long before I run out of cores, but the negative scaling seems to have mostly gone.
Peak memory use is now down to 2.7GB even with full 24-thread concurrency - still fairly high, but much better than when we started, which was more like 24GB.
Still seeing negative scaling on my own site:
Might be worth grabbing other real-world examples and see if this is a common pattern.
Whoa those are some big differences.
On the docs:
My blog shows roughly the same thing as the doc site: it is the fastest at 2 and gets worse and worse after that.
It really looks like we still need to do some tuning with Rayon after all, your site is 5x slower and the docs 25% slower but I'm guessing it takes longer if you have more cores
On big-site and huge-kb, RAYON_NUM_THREAD=3 is the best for me. I don't really know what to do there.
Docs:
https://hur.st/flame/gutenberg-docs-rayon-24-99215.svg
syntect occurs in nearly 62% of the sampled stacks. Nearly 30% in get_highlighter().
40% of the total samples are in syntect::dumps::from_binary().
Instrumenting the thread_local! with different thread counts gives me:
39.2% in Scope::new():
pub fn new(s: &str) -> Result<Scope, ParseScopeError> {
let mut repo = SCOPE_REPO.lock().unwrap();
repo.build(s.trim())
}
A quick hack using syntect master looks promising: SyntaxSet is now Send + Sync and a plain lazy_static! can be used. After rebuilding the dump files it uses, a docs build now looks much better:
My personal site is much better too. Before:
After:
Updated flame graph for comparison purposes: https://hur.st/flame/gutenberg-docs-rayon-24-syntect3.svg
That's some great news! I have been following the work on syntect and v3 should be released soon-ish
Wow these speedups look amazing <3
So I tried to remove the clone by using slotmap on a WIP branch: https://github.com/Keats/gutenberg/pull/459 (gutenberg serve is probably broken on it if content changes)
It is .... actually slower than next right now. Loading is faster but rendering clones way too much, I can't even build huge-blog anymore. I must have messed up something pretty badly as I would have expected the number of clones of Values to be roughly identical to the current Page/Section clone and serialization...
I would appreciate some pairs of eyes on that PR to spot what I am doing wrong.
The code is still very raw and has some pretty bad parts but it builds site correctly and passes all the tests except the ones from the rebuild crate since it might need to be changed quite a bit if loading becomes very cheap.
The idea is that there is Library that holds pages and sections which are referred to via a Key generated by slotmap. Once all the pages/sections are populated with keys, it caches the Value for that page/section meaning that rendering will just clone it without going through the serialization again.
I believe it would be possible to remove a good chunk of clone by passing borrowed Values to Tera::render but that requires to check if it's possible first and then to add the code for it.
Ooh, neat. huge-blog builds here, but with nearly 2x the memory use and 2x the runtime.
Flamegraph: https://hur.st/flame/gutenberg-huge-blog-slotmap-10aba2.svg
Nearly half of runtime's in serde.
Yep I get the same results with valgrind, it's all spent cloning Values. I don't really understand why it is copying twice more than before though, I expected it to be the same :/
Well, now instead of going from {Page,Section} -> Value, it's going {Page,Section} -> Value -> Value, no?
Without Tera being able to borrow it, I don't think it's really going to help.
@Freaky I've pushed a commit that uses this commit https://github.com/Keats/tera/pull/345/commits/efb8af88e4768d119f06579f2b66d75025470030 and we're back to reasonable speed o/
An additional speedup would be to have some way of taking some Vec<&Value> in Tera but that looks very messy. There might still be some silly things in the current code though!
Next step is to clean/document the code and rewrite the rebuild component as it is now ~30x faster to call populate_sections for example.
Yes, that's much better - half the runtime, nearly half the memory use, though latter's slightly higher than the previous baseline - 2.7GB -> 5GB -> 2.9GB.
That's only 1.5% of my main machine, but it's probably worth considering it's also about 75% of a lot of systems, particularly cheap VPS'.
That's only 1.5% of my main machine, but it's probably worth considering it's also about 75% of a lot of systems, particularly cheap VPS'.
To be fair you probably don't build a 10k pages site on a VPS. Smashing magazine moved to Hugo and only had 7500 pages: https://discourse.gohugo.io/t/smashing-magazine-s-redesign-powered-by-hugo-jamstack/5826/8
Turns out the caching layer is actually completely useless and therefore so is Tera render_with_borrowed, which I should probably remove.
Caching would only help if it was somehow possible to pass Vec<&Value> for taxonomies. It might be possible to cache the SerializedSection to avoid some looping but I'm not sure it would make a big difference.
https://github.com/Keats/gutenberg/pull/459 is ready for reviews if anyone has time!
Slotmap + syntect 3 are in the next branch.

Excellent. I'm seeing maybe ~5% performance bump on huge-blog, but also a ~13% reduction in memory use.
Syntect savings are as seen in my experimental branch, which is probably the biggest thing for me - 1.4s to 0.2s is quite noticeable :)
Latest idea: https://github.com/Keats/gutenberg/issues/480
This would solve some of the repeated serializations we're doing and very often not even using at all but is a slightly worse UX so I'm a bit conflicted.
Memory usage is still way too high but that's good enough for the 0.5.0 release tomorrow (hopefully)
What figures are you seeing?
To render a blog with 10k pages with taxonomies + pagination + syntax highlighting: around 15s and 3GB of ram.
Most helpful comment
Wow these speedups look amazing <3