[Performance] How fast/slow should Statiq.Web be?

[flcdrg]

I'm experimenting with migrating my blog from Jekyll to Statiq.Web.

One issue I'm seeing at the moment is the time it's taking for dotnet run to complete.. It is taking almost 30 minutes to process my blog posts.

Am I doing something wrong?

My Program.cs only consists of

using Statiq.App;
using Statiq.Web;

await Bootstrapper
        .Factory        
        .CreateWeb(args)
        .RunAsync();

I also cloned in the CleanBlog theme.

Here's the output from dotnet run

dotnet run --configuration release
[INFO] Statiq Framework version 1.0.0-beta.60+ea55317a9a78127a162a36ff396a08bb175c219a
[INFO] Statiq Web version 1.0.0+0a4e0ba8b318615674e2dea1fa5cf4dcc12a3887
[INFO] Root path:
       C:/dev/git/flcdrg.github.io
[INFO] Input path(s):
       theme/input
       input
[INFO] Output path:
       output
[INFO] Temp path:
       temp
[INFO] Cache path:
       cache
[INFO] ========== Execution ==========
[INFO] Executing 11 pipelines (AnalyzeContent, Archives, Assets, Content, Data, DirectoryMetadata, Feeds, Inputs, Redirects, SearchIndex, Sitemap)
[INFO] Cleaned temp directory C:/dev/git/flcdrg.github.io/temp
[INFO] Restored write tracking data from C:/dev/git/flcdrg.github.io/cache/writecache.json
[INFO] Restored Razor compilation cache from C:/dev/git/flcdrg.github.io/cache/razorcache.json with 1071 assemblies
[INFO] -> DirectoryMetadata/Input » Starting DirectoryMetadata Input phase execution... (0 input document(s), 1 module(s))
[INFO] -> Inputs/Input » Starting Inputs Input phase execution... (0 input document(s), 1 module(s))
[INFO] <- DirectoryMetadata/Input » Finished DirectoryMetadata Input phase execution (1 output document(s), 441 ms)
[INFO] -> DirectoryMetadata/Process » Starting DirectoryMetadata Process phase execution... (1 input document(s), 1 module(s))
[INFO] <- DirectoryMetadata/Process » Finished DirectoryMetadata Process phase execution (1 output document(s), 13 ms)
[INFO] <- Inputs/Input » Finished Inputs Input phase execution (1711 output document(s), 597 ms)
[INFO] -> Inputs/Process » Starting Inputs Process phase execution... (1711 input document(s), 8 module(s))
[INFO] <- Inputs/Process » Finished Inputs Process phase execution (1710 output document(s), 6607 ms)
[INFO] -> Data/Process » Starting Data Process phase execution... (0 input document(s), 5 module(s))
[INFO] -> Assets/Process » Starting Assets Process phase execution... (0 input document(s), 3 module(s))
[INFO] <- Data/Process » Finished Data Process phase execution (0 output document(s), 11 ms)
[INFO] -> Content/Process » Starting Content Process phase execution... (0 input document(s), 4 module(s))
[INFO] <- Content/Process » Finished Content Process phase execution (1057 output document(s), 798 ms)
[INFO] -> Redirects/Process » Starting Redirects Process phase execution... (0 input document(s), 2 module(s))
[INFO] -> Archives/Process » Starting Archives Process phase execution... (0 input document(s), 3 module(s))
[INFO] <- Redirects/Process » Finished Redirects Process phase execution (0 output document(s), 6 ms)
[INFO] <- Assets/Process » Finished Assets Process phase execution (649 output document(s), 1151 ms)
[INFO] <- Archives/Process » Finished Archives Process phase execution (563 output document(s), 446827 ms)
[INFO] -> Feeds/Process » Starting Feeds Process phase execution... (0 input document(s), 3 module(s))
[INFO] <- Feeds/Process » Finished Feeds Process phase execution (2 output document(s), 152656 ms)
[INFO] -> Content/PostProcess » Starting Content PostProcess phase execution... (1057 input document(s), 1 module(s))
[INFO] -> SearchIndex/PostProcess » Starting SearchIndex PostProcess phase execution... (0 input document(s), 1 module(s))
[INFO] <- SearchIndex/PostProcess » Finished SearchIndex PostProcess phase execution (0 output document(s), 0 ms)
[INFO] -> Archives/PostProcess » Starting Archives PostProcess phase execution... (563 input document(s), 1 module(s))
[INFO] -> Assets/Output » Starting Assets Output phase execution... (649 input document(s), 2 module(s))
[INFO] -> SearchIndex/Output » Starting SearchIndex Output phase execution... (0 input document(s), 1 module(s))
[INFO] -> Redirects/Output » Starting Redirects Output phase execution... (0 input document(s), 1 module(s))
[INFO] -> Data/Output » Starting Data Output phase execution... (0 input document(s), 2 module(s))
[INFO] -> Sitemap/PostProcess » Starting Sitemap PostProcess phase execution... (0 input document(s), 1 module(s))
[INFO] -> Feeds/Output » Starting Feeds Output phase execution... (2 input document(s), 2 module(s))
[INFO] <- Redirects/Output » Finished Redirects Output phase execution (0 output document(s), 3 ms)
[INFO] <- SearchIndex/Output » Finished SearchIndex Output phase execution (0 output document(s), 3 ms)
[INFO] <- Data/Output » Finished Data Output phase execution (0 output document(s), 3 ms)
[INFO] <- Sitemap/PostProcess » Finished Sitemap PostProcess phase execution (1 output document(s), 72 ms)
[INFO] -> Sitemap/Output » Starting Sitemap Output phase execution... (1 input document(s), 1 module(s))
[INFO] [Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager] User profile is available. Using 'C:\Users\david\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
[INFO] <- Assets/Output » Finished Assets Output phase execution (649 output document(s), 120 ms)
[INFO] <- Sitemap/Output » Finished Sitemap Output phase execution (1 output document(s), 402 ms)
[INFO] <- Feeds/Output » Finished Feeds Output phase execution (2 output document(s), 12186 ms)
[INFO] <- Content/PostProcess » Finished Content PostProcess phase execution (1057 output document(s), 765780 ms)
[INFO] -> Content/Output » Starting Content Output phase execution... (1057 input document(s), 2 module(s))
[INFO] <- Content/Output » Finished Content Output phase execution (1057 output document(s), 214275 ms)
[INFO] <- Archives/PostProcess » Finished Archives PostProcess phase execution (563 output document(s), 987558 ms)
[INFO] -> Archives/Output » Starting Archives Output phase execution... (563 input document(s), 2 module(s))
[INFO] <- Archives/Output » Finished Archives Output phase execution (563 output document(s), 159 ms)
[INFO] -> AnalyzeContent/Input » Starting AnalyzeContent Input phase execution... (0 input document(s), 1 module(s))
[INFO] <- AnalyzeContent/Input » Finished AnalyzeContent Input phase execution (2269 output document(s), 1 ms)
[INFO] AnalyzeContent/Process » Running 3 analyzers (ValidateAbsoluteLinks, ValidateRelativeLinks, FencedCodeBlocksShouldHaveLanguage)
[INFO] Removed 0 stale Razor assemblies from the cache
[INFO] Cached and saved 0 new Razor assemblies
[INFO] Deleted 0 stale cached Razor assembly files
[INFO] Cleaned 0 files not written to output directory C:/dev/git/flcdrg.github.io/output during current execution
[INFO] ========== Execution Summary ==========

Number of output documents per pipeline and phase:

 | Pipeline          | Input         | Process         | PostProcess      | Output           | Total Time |
 |--------------------------------------------------------------------------------------------------------|
 | AnalyzeContent    | 2269 (1 ms)   |                 |                  |                  | 1 ms       |
 | Archives          |               | 563 (446827 ms) | 563 (987558 ms)  | 563 (159 ms)     | 1434544 ms |
 | Assets            |               | 649 (1151 ms)   |                  | 649 (120 ms)     | 1271 ms    |
 | Content           |               | 1057 (798 ms)   | 1057 (765780 ms) | 1057 (214275 ms) | 980853 ms  |
 | Data              |               | 0 (11 ms)       |                  | 0 (3 ms)         | 14 ms      |
 | DirectoryMetadata | 1 (441 ms)    | 1 (13 ms)       |                  |                  | 454 ms     |
 | Feeds             |               | 2 (152656 ms)   |                  | 2 (12186 ms)     | 164842 ms  |
 | Inputs            | 1711 (597 ms) | 1710 (6607 ms)  |                  |                  | 7204 ms    |
 | Redirects         |               | 0 (6 ms)        |                  | 0 (3 ms)         | 9 ms       |
 | SearchIndex       |               |                 | 0 (0 ms)         | 0 (3 ms)         | 3 ms       |
 | Sitemap           |               |                 | 1 (72 ms)        | 1 (402 ms)       | 474 ms     |

Pipeline phase timeline:

 | Pipeline          | Timeline (1595222 total ms not including overhead)                                   |
 |----------------------------------------------------------------------------------------------------------|
 | AnalyzeContent    |                                                                                  I   |
 | Archives          |  P---------------------        T------------------------------------------------O    |
 | Assets            |  P                             O                                                     |
 | Content           |  P                             T-------------------------------------O----------     |
 | Data              |  P                             O                                                     |
 | DirectoryMetadata | IP                                                                                   |
 | Feeds             |                        P-------O                                                     |
 | Inputs            |  IP                                                                                  |
 | Redirects         |  P                             O                                                     |
 | SearchIndex       |                                TO                                                    |
 | Sitemap           |                                TO                                                    |


[INFO] ========== Analyzer Results ==========
(removed for brevity)
[WARN] 160 total relative links could not be validated (ValidateRelativeLinks)
[INFO] ========== Completed ==========
[INFO] 2272 total files output (written or already existed)
[INFO] 447 actual files written
[INFO] 1825 files already existed
[INFO] Finished in 1596219 ms:
[INFO] - Before Engine Execution Clean in 146 ms
[INFO] - Before Engine Execution Events in 141 ms
[INFO] - Analyzer Before Engine Execution Events in 1 ms
[INFO] - Engine Execution in 1595662 ms
[INFO] - After Engine Execution Events in 177 ms
[INFO] - After Engine Execution Clean in 89 ms
[INFO] Cleaned temp directory C:/dev/git/flcdrg.github.io/temp

[daveaglick]

That seems really excessive. My own blog has around 200 posts and if I extrapolate that to 1,000 with a linear assumption for performance it's no where close to this. Of course, system specs, memory, etc. all come into play - but even then this seems out of the expected range given past experiments I've done up to 10,000 randomly generated posts.

Two things I do notice:

• The output phase is even taking a while (upwards of four minutes) - that seems very odd, especially when it's reporting 1,825 files were already on disk and didn't need to be output. It only wrote 447 files, and it should never take 4 minutes to output 450ish files.
• The archives process phase took a lot longer than expected. Razor is applied in the post-process phase, so if a pipeline like archives is taking time in the process phase, something else other than Razor is what's causing it (Razor is usually the performance culprit).

This all makes me wonder if there's a race condition or a leak or something - I.e. something happening under the hood in this particular case that's not directly related to generating the site. Any change this repo with the Statiq support is public in a branch or something somewhere?

[flcdrg]

Out of interest, I renamed the 'theme' folder so it wouldn't be included and the time came right down to about 7 seconds. Tends to point the finger at something in the theme logic.

Unfortunately my repo is not public. It's just a bunch of .md files so not sure there's anything particularly odd in there.

[daveaglick]

That's a good clue though. It's been a while since I've run a large number of files test, so it's possible something in the CleanBlog theme has created scaling problems since the last time. I'll start there and see if I can isolate the issue through elimination.

[flcdrg]

I have captured a dotTrace snapshot file. Happy to share that with you if that would be useful.

[darrelmiller]

I'm seeing similar perf issues.

When I do --clean-mode full it actually gets a bit faster.

[daveaglick]

@darrelmiller any chance you're using a theme, or is this right out of the box with just your own Markdown and layouts?

[darrelmiller]

This is with the Cleanblog theme. I ran the VS profiler on the run and it seems to spend a whole lot of time calling System.Marvin.ComputeHash64 via the Concurrent dictionary. The source is here https://github.com/darrelmiller/apievolutionblog. I'll do some more poking around with the profiler and let you know if I find anything.

[daveaglick]

That suggests maybe it's with the caching logic (which relies in part on content hashes). If that's the case though I wouldn't necessarily expect theme vs. no theme to make a big difference. I probably won't have a chance to dig in until later this week, so let me know if you find something interesting before then.

Happy New Year! 🎇